Add more extensive debug-level logging

- Logging of event IDs
- Logging of command invocations (at DEBUG)

PluralKit.Bot/Bot.cs

@@ -11,13 +11,9 @@ using Discord.Commands;
 using Discord.WebSocket;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
-using NodaTime;
 using Sentry;
 using Serilog;
-using Serilog.Core;
 using Serilog.Events;
-using Serilog.Formatting.Compact;
-using Serilog.Sinks.SystemConsole.Themes;
 
 namespace PluralKit.Bot
 {
@@ -130,7 +126,10 @@ namespace PluralKit.Bot
             .AddScoped(_ => new Sentry.Scope(null))
             .AddTransient<PKEventHandler>()
 
-            .AddSingleton(svc => InitUtils.InitLogger(svc.GetRequiredService<CoreConfig>(), "bot"))
+            .AddScoped<EventIdProvider>()
+            .AddSingleton(svc => new LoggerProvider(svc.GetRequiredService<CoreConfig>(), "bot"))
+            .AddScoped(svc => svc.GetRequiredService<LoggerProvider>().RootLogger.ForContext("EventId", svc.GetRequiredService<EventIdProvider>().EventId))
+            
             .BuildServiceProvider();
     }
     class Bot
@@ -333,6 +332,8 @@ namespace PluralKit.Bot
                 arg.HasStringPrefix("pk!", ref argPos, StringComparison.OrdinalIgnoreCase) ||
                 arg.HasMentionPrefix(_client.CurrentUser, ref argPos))
             {
+                _logger.Debug("Parsing command {Command} from message {Channel}-{Message}", msg.Content, msg.Channel.Id, msg.Id);
+                
                 // Essentially move the argPos pointer by however much whitespace is at the start of the post-argPos string
                 var trimStartLengthDiff = arg.Content.Substring(argPos).Length -
                                           arg.Content.Substring(argPos).TrimStart().Length;

PluralKit.Core/Utils.cs

@@ -17,7 +17,11 @@ using NodaTime.Text;
 using Npgsql;
 using PluralKit.Core;
 using Serilog;
+using Serilog.Core;
+using Serilog.Events;
 using Serilog.Formatting.Compact;
+using Serilog.Formatting.Display;
+using Serilog.Formatting.Json;
 using Serilog.Sinks.SystemConsole.Themes;
 
 
@@ -304,13 +308,15 @@ namespace PluralKit
         {
             return new LoggerConfiguration()
                 .ConfigureForNodaTime(DateTimeZoneProviders.Tzdb)
+                .MinimumLevel.Debug()
                 .WriteTo.File(
-                    new CompactJsonFormatter(),
+                    new RenderedCompactJsonFormatter(),
                     (config.LogDir ?? "logs") + $"/pluralkit.{component}.log",
                     rollingInterval: RollingInterval.Day,
                     flushToDiskInterval: TimeSpan.FromSeconds(10),
+                    restrictedToMinimumLevel: LogEventLevel.Information,
                     buffered: true)
-                .WriteTo.Console(theme: AnsiConsoleTheme.Code)
+                .WriteTo.Console(theme: AnsiConsoleTheme.Code, outputTemplate:"[{Timestamp:HH:mm:ss}] [{EventId}] {Level:u3} {Message:lj}{NewLine}{Exception}")
                 .CreateLogger();
         }
 
@@ -323,6 +329,18 @@ namespace PluralKit
         }
     }
 
+    public class LoggerProvider
+    {
+        private CoreConfig _config;
+        public ILogger RootLogger { get; }
+
+        public LoggerProvider(CoreConfig config, string component)
+        {
+            _config = config;
+            RootLogger = InitUtils.InitLogger(_config, component);
+        }
+    }
+
     public class UlongEncodeAsLongHandler : SqlMapper.TypeHandler<ulong>
     {
         public override ulong Parse(object value)
@@ -457,4 +475,14 @@ namespace PluralKit
 
         public ConnectionState State => _impl.State;
     }
+
+    public class EventIdProvider
+    {
+        public Guid EventId { get; }
+
+        public EventIdProvider()
+        {
+            EventId = Guid.NewGuid();
+        }
+    }
 }