From ae82bb416807680b33fae5e0857d94ff5088484c Mon Sep 17 00:00:00 2001 From: Ske Date: Thu, 10 Jun 2021 14:21:05 +0200 Subject: [PATCH] Updates to Elastic logging --- Myriad/Gateway/Cluster.cs | 2 +- .../Gateway/Limit/LocalGatewayRatelimiter.cs | 2 +- .../Limit/TwilightGatewayRatelimiter.cs | 2 +- Myriad/Gateway/Shard.cs | 6 +- Myriad/Gateway/State/ShardStateManager.cs | 4 +- Myriad/Rest/BaseRestClient.cs | 22 ++-- Myriad/Rest/Ratelimit/Bucket.cs | 4 +- PluralKit.Bot/Bot.cs | 15 +-- PluralKit.Bot/Modules.cs | 1 + .../Services/CommandMessageService.cs | 2 +- PluralKit.Bot/Services/WebhookCacheService.cs | 2 +- .../Tracing/DiscordRequestObserver.cs | 4 + PluralKit.Bot/Tracing/EventDestructuring.cs | 58 ---------- .../Utils/SerilogGatewayEnricherFactory.cs | 104 ++++++++++++++++++ PluralKit.Core/CoreConfig.cs | 3 +- PluralKit.Core/Database/Database.cs | 2 +- .../Database/Repository/ModelRepository.cs | 3 +- PluralKit.Core/Modules/LoggingModule.cs | 11 +- 18 files changed, 150 insertions(+), 97 deletions(-) delete mode 100644 PluralKit.Bot/Tracing/EventDestructuring.cs create mode 100644 PluralKit.Bot/Utils/SerilogGatewayEnricherFactory.cs diff --git a/Myriad/Gateway/Cluster.cs b/Myriad/Gateway/Cluster.cs index d7e0eadb..b41d8c19 100644 --- a/Myriad/Gateway/Cluster.cs +++ b/Myriad/Gateway/Cluster.cs @@ -21,7 +21,7 @@ namespace Myriad.Gateway public Cluster(GatewaySettings gatewaySettings, ILogger logger) { _gatewaySettings = gatewaySettings; - _logger = logger; + _logger = logger.ForContext(); } public Func? EventReceived { get; set; } diff --git a/Myriad/Gateway/Limit/LocalGatewayRatelimiter.cs b/Myriad/Gateway/Limit/LocalGatewayRatelimiter.cs index 995f7288..1661dffc 100644 --- a/Myriad/Gateway/Limit/LocalGatewayRatelimiter.cs +++ b/Myriad/Gateway/Limit/LocalGatewayRatelimiter.cs @@ -56,7 +56,7 @@ namespace Myriad.Gateway.Limit if (!queue.TryDequeue(out var tcs)) continue; - _logger.Information( + _logger.Debug( "Allowing identify for bucket {BucketId} through ({QueueLength} left in bucket queue)", bucket, queue.Count); tcs.SetResult(); diff --git a/Myriad/Gateway/Limit/TwilightGatewayRatelimiter.cs b/Myriad/Gateway/Limit/TwilightGatewayRatelimiter.cs index 7859eade..036c4ac5 100644 --- a/Myriad/Gateway/Limit/TwilightGatewayRatelimiter.cs +++ b/Myriad/Gateway/Limit/TwilightGatewayRatelimiter.cs @@ -14,7 +14,7 @@ namespace Myriad.Gateway.Limit public TwilightGatewayRatelimiter(ILogger logger, string url) { _url = url; - _logger = logger; + _logger = logger.ForContext(); } public async Task Identify(int shard) diff --git a/Myriad/Gateway/Shard.cs b/Myriad/Gateway/Shard.cs index c7f84230..720ca17d 100644 --- a/Myriad/Gateway/Shard.cs +++ b/Myriad/Gateway/Shard.cs @@ -9,6 +9,7 @@ using Myriad.Serialization; using Myriad.Types; using Serilog; +using Serilog.Context; namespace Myriad.Gateway { @@ -50,7 +51,7 @@ namespace Myriad.Gateway _info = info; _ratelimiter = ratelimiter; _url = url; - _logger = logger; + _logger = logger.ForContext().ForContext("ShardId", info.ShardId); _stateManager = new ShardStateManager(info, _jsonSerializerOptions, logger) { HandleEvent = HandleEvent, @@ -70,6 +71,9 @@ namespace Myriad.Gateway private async Task ShardLoop() { + // may be superfluous but this adds shard id to ambient context which is nice + using var _ = LogContext.PushProperty("ShardId", _info.ShardId); + while (true) { try diff --git a/Myriad/Gateway/State/ShardStateManager.cs b/Myriad/Gateway/State/ShardStateManager.cs index f57b1c91..1cd0229c 100644 --- a/Myriad/Gateway/State/ShardStateManager.cs +++ b/Myriad/Gateway/State/ShardStateManager.cs @@ -140,8 +140,8 @@ namespace Myriad.Gateway _hasReceivedHeartbeatAck = true; _latency = DateTimeOffset.UtcNow - _lastHeartbeatSent; OnHeartbeatReceived?.Invoke(_latency!.Value); - _logger.Information("Shard {ShardId}: Received Heartbeat (latency {Latency} ms)", - _info.ShardId, _latency); + _logger.Debug("Shard {ShardId}: Received Heartbeat (latency {Latency:N2} ms)", + _info.ShardId, _latency?.TotalMilliseconds); return Task.CompletedTask; } diff --git a/Myriad/Rest/BaseRestClient.cs b/Myriad/Rest/BaseRestClient.cs index 374640a6..8f327508 100644 --- a/Myriad/Rest/BaseRestClient.cs +++ b/Myriad/Rest/BaseRestClient.cs @@ -16,6 +16,7 @@ using Myriad.Serialization; using Polly; using Serilog; +using Serilog.Context; namespace Myriad.Rest { @@ -172,8 +173,10 @@ namespace Myriad.Rest { return await _retryPolicy.ExecuteAsync(async _ => { + using var __ = LogContext.PushProperty("EndpointName", ratelimitParams.endpointName); + var request = createRequest(); - _logger.Debug("Sending request: {RequestMethod} {RequestPath}", + _logger.Debug("Request: {RequestMethod} {RequestPath}", request.Method, request.RequestUri); request.Version = _httpVersion; @@ -185,9 +188,8 @@ namespace Myriad.Rest stopwatch.Stop(); _logger.Debug( - "Received response in {ResponseDurationMs} ms: {RequestMethod} {RequestPath} -> {StatusCode} {ReasonPhrase}", - stopwatch.ElapsedMilliseconds, request.Method, request.RequestUri, (int) response.StatusCode, - response.ReasonPhrase); + "Response: {RequestMethod} {RequestPath} -> {StatusCode} {ReasonPhrase} (in {ResponseDurationMs} ms)", + request.Method, request.RequestUri, (int) response.StatusCode, response.ReasonPhrase, stopwatch.ElapsedMilliseconds); await HandleApiError(response, ignoreNotFound); @@ -208,14 +210,16 @@ namespace Myriad.Rest if (response.StatusCode == HttpStatusCode.NotFound && ignoreNotFound) return; - throw await CreateDiscordException(response); + var body = await response.Content.ReadAsStringAsync(); + var apiError = TryParseApiError(body); + if (apiError != null) + _logger.Warning("Discord API error: {DiscordErrorCode} {DiscordErrorMessage}", apiError.Code, apiError.Message); + + throw CreateDiscordException(response, body, apiError); } - private async ValueTask CreateDiscordException(HttpResponseMessage response) + private DiscordRequestException CreateDiscordException(HttpResponseMessage response, string body, DiscordApiError? apiError) { - var body = await response.Content.ReadAsStringAsync(); - var apiError = TryParseApiError(body); - return response.StatusCode switch { HttpStatusCode.BadRequest => new BadRequestException(response, body, apiError), diff --git a/Myriad/Rest/Ratelimit/Bucket.cs b/Myriad/Rest/Ratelimit/Bucket.cs index 918b11b2..da11dc2b 100644 --- a/Myriad/Rest/Ratelimit/Bucket.cs +++ b/Myriad/Rest/Ratelimit/Bucket.cs @@ -50,7 +50,7 @@ namespace Myriad.Rest.Ratelimit if (Remaining > 0) { - _logger.Debug( + _logger.Verbose( "{BucketKey}/{BucketMajor}: Bucket has [{BucketRemaining}/{BucketLimit} left], allowing through", Key, Major, Remaining, Limit); Remaining--; @@ -82,7 +82,7 @@ namespace Myriad.Rest.Ratelimit var headerNextReset = DateTimeOffset.UtcNow + headers.ResetAfter.Value; // todo: server time if (_nextReset == null || headerNextReset > _nextReset) { - _logger.Debug("{BucketKey}/{BucketMajor}: Received reset time {NextReset} from server (after: {NextResetAfter}, remaining: {Remaining}, local remaining: {LocalRemaining})", + _logger.Verbose("{BucketKey}/{BucketMajor}: Received reset time {NextReset} from server (after: {NextResetAfter}, remaining: {Remaining}, local remaining: {LocalRemaining})", Key, Major, headerNextReset, headers.ResetAfter.Value, headers.Remaining, Remaining); _nextReset = headerNextReset; diff --git a/PluralKit.Bot/Bot.cs b/PluralKit.Bot/Bot.cs index 94ee2816..087e5d38 100644 --- a/PluralKit.Bot/Bot.cs +++ b/PluralKit.Bot/Bot.cs @@ -176,14 +176,13 @@ namespace PluralKit.Bot async Task HandleEventInner() { await Task.Yield(); - - using var _ = LogContext.PushProperty("EventId", Guid.NewGuid()); - _logger - .ForContext("Elastic", "yes?") - .Verbose("Gateway event: {@Event}", evt); - + await using var serviceScope = _services.BeginLifetimeScope(); + using var _ = LogContext.PushProperty("EventId", Guid.NewGuid()); + using var __ = LogContext.Push(serviceScope.Resolve().GetEnricher(shard, evt)); + _logger.Verbose("Received gateway event: {@Event}", evt); + // 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 var sentryEnricher = serviceScope.ResolveOptional>(); sentryEnricher?.Enrich(serviceScope.Resolve(), shard, evt); @@ -218,9 +217,7 @@ namespace PluralKit.Bot // Make this beforehand so we can access the event ID for logging var sentryEvent = new SentryEvent(exc); - _logger - .ForContext("Elastic", "yes?") - .Error(exc, "Exception in event handler: {SentryEventId}", sentryEvent.EventId); + _logger.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 MessageCreateEvent mc && mc.Author.Id == shard.User?.Id) diff --git a/PluralKit.Bot/Modules.cs b/PluralKit.Bot/Modules.cs index 9a80834f..beca477f 100644 --- a/PluralKit.Bot/Modules.cs +++ b/PluralKit.Bot/Modules.cs @@ -116,6 +116,7 @@ namespace PluralKit.Bot Timeout = TimeSpan.FromSeconds(5) }).AsSelf().SingleInstance(); builder.RegisterInstance(SystemClock.Instance).As(); + builder.RegisterType().AsSelf().SingleInstance(); builder.RegisterType().AsSelf().SingleInstance(); } diff --git a/PluralKit.Bot/Services/CommandMessageService.cs b/PluralKit.Bot/Services/CommandMessageService.cs index 8d44b97d..b666fd0b 100644 --- a/PluralKit.Bot/Services/CommandMessageService.cs +++ b/PluralKit.Bot/Services/CommandMessageService.cs @@ -22,7 +22,7 @@ namespace PluralKit.Bot _db = db; _repo = repo; _clock = clock; - _logger = logger; + _logger = logger.ForContext(); } public async Task RegisterMessage(ulong messageId, ulong authorId) diff --git a/PluralKit.Bot/Services/WebhookCacheService.cs b/PluralKit.Bot/Services/WebhookCacheService.cs index 9005c276..7d0f6239 100644 --- a/PluralKit.Bot/Services/WebhookCacheService.cs +++ b/PluralKit.Bot/Services/WebhookCacheService.cs @@ -71,7 +71,7 @@ namespace PluralKit.Bot public async Task InvalidateAndRefreshWebhook(ulong channelId, Webhook webhook) { // note: webhook.ChannelId may not be the same as channelId >.> - _logger.Information("Refreshing webhook for channel {Channel}", webhook.ChannelId); + _logger.Debug("Refreshing webhook for channel {Channel}", webhook.ChannelId); _webhooks.TryRemove(webhook.ChannelId, out _); return await GetWebhook(channelId); diff --git a/PluralKit.Bot/Tracing/DiscordRequestObserver.cs b/PluralKit.Bot/Tracing/DiscordRequestObserver.cs index 66a8a8b9..a832c04d 100644 --- a/PluralKit.Bot/Tracing/DiscordRequestObserver.cs +++ b/PluralKit.Bot/Tracing/DiscordRequestObserver.cs @@ -16,6 +16,7 @@ using Serilog.Context; namespace PluralKit.Bot { + // TODO: phase this out; it currently still handles metrics but that needs to be moved to Myriad probably? public class DiscordRequestObserver: IObserver> { private readonly IMetrics _metrics; @@ -77,6 +78,8 @@ namespace PluralKit.Bot { var endpoint = GetEndpointName(response.RequestMessage); + // (see phase-out notice at top of file) + /* using (LogContext.PushProperty("Elastic", "yes?")) { if ((int) response.StatusCode >= 400) @@ -101,6 +104,7 @@ namespace PluralKit.Bot response.ReasonPhrase, activity.Duration.TotalMilliseconds); } + */ if (IsDiscordApiRequest(response)) { diff --git a/PluralKit.Bot/Tracing/EventDestructuring.cs b/PluralKit.Bot/Tracing/EventDestructuring.cs deleted file mode 100644 index e685c43f..00000000 --- a/PluralKit.Bot/Tracing/EventDestructuring.cs +++ /dev/null @@ -1,58 +0,0 @@ -using System.Collections.Generic; - -using Myriad.Gateway; - -using Serilog.Core; -using Serilog.Events; - -namespace PluralKit.Bot -{ - // This class is unused and commented out in Init.cs - it's here from before the lib conversion. Is it needed?? - public class EventDestructuring: IDestructuringPolicy - { - public bool TryDestructure(object value, ILogEventPropertyValueFactory propertyValueFactory, - out LogEventPropertyValue result) - { - if (!(value is IGatewayEvent evt)) - { - result = null; - return false; - } - - var props = new List - { - new("Type", new ScalarValue(evt.EventType())), - }; - - void AddMessage(ulong id, ulong channelId, ulong? guildId, ulong? author) - { - props.Add(new LogEventProperty("MessageId", new ScalarValue(id))); - props.Add(new LogEventProperty("ChannelId", new ScalarValue(channelId))); - props.Add(new LogEventProperty("GuildId", new ScalarValue(guildId ?? 0))); - - if (author != null) - props.Add(new LogEventProperty("AuthorId", new ScalarValue(author))); - } - - if (value is MessageCreateEvent mc) - AddMessage(mc.Id, mc.ChannelId, mc.GuildId, mc.Author.Id); - else if (value is MessageUpdateEvent mu) - AddMessage(mu.Id, mu.ChannelId, mu.GuildId.Value, mu.Author.Value?.Id); - else if (value is MessageDeleteEvent md) - AddMessage(md.Id, md.ChannelId, md.GuildId, null); - else if (value is MessageReactionAddEvent mra) - { - AddMessage(mra.MessageId, mra.ChannelId, mra.GuildId, null); - props.Add(new LogEventProperty("ReactingUserId", new ScalarValue(mra.Emoji))); - props.Add(new LogEventProperty("Emoji", new ScalarValue(mra.Emoji.Name))); - } - - // Want shard last, just for visual reasons - // TODO: D#+ update means we can't pull shard ID out of this, what do? - // props.Add(new LogEventProperty("Shard", new ScalarValue(dea.Client.ShardId))); - - result = new StructureValue(props); - return true; - } - } -} \ No newline at end of file diff --git a/PluralKit.Bot/Utils/SerilogGatewayEnricherFactory.cs b/PluralKit.Bot/Utils/SerilogGatewayEnricherFactory.cs new file mode 100644 index 00000000..81597d54 --- /dev/null +++ b/PluralKit.Bot/Utils/SerilogGatewayEnricherFactory.cs @@ -0,0 +1,104 @@ +using System.Collections.Generic; + +using Myriad.Cache; +using Myriad.Extensions; +using Myriad.Gateway; + +using Serilog.Core; +using Serilog.Events; + +namespace PluralKit.Bot +{ + public class SerilogGatewayEnricherFactory + { + private readonly Bot _bot; + private readonly IDiscordCache _cache; + + public SerilogGatewayEnricherFactory(Bot bot, IDiscordCache cache) + { + _bot = bot; + _cache = cache; + } + + public ILogEventEnricher GetEnricher(Shard shard, IGatewayEvent evt) + { + var props = new List + { + new("ShardId", new ScalarValue(shard.ShardId)), + }; + + var (guild, channel) = GetGuildChannelId(evt); + var user = GetUserId(evt); + var message = GetMessageId(evt); + + if (guild != null) + props.Add(new("GuildId", new ScalarValue(guild.Value))); + + if (channel != null) + { + props.Add(new("GuildId", new ScalarValue(channel.Value))); + + var botPermissions = _bot.PermissionsIn(channel.Value); + props.Add(new("BotPermissions", new ScalarValue(botPermissions))); + } + + if (message != null) + props.Add(new("MessageId", new ScalarValue(message.Value))); + + if (user != null) + props.Add(new("UserId", new ScalarValue(user.Value))); + + if (evt is MessageCreateEvent mce) + props.Add(new("UserPermissions", new ScalarValue(_cache.PermissionsFor(mce)))); + + return new Inner(props); + } + + private (ulong?, ulong?) GetGuildChannelId(IGatewayEvent evt) => evt switch + { + ChannelCreateEvent e => (e.GuildId, e.Id), + ChannelUpdateEvent e => (e.GuildId, e.Id), + ChannelDeleteEvent e => (e.GuildId, e.Id), + MessageCreateEvent e => (e.GuildId, e.ChannelId), + MessageUpdateEvent e => (e.GuildId.Value, e.ChannelId), + MessageDeleteEvent e => (e.GuildId, e.ChannelId), + MessageDeleteBulkEvent e => (e.GuildId, e.ChannelId), + MessageReactionAddEvent e => (e.GuildId, e.ChannelId), + MessageReactionRemoveEvent e => (e.GuildId, e.ChannelId), + MessageReactionRemoveAllEvent e => (e.GuildId, e.ChannelId), + MessageReactionRemoveEmojiEvent e => (e.GuildId, e.ChannelId), + InteractionCreateEvent e => (e.GuildId, e.ChannelId), + _ => (null, null) + }; + + private ulong? GetUserId(IGatewayEvent evt) => evt switch + { + MessageCreateEvent e => e.Author.Id, + MessageUpdateEvent e => e.Author.HasValue ? e.Author.Value.Id : null, + MessageReactionAddEvent e => e.UserId, + MessageReactionRemoveEvent e => e.UserId, + InteractionCreateEvent e => e.Member?.User?.Id // todo: these nullable? + }; + + private ulong? GetMessageId(IGatewayEvent evt) => evt switch + { + MessageCreateEvent e => e.Id, + MessageUpdateEvent e => e.Id, + MessageDeleteEvent e => e.Id, + MessageReactionAddEvent e => e.MessageId, + MessageReactionRemoveEvent e => e.MessageId, + MessageReactionRemoveAllEvent e => e.MessageId, + MessageReactionRemoveEmojiEvent e => e.MessageId, + InteractionCreateEvent e => e.Message?.Id, + }; + + private record Inner(List Properties): ILogEventEnricher + { + public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) + { + foreach (var prop in Properties) + logEvent.AddPropertyIfAbsent(prop); + } + } + } +} \ No newline at end of file diff --git a/PluralKit.Core/CoreConfig.cs b/PluralKit.Core/CoreConfig.cs index 800547a4..98d4a296 100644 --- a/PluralKit.Core/CoreConfig.cs +++ b/PluralKit.Core/CoreConfig.cs @@ -9,9 +9,10 @@ namespace PluralKit.Core public string InfluxUrl { get; set; } public string InfluxDb { get; set; } public string LogDir { get; set; } - public string ElasticUrl { get; set; } + public string? ElasticUrl { get; set; } public LogEventLevel ConsoleLogLevel { get; set; } = LogEventLevel.Debug; + public LogEventLevel ElasticLogLevel { get; set; } = LogEventLevel.Information; public LogEventLevel FileLogLevel { get; set; } = LogEventLevel.Information; } } \ No newline at end of file diff --git a/PluralKit.Core/Database/Database.cs b/PluralKit.Core/Database/Database.cs index 14eee429..cd614c92 100644 --- a/PluralKit.Core/Database/Database.cs +++ b/PluralKit.Core/Database/Database.cs @@ -33,7 +33,7 @@ namespace PluralKit.Core _config = config; _countHolder = countHolder; _metrics = metrics; - _logger = logger; + _logger = logger.ForContext(); _connectionString = new NpgsqlConnectionStringBuilder(_config.Database) { diff --git a/PluralKit.Core/Database/Repository/ModelRepository.cs b/PluralKit.Core/Database/Repository/ModelRepository.cs index d3814329..40bca720 100644 --- a/PluralKit.Core/Database/Repository/ModelRepository.cs +++ b/PluralKit.Core/Database/Repository/ModelRepository.cs @@ -8,8 +8,7 @@ namespace PluralKit.Core public ModelRepository(ILogger logger) { - _logger = logger.ForContext() - .ForContext("Elastic", "yes?"); + _logger = logger.ForContext(); } } } \ No newline at end of file diff --git a/PluralKit.Core/Modules/LoggingModule.cs b/PluralKit.Core/Modules/LoggingModule.cs index 7a9ffdaa..33d7e584 100644 --- a/PluralKit.Core/Modules/LoggingModule.cs +++ b/PluralKit.Core/Modules/LoggingModule.cs @@ -52,7 +52,6 @@ namespace PluralKit.Core // Don't want App.Metrics/D#+ spam .MinimumLevel.Override("App.Metrics", LogEventLevel.Information) - .MinimumLevel.Override("DSharpPlus", LogEventLevel.Debug) // Actual formatting for these is handled in ScalarFormatting .Destructure.AsScalar() @@ -98,14 +97,12 @@ namespace PluralKit.Core { AutoRegisterTemplate = true, AutoRegisterTemplateVersion = AutoRegisterTemplateVersion.ESv7, - MinimumLogEventLevel = LogEventLevel.Verbose, + MinimumLogEventLevel = config.ElasticLogLevel, IndexFormat = "pluralkit-logs-{0:yyyy.MM.dd}", - CustomFormatter = new ScalarFormatting.Elasticsearch() + CustomFormatter = new ScalarFormatting.Elasticsearch(), }; - - logCfg.WriteTo - .Conditional(e => e.Properties.ContainsKey("Elastic"), - c => c.Elasticsearch(elasticConfig)); + + logCfg.WriteTo.Elasticsearch(elasticConfig); } _fn.Invoke(logCfg);