diff --git a/README.md b/README.md index 5922a7f..f7ea0d5 100644 --- a/README.md +++ b/README.md @@ -136,7 +136,7 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env) - `ApplicationVersion`: Version of your application (auto-detected from assembly) - `LoggingLevel`: Minimum level as Serilog's `LogEventLevel` number: 0=Verbose, 1=Debug, 2=Information (default), 3=Warning, 4=Error, 5=Fatal. `Microsoft.AspNetCore` and `Microsoft.EntityFrameworkCore` are always held at Warning. - `Environments`: Comma-separated list of environments where logging is active -- `LogRequests`: Write one line per HTTP request with its duration, status and a `Route` property holding the route template (`/api/orders/{id}`), so requests can be grouped per endpoint. Kept even when `LoggingLevel` is above Information. Default `true`. +- `LogRequests`: Write one line per HTTP request with its duration, status and a `Route` property holding the route template (`/api/orders/{id}`), so requests can be grouped per endpoint, plus `User` (the caller's name identifier, when signed in) and `UserAgent` (cut to 200 characters), so requests can be counted per caller. Kept even when `LoggingLevel` is above Information. Default `true`. - `SlowQueryMilliseconds`: EF Core commands taking at least this long are logged ("Executed DbCommand (Nms)"), so a slow request can be traced to its query; faster ones are not logged. Failed commands always are. `0` disables. Default `500`. - `QuietRequestPaths`: Comma-separated path prefixes whose successful requests are dropped (default `/health,/healthz,/metrics`). Failures are still logged. diff --git a/SW.Logger.Console/RequestLogging.cs b/SW.Logger.Console/RequestLogging.cs index 76f8534..39270cd 100644 --- a/SW.Logger.Console/RequestLogging.cs +++ b/SW.Logger.Console/RequestLogging.cs @@ -1,15 +1,21 @@ +using System.Security.Claims; using Microsoft.AspNetCore.Builder; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Routing; +using Microsoft.Extensions.DependencyInjection; using Serilog; using Serilog.AspNetCore; using Serilog.Events; +using SW.PrimitiveTypes; namespace SW.Logger.Console; internal static class RequestLogging { public const string RouteProperty = "Route"; + public const string UserProperty = "User"; + public const string UserAgentProperty = "UserAgent"; + public const int MaxUserAgentLength = 200; public const string UnmatchedRoute = "unmatched"; /// @@ -24,6 +30,29 @@ public static string GetRoute(HttpContext httpContext) return raw.StartsWith('/') ? raw : "/" + raw; } + /// + /// Who made the request, so calls can be counted per caller. The request line is written after + /// the rest of the pipeline has finished, outside the scope UseRequestContextLogEnricher pushes + /// User into, so it has to be read again here. + /// + public static string? GetUser(HttpContext httpContext) + { + var requestContext = httpContext.RequestServices?.GetService(); + if (requestContext is { IsValid: true } && requestContext.GetNameIdentifier() is { Length: > 0 } id) + return id; + return httpContext.User?.FindFirst(ClaimTypes.NameIdentifier)?.Value is { Length: > 0 } claim + ? claim + : null; + } + + /// The client's User-Agent, cut to a fixed length so one client can't bloat every line. + public static string? GetUserAgent(HttpContext httpContext) + { + var value = httpContext.Request.Headers.UserAgent.ToString(); + if (string.IsNullOrWhiteSpace(value)) return null; + return value.Length > MaxUserAgentLength ? value[..MaxUserAgentLength] : value; + } + public static LogEventLevel GetLevel(HttpContext httpContext, Exception? ex, string[] quietPaths) { if (ex != null || httpContext.Response.StatusCode >= 500) @@ -50,7 +79,13 @@ public static void Configure(RequestLoggingOptions options, LoggerOptions logger { var quietPaths = ParsePaths(loggerOptions.QuietRequestPaths); options.EnrichDiagnosticContext = (diagnosticContext, httpContext) => + { diagnosticContext.Set(RouteProperty, GetRoute(httpContext)); + if (GetUser(httpContext) is { } user) + diagnosticContext.Set(UserProperty, user); + if (GetUserAgent(httpContext) is { } userAgent) + diagnosticContext.Set(UserAgentProperty, userAgent); + }; options.GetLevel = (httpContext, _, ex) => GetLevel(httpContext, ex, quietPaths); } diff --git a/SW.Logger.UnitTests/EndToEndTests.cs b/SW.Logger.UnitTests/EndToEndTests.cs index e2f9e2a..8dbdc0f 100644 --- a/SW.Logger.UnitTests/EndToEndTests.cs +++ b/SW.Logger.UnitTests/EndToEndTests.cs @@ -1,3 +1,4 @@ +using System.Security.Claims; using Microsoft.AspNetCore.Builder; using Microsoft.AspNetCore.Hosting; using Microsoft.AspNetCore.TestHost; @@ -15,7 +16,11 @@ public class EndToEndTests private static async Task Run(int loggingLevel, params string[] paths) => await Run(loggingLevel, null, paths); - private static async Task Run(int loggingLevel, Action act, params string[] paths) + private static async Task Run(int loggingLevel, Action act, params string[] paths) => + await Run(loggingLevel, act, null, paths); + + private static async Task Run(int loggingLevel, Action act, + Action configureClient, params string[] paths) { var original = System.Console.Out; var captured = new StringWriter(); @@ -30,12 +35,21 @@ private static async Task Run(int loggingLevel, Action a o.LoggingLevel = loggingLevel; }); var app = builder.Build(); + // Stands in for authentication: a request with an X-Test-User header is signed in as that user. + app.Use(async (ctx, next) => + { + if (ctx.Request.Headers.TryGetValue("X-Test-User", out var user)) + ctx.User = new ClaimsPrincipal(new ClaimsIdentity( + new[] { new Claim(ClaimTypes.NameIdentifier, user.ToString()) }, "test")); + await next(); + }); app.UseSWConsoleLogger(); app.UseRouting(); app.UseEndpoints(e => e.MapGet("/api/orders/{id}", (int id) => "ok")); await app.StartAsync(); act?.Invoke(app.Services.GetRequiredService()); var client = app.GetTestClient(); + configureClient?.Invoke(client); foreach (var p in paths) await client.GetAsync(p); await app.StopAsync(); } @@ -58,6 +72,26 @@ public async Task Request_line_carries_the_route_template(int level) Assert.DoesNotContain("\"RequestPath\":\"/health\"", output); } + [Fact] + public async Task Request_line_carries_the_caller() + { + var output = await Run(3, null, c => + { + c.DefaultRequestHeaders.Add("X-Test-User", "customer-42"); + c.DefaultRequestHeaders.UserAgent.ParseAdd("RestSharp/110.2.0.0"); + }, "/api/orders/1"); + Assert.Contains("\"User\":\"customer-42\"", output); + Assert.Contains("\"UserAgent\":\"RestSharp/110.2.0.0\"", output); + } + + [Fact] + public async Task Anonymous_request_line_has_no_user() + { + var output = await Run(3, "/api/orders/1"); + Assert.Contains("\"Route\":\"/api/orders/{id}\"", output); + Assert.DoesNotContain("\"User\":", output); + } + [Fact] public async Task Framework_internals_are_quiet() { diff --git a/SW.Logger.UnitTests/RequestLoggingTests.cs b/SW.Logger.UnitTests/RequestLoggingTests.cs index c4efc30..0deaa08 100644 --- a/SW.Logger.UnitTests/RequestLoggingTests.cs +++ b/SW.Logger.UnitTests/RequestLoggingTests.cs @@ -83,4 +83,20 @@ public void Failed_ef_command_is_kept() => [Fact] public void Other_sources_are_untouched() => Assert.False(RequestLogging.IsFastEfCommand(Ef(LogEventLevel.Information, "1", "Other"), 500)); + + [Fact] + public void User_agent_is_cut_to_a_fixed_length() + { + var ctx = Context("/x"); + ctx.Request.Headers.UserAgent = new string('a', 500); + Assert.Equal(RequestLogging.MaxUserAgentLength, RequestLogging.GetUserAgent(ctx)!.Length); + } + + [Fact] + public void No_user_agent_and_no_user_give_null() + { + var ctx = Context("/x"); + Assert.Null(RequestLogging.GetUserAgent(ctx)); + Assert.Null(RequestLogging.GetUser(ctx)); + } }