diff --git a/PluralKit.Bot/Bot.cs b/PluralKit.Bot/Bot.cs index f63aec6a..eb8de635 100644 --- a/PluralKit.Bot/Bot.cs +++ b/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) diff --git a/PluralKit.Bot/Services/PeriodicStatCollector.cs b/PluralKit.Bot/Services/PeriodicStatCollector.cs index e49db00a..9794213f 100644 --- a/PluralKit.Bot/Services/PeriodicStatCollector.cs +++ b/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 diff --git a/PluralKit.Bot/Tracing/DiscordRequestObserver.cs b/PluralKit.Bot/Tracing/DiscordRequestObserver.cs index 756d4ec3..16dd264d 100644 --- a/PluralKit.Bot/Tracing/DiscordRequestObserver.cs +++ b/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, diff --git a/PluralKit.Bot/Tracing/EventDestructuring.cs b/PluralKit.Bot/Tracing/EventDestructuring.cs index 10ca6a8a..d302cd54 100644 --- a/PluralKit.Bot/Tracing/EventDestructuring.cs +++ b/PluralKit.Bot/Tracing/EventDestructuring.cs @@ -22,7 +22,6 @@ namespace PluralKit.Bot var props = new List { new LogEventProperty("Type", new ScalarValue(dea.EventType())), - new LogEventProperty("Shard", new ScalarValue(dea.Client.ShardId)) }; void AddMessage(DiscordMessage msg) @@ -47,6 +46,9 @@ namespace PluralKit.Bot props.Add(new LogEventProperty("ReactingUserId", new ScalarValue(mra.User.Id))); 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; diff --git a/PluralKit.Core/Logging/PatchObjectDestructuring.cs b/PluralKit.Core/Logging/PatchObjectDestructuring.cs new file mode 100644 index 00000000..8696e0a7 --- /dev/null +++ b/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(); + 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; + } + } +} \ No newline at end of file diff --git a/PluralKit.Core/Logging/ScalarFormatting.cs b/PluralKit.Core/Logging/ScalarFormatting.cs new file mode 100644 index 00000000..394c3c15 --- /dev/null +++ b/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); + } + } + } +} \ No newline at end of file diff --git a/PluralKit.Core/Models/GroupId.cs b/PluralKit.Core/Models/GroupId.cs index 428251da..b294f56c 100644 --- a/PluralKit.Core/Models/GroupId.cs +++ b/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}"; } } \ No newline at end of file diff --git a/PluralKit.Core/Models/Patch/ModelPatchExt.cs b/PluralKit.Core/Models/Patch/ModelPatchExt.cs index f18b0ba7..64661a33 100644 --- a/PluralKit.Core/Models/Patch/ModelPatchExt.cs +++ b/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 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(query, pms); } - public static Task DeleteSystem(this IPKConnection conn, SystemId id) => - conn.ExecuteAsync("delete from systems where id = @Id", new {Id = id}); + public static Task DeleteSystem(this IPKConnection conn, SystemId id) + { + Log.ForContext("Elastic", "yes?").Information("Deleted {SystemId}", id); + return conn.ExecuteAsync("delete from systems where id = @Id", new {Id = id}); + } - public static Task CreateMember(this IPKConnection conn, SystemId system, string memberName) => - conn.QueryFirstAsync( + public static async Task CreateMember(this IPKConnection conn, SystemId system, string memberName) + { + var member = await conn.QueryFirstAsync( "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 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(query, pms); } - public static Task DeleteMember(this IPKConnection conn, MemberId id) => - conn.ExecuteAsync("delete from members where id = @Id", new {Id = id}); + public static Task DeleteMember(this IPKConnection conn, MemberId 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 CreateGroup(this IPKConnection conn, SystemId system, string name) => - conn.QueryFirstAsync( + public static async Task CreateGroup(this IPKConnection conn, SystemId system, string name) + { + var group = await conn.QueryFirstAsync( "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 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(query, pms); } - public static Task DeleteGroup(this IPKConnection conn, GroupId group) => - conn.ExecuteAsync("delete from groups where id = @Id", new {Id = group }); + public static Task DeleteGroup(this IPKConnection conn, GroupId 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 members) + public static async Task AddMembersToGroup(this IPKConnection conn, GroupId group, IReadOnlyCollection 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 members) => - conn.ExecuteAsync("delete from group_members where group_id = @Group and member_id = any(@Members)", - new {Group = group, Members = members.ToArray() }); + public static Task RemoveMembersFromGroup(this IPKConnection conn, GroupId group, IReadOnlyCollection members) + { + 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()}); + } } } \ No newline at end of file diff --git a/PluralKit.Core/Modules.cs b/PluralKit.Core/Modules.cs index e99c24be..1cf358d8 100644 --- a/PluralKit.Core/Modules.cs +++ b/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() + .Destructure.AsScalar() + .Destructure.AsScalar() + .Destructure.AsScalar() + .Destructure.With() + .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, - formatProvider: new UTCTimestampFormatProvider())); + a.Console( + 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); - return logger.CreateLogger(); + _fn.Invoke(logCfg); + return Log.Logger = logCfg.CreateLogger(); } } diff --git a/PluralKit.Core/Services/PostgresDataStore.cs b/PluralKit.Core/Services/PostgresDataStore.cs index 68ac0401..3e364be8 100644 --- a/PluralKit.Core/Services/PostgresDataStore.cs +++ b/PluralKit.Core/Services/PostgresDataStore.cs @@ -10,13 +10,15 @@ using Serilog; namespace PluralKit.Core { public class PostgresDataStore: IDataStore { - private IDatabase _conn; - private ILogger _logger; + private readonly IDatabase _conn; + private readonly ILogger _logger; public PostgresDataStore(IDatabase conn, ILogger logger) { _conn = conn; - _logger = logger; + _logger = logger + .ForContext() + .ForContext("Elastic", "yes?"); } public async Task CreateSystem(string systemName = null) { @@ -24,7 +26,7 @@ namespace PluralKit.Core { using (var conn = await _conn.Obtain()) system = await conn.QuerySingleAsync("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 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 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 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 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); } } @@ -155,8 +158,8 @@ 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 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> GetPeriodFronters(PKSystem system, Instant periodStart, Instant periodEnd) diff --git a/PluralKit.Core/Utils/Partial.cs b/PluralKit.Core/Utils/Partial.cs index 3ba2c0f6..e64b2738 100644 --- a/PluralKit.Core/Utils/Partial.cs +++ b/PluralKit.Core/Utils/Partial.cs @@ -10,10 +10,11 @@ using Newtonsoft.Json; namespace PluralKit.Core { [JsonConverter(typeof(PartialConverter))] - public struct Partial: IEnumerable + public struct Partial: IEnumerable, 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 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,