fix: better logging

- verbose logging for log channel resolving logic
- don't LOG TOKENS TO THE CONSOLE OR SEQ
- actually log verbose logs to seq
- report open db connections to prometheus

Catalogger.Backend/CataloggerMetrics.cs

@@ -29,6 +29,11 @@ public static class CataloggerMetrics
 
     public static long MessageRateMinute { get; set; }
 
+    public static readonly Gauge DatabaseConnections = Metrics.CreateGauge(
+        "catalogger_open_database_connections",
+        "Number of open database connections"
+    );
+
     public static readonly Gauge GuildsCached = Metrics.CreateGauge(
         "catalogger_cache_guilds",
         "Number of guilds in the cache"

Catalogger.Backend/Database/DatabaseConnection.cs

@@ -20,14 +20,9 @@ using Npgsql;
 
 namespace Catalogger.Backend.Database;
 
-public class DatabaseConnection(Guid id, ILogger logger, NpgsqlConnection inner)
-    : DbConnection,
-        IDisposable
+public class DatabaseConnection(NpgsqlConnection inner) : DbConnection, IDisposable
 {
-    public Guid ConnectionId => id;
     public NpgsqlConnection Inner => inner;
-    private readonly ILogger _logger = logger.ForContext<DatabaseConnection>();
-    private readonly DateTimeOffset _openTime = DateTimeOffset.UtcNow;
 
     private bool _hasClosed;
 
@@ -43,8 +38,6 @@ public class DatabaseConnection(Guid id, ILogger logger, NpgsqlConnection inner)
         }
 
         DatabasePool.DecrementConnections();
-        var openFor = DateTimeOffset.UtcNow - _openTime;
-        _logger.Verbose("Closing connection {ConnId}, open for {OpenFor}", ConnectionId, openFor);
         _hasClosed = true;
         await inner.CloseAsync();
     }
@@ -52,11 +45,7 @@ public class DatabaseConnection(Guid id, ILogger logger, NpgsqlConnection inner)
     protected override async ValueTask<DbTransaction> BeginDbTransactionAsync(
         IsolationLevel isolationLevel,
         CancellationToken cancellationToken
-    )
-    {
-        _logger.Verbose("Beginning transaction on connection {ConnId}", ConnectionId);
-        return await inner.BeginTransactionAsync(isolationLevel, cancellationToken);
-    }
+    ) => await inner.BeginTransactionAsync(isolationLevel, cancellationToken);
 
     public new void Dispose()
     {

Catalogger.Backend/Database/DatabasePool.cs

@@ -24,18 +24,13 @@ namespace Catalogger.Backend.Database;
 
 public class DatabasePool
 {
-    private readonly ILogger _rootLogger;
-    private readonly ILogger _logger;
     private readonly NpgsqlDataSource _dataSource;
 
     private static int _openConnections;
     public static int OpenConnections => _openConnections;
 
-    public DatabasePool(Config config, ILogger logger, ILoggerFactory? loggerFactory)
+    public DatabasePool(Config config, ILoggerFactory? loggerFactory)
     {
-        _rootLogger = logger;
-        _logger = logger.ForContext<DatabasePool>();
-
         var connString = new NpgsqlConnectionStringBuilder(config.Database.Url)
         {
             Timeout = config.Database.Timeout ?? 5,
@@ -49,27 +44,10 @@ public class DatabasePool
         _dataSource = dataSourceBuilder.Build();
     }
 
-    public async Task<DatabaseConnection> AcquireAsync(CancellationToken ct = default)
-    {
-        return new DatabaseConnection(
-            LogOpen(),
-            _rootLogger,
-            await _dataSource.OpenConnectionAsync(ct)
-        );
-    }
+    public async Task<DatabaseConnection> AcquireAsync(CancellationToken ct = default) =>
+        new(await _dataSource.OpenConnectionAsync(ct));
 
-    public DatabaseConnection Acquire()
-    {
-        return new DatabaseConnection(LogOpen(), _rootLogger, _dataSource.OpenConnection());
-    }
-
-    private Guid LogOpen()
-    {
-        var connId = Guid.NewGuid();
-        _logger.Verbose("Opening database connection {ConnId}", connId);
-        IncrementConnections();
-        return connId;
-    }
+    public DatabaseConnection Acquire() => new(_dataSource.OpenConnection());
 
     public async Task ExecuteAsync(
         Func<DatabaseConnection, Task> func,

Catalogger.Backend/Extensions/StartupExtensions.cs

@@ -51,19 +51,22 @@ public static class StartupExtensions
     {
         var logCfg = new LoggerConfiguration()
             .Enrich.FromLogContext()
-            .MinimumLevel.Is(config.Logging.LogEventLevel)
+            .MinimumLevel.Verbose()
+            // Most Microsoft.* package logs are needlessly verbose, so we restrict them to INFO level and up
+            .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
             // ASP.NET's built in request logs are extremely verbose, so we use Serilog's instead.
             // Serilog doesn't disable the built-in logs, so we do it here.
-            .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
-            .MinimumLevel.Override(
-                "Microsoft.EntityFrameworkCore.Database.Command",
-                config.Logging.LogQueries ? LogEventLevel.Information : LogEventLevel.Fatal
-            )
             .MinimumLevel.Override("Microsoft.AspNetCore.Hosting", LogEventLevel.Warning)
             .MinimumLevel.Override("Microsoft.AspNetCore.Mvc", LogEventLevel.Warning)
             .MinimumLevel.Override("Microsoft.AspNetCore.Routing", LogEventLevel.Warning)
+            // Let's not put webhook tokens and even *full bot tokens* in the logs, thank you
+            .MinimumLevel.Override("System.Net.Http.HttpClient", LogEventLevel.Warning)
             // The default theme doesn't support light mode
-            .WriteTo.Console(theme: AnsiConsoleTheme.Sixteen, applyThemeToRedirectedOutput: true);
+            .WriteTo.Console(
+                theme: AnsiConsoleTheme.Sixteen,
+                applyThemeToRedirectedOutput: true,
+                restrictedToMinimumLevel: config.Logging.LogEventLevel
+            );
 
         if (config.Logging.SeqLogUrl != null)
         {

Catalogger.Backend/Services/MetricsCollectionService.cs

@@ -43,6 +43,7 @@ public class MetricsCollectionService(
 
         var messageCount = await conn.ExecuteScalarAsync<int>("select count(id) from messages");
 
+        CataloggerMetrics.DatabaseConnections.Set(DatabasePool.OpenConnections);
         CataloggerMetrics.GuildsCached.Set(guildCache.Size);
         CataloggerMetrics.ChannelsCached.Set(channelCache.Size);
         CataloggerMetrics.RolesCached.Set(roleCache.Size);

Catalogger.Backend/Services/WebhookExecutorService.cs

@@ -315,6 +315,13 @@ public class WebhookExecutorService(
         Snowflake channelId
     )
     {
+        _logger.Verbose(
+            "Getting log channel for event {Event} in guild {GuildId} and channel {ChannelId}",
+            logChannelType,
+            guild.Id,
+            channelId
+        );
+
         if (!channelCache.TryGet(channelId, out var channel))
             return GetDefaultLogChannel(guild, logChannelType);
 
@@ -329,7 +336,13 @@ public class WebhookExecutorService(
             // parent_id should always have a value for threads
             channelId = channel.ParentID.Value!.Value;
             if (!channelCache.TryGet(channelId, out var parentChannel))
+            {
+                _logger.Verbose(
+                    "Parent channel for thread {ChannelId} is not in cache, returning the default log channel",
+                    channelId
+                );
                 return GetDefaultLogChannel(guild, logChannelType);
+            }
             categoryId = parentChannel.ParentID.Value;
         }
         else
@@ -343,8 +356,16 @@ public class WebhookExecutorService(
             guild.IgnoredChannels.Contains(channelId.Value)
             || (categoryId != null && guild.IgnoredChannels.Contains(categoryId.Value.Value))
         )
+        {
+            _logger.Verbose(
+                "Channel {ChannelId} or its parent {CategoryId} is ignored",
+                channelId,
+                categoryId
+            );
             return null;
+        }
 
+        _logger.Verbose("Returning default log channel for {EventType}", logChannelType);
         return GetDefaultLogChannel(guild, logChannelType);
     }
 
@@ -355,13 +376,29 @@ public class WebhookExecutorService(
         ulong? userId = null
     )
     {
+        _logger.Verbose(
+            "Getting log channel for event {Event}. Channel ID: {ChannelId}, user ID: {UserId}",
+            logChannelType,
+            channelId,
+            userId
+        );
+
         // Check if the user is ignored globally
         if (userId != null && guild.Messages.IgnoredUsers.Contains(userId.Value))
+        {
+            _logger.Verbose("User {UserId} is ignored globally", userId);
             return null;
+        }
 
         // If the user isn't ignored and we didn't get a channel ID, return the default log channel
         if (channelId == null)
+        {
+            _logger.Verbose(
+                "No channel ID given so returning default channel for {Event}",
+                logChannelType
+            );
             return GetDefaultLogChannel(guild, logChannelType);
+        }
 
         if (!channelCache.TryGet(channelId.Value, out var channel))
             return null;
@@ -377,7 +414,13 @@ public class WebhookExecutorService(
             // parent_id should always have a value for threads
             channelId = channel.ParentID.Value!.Value;
             if (!channelCache.TryGet(channelId.Value, out var parentChannel))
+            {
+                _logger.Verbose(
+                    "Parent channel for thread {ChannelId} is not in cache, returning the default log channel",
+                    channelId
+                );
                 return GetDefaultLogChannel(guild, logChannelType);
+            }
             categoryId = parentChannel.ParentID.Value;
         }
         else
@@ -391,7 +434,14 @@ public class WebhookExecutorService(
             guild.Messages.IgnoredChannels.Contains(channelId.Value.Value)
             || categoryId != null && guild.Messages.IgnoredChannels.Contains(categoryId.Value.Value)
         )
+        {
+            _logger.Verbose(
+                "Channel {ChannelId} or its parent {CategoryId} is ignored",
+                channelId,
+                categoryId
+            );
             return null;
+        }
 
         if (userId != null)
         {
@@ -408,13 +458,27 @@ public class WebhookExecutorService(
                         : []
                 ) ?? [];
             if (channelIgnoredUsers.Concat(categoryIgnoredUsers).Contains(userId.Value))
+            {
+                _logger.Verbose(
+                    "User {UserId} is ignored in {ChannelId} or its category {CategoryId}",
+                    userId,
+                    channelId,
+                    categoryId
+                );
                 return null;
             }
+        }
 
         // These three events can be redirected to other channels. Redirects can be on a channel or category level.
         // The events are only redirected if they're supposed to be logged in the first place.
         if (GetDefaultLogChannel(guild, logChannelType) == 0)
+        {
+            _logger.Verbose(
+                "No default log channel for event {EventType}, ignoring event",
+                logChannelType
+            );
             return null;
+        }
 
         var categoryRedirect =
             categoryId != null
@@ -422,10 +486,29 @@ public class WebhookExecutorService(
                 : 0;
 
         if (guild.Channels.Redirects.TryGetValue(channelId.Value.Value, out var channelRedirect))
+        {
+            _logger.Verbose(
+                "Messages from channel {ChannelId} should be redirected to {RedirectId}",
+                channelId,
+                channelRedirect
+            );
             return channelRedirect;
-        return categoryRedirect != 0
-            ? categoryRedirect
-            : GetDefaultLogChannel(guild, logChannelType);
+        }
+
+        if (categoryRedirect != 0)
+        {
+            _logger.Verbose(
+                "Messages from categoryId {CategoryId} should be redirected to {RedirectId}",
+                categoryId,
+                categoryRedirect
+            );
+        }
+
+        _logger.Verbose(
+            "No redirects or ignores for event {EventType}, returning default log channel",
+            logChannelType
+        );
+        return GetDefaultLogChannel(guild, logChannelType);
     }
 
     public static ulong GetDefaultLogChannel(Guild guild, LogChannelType logChannelType) =>

Catalogger.GoImporter/Program.cs

@@ -43,7 +43,7 @@ internal class Program
             return;
         }
 
-        var db = new DatabasePool(config, Log.Logger, null);
+        var db = new DatabasePool(config, null);
         DatabasePool.ConfigureDapper();
         if (Environment.GetEnvironmentVariable("MIGRATE") == "true")
         {