More updates to event infrastructure

PluralKit.Bot/Bot.cs

@@ -103,18 +103,9 @@ namespace PluralKit.Bot
             async Task HandleEventInner()
             {
                 using var _ = LogContext.PushProperty("EventId", Guid.NewGuid());
-                
+                _logger
-                // Mainly for testing ELK volume atm, no-op unless Elastic is configured
+                    .ForContext("Elastic", "yes?")
-                if (evt is MessageCreateEventArgs mc)
+                    .Debug("Gateway event: {@Event}", evt);
-                    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();
                 
@@ -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)

PluralKit.Bot/Init.cs

@@ -116,7 +116,10 @@ namespace PluralKit.Bot
             var builder = new ContainerBuilder();
             builder.RegisterInstance(config);
             builder.RegisterModule(new ConfigModule<BotConfig>("Bot"));
-            builder.RegisterModule(new LoggingModule("bot"));
+            builder.RegisterModule(new LoggingModule("bot", cfg =>
+            {
+                cfg.Destructure.With<EventDestructuring>();
+            }));
             builder.RegisterModule(new MetricsModule());
             builder.RegisterModule<DataStoreModule>();
             builder.RegisterModule<BotModule>();

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 endpoint = Endpoint(response.RequestMessage);
-            var route = $"{response.RequestMessage.Method} {routePath}";
 
             using (LogContext.PushProperty("Elastic", "yes?"))
             {
@@ -67,10 +79,10 @@ namespace PluralKit.Bot
                     LogContext.PushProperty("ResponseBody", content);
                 }
                 
-                LogContext.PushProperty("RequestUrlRoute", route);
+                _logger
-                
+                    .ForContext("RequestUrlRoute", endpoint)
-                _logger.Information(
+                    .Information(
-                    "HTTP {RequestMethod} {RequestUrl} -> {ResponseStatusCode} {ResponseStatusString} (in {RequestDurationMs:F1} ms)",
+                    "HTTP: {RequestMethod} {RequestUrl} -> {ResponseStatusCode} {ResponseStatusString} (in {RequestDurationMs:F1} ms)",
                     response.RequestMessage.Method,
                     response.RequestMessage.RequestUri,
                     (int) response.StatusCode,
@@ -80,18 +92,32 @@ 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<string, object> value)
         {
-            if (value.Key == "System.Net.Http.HttpRequestOut.Stop")
+            switch (value.Key)
+            {
+                case "System.Net.Http.HttpRequestOut.Stop":
+                {
+                    var data = Unsafe.As<ActivityStopData>(value.Value);
+                    if (data.Response != null)
                     {
-                var data = Unsafe.As<TypedData>(value.Value);
                         var _ = HandleResponse(data.Response, Activity.Current);
                     }
+
+                    break;
+                }
+                case "System.Net.Http.Exception":
+                {
+                    var data = Unsafe.As<ExceptionData>(value.Value);
+                    HandleException(data.Exception, data.Request);
+                    break;
+                }
+            }
         }
 
         public static void Install(IComponentContext services)
@@ -99,7 +125,8 @@ namespace PluralKit.Bot
             DiagnosticListener.AllListeners.Subscribe(new ListenerObserver(services));
         }
         
-        private class TypedData
+#pragma warning disable 649
+        private class ActivityStopData
         {
             // Field order here matters!
             public HttpResponseMessage Response;
@@ -107,6 +134,14 @@ namespace PluralKit.Bot
             public TaskStatus RequestTaskStatus;
         }
         
+        private class ExceptionData
+        {
+            // Field order here matters!
+            public Exception Exception;
+            public HttpRequestMessage Request;
+        }
+#pragma warning restore 649
+
         public class ListenerObserver: IObserver<DiagnosticListener>
         {
             private readonly IComponentContext _services;

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<LogEventProperty>
+            {
+                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;
+        }
+    }
+}

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;
@@ -38,9 +39,11 @@ namespace PluralKit.Bot
         // I added <? and >? at the start/end; they need to be handled specially later...
         private static readonly Regex UNBROKEN_LINK_REGEX = new Regex("<?(https?:\\/\\/[^\\s<]+[^<.,:;\"')\\]\\s])>?");
 
-        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})";
         }
 
@@ -129,13 +132,16 @@ namespace PluralKit.Bot
             return input?.Replace("%20", "+");
         }
 
-        public static Task<DiscordMessage> SendMessageFixedAsync(this DiscordChannel channel, string content = null, DiscordEmbed embed = null, IEnumerable<IMention> mentions = null) =>
+        public static Task<DiscordMessage> SendMessageFixedAsync(this DiscordChannel channel, string content = null,
+                                                                 DiscordEmbed embed = null,
+                                                                 IEnumerable<IMention> 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<DiscordMessage> SendMessageFixedAsync(this DiscordMember member, string content = null, DiscordEmbed embed = null) =>
+        public static Task<DiscordMessage> 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)
@@ -163,7 +169,8 @@ namespace PluralKit.Bot
             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;
@@ -183,7 +190,8 @@ namespace PluralKit.Bot
             return false;
         }
 
-        public static IEnumerable<IMention> ParseAllMentions(this string input, bool allowEveryone = false, DiscordGuild guild = null)
+        public static IEnumerable<IMention> ParseAllMentions(this string input, bool allowEveryone = false,
+                                                             DiscordGuild guild = null)
         {
             var mentions = new List<IMention>();
             mentions.AddRange(USER_MENTION.Matches(input)
@@ -256,12 +264,15 @@ namespace PluralKit.Bot
         {
             async Task<DiscordMember> Inner() =>
                 await (await client.GetGuildAsync(guild)).GetMemberAsync(user);
+
             return WrapDiscordCall(Inner());
         }
+
         public static Task<DiscordMember> GetMember(this DiscordClient client, ulong guild, ulong user)
         {
             async Task<DiscordMember> Inner() =>
                 await (await client.GetGuildAsync(guild)).GetMemberAsync(user);
+
             return WrapDiscordCall(Inner());
         }
 
@@ -282,17 +293,21 @@ namespace PluralKit.Bot
                 shard.Guilds.TryGetValue(id, out guild);
                 if (guild != null) return guild;
             }
+
             return null;
         }
 
-        public static async Task<DiscordChannel> GetChannel(this DiscordShardedClient client, ulong id, ulong? guildId = null)
+        public static async Task<DiscordChannel> 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);
         }
 
@@ -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", "");
     }
 }

PluralKit.Core/Modules.cs

@@ -82,10 +82,12 @@ namespace PluralKit.Core
     public class LoggingModule: Module
     {
         private readonly string _component;
+        private readonly Action<LoggerConfiguration> _fn;
 
-        public LoggingModule(string component)
+        public LoggingModule(string component, Action<LoggerConfiguration> 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();
         }
     }