From 94b307e23aef10962b8e8d25a57d8df9e18042cb Mon Sep 17 00:00:00 2001 From: Jon Menzies-Smith Date: Mon, 6 Jan 2025 11:34:52 +0000 Subject: [PATCH 1/2] Issue #389 Add option to add ElapsedMs to the HttpContext before enrishing diagnostic contect. --- .../AspNetCore/RequestLoggingMiddleware.cs | 7 ++++++ .../AspNetCore/RequestLoggingOptions.cs | 13 ++++++++++- .../SerilogWebHostBuilderExtensionsTests.cs | 23 +++++++++++++++++++ 3 files changed, 42 insertions(+), 1 deletion(-) diff --git a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs index a8ec777..f1708ce 100644 --- a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs +++ b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs @@ -32,6 +32,7 @@ class RequestLoggingMiddleware readonly Func> _getMessageTemplateProperties; readonly ILogger? _logger; readonly bool _includeQueryInRequestPath; + readonly bool _addElapsedToHttpContext; static readonly LogEventProperty[] NoProperties = []; public RequestLoggingMiddleware(RequestDelegate next, DiagnosticContext diagnosticContext, RequestLoggingOptions options) @@ -45,6 +46,7 @@ public RequestLoggingMiddleware(RequestDelegate next, DiagnosticContext diagnost _messageTemplate = new MessageTemplateParser().Parse(options.MessageTemplate); _logger = options.Logger?.ForContext(); _includeQueryInRequestPath = options.IncludeQueryInRequestPath; + _addElapsedToHttpContext = options.AddElapsedToHttpContext; _getMessageTemplateProperties = options.GetMessageTemplateProperties; } @@ -82,6 +84,11 @@ bool LogCompletion(HttpContext httpContext, DiagnosticContextCollector collector if (!logger.IsEnabled(level)) return false; + if (_addElapsedToHttpContext) + { + httpContext.Items.Add(RequestLoggingOptions.HttpContextItemsElapsedKey, elapsedMs); + } + _enrichDiagnosticContext?.Invoke(_diagnosticContext, httpContext); if (!collector.TryComplete(out var collectedProperties, out var collectedException)) diff --git a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs index fe9c1ab..e92859e 100644 --- a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs +++ b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs @@ -26,7 +26,7 @@ public class RequestLoggingOptions { const string DefaultRequestCompletionMessageTemplate = "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms"; - + static LogEventLevel DefaultGetLevel(HttpContext ctx, double _, Exception? ex) => ex != null ? LogEventLevel.Error @@ -41,6 +41,11 @@ static IEnumerable DefaultGetMessageTemplateProperties(HttpCon new LogEventProperty("StatusCode", new ScalarValue(statusCode)), new LogEventProperty("Elapsed", new ScalarValue(elapsedMs)) ]; + + /// + /// The key used to add the ElapsedMs value to Items collection + /// + public const string HttpContextItemsElapsedKey = "Serilog.AspNetCore.ElapsedMs"; /// /// Gets or sets the message template. The default value is @@ -80,6 +85,12 @@ static IEnumerable DefaultGetMessageTemplateProperties(HttpCon /// that is attached to request log events. The default is false. /// public bool IncludeQueryInRequestPath { get; set; } + + + /// + /// Add the elapsed millisecond value to the Items collection before invoking EnrichDiagnosticContext + /// + public bool AddElapsedToHttpContext { get; set; } /// /// A function to specify the values of the MessageTemplateProperties. diff --git a/test/Serilog.AspNetCore.Tests/SerilogWebHostBuilderExtensionsTests.cs b/test/Serilog.AspNetCore.Tests/SerilogWebHostBuilderExtensionsTests.cs index 61ea07a..0f43d27 100644 --- a/test/Serilog.AspNetCore.Tests/SerilogWebHostBuilderExtensionsTests.cs +++ b/test/Serilog.AspNetCore.Tests/SerilogWebHostBuilderExtensionsTests.cs @@ -64,6 +64,29 @@ public async Task RequestLoggingMiddlewareShouldEnrich() Assert.True(completionEvent.Properties.ContainsKey("Elapsed")); } + + [Fact] + public async Task RequestLoggingMiddlewareShouldEnrichWithElapsed() + { + var (sink, web) = Setup(options => + { + options.AddElapsedToHttpContext = true; + options.EnrichDiagnosticContext += (diagnosticContext, httpContext) => + { + var elapsedValue = (double)(httpContext.Items[RequestLoggingOptions.HttpContextItemsElapsedKey] ?? -0.1); + diagnosticContext.Set("ElapsedValue", elapsedValue); + }; + }); + + await web.CreateClient().GetAsync("/resource"); + + Assert.NotEmpty(sink.Writes); + + var completionEvent = sink.Writes.First(logEvent => Matching.FromSource()(logEvent)); + + Assert.True((double)completionEvent.Properties["ElapsedValue"].LiteralValue()! > 0); + } + [Fact] public async Task RequestLoggingMiddlewareShouldEnrichWithCustomisedProperties() { From 06479d44d9a9105efcbbdc6ff8373539696c83f1 Mon Sep 17 00:00:00 2001 From: Jon Menzies-Smith Date: Mon, 6 Jan 2025 11:40:39 +0000 Subject: [PATCH 2/2] tidy --- src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs | 5 ++--- .../SerilogWebHostBuilderExtensionsTests.cs | 1 - 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs index e92859e..b7937ec 100644 --- a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs +++ b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs @@ -26,7 +26,7 @@ public class RequestLoggingOptions { const string DefaultRequestCompletionMessageTemplate = "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms"; - + static LogEventLevel DefaultGetLevel(HttpContext ctx, double _, Exception? ex) => ex != null ? LogEventLevel.Error @@ -85,8 +85,7 @@ static IEnumerable DefaultGetMessageTemplateProperties(HttpCon /// that is attached to request log events. The default is false. /// public bool IncludeQueryInRequestPath { get; set; } - - + /// /// Add the elapsed millisecond value to the Items collection before invoking EnrichDiagnosticContext /// diff --git a/test/Serilog.AspNetCore.Tests/SerilogWebHostBuilderExtensionsTests.cs b/test/Serilog.AspNetCore.Tests/SerilogWebHostBuilderExtensionsTests.cs index 0f43d27..8d84553 100644 --- a/test/Serilog.AspNetCore.Tests/SerilogWebHostBuilderExtensionsTests.cs +++ b/test/Serilog.AspNetCore.Tests/SerilogWebHostBuilderExtensionsTests.cs @@ -63,7 +63,6 @@ public async Task RequestLoggingMiddlewareShouldEnrich() Assert.Equal("GET", completionEvent.Properties["RequestMethod"].LiteralValue()); Assert.True(completionEvent.Properties.ContainsKey("Elapsed")); } - [Fact] public async Task RequestLoggingMiddlewareShouldEnrichWithElapsed()