Add Elastic-bound logging of (almost) all database update events

PluralKit.Bot/Bot.cs

@@ -175,14 +175,14 @@ namespace PluralKit.Bot
         
         private async Task UpdatePeriodic()
         {
-            _logger.Information("Running once-per-minute scheduled tasks");
+            _logger.Debug("Running once-per-minute scheduled tasks");
 
             await UpdateBotStatus();
 
             // Collect some stats, submit them to the metrics backend
             await _collector.CollectStats();
             await Task.WhenAll(((IMetricsRoot) _metrics).ReportRunner.RunAllAsync());
-            _logger.Information("Submitted metrics to backend");
+            _logger.Debug("Submitted metrics to backend");
         }
 
         private async Task UpdateBotStatus(DiscordClient specificShard = null)

PluralKit.Bot/Services/PeriodicStatCollector.cs

@@ -101,7 +101,7 @@ namespace PluralKit.Bot
             _metrics.Measure.Gauge.SetValue(BotMetrics.WebhookCacheSize, _webhookCache.CacheSize);
 
             stopwatch.Stop();
-            _logger.Information("Updated metrics in {Time}", stopwatch.ElapsedDuration());
+            _logger.Debug("Updated metrics in {Time}", stopwatch.ElapsedDuration());
         }
 
         public class Counts

PluralKit.Bot/Tracing/DiscordRequestObserver.cs

@@ -81,7 +81,7 @@ namespace PluralKit.Bot
                 
                 _logger
                     .ForContext("RequestUrlRoute", endpoint)
-                    .Information(
+                    .Debug(
                     "HTTP: {RequestMethod} {RequestUrl} -> {ResponseStatusCode} {ResponseStatusString} (in {RequestDurationMs:F1} ms)",
                     response.RequestMessage.Method,
                     response.RequestMessage.RequestUri,

PluralKit.Bot/Tracing/EventDestructuring.cs

@@ -22,7 +22,6 @@ namespace PluralKit.Bot
             var props = new List<LogEventProperty>
             {
                 new LogEventProperty("Type", new ScalarValue(dea.EventType())),
-                new LogEventProperty("Shard", new ScalarValue(dea.Client.ShardId))
             };
 
             void AddMessage(DiscordMessage msg)
@@ -48,6 +47,9 @@ namespace PluralKit.Bot
                 props.Add(new LogEventProperty("Emoji", new ScalarValue(mra.Emoji.GetDiscordName())));
             }
             
+            // Want shard last, just for visual reasons
+            props.Add(new LogEventProperty("Shard", new ScalarValue(dea.Client.ShardId)));
+
             result = new StructureValue(props);
             return true;
         }

PluralKit.Core/Logging/PatchObjectDestructuring.cs

@@ -0,0 +1,30 @@
+using System.Collections.Generic;
+
+using Serilog.Core;
+using Serilog.Events;
+
+namespace PluralKit.Core
+{
+    public class PatchObjectDestructuring: IDestructuringPolicy
+    {
+        public bool TryDestructure(object value, ILogEventPropertyValueFactory factory,
+                                   out LogEventPropertyValue result)
+        {
+            result = null;
+            if (!(value is PatchObject po)) return false;
+            
+            var propList = new List<LogEventProperty>();
+            foreach (var props in po.GetType().GetProperties())
+            {
+                var propValue = props.GetValue(po);
+                if (propValue is IPartial p && p.IsPresent)
+                    propList.Add(new LogEventProperty(props.Name, factory.CreatePropertyValue(p.RawValue)));
+                else if (!(propValue is IPartial))
+                    propList.Add(new LogEventProperty(props.Name, factory.CreatePropertyValue(propValue)));
+            }
+
+            result = new StructureValue(propList);
+            return true;
+        }
+    }
+}

PluralKit.Core/Logging/ScalarFormatting.cs

@@ -0,0 +1,54 @@
+using System;
+using System.IO;
+
+using Serilog.Formatting.Elasticsearch;
+using Serilog.Formatting.Json;
+
+namespace PluralKit.Core
+{
+    public class ScalarFormatting
+    {
+        private static bool Write(object value, TextWriter output)
+        {
+            if (value is SystemId si)
+                output.Write(si.Value);
+            else if (value is MemberId mi)
+                output.Write(mi.Value);
+            else if (value is GroupId gi)
+                output.Write(gi.Value);
+            else if (value is SwitchId swi)
+                output.Write(swi.Value);
+            else
+                return false;
+            return true;
+        }
+
+        private static void WriteV(object value, TextWriter output) => Write(value, output);
+
+        public class Elasticsearch: ElasticsearchJsonFormatter
+        {
+            public Elasticsearch(bool omitEnclosingObject = false, string closingDelimiter = null,
+                                 bool renderMessage = true, IFormatProvider formatProvider = null,
+                                 ISerializer serializer = null, bool inlineFields = false,
+                                 bool renderMessageTemplate = true, bool formatStackTraceAsArray = false): base(
+                omitEnclosingObject, closingDelimiter, renderMessage, formatProvider, serializer, inlineFields,
+                renderMessageTemplate, formatStackTraceAsArray)
+            {
+                AddLiteralWriter(typeof(SystemId), WriteV);
+                AddLiteralWriter(typeof(MemberId), WriteV);
+                AddLiteralWriter(typeof(GroupId), WriteV);
+                AddLiteralWriter(typeof(SwitchId), WriteV);
+            }
+        }
+
+        public class JsonValue: JsonValueFormatter
+        {
+            protected override void FormatLiteralValue(object value, TextWriter output)
+            {
+                if (Write(value, output))
+                    return;
+                base.FormatLiteralValue(value, output);
+            }
+        }
+    }
+}

PluralKit.Core/Models/GroupId.cs

@@ -21,6 +21,6 @@
 
         public int CompareTo(GroupId other) => Value.CompareTo(other.Value);
         
-        public override string ToString() => $"Member #{Value}";
+        public override string ToString() => $"Group #{Value}";
     }
 }

PluralKit.Core/Models/Patch/ModelPatchExt.cs

@@ -4,40 +4,56 @@ using System.Threading.Tasks;
 
 using Dapper;
 
+using Serilog;
+
 namespace PluralKit.Core
 {
     public static class ModelPatchExt
     {
         public static Task<PKSystem> UpdateSystem(this IPKConnection conn, SystemId id, SystemPatch patch)
         {
+            Log.ForContext("Elastic", "yes?").Information("Updated {SystemId}: {@SystemPatch}", id, patch);
             var (query, pms) = patch.Apply(UpdateQueryBuilder.Update("systems", "id = @id"))
                 .WithConstant("id", id)
                 .Build("returning *");
             return conn.QueryFirstAsync<PKSystem>(query, pms);
         }
 
-        public static Task DeleteSystem(this IPKConnection conn, SystemId id) =>
+        public static Task DeleteSystem(this IPKConnection conn, SystemId id)
-            conn.ExecuteAsync("delete from systems where id = @Id", new {Id = id});
+        {
+            Log.ForContext("Elastic", "yes?").Information("Deleted {SystemId}", id);
+            return conn.ExecuteAsync("delete from systems where id = @Id", new {Id = id});
+        }
 
-        public static Task<PKMember> CreateMember(this IPKConnection conn, SystemId system, string memberName) =>
+        public static async Task<PKMember> CreateMember(this IPKConnection conn, SystemId system, string memberName)
-            conn.QueryFirstAsync<PKMember>(
+        {
+            var member = await conn.QueryFirstAsync<PKMember>(
                 "insert into members (hid, system, name) values (find_free_member_hid(), @SystemId, @Name) returning *",
                 new {SystemId = system, Name = memberName});
+            Log.ForContext("Elastic", "yes?").Information("Created {MemberId} in {SystemId}: {MemberName}", 
+                system, member.Id, memberName);
+            return member;
+        }
 
         public static Task<PKMember> UpdateMember(this IPKConnection conn, MemberId id, MemberPatch patch)
         {
+            Log.ForContext("Elastic", "yes?").Information("Updated {MemberId}: {@MemberPatch}", id, patch);
             var (query, pms) = patch.Apply(UpdateQueryBuilder.Update("members", "id = @id"))
                 .WithConstant("id", id)
                 .Build("returning *");
             return conn.QueryFirstAsync<PKMember>(query, pms);
         }
         
-        public static Task DeleteMember(this IPKConnection conn, MemberId id) =>
+        public static Task DeleteMember(this IPKConnection conn, MemberId id)
-            conn.ExecuteAsync("delete from members where id = @Id", new {Id = id});
+        {
+            Log.ForContext("Elastic", "yes?").Information("Deleted {MemberId}", id);
+            return conn.ExecuteAsync("delete from members where id = @Id", new {Id = id});
+        }
 
         public static Task UpsertSystemGuild(this IPKConnection conn, SystemId system, ulong guild,
                                              SystemGuildPatch patch)
         {
+            Log.ForContext("Elastic", "yes?").Information("Updated {SystemId} in guild {GuildId}: {@SystemGuildPatch}",  system, guild, patch);
             var (query, pms) = patch.Apply(UpdateQueryBuilder.Upsert("system_guild", "system, guild"))
                 .WithConstant("system", system)
                 .WithConstant("guild", guild)
@@ -48,6 +64,7 @@ namespace PluralKit.Core
         public static Task UpsertMemberGuild(this IPKConnection conn, MemberId member, ulong guild,
                                              MemberGuildPatch patch)
         {
+            Log.ForContext("Elastic", "yes?").Information("Updated {MemberId} in guild {GuildId}: {@MemberGuildPatch}",  member, guild, patch);
             var (query, pms) = patch.Apply(UpdateQueryBuilder.Upsert("member_guild", "member, guild"))
                 .WithConstant("member", member)
                 .WithConstant("guild", guild)
@@ -57,29 +74,38 @@ namespace PluralKit.Core
         
         public static Task UpsertGuild(this IPKConnection conn, ulong guild, GuildPatch patch)
         {
+            Log.ForContext("Elastic", "yes?").Information("Updated guild {GuildId}: {@GuildPatch}",  guild, patch);
             var (query, pms) = patch.Apply(UpdateQueryBuilder.Upsert("servers", "id"))
                 .WithConstant("id", guild)
                 .Build();
             return conn.ExecuteAsync(query, pms);
         }
         
-        public static Task<PKGroup> CreateGroup(this IPKConnection conn, SystemId system, string name) =>
+        public static async Task<PKGroup> CreateGroup(this IPKConnection conn, SystemId system, string name)
-            conn.QueryFirstAsync<PKGroup>(
+        {
+            var group = await conn.QueryFirstAsync<PKGroup>(
                 "insert into groups (hid, system, name) values (find_free_group_hid(), @System, @Name) returning *",
                 new {System = system, Name = name});
+            Log.ForContext("Elastic", "yes?").Information("Created group {GroupId} in system {SystemId}: {GroupName}", group.Id, system, name);
+            return group;
+        }
 
         public static Task<PKGroup> UpdateGroup(this IPKConnection conn, GroupId id, GroupPatch patch)
         {
+            Log.ForContext("Elastic", "yes?").Information("Updated {GroupId}: {@GroupPatch}", id, patch);
             var (query, pms) = patch.Apply(UpdateQueryBuilder.Update("groups", "id = @id"))
                 .WithConstant("id", id)
                 .Build("returning *");
             return conn.QueryFirstAsync<PKGroup>(query, pms);
         }
         
-        public static Task DeleteGroup(this IPKConnection conn, GroupId group) =>
+        public static Task DeleteGroup(this IPKConnection conn, GroupId group)
-            conn.ExecuteAsync("delete from groups where id = @Id", new {Id = group });
+        {
+            Log.ForContext("Elastic", "yes?").Information("Deleted {GroupId}", group);
+            return conn.ExecuteAsync("delete from groups where id = @Id", new {Id = @group});
+        }
 
-        public static async Task AddMembersToGroup(this IPKConnection conn, GroupId group, IEnumerable<MemberId> members)
+        public static async Task AddMembersToGroup(this IPKConnection conn, GroupId group, IReadOnlyCollection<MemberId> members)
         {
             await using var w = conn.BeginBinaryImport("copy group_members (group_id, member_id) from stdin (format binary)");
             foreach (var member in members)
@@ -89,10 +115,14 @@ namespace PluralKit.Core
                 await w.WriteAsync(member.Value);
             }
             await w.CompleteAsync();
+            Log.ForContext("Elastic", "yes?").Information("Added members to {GroupId}: {MemberIds}", group, members);
         }
         
-        public static Task RemoveMembersFromGroup(this IPKConnection conn, GroupId group, IEnumerable<MemberId> members) =>
+        public static Task RemoveMembersFromGroup(this IPKConnection conn, GroupId group, IReadOnlyCollection<MemberId> members)
-            conn.ExecuteAsync("delete from group_members where group_id = @Group and member_id = any(@Members)",
+        {
-                new {Group = group, Members = members.ToArray() });
+            Log.ForContext("Elastic", "yes?").Information("Removed members from {GroupId}: {MemberIds}", group, members);
+            return conn.ExecuteAsync("delete from group_members where group_id = @Group and member_id = any(@Members)",
+                new {Group = @group, Members = members.ToArray()});
+        }
     }
 }

PluralKit.Core/Modules.cs

@@ -97,12 +97,21 @@ namespace PluralKit.Core
 
         private ILogger InitLogger(CoreConfig config)
         {
+            var consoleTemplate = "[{Timestamp:HH:mm:ss.fff}] {Level:u3} {Message:lj}{NewLine}{Exception}";
             var outputTemplate = "[{Timestamp:yyyy-MM-dd HH:mm:ss.ffffff}] {Level:u3} {Message:lj}{NewLine}{Exception}";
             
-            var logger = new LoggerConfiguration()
+            var logCfg = new LoggerConfiguration()
                 .Enrich.FromLogContext()
                 .ConfigureForNodaTime(DateTimeZoneProviders.Tzdb)
                 .MinimumLevel.Is(config.ConsoleLogLevel)
+                
+                // Actual formatting for these is handled in ScalarFormatting
+                .Destructure.AsScalar<SystemId>()
+                .Destructure.AsScalar<MemberId>()
+                .Destructure.AsScalar<GroupId>()
+                .Destructure.AsScalar<SwitchId>()
+                .Destructure.With<PatchObjectDestructuring>()
+                
                 .WriteTo.Async(a =>
                 {
                     // Both the same output, except one is raw compact JSON and one is plain text.
@@ -118,17 +127,18 @@ namespace PluralKit.Core
                         buffered: true);
 
                     a.File(
-                        new RenderedCompactJsonFormatter(),
+                        new RenderedCompactJsonFormatter(new ScalarFormatting.JsonValue()),
                         (config.LogDir ?? "logs") + $"/pluralkit.{_component}.json",
                         rollingInterval: RollingInterval.Day,
                         flushToDiskInterval: TimeSpan.FromMilliseconds(50),
                         restrictedToMinimumLevel: config.FileLogLevel,
                         buffered: true);
                 })
-                // TODO: render as UTC in the console, too? or just in log files
                 .WriteTo.Async(a =>
-                    a.Console(theme: AnsiConsoleTheme.Code, outputTemplate: outputTemplate,
+                    a.Console(
-                        formatProvider: new UTCTimestampFormatProvider()));
+                        theme: AnsiConsoleTheme.Code,
+                        outputTemplate: consoleTemplate,
+                        restrictedToMinimumLevel: config.ConsoleLogLevel));
 
             if (config.ElasticUrl != null)
             {
@@ -137,16 +147,17 @@ namespace PluralKit.Core
                     AutoRegisterTemplate = true,
                     AutoRegisterTemplateVersion = AutoRegisterTemplateVersion.ESv7,
                     MinimumLogEventLevel = LogEventLevel.Verbose,
-                    IndexFormat = "pluralkit-logs-{0:yyyy.MM.dd}"
+                    IndexFormat = "pluralkit-logs-{0:yyyy.MM.dd}",
+                    CustomFormatter = new ScalarFormatting.Elasticsearch()
                 };
                
-                logger.WriteTo
+                logCfg.WriteTo
                     .Conditional(e => e.Properties.ContainsKey("Elastic"), 
                         c => c.Elasticsearch(elasticConfig));
             }
 
-            _fn.Invoke(logger);
+            _fn.Invoke(logCfg);
-            return logger.CreateLogger();
+            return Log.Logger = logCfg.CreateLogger();
         }
     }
 

PluralKit.Core/Services/PostgresDataStore.cs

@@ -10,13 +10,15 @@ using Serilog;
 
 namespace PluralKit.Core {
     public class PostgresDataStore: IDataStore {
-        private IDatabase _conn;
+        private readonly IDatabase _conn;
-        private ILogger _logger;
+        private readonly ILogger _logger;
 
         public PostgresDataStore(IDatabase conn, ILogger logger)
         {
             _conn = conn;
-            _logger = logger;
+            _logger = logger
+                .ForContext<PostgresDataStore>()
+                .ForContext("Elastic", "yes?");
         }
         
         public async Task<PKSystem> CreateSystem(string systemName = null) {
@@ -24,7 +26,7 @@ namespace PluralKit.Core {
             using (var conn = await _conn.Obtain())
                 system = await conn.QuerySingleAsync<PKSystem>("insert into systems (hid, name) values (find_free_system_hid(), @Name) returning *", new { Name = systemName });
 
-            _logger.Information("Created system {System}", system.Id);
+            _logger.Information("Created {SystemId}", system.Id);
             // New system has no accounts, therefore nothing gets cached, therefore no need to invalidate caches right here
             return system;
         }
@@ -35,14 +37,14 @@ namespace PluralKit.Core {
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("insert into accounts (uid, system) values (@Id, @SystemId) on conflict do nothing", new { Id = accountId, SystemId = system.Id });
 
-            _logger.Information("Linked system {System} to account {Account}", system.Id, accountId);
+            _logger.Information("Linked account {UserId} to {SystemId}", system.Id, accountId);
         }
 
         public async Task RemoveAccount(PKSystem system, ulong accountId) {
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("delete from accounts where uid = @Id and system = @SystemId", new { Id = accountId, SystemId = system.Id });
 
-            _logger.Information("Unlinked system {System} from account {Account}", system.Id, accountId);
+            _logger.Information("Unlinked account {UserId} from {SystemId}", system.Id, accountId);
         }
 
         public async Task<PKSystem> GetSystemByAccount(ulong accountId) {
@@ -65,6 +67,7 @@ namespace PluralKit.Core {
         {
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("delete from switches where system = @Id", system);
+            _logger.Information("Deleted all switches in {SystemId}", system.Id);
         }
 
         public async Task<PKMember> GetMemberByHid(string hid) {
@@ -102,7 +105,7 @@ namespace PluralKit.Core {
                 OriginalMid = triggerMessageId
             });
 
-            _logger.Debug("Stored message {Message} in channel {Channel}", postedMessageId, channelId);
+            // todo: _logger.Debug("Stored message {Message} in channel {Channel}", postedMessageId, channelId);
         }
 
         public async Task<FullMessage> GetMessage(ulong id)
@@ -119,7 +122,7 @@ namespace PluralKit.Core {
         public async Task DeleteMessage(ulong id) {
             using (var conn = await _conn.Obtain())
                 if (await conn.ExecuteAsync("delete from messages where mid = @Id", new { Id = id }) > 0)
-                    _logger.Information("Deleted message {Message}", id);
+                    _logger.Information("Deleted message {MessageId} from database", id);
         }
 
         public async Task DeleteMessagesBulk(IReadOnlyCollection<ulong> ids)
@@ -130,7 +133,7 @@ namespace PluralKit.Core {
                 // Hence we map them to single longs, which *are* supported (this is ok since they're Technically (tm) stored as signed longs in the db anyway)
                 var foundCount = await conn.ExecuteAsync("delete from messages where mid = any(@Ids)", new {Ids = ids.Select(id => (long) id).ToArray()});
                 if (foundCount > 0)
-                    _logger.Information("Bulk deleted messages {Messages}, {FoundCount} found", ids, foundCount);
+                    _logger.Information("Bulk deleted messages ({FoundCount} found) from database: {MessageIds}", foundCount, ids);
             }
         }
 
@@ -156,7 +159,7 @@ namespace PluralKit.Core {
             // Finally we commit the tx, since the using block will otherwise rollback it
             await tx.CommitAsync();
             
-            _logger.Information("Registered switch {Switch} in system {System} with members {@Members}", sw.Id, system, members.Select(m => m.Id));
+            _logger.Information("Created {SwitchId} in {SystemId}: {Members}", sw.Id, system, members.Select(m => m.Id));
         }
 
         public IAsyncEnumerable<PKSwitch> GetSwitches(SystemId system)
@@ -227,7 +230,7 @@ namespace PluralKit.Core {
                 await conn.ExecuteAsync("update switches set timestamp = @Time where id = @Id",
                     new {Time = time, Id = sw.Id});
 
-            _logger.Information("Moved switch {Switch} to {Time}", sw.Id, time);
+            _logger.Information("Updated {SwitchId} timestamp: {SwitchTimestamp}", sw.Id, time);
         }
 
         public async Task DeleteSwitch(PKSwitch sw)
@@ -235,7 +238,7 @@ namespace PluralKit.Core {
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("delete from switches where id = @Id", new {Id = sw.Id});
 
-            _logger.Information("Deleted switch {Switch}");
+            _logger.Information("Deleted {Switch}", sw.Id);
         }
 
         public async Task<IEnumerable<SwitchListEntry>> GetPeriodFronters(PKSystem system, Instant periodStart, Instant periodEnd)

PluralKit.Core/Utils/Partial.cs

@@ -10,10 +10,11 @@ using Newtonsoft.Json;
 namespace PluralKit.Core
 {
     [JsonConverter(typeof(PartialConverter))]
-    public struct Partial<T>: IEnumerable<T>
+    public struct Partial<T>: IEnumerable<T>, IPartial
     {
         public bool IsPresent { get; }
         public T Value { get; }
+        public object? RawValue => Value;
 
         private Partial(bool isPresent, T value)
         {
@@ -34,6 +35,12 @@ namespace PluralKit.Core
         public static implicit operator Partial<T>(T val) => Present(val);
     }
 
+    public interface IPartial
+    {
+        public bool IsPresent { get; }
+        public object? RawValue { get; }
+    }
+
     public class PartialConverter: JsonConverter
     {
         public override object? ReadJson(JsonReader reader, Type objectType, object? existingValue,