Logging improvements

Log to file Add correlation vector to logs Add IP to logs Add API Key to logs
gwdevhub · Aug 15, 2024 · f93b177 · f93b177
1 parent 8399cc6
commit f93b177
Show file tree

Hide file tree

Showing 22 changed files with 238 additions and 77 deletions.
diff --git a/GuildWarsPartySearch/Config.Debug.json b/GuildWarsPartySearch/Config.Debug.json
@@ -1,9 +1,16 @@
 {
   "Logging": {
-    "LogLevel": {
+    "MinimumLevel": {
       "Default": "Debug",
-      "Microsoft": "Warning",
-      "Microsoft.Hosting.Lifetime": "Information"
+      "Override": {
+        "Microsoft": "Warning",
+        "Microsoft.Hosting.Lifetime": "Information",
+        "GuildWarsPartySearch.Server.Middleware": "Information",
+        "GuildWarsPartySearch.Server.Services.Permissions.PermissionService": "Information",
+        "GuildWarsPartySearch.Server.Services.Database": "Information",
+        "GuildWarsPartySearch.Server.Endpoints.LiveFeed": "Information",
+        "GuildWarsPartySearch.Server.Endpoints.PostPartySearch": "Debug"
+      }
     }
   },
   "EnvironmentOptions": {
@@ -12,8 +19,7 @@
   "ServerOptions": {
     "InactivityTimeout": "0:0:5",
     "HeartbeatFrequency": "0:0:1",
-    "Port": 80,
-    "LogHeaders": true
+    "Port": 80
   },
   "SQLiteDatabaseOptions": {
     "Path": "partysearches.db"

diff --git a/GuildWarsPartySearch/Config.Production.json b/GuildWarsPartySearch/Config.Production.json
@@ -1,9 +1,16 @@
 {
   "Logging": {
-    "LogLevel": {
+    "MinimumLevel": {
       "Default": "Debug",
-      "Microsoft": "Warning",
-      "Microsoft.Hosting.Lifetime": "Information"
+      "Override": {
+        "Microsoft": "Warning",
+        "Microsoft.Hosting.Lifetime": "Information",
+        "GuildWarsPartySearch.Server.Middleware": "Information",
+        "GuildWarsPartySearch.Server.Services.Permissions.PermissionService": "Information",
+        "GuildWarsPartySearch.Server.Services.Database": "Information",
+        "GuildWarsPartySearch.Server.Endpoints.LiveFeed": "Information",
+        "GuildWarsPartySearch.Server.Endpoints.PostPartySearch": "Debug"
+      }
     }
   },
   "EnvironmentOptions": {
@@ -12,8 +19,7 @@
   "ServerOptions": {
     "InactivityTimeout": "0:0:5",
     "HeartbeatFrequency": "0:0:1",
-    "Port": 80,
-    "LogHeaders": false
+    "Port": 80
   },
   "SQLiteDatabaseOptions": {
     "Path": "partysearches.db"

diff --git a/GuildWarsPartySearch/Endpoints/LiveFeed.cs b/GuildWarsPartySearch/Endpoints/LiveFeed.cs
@@ -45,7 +45,7 @@ await this.SendMessage(new PartySearchList
     public override async Task SocketAccepted(CancellationToken cancellationToken)
     {
         var ipAddress = this.Context?.Request.HttpContext.GetClientIP();
-        var scopedLogger = this.logger.CreateScopedLogger(nameof(this.SocketAccepted), ipAddress ?? string.Empty);
+        var scopedLogger = this.logger.CreateScopedLogger(nameof(this.SocketAccepted), string.Empty);
         if (!await this.liveFeedService.AddClient(this.WebSocket!, ipAddress, this.Context?.GetPermissionLevel() ?? Models.PermissionLevel.None, cancellationToken))
         {
             scopedLogger.LogError("Client rejected");
@@ -66,7 +66,7 @@ await this.SendMessage(new PartySearchList
     public override Task SocketClosed()
     {
         var ipAddress = this.Context?.Request.HttpContext.GetClientIP();
-        var scopedLogger = this.logger.CreateScopedLogger(nameof(this.SocketClosed), ipAddress ?? string.Empty);
+        var scopedLogger = this.logger.CreateScopedLogger(nameof(this.SocketClosed), string.Empty);
         this.liveFeedService.RemoveClient(this.WebSocket!, ipAddress);
         scopedLogger.LogDebug("Client removed from livefeed");
         return Task.CompletedTask;

diff --git a/GuildWarsPartySearch/Endpoints/PostPartySearch.cs b/GuildWarsPartySearch/Endpoints/PostPartySearch.cs
@@ -77,7 +77,7 @@ public override async Task ExecuteAsync(PostPartySearchRequest? message, Cancell
             throw new InvalidOperationException("Unable to extract user agent on client disconnect");
         }
 
-        var scopedLogger = this.logger.CreateScopedLogger(nameof(this.ExecuteAsync), userAgent);
+        var scopedLogger = this.logger.CreateScopedLogger(nameof(this.ExecuteAsync), string.Empty);
         try
         {
             var currentBot = await this.botStatusService.GetBot(userAgent, cancellationToken);

diff --git a/GuildWarsPartySearch/Endpoints/WebSocketRouteBase.cs b/GuildWarsPartySearch/Endpoints/WebSocketRouteBase.cs
@@ -48,7 +48,7 @@ public sealed override Task ExecuteAsync(WebSocketMessageType type, byte[] data,
         }
         catch(Exception ex)
         {
-            var scoppedLogger = this.Context!.RequestServices.GetRequiredService<ILogger<WebSocketRouteBase>>().CreateScopedLogger(nameof(this.ExecuteAsync), string.Empty);
+            var scoppedLogger = this.Context!.RequestServices.GetRequiredService<ILogger<WebSocketRouteBase<TReceiveType>>>().CreateScopedLogger(nameof(this.ExecuteAsync), string.Empty);
             scoppedLogger.LogError(ex, "Failed to process data");
             throw;
         }
@@ -109,7 +109,7 @@ public Task SendMessage(TSendType sendType, CancellationToken cancellationToken)
         }
         catch(Exception ex )
         {
-            var scoppedLogger = this.Context!.RequestServices.GetRequiredService<ILogger<WebSocketRouteBase>>().CreateScopedLogger(nameof(this.SendMessage), typeof(TSendType).Name);
+            var scoppedLogger = this.Context!.RequestServices.GetRequiredService<ILogger<WebSocketRouteBase<TReceiveType, TSendType>>>().CreateScopedLogger(nameof(this.SendMessage), string.Empty);
             scoppedLogger.LogError(ex, "Failed to send data");
             throw;
         }

diff --git a/GuildWarsPartySearch/Extensions/HttpContextExtensions.cs b/GuildWarsPartySearch/Extensions/HttpContextExtensions.cs
@@ -1,10 +1,14 @@
 using GuildWarsPartySearch.Server.Models;
+using Microsoft.CorrelationVector;
+using Serilog.Context;
 using System.Core.Extensions;
 
 namespace GuildWarsPartySearch.Server.Extensions;
 
 public static class HttpContextExtensions
 {
+    private const string CorrelationVectorKey = "CorrelationVector";
+    private const string ApiKey = "ApiKey";
     private const string PermissionLevelKey = "PermissionLevel";
     private const string PermissionReasonKey = "PermissionReason";
     private const string ClientIPKey = "ClientIP";
@@ -57,4 +61,40 @@ public static string GetClientIP(this HttpContext context)
 
         return ipStr;
     }
+
+    public static void SetApiKey(this HttpContext context, string apiKey)
+    {
+        context.ThrowIfNull()
+            .Items.Add(ApiKey, apiKey);
+    }
+
+    public static string GetApiKey(this HttpContext context)
+    {
+        context.ThrowIfNull();
+        if (!context.Items.TryGetValue(ApiKey, out var apiKey) ||
+            apiKey is not string apiKeyStr)
+        {
+            throw new InvalidOperationException("Unable to extract API Key from context");
+        }
+
+        return apiKeyStr;
+    }
+
+    public static void SetCorrelationVector(this HttpContext context, CorrelationVector cv)
+    {
+        context.ThrowIfNull()
+            .Items.Add(CorrelationVectorKey, cv);
+    }
+
+    public static CorrelationVector GetCorrelationVector(this HttpContext context)
+    {
+        context.ThrowIfNull();
+        if (!context.Items.TryGetValue(CorrelationVectorKey, out var cvVal) ||
+            cvVal is not CorrelationVector cv)
+        {
+            throw new InvalidOperationException("Unable to extract API Key from context");
+        }
+
+        return cv;
+    }
 }
diff --git a/GuildWarsPartySearch/Extensions/WebApplicationBuilderExtensions.cs b/GuildWarsPartySearch/Extensions/WebApplicationBuilderExtensions.cs
@@ -14,6 +14,12 @@ public static WebApplicationBuilder ConfigureExtended<TOptions>(this WebApplicat
         return builder;
     }
 
+    public static IConfigurationSection GetRequiredSection<TOptions>(this ConfigurationManager configurationManager)
+    {
+        configurationManager.ThrowIfNull();
+        return configurationManager.GetRequiredSection(GetOptionsName<TOptions>());
+    }
+
     private static string GetOptionsName<TOptions>()
     {
         var maybeAttribute = typeof(TOptions).GetCustomAttributes(false).OfType<OptionsNameAttribute>().FirstOrDefault();

diff --git a/GuildWarsPartySearch/GuildWarsPartySearch.Server.csproj b/GuildWarsPartySearch/GuildWarsPartySearch.Server.csproj
@@ -14,7 +14,10 @@
 
   <ItemGroup>
     <PackageReference Include="App.Metrics.AspNetCore.All" Version="4.3.0" />
+    <PackageReference Include="Microsoft.CorrelationVector" Version="1.0.42" />
     <PackageReference Include="Microsoft.Data.Sqlite" Version="8.0.7" />
+    <PackageReference Include="Serilog.AspNetCore" Version="8.0.2" />
+    <PackageReference Include="Serilog.Sinks.File" Version="6.0.0" />
     <PackageReference Include="Swashbuckle.AspNetCore" Version="6.7.0" />
     <PackageReference Include="Swashbuckle.AspNetCore.Annotations" Version="6.7.0" />
     <PackageReference Include="Swashbuckle.AspNetCore.Swagger" Version="6.7.0" />

diff --git a/GuildWarsPartySearch/Launch/Program.cs b/GuildWarsPartySearch/Launch/Program.cs
@@ -1,5 +1,6 @@
 // See https://aka.ms/new-console-template for more information
 using App.Metrics;
+using GuildWarsPartySearch.Server.Extensions;
 using GuildWarsPartySearch.Server.Middleware;
 using GuildWarsPartySearch.Server.Options;
 using Microsoft.Extensions.FileProviders;
@@ -26,9 +27,9 @@ private static async Task Main()
 
         builder.Configuration.AddConfiguration(config);
 
-        var options = builder.Configuration.GetRequiredSection(nameof(ServerOptions)).Get<ServerOptions>();
-        var environmentOptions = builder.Configuration.GetRequiredSection(nameof(EnvironmentOptions)).Get<EnvironmentOptions>()!;
-        var contentOptions = builder.Configuration.GetRequiredSection(nameof(ContentOptions)).Get<ContentOptions>()!;
+        var options = builder.Configuration.GetRequiredSection<ServerOptions>().Get<ServerOptions>();
+        var environmentOptions = builder.Configuration.GetRequiredSection<EnvironmentOptions>().Get<EnvironmentOptions>()!;
+        var contentOptions = builder.Configuration.GetRequiredSection<ContentOptions>().Get<ContentOptions>()!;
 
         builder.Environment.EnvironmentName = environmentOptions.Name?.ThrowIfNull()!;
 
@@ -56,7 +57,7 @@ private static async Task Main()
             c.EnableAnnotations();
         });
         builder.Services.AddSingleton(jsonOptions);
-        builder.Logging.SetupLogging();
+        builder.Logging.SetupLogging(config);
         builder.Services.SetupServices();
         builder.Services.AddControllers();
         builder.Services.AddMetrics(metrics);
@@ -78,8 +79,10 @@ private static async Task Main()
         }
 
         var app = builder.Build();
-        app.UseMiddleware<IPExtractingMiddleware>()
+        app.UseMiddleware<CorrelationVectorMiddleware>()
+           .UseMiddleware<IPExtractingMiddleware>()
            .UseMiddleware<PermissioningMiddleware>()
+           .UseMiddleware<LoggingEnrichmentMiddleware>()
            .UseMiddleware<HeaderLoggingMiddleware>()
            .UseSwagger()
            .UseWebSockets()

diff --git a/GuildWarsPartySearch/Launch/ServerConfiguration.cs b/GuildWarsPartySearch/Launch/ServerConfiguration.cs
@@ -13,6 +13,9 @@
 using GuildWarsPartySearch.Server.Services.Processing;
 using Microsoft.Data.Sqlite;
 using Microsoft.Extensions.Options;
+using Serilog;
+using Serilog.Settings.Configuration;
+using Serilog.Sinks.File;
 using System.Core.Extensions;
 using System.Extensions;
 using System.Text.Json.Serialization;
@@ -38,18 +41,34 @@ public static WebApplicationBuilder SetupHostedServices(this WebApplicationBuild
     public static IConfigurationBuilder SetupConfiguration(this IConfigurationBuilder builder)
     {
         builder.ThrowIfNull()
-            .SetBasePath(Path.GetDirectoryName(System.Reflection.Assembly.GetEntryAssembly()?.Location) ?? throw new InvalidOperationException("Unable to figure out base directory"))
+            .SetBasePath(GetBasePath())
             .AddJsonFile("Config.json", false)
             .AddEnvironmentVariables();
 
         return builder;
     }
 
-    public static ILoggingBuilder SetupLogging(this ILoggingBuilder builder)
+    public static ILoggingBuilder SetupLogging(this ILoggingBuilder builder, IConfigurationRoot config)
     {
         builder.ThrowIfNull()
             .ClearProviders()
-            .AddConsole(o => o.TimestampFormat = "[yyyy-MM-dd HH:mm:ss] ");
+            .AddSerilog(logger: new LoggerConfiguration()
+                .ReadFrom.Configuration(config, readerOptions: new ConfigurationReaderOptions
+                {
+                    SectionName = "Logging"
+                })
+                .Enrich.FromLogContext()
+                .WriteTo.Console(
+                    outputTemplate: "[{Timestamp:yyyy-MM-dd HH:mm:ss}] {Level:u4}: [{ClientIP}] [{ApiKey}] [{CorrelationVector}] [{SourceContext}]{NewLine}{Message:lj}{NewLine}{Exception}",
+                    theme: Serilog.Sinks.SystemConsole.Themes.SystemConsoleTheme.Colored)
+                .WriteTo.File(
+                    path: Path.Combine(GetBasePath(), "logs/log-.txt"),
+                    rollingInterval: RollingInterval.Day,
+                    retainedFileCountLimit: 7,
+                    fileSizeLimitBytes: 10 * 1024 * 1024,
+                    rollOnFileSizeLimit: true,
+                    outputTemplate: "[{Timestamp:yyyy-MM-dd HH:mm:ss}] {Level:u4}: [{ClientIP}] [{ApiKey}] [{CorrelationVector}] [{SourceContext}] - {Message:lj}{NewLine}{Exception}")
+                .CreateLogger());
 
         return builder;
     }
@@ -76,8 +95,7 @@ public static IServiceCollection SetupServices(this IServiceCollection services)
         services.AddSingleton(sp =>
         {
             var options = sp.GetRequiredService<IOptions<SQLiteDatabaseOptions>>();
-            var absolutePath = Path.Combine(
-                Path.GetDirectoryName(System.Reflection.Assembly.GetEntryAssembly()?.Location) ?? throw new InvalidOperationException("Unable to figure out base directory"), options.Value.Path);
+            var absolutePath = Path.Combine(GetBasePath(), options.Value.Path);
             SQLitePCL.raw.SetProvider(new SQLitePCL.SQLite3Provider_e_sqlite3());
             var connection = new SqliteConnection($"Data Source={absolutePath}");
             connection.Open();
@@ -90,9 +108,11 @@ public static IServiceCollection SetupServices(this IServiceCollection services)
         services.AddScoped<IPExtractingMiddleware>();
         services.AddScoped<PermissioningMiddleware>();
         services.AddScoped<HeaderLoggingMiddleware>();
+        services.AddScoped<CorrelationVectorMiddleware>();
         services.AddScoped<UserAgentRequired>();
         services.AddScoped<AdminPermissionRequired>();
         services.AddScoped<BotPermissionRequired>();
+        services.AddScoped<LoggingEnrichmentMiddleware>();
         services.AddScoped<IPartySearchService, PartySearchService>();
         services.AddScoped<ICharNameValidator, CharNameValidator>();
         services.AddScoped<IPermissionService, PermissionService>();
@@ -107,4 +127,9 @@ public static WebApplication SetupRoutes(this WebApplication app)
 
         return app;
     }
+
+    private static string GetBasePath()
+    {
+        return Path.GetDirectoryName(System.Reflection.Assembly.GetEntryAssembly()?.Location) ?? throw new InvalidOperationException("Unable to get base path");
+    }
 }
diff --git a/GuildWarsPartySearch/Middleware/CorrelationVectorMiddleware.cs b/GuildWarsPartySearch/Middleware/CorrelationVectorMiddleware.cs
@@ -0,0 +1,24 @@
+
+using GuildWarsPartySearch.Server.Extensions;
+using Microsoft.CorrelationVector;
+
+namespace GuildWarsPartySearch.Server.Middleware;
+
+public sealed class CorrelationVectorMiddleware : IMiddleware
+{
+    private const string CorrelationVectorHeader = "X-Correlation-Vector";
+
+    public Task InvokeAsync(HttpContext context, RequestDelegate next)
+    {
+        var cv = new CorrelationVector();
+        if (context.Items.TryGetValue(CorrelationVectorHeader, out var correlationVectorVal) &&
+            correlationVectorVal is string correlationVectorStr)
+        {
+            cv = CorrelationVector.Parse(correlationVectorStr);
+            cv.Increment();
+        }
+
+        context.SetCorrelationVector(cv);
+        return next(context);
+    }
+}
diff --git a/GuildWarsPartySearch/Middleware/HeaderLoggingMiddleware.cs b/GuildWarsPartySearch/Middleware/HeaderLoggingMiddleware.cs
@@ -21,13 +21,9 @@ public HeaderLoggingMiddleware(
 
     public async Task InvokeAsync(HttpContext context, RequestDelegate next)
     {
-        if (this.options.LogHeaders)
-        {
-            var clientIp = context.Request.HttpContext.GetClientIP();
-            var scopedLogger = this.logger.CreateScopedLogger(nameof(this.InvokeAsync), clientIp);
-            scopedLogger.LogDebug(string.Join("\n", context.Request.Headers.Select(kvp => $"{kvp.Key}: {string.Join(",", kvp.Value.OfType<string>())}")));
-        }
-
+        var clientIp = context.Request.HttpContext.GetClientIP();
+        var scopedLogger = this.logger.CreateScopedLogger(nameof(this.InvokeAsync), string.Empty);
+        scopedLogger.LogDebug(string.Join("\n", context.Request.Headers.Select(kvp => $"{kvp.Key}: {string.Join(",", kvp.Value.OfType<string>())}")));
         await next(context);
     }
 }
diff --git a/GuildWarsPartySearch/Middleware/IPExtractingMiddleware.cs b/GuildWarsPartySearch/Middleware/IPExtractingMiddleware.cs
@@ -1,6 +1,4 @@
 using GuildWarsPartySearch.Server.Extensions;
-using System.Core.Extensions;
-using System.Extensions;
 
 namespace GuildWarsPartySearch.Server.Middleware;
 
@@ -9,18 +7,13 @@ public sealed class IPExtractingMiddleware : IMiddleware
     private const string XForwardedForHeaderKey = "X-Forwarded-For";
     private const string CFConnectingIPHeaderKey = "CF-Connecting-IP";
 
-    private readonly ILogger<IPExtractingMiddleware> logger;
-
-    public IPExtractingMiddleware(
-        ILogger<IPExtractingMiddleware> logger)
+    public IPExtractingMiddleware()
     {
-        this.logger = logger.ThrowIfNull();
     }
 
     public async Task InvokeAsync(HttpContext context, RequestDelegate next)
     {
         var address = context.Connection.RemoteIpAddress?.ToString();
-        var scopedLogger = this.logger.CreateScopedLogger(nameof(this.InvokeAsync), address ?? string.Empty);
         context.Request.Headers.TryGetValue(CFConnectingIPHeaderKey, out var cfConnectingIpValues);
         if (cfConnectingIpValues.FirstOrDefault() is string xCfIpAddress)
         {

diff --git a/GuildWarsPartySearch/Middleware/LoggingEnrichmentMiddleware.cs b/GuildWarsPartySearch/Middleware/LoggingEnrichmentMiddleware.cs
@@ -0,0 +1,18 @@
+using GuildWarsPartySearch.Server.Extensions;
+using Serilog.Context;
+
+namespace GuildWarsPartySearch.Server.Middleware;
+
+public sealed class LoggingEnrichmentMiddleware : IMiddleware
+{
+    public Task InvokeAsync(HttpContext context, RequestDelegate next)
+    {
+        var ip = context.GetClientIP();
+        var apiKey = context.GetApiKey();
+        var cv = context.GetCorrelationVector();
+        LogContext.PushProperty("ApiKey", apiKey);
+        LogContext.PushProperty("ClientIP", ip);
+        LogContext.PushProperty("CorrelationVector", cv);
+        return next(context);
+    }
+}