diff --git a/PluralKit.Bot/Bot.cs b/PluralKit.Bot/Bot.cs index 6ccb3e2a..f63aec6a 100644 --- a/PluralKit.Bot/Bot.cs +++ b/PluralKit.Bot/Bot.cs @@ -103,19 +103,10 @@ namespace PluralKit.Bot async Task HandleEventInner() { using var _ = LogContext.PushProperty("EventId", Guid.NewGuid()); + _logger + .ForContext("Elastic", "yes?") + .Debug("Gateway event: {@Event}", evt); - // Mainly for testing ELK volume atm, no-op unless Elastic is configured - if (evt is MessageCreateEventArgs mc) - using (LogContext.PushProperty("Elastic", "yes?")) - _logger.Information("Received event {@Event}", new - { - Type = mc.GetType().Name.Replace("EventArgs", ""), - MessageId = mc.Message.Id, - ChannelId = mc.Channel.Id, - GuildId = mc.Guild?.Id ?? 0, - UserId = mc.Author.Id, - }); - await using var serviceScope = _services.BeginLifetimeScope(); // Also, find a Sentry enricher for the event type (if one is present), and ask it to put some event data in the Sentry scope @@ -146,7 +137,13 @@ namespace PluralKit.Bot // Make this beforehand so we can access the event ID for logging var sentryEvent = new SentryEvent(exc); - _logger.Error(exc, "Exception in bot event handler (Sentry ID: {SentryEventId})", sentryEvent.EventId); + _logger + .ForContext("Elastic", "yes?") + .Error(exc, "Exception in event handler: {{SentryEventId}}", sentryEvent.EventId); + + // If the event is us responding to our own error messages, don't bother logging + if (evt is MessageCreateEventArgs mc && mc.Author.Id == _client.CurrentUser.Id) + return; var shouldReport = exc.IsOurProblem(); if (shouldReport) diff --git a/PluralKit.Bot/Init.cs b/PluralKit.Bot/Init.cs index 75a3421e..f3255434 100644 --- a/PluralKit.Bot/Init.cs +++ b/PluralKit.Bot/Init.cs @@ -116,7 +116,10 @@ namespace PluralKit.Bot var builder = new ContainerBuilder(); builder.RegisterInstance(config); builder.RegisterModule(new ConfigModule("Bot")); - builder.RegisterModule(new LoggingModule("bot")); + builder.RegisterModule(new LoggingModule("bot", cfg => + { + cfg.Destructure.With(); + })); builder.RegisterModule(new MetricsModule()); builder.RegisterModule(); builder.RegisterModule(); diff --git a/PluralKit.Bot/Tracing/DiscordRequestObserver.cs b/PluralKit.Bot/Tracing/DiscordRequestObserver.cs index 621a5cb9..756d4ec3 100644 --- a/PluralKit.Bot/Tracing/DiscordRequestObserver.cs +++ b/PluralKit.Bot/Tracing/DiscordRequestObserver.cs @@ -30,7 +30,7 @@ namespace PluralKit.Bot public void OnError(Exception error) { } - public string NormalizeRoutePath(string url) + private string NormalizeRoutePath(string url) { url = Regex.Replace(url, @"/channels/\d{17,19}", "/channels/{channel_id}"); url = Regex.Replace(url, @"/messages/\d{17,19}", "/messages/{message_id}"); @@ -51,13 +51,25 @@ namespace PluralKit.Bot return url; } - public async Task HandleResponse(HttpResponseMessage response, Activity activity) + private string Endpoint(HttpRequestMessage req) + { + var routePath = NormalizeRoutePath(req.RequestUri.LocalPath.Replace("/api/v7", "")); + return $"{req.Method} {routePath}"; + } + + private void HandleException(Exception exc, HttpRequestMessage req) + { + _logger + .ForContext("RequestUrlRoute", Endpoint(req)) + .Error(exc, "HTTP error: {RequestMethod} {RequestUrl}", req.Method, req.RequestUri); + } + + private async Task HandleResponse(HttpResponseMessage response, Activity activity) { if (response.RequestMessage.RequestUri.Host != "discord.com") return; - var routePath = NormalizeRoutePath(response.RequestMessage.RequestUri.LocalPath.Replace("/api/v7", "")); - var route = $"{response.RequestMessage.Method} {routePath}"; + var endpoint = Endpoint(response.RequestMessage); using (LogContext.PushProperty("Elastic", "yes?")) { @@ -67,10 +79,10 @@ namespace PluralKit.Bot LogContext.PushProperty("ResponseBody", content); } - LogContext.PushProperty("RequestUrlRoute", route); - - _logger.Information( - "HTTP {RequestMethod} {RequestUrl} -> {ResponseStatusCode} {ResponseStatusString} (in {RequestDurationMs:F1} ms)", + _logger + .ForContext("RequestUrlRoute", endpoint) + .Information( + "HTTP: {RequestMethod} {RequestUrl} -> {ResponseStatusCode} {ResponseStatusString} (in {RequestDurationMs:F1} ms)", response.RequestMessage.Method, response.RequestMessage.RequestUri, (int) response.StatusCode, @@ -80,32 +92,55 @@ namespace PluralKit.Bot var timer = _metrics.Provider.Timer.Instance(BotMetrics.DiscordApiRequests, new MetricTags( new[] {"endpoint", "status_code"}, - new[] {route, ((int) response.StatusCode).ToString()} + new[] {endpoint, ((int) response.StatusCode).ToString()} )); timer.Record(activity.Duration.Ticks / 10, TimeUnit.Microseconds); } public void OnNext(KeyValuePair value) { - if (value.Key == "System.Net.Http.HttpRequestOut.Stop") + switch (value.Key) { - var data = Unsafe.As(value.Value); - var _ = HandleResponse(data.Response, Activity.Current); + case "System.Net.Http.HttpRequestOut.Stop": + { + var data = Unsafe.As(value.Value); + if (data.Response != null) + { + var _ = HandleResponse(data.Response, Activity.Current); + } + + break; + } + case "System.Net.Http.Exception": + { + var data = Unsafe.As(value.Value); + HandleException(data.Exception, data.Request); + break; + } } } - + public static void Install(IComponentContext services) { DiagnosticListener.AllListeners.Subscribe(new ListenerObserver(services)); } - private class TypedData +#pragma warning disable 649 + private class ActivityStopData { // Field order here matters! public HttpResponseMessage Response; public HttpRequestMessage Request; public TaskStatus RequestTaskStatus; } + + private class ExceptionData + { + // Field order here matters! + public Exception Exception; + public HttpRequestMessage Request; + } +#pragma warning restore 649 public class ListenerObserver: IObserver { diff --git a/PluralKit.Bot/Tracing/EventDestructuring.cs b/PluralKit.Bot/Tracing/EventDestructuring.cs new file mode 100644 index 00000000..10ca6a8a --- /dev/null +++ b/PluralKit.Bot/Tracing/EventDestructuring.cs @@ -0,0 +1,55 @@ +using System.Collections.Generic; + +using DSharpPlus.Entities; +using DSharpPlus.EventArgs; + +using Serilog.Core; +using Serilog.Events; + +namespace PluralKit.Bot +{ + public class EventDestructuring: IDestructuringPolicy + { + public bool TryDestructure(object value, ILogEventPropertyValueFactory propertyValueFactory, + out LogEventPropertyValue result) + { + if (!(value is DiscordEventArgs dea)) + { + result = null; + return false; + } + + var props = new List + { + new LogEventProperty("Type", new ScalarValue(dea.EventType())), + new LogEventProperty("Shard", new ScalarValue(dea.Client.ShardId)) + }; + + void AddMessage(DiscordMessage msg) + { + props.Add(new LogEventProperty("MessageId", new ScalarValue(msg.Id))); + props.Add(new LogEventProperty("ChannelId", new ScalarValue(msg.ChannelId))); + props.Add(new LogEventProperty("GuildId", new ScalarValue(msg.Channel.GuildId))); + + if (msg.Author != null) + props.Add(new LogEventProperty("AuthorId", new ScalarValue(msg.Author.Id))); + } + + if (value is MessageCreateEventArgs mc) + AddMessage(mc.Message); + else if (value is MessageUpdateEventArgs mu) + AddMessage(mu.Message); + else if (value is MessageDeleteEventArgs md) + AddMessage(md.Message); + else if (value is MessageReactionAddEventArgs mra) + { + AddMessage(mra.Message); + props.Add(new LogEventProperty("ReactingUserId", new ScalarValue(mra.User.Id))); + props.Add(new LogEventProperty("Emoji", new ScalarValue(mra.Emoji.GetDiscordName()))); + } + + result = new StructureValue(props); + return true; + } + } +} \ No newline at end of file diff --git a/PluralKit.Bot/Utils/DiscordUtils.cs b/PluralKit.Bot/Utils/DiscordUtils.cs index 57422636..90075445 100644 --- a/PluralKit.Bot/Utils/DiscordUtils.cs +++ b/PluralKit.Bot/Utils/DiscordUtils.cs @@ -9,6 +9,7 @@ using System.Threading.Tasks; using DSharpPlus; using DSharpPlus.Entities; +using DSharpPlus.EventArgs; using DSharpPlus.Exceptions; using NodaTime; @@ -23,13 +24,13 @@ namespace PluralKit.Bot public static DiscordColor Green = new DiscordColor(0x00cc78); public static DiscordColor Red = new DiscordColor(0xef4b3d); public static DiscordColor Gray = new DiscordColor(0x979c9f); - + public static Permissions DM_PERMISSIONS = (Permissions) 0b00000_1000110_1011100110000_000000; - + private static readonly Regex USER_MENTION = new Regex("<@!?(\\d{17,19})>"); private static readonly Regex ROLE_MENTION = new Regex("<@&(\\d{17,19})>"); private static readonly Regex EVERYONE_HERE_MENTION = new Regex("@(everyone|here)"); - + // Discord uses Khan Academy's simple-markdown library for parsing Markdown, // which uses the following regex for link detection: // ^(https?:\/\/[^\s<]+[^<.,:;"')\]\s]) @@ -38,9 +39,11 @@ namespace PluralKit.Bot // I added ? at the start/end; they need to be handled specially later... private static readonly Regex UNBROKEN_LINK_REGEX = new Regex("?"); - private static readonly FieldInfo _roleIdsField = typeof(DiscordMember).GetField("_role_ids", BindingFlags.NonPublic | BindingFlags.Instance); + private static readonly FieldInfo _roleIdsField = + typeof(DiscordMember).GetField("_role_ids", BindingFlags.NonPublic | BindingFlags.Instance); - public static string NameAndMention(this DiscordUser user) { + public static string NameAndMention(this DiscordUser user) + { return $"{user.Username}#{user.Discriminator} ({user.Mention})"; } @@ -50,12 +53,12 @@ namespace PluralKit.Bot { ValidateCachedRoles(member); var permissions = channel.PermissionsFor(member); - + // This method doesn't account for channels without read permissions // If we don't have read permissions in the channel, we don't have *any* permissions if ((permissions & Permissions.AccessChannels) != Permissions.AccessChannels) return Permissions.None; - + return permissions; } @@ -78,16 +81,16 @@ namespace PluralKit.Bot if (member != null) return PermissionsInSync(channel, member); } - + return PermissionsInSync(channel, user); } - + // Same as PermissionsIn, but always synchronous. DiscordUser must be a DiscordMember if channel is in guild. public static Permissions PermissionsInSync(this DiscordChannel channel, DiscordUser user) { if (channel.Guild != null && !(user is DiscordMember)) throw new ArgumentException("Function was passed a guild channel but a non-member DiscordUser"); - + if (user is DiscordMember m) return PermissionsInGuild(channel, m); if (channel.Type == ChannelType.Private) return DM_PERMISSIONS; return Permissions.None; @@ -106,7 +109,7 @@ namespace PluralKit.Bot public static bool BotHasAllPermissions(this DiscordChannel channel, Permissions permissionSet) => (BotPermissions(channel) & permissionSet) == permissionSet; - public static Instant SnowflakeToInstant(ulong snowflake) => + public static Instant SnowflakeToInstant(ulong snowflake) => Instant.FromUtc(2015, 1, 1, 0, 0, 0) + Duration.FromMilliseconds(snowflake >> 22); public static ulong InstantToSnowflake(Instant time) => @@ -128,42 +131,46 @@ namespace PluralKit.Bot // Workaround for https://github.com/DSharpPlus/DSharpPlus/issues/565 return input?.Replace("%20", "+"); } - - public static Task SendMessageFixedAsync(this DiscordChannel channel, string content = null, DiscordEmbed embed = null, IEnumerable mentions = null) => + + public static Task SendMessageFixedAsync(this DiscordChannel channel, string content = null, + DiscordEmbed embed = null, + IEnumerable mentions = null) => // Passing an empty list blocks all mentions by default (null allows all through) channel.SendMessageAsync(content, embed: embed, mentions: mentions ?? new IMention[0]); - + // This doesn't do anything by itself (DiscordMember.SendMessageAsync doesn't take a mentions argument) // It's just here for consistency so we don't use the standard SendMessageAsync method >.> - public static Task SendMessageFixedAsync(this DiscordMember member, string content = null, DiscordEmbed embed = null) => + public static Task SendMessageFixedAsync(this DiscordMember member, string content = null, + DiscordEmbed embed = null) => member.SendMessageAsync(content, embed: embed); public static bool TryGetCachedUser(this DiscordClient client, ulong id, out DiscordUser user) { user = null; - + var cache = (ConcurrentDictionary) typeof(BaseDiscordClient) .GetProperty("UserCache", BindingFlags.Instance | BindingFlags.NonPublic) ?.GetValue(client); return cache != null && cache.TryGetValue(id, out user); } - + public static DiscordColor? ToDiscordColor(this string color) { if (int.TryParse(color, NumberStyles.HexNumber, null, out var colorInt)) return new DiscordColor(colorInt); throw new ArgumentException($"Invalid color string '{color}'."); } - + public static bool HasMentionPrefix(string content, ref int argPos, out ulong mentionId) { mentionId = 0; - + // Roughly ported from Discord.Commands.MessageExtensions.HasMentionPrefix if (string.IsNullOrEmpty(content) || content.Length <= 3 || (content[0] != '<' || content[1] != '@')) return false; int num = content.IndexOf('>'); - if (num == -1 || content.Length < num + 2 || content[num + 1] != ' ' || !TryParseMention(content.Substring(0, num + 1), out mentionId)) + if (num == -1 || content.Length < num + 2 || content[num + 1] != ' ' || + !TryParseMention(content.Substring(0, num + 1), out mentionId)) return false; argPos = num + 2; return true; @@ -174,7 +181,7 @@ namespace PluralKit.Bot if (ulong.TryParse(potentialMention, out id)) return true; var match = USER_MENTION.Match(potentialMention); - if (match.Success && match.Index == 0 && match.Length == potentialMention.Length) + if (match.Success && match.Index == 0 && match.Length == potentialMention.Length) { id = ulong.Parse(match.Groups[1].Value, NumberStyles.None, CultureInfo.InvariantCulture); return true; @@ -183,12 +190,13 @@ namespace PluralKit.Bot return false; } - public static IEnumerable ParseAllMentions(this string input, bool allowEveryone = false, DiscordGuild guild = null) + public static IEnumerable ParseAllMentions(this string input, bool allowEveryone = false, + DiscordGuild guild = null) { var mentions = new List(); mentions.AddRange(USER_MENTION.Matches(input) .Select(x => new UserMention(ulong.Parse(x.Groups[1].Value)) as IMention)); - + // Only allow role mentions through where the role is actually listed as *mentionable* // (ie. any user can @ them, regardless of permissions) // Still let the allowEveryone flag override this though (privileged users can @ *any* role) @@ -213,7 +221,7 @@ namespace PluralKit.Bot { if (input == null) return null; - + // Break all pairs of backticks by placing a ZWNBSP (U+FEFF) between them. // Run twice to catch any pairs that are created from the first pass var escaped = input @@ -223,7 +231,7 @@ namespace PluralKit.Bot // Escape the start/end of the string if necessary to better "connect" with other things if (escaped.StartsWith("`")) escaped = "\ufeff" + escaped; if (escaped.EndsWith("`")) escaped = escaped + "\ufeff"; - + return escaped; } @@ -234,38 +242,41 @@ namespace PluralKit.Bot return $"``{EscapeBacktickPair(input)}``"; } - public static Task GetUser(this DiscordRestClient client, ulong id) => + public static Task GetUser(this DiscordRestClient client, ulong id) => WrapDiscordCall(client.GetUserAsync(id)); - public static Task GetUser(this DiscordClient client, ulong id) => + public static Task GetUser(this DiscordClient client, ulong id) => WrapDiscordCall(client.GetUserAsync(id)); - public static Task GetChannel(this DiscordRestClient client, ulong id) => + public static Task GetChannel(this DiscordRestClient client, ulong id) => WrapDiscordCall(client.GetChannelAsync(id)); - - public static Task GetChannel(this DiscordClient client, ulong id) => + + public static Task GetChannel(this DiscordClient client, ulong id) => WrapDiscordCall(client.GetChannelAsync(id)); - - public static Task GetGuild(this DiscordRestClient client, ulong id) => + + public static Task GetGuild(this DiscordRestClient client, ulong id) => WrapDiscordCall(client.GetGuildAsync(id)); - - public static Task GetGuild(this DiscordClient client, ulong id) => + + public static Task GetGuild(this DiscordClient client, ulong id) => WrapDiscordCall(client.GetGuildAsync(id)); - + public static Task GetMember(this DiscordRestClient client, ulong guild, ulong user) { - async Task Inner() => - await (await client.GetGuildAsync(guild)).GetMemberAsync(user); - return WrapDiscordCall(Inner()); - } - public static Task GetMember(this DiscordClient client, ulong guild, ulong user) - { - async Task Inner() => + async Task Inner() => await (await client.GetGuildAsync(guild)).GetMemberAsync(user); + return WrapDiscordCall(Inner()); } - public static Task GetMember(this DiscordGuild guild, ulong user) => + public static Task GetMember(this DiscordClient client, ulong guild, ulong user) + { + async Task Inner() => + await (await client.GetGuildAsync(guild)).GetMemberAsync(user); + + return WrapDiscordCall(Inner()); + } + + public static Task GetMember(this DiscordGuild guild, ulong user) => WrapDiscordCall(guild.GetMemberAsync(user)); public static Task GetMessage(this DiscordChannel channel, ulong id) => @@ -282,17 +293,21 @@ namespace PluralKit.Bot shard.Guilds.TryGetValue(id, out guild); if (guild != null) return guild; } + return null; } - public static async Task GetChannel(this DiscordShardedClient client, ulong id, ulong? guildId = null) + public static async Task GetChannel(this DiscordShardedClient client, ulong id, + ulong? guildId = null) { // we need to know the channel's guild ID to get the cached guild object, so we grab it from the API - if (guildId == null) { + if (guildId == null) + { var channel = await WrapDiscordCall(client.ShardClients.Values.FirstOrDefault().GetChannelAsync(id)); if (channel != null) guildId = channel.GuildId; else return null; // we probably don't have the guild in cache if the API doesn't give it to us } + return client.GetGuild(guildId.Value).GetChannel(id); } @@ -325,7 +340,7 @@ namespace PluralKit.Bot // Add the first page to the embed description if (pages.Count > 0) eb.WithDescription(pages[0]); - + // Add the rest to blank-named (\u200B) fields for (var i = 1; i < pages.Count; i++) eb.AddField("\u200B", pages[i]); @@ -343,5 +358,8 @@ namespace PluralKit.Bot return match.Value; return $"<{match.Value}>"; }); + + public static string EventType(this DiscordEventArgs evt) => + evt.GetType().Name.Replace("EventArgs", ""); } } diff --git a/PluralKit.Core/Modules.cs b/PluralKit.Core/Modules.cs index 0a490b35..e99c24be 100644 --- a/PluralKit.Core/Modules.cs +++ b/PluralKit.Core/Modules.cs @@ -82,10 +82,12 @@ namespace PluralKit.Core public class LoggingModule: Module { private readonly string _component; + private readonly Action _fn; - public LoggingModule(string component) + public LoggingModule(string component, Action fn = null) { _component = component; + _fn = fn ?? (_ => { }); } protected override void Load(ContainerBuilder builder) @@ -143,6 +145,7 @@ namespace PluralKit.Core c => c.Elasticsearch(elasticConfig)); } + _fn.Invoke(logger); return logger.CreateLogger(); } }