Updates to Elastic logging

Myriad/Gateway/Cluster.cs

@@ -21,7 +21,7 @@ namespace Myriad.Gateway
         public Cluster(GatewaySettings gatewaySettings, ILogger logger)
         {
             _gatewaySettings = gatewaySettings;
-            _logger = logger;
+            _logger = logger.ForContext<Cluster>();
         }
 
         public Func<Shard, IGatewayEvent, Task>? EventReceived { get; set; }

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();

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<TwilightGatewayRatelimiter>();
         }
 
         public async Task Identify(int shard)

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<Shard>().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

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)",
+            _logger.Debug("Shard {ShardId}: Received Heartbeat (latency {Latency:N2} ms)",
-                _info.ShardId, _latency);
+                _info.ShardId, _latency?.TotalMilliseconds);
             return Task.CompletedTask;
         }
 

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}",
+                        "Response: {RequestMethod} {RequestPath} -> {StatusCode} {ReasonPhrase} (in {ResponseDurationMs} ms)",
-                        stopwatch.ElapsedMilliseconds, request.Method, request.RequestUri, (int) response.StatusCode,
+                        request.Method, request.RequestUri, (int) response.StatusCode, response.ReasonPhrase, stopwatch.ElapsedMilliseconds);
-                        response.ReasonPhrase);
 
                     await HandleApiError(response, ignoreNotFound);
 
@@ -208,14 +210,16 @@ namespace Myriad.Rest
             if (response.StatusCode == HttpStatusCode.NotFound && ignoreNotFound)
                 return;
 
-            throw await CreateDiscordException(response);
-        }
-
-        private async ValueTask<DiscordRequestException> CreateDiscordException(HttpResponseMessage 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 DiscordRequestException CreateDiscordException(HttpResponseMessage response, string body, DiscordApiError? apiError)
+        {
             return response.StatusCode switch
             {
                 HttpStatusCode.BadRequest => new BadRequestException(response, body, apiError),

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;

PluralKit.Bot/Bot.cs

@@ -177,13 +177,12 @@ namespace PluralKit.Bot
             {
                 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<SerilogGatewayEnricherFactory>().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<ISentryEnricher<T>>();
                 sentryEnricher?.Enrich(serviceScope.Resolve<Scope>(), 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
+            _logger.Error(exc, "Exception in event handler: {SentryEventId}", sentryEvent.EventId);
-                .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 MessageCreateEvent mc && mc.Author.Id == shard.User?.Id)

PluralKit.Bot/Modules.cs

@@ -116,6 +116,7 @@ namespace PluralKit.Bot
                 Timeout = TimeSpan.FromSeconds(5)
             }).AsSelf().SingleInstance();
             builder.RegisterInstance(SystemClock.Instance).As<IClock>();
+            builder.RegisterType<SerilogGatewayEnricherFactory>().AsSelf().SingleInstance();
 
             builder.RegisterType<DiscordRequestObserver>().AsSelf().SingleInstance();
         }

PluralKit.Bot/Services/CommandMessageService.cs

@@ -22,7 +22,7 @@ namespace PluralKit.Bot
             _db = db;
             _repo = repo;
             _clock = clock;
-            _logger = logger;
+            _logger = logger.ForContext<CommandMessageService>();
         }
 
         public async Task RegisterMessage(ulong messageId, ulong authorId)

PluralKit.Bot/Services/WebhookCacheService.cs

@@ -71,7 +71,7 @@ namespace PluralKit.Bot
         public async Task<Webhook> 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);

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<KeyValuePair<string, object>>
     {
         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))
             {

PluralKit.Bot/Tracing/EventDestructuring.cs

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

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<LogEventProperty>
+            {
+                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<LogEventProperty> Properties): ILogEventEnricher
+        {
+            public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
+            {
+                foreach (var prop in Properties) 
+                    logEvent.AddPropertyIfAbsent(prop);
+            }
+        }
+    }
+}

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;
     }
 }

PluralKit.Core/Database/Database.cs

@@ -33,7 +33,7 @@ namespace PluralKit.Core
             _config = config;
             _countHolder = countHolder;
             _metrics = metrics;
-            _logger = logger;
+            _logger = logger.ForContext<Database>();
             
             _connectionString = new NpgsqlConnectionStringBuilder(_config.Database)
             {

PluralKit.Core/Database/Repository/ModelRepository.cs

@@ -8,8 +8,7 @@ namespace PluralKit.Core
 
         public ModelRepository(ILogger logger)
         {
-            _logger = logger.ForContext<ILogger>()
+            _logger = logger.ForContext<ModelRepository>();
-                .ForContext("Elastic", "yes?");
         }
     }
 }

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<SystemId>()
@@ -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
+                logCfg.WriteTo.Elasticsearch(elasticConfig);
-                    .Conditional(e => e.Properties.ContainsKey("Elastic"), 
-                        c => c.Elasticsearch(elasticConfig));
             }
 
             _fn.Invoke(logCfg);