From bf8b919f24acdd211cc362c1599d70f2a8733efd Mon Sep 17 00:00:00 2001 From: Hilmar Bunjes Date: Wed, 20 Sep 2023 09:07:03 +0200 Subject: [PATCH 1/3] Add EnrichDiagnosticContextAsync to allow async calls during request completion If you want to add properties to the diagnostic context that require async calls (e.g. reading request body), EnrichDiagnosticContextAsync allows to hand over your own async method. --- README.md | 7 +++++++ .../AspNetCore/RequestLoggingMiddleware.cs | 13 +++++++++++++ .../AspNetCore/RequestLoggingOptions.cs | 8 ++++++++ 3 files changed, 28 insertions(+) diff --git a/README.md b/README.md index f4c2578..e9f5c8b 100644 --- a/README.md +++ b/README.md @@ -163,6 +163,13 @@ app.UseSerilogRequestLogging(options => diagnosticContext.Set("RequestHost", httpContext.Request.Host.Value); diagnosticContext.Set("RequestScheme", httpContext.Request.Scheme); }; + + // Use an async method to add additional properties that can only be retrieved + // asynchronously like request body + options.EnrichDiagnosticContextAsync = async (diagnosticContext, httpContext) => + { + await AddRequestBodyAsync(diagnosticContext, httpContext); + }; }); ``` diff --git a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs index 0b0b3eb..43ffead 100644 --- a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs +++ b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs @@ -28,6 +28,7 @@ class RequestLoggingMiddleware readonly DiagnosticContext _diagnosticContext; readonly MessageTemplate _messageTemplate; readonly Action? _enrichDiagnosticContext; + readonly Func? _enrichDiagnosticContextAsync; readonly Func _getLevel; readonly Func> _getMessageTemplateProperties; readonly ILogger? _logger; @@ -42,6 +43,7 @@ public RequestLoggingMiddleware(RequestDelegate next, DiagnosticContext diagnost _getLevel = options.GetLevel; _enrichDiagnosticContext = options.EnrichDiagnosticContext; + _enrichDiagnosticContextAsync = options.EnrichDiagnosticContextAsync; _messageTemplate = new MessageTemplateParser().Parse(options.MessageTemplate); _logger = options.Logger?.ForContext(); _includeQueryInRequestPath = options.IncludeQueryInRequestPath; @@ -61,11 +63,14 @@ public async Task Invoke(HttpContext httpContext) await _next(httpContext); var elapsedMs = GetElapsedMilliseconds(start, Stopwatch.GetTimestamp()); var statusCode = httpContext.Response.StatusCode; + await CallEnrichDiagnosticContextAsync(httpContext); LogCompletion(httpContext, collector, statusCode, elapsedMs, null); } catch (Exception ex) // Never caught, because `LogCompletion()` returns false. This ensures e.g. the developer exception page is still // shown, although it does also mean we see a duplicate "unhandled exception" event from ASP.NET Core. + // We do not call _enrichDiagnosticContextAsync> here because we cannot do that in the filter and do not + // want to unwind the stack by rethrowing the exception. when (LogCompletion(httpContext, collector, 500, GetElapsedMilliseconds(start, Stopwatch.GetTimestamp()), ex)) { } @@ -75,6 +80,14 @@ public async Task Invoke(HttpContext httpContext) } } + async Task CallEnrichDiagnosticContextAsync(HttpContext httpContext) + { + if (_enrichDiagnosticContextAsync != null) + { + await _enrichDiagnosticContextAsync.Invoke(_diagnosticContext, httpContext); + } + } + bool LogCompletion(HttpContext httpContext, DiagnosticContextCollector collector, int statusCode, double elapsedMs, Exception? ex) { var logger = _logger ?? Log.ForContext(); diff --git a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs index d782e6d..e901346 100644 --- a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs +++ b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingOptions.cs @@ -69,6 +69,14 @@ static IEnumerable DefaultGetMessageTemplateProperties(HttpCon /// A callback that can be used to set additional properties on the request completion event. /// public Action? EnrichDiagnosticContext { get; set; } + + /// + /// An async callback that can be used to set additional properties on the request completion event. + /// Can be used in addition to if you need async calls (e.g. for getting the + /// request body) and will be called before the synchronous method. + /// + /// Execution is not guaranteed if an exception occurs during finalizing the diagnostic entries. + public Func? EnrichDiagnosticContextAsync { get; set; } /// /// The logger through which request completion events will be logged. The default is to use the From 986563a920293b1c4f0c6ddb3dca100a8e98e3c9 Mon Sep 17 00:00:00 2001 From: Hilmar Bunjes Date: Wed, 27 Sep 2023 21:41:23 +0200 Subject: [PATCH 2/3] Make sure the async enricher is only called if logger is enabled and also in case of an exception thrown before --- .../AspNetCore/RequestLoggingMiddleware.cs | 42 +++++++++++++------ 1 file changed, 29 insertions(+), 13 deletions(-) diff --git a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs index 43ffead..c24ef5e 100644 --- a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs +++ b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs @@ -56,42 +56,58 @@ public async Task Invoke(HttpContext httpContext) if (httpContext == null) throw new ArgumentNullException(nameof(httpContext)); var start = Stopwatch.GetTimestamp(); - var collector = _diagnosticContext.BeginCollection(); + ILogger? logger = null; + var level = LogEventLevel.Information; // only used if _getLevel throws an exception + double elapsedMs; + try { await _next(httpContext); - var elapsedMs = GetElapsedMilliseconds(start, Stopwatch.GetTimestamp()); + elapsedMs = GetElapsedMilliseconds(start, Stopwatch.GetTimestamp()); var statusCode = httpContext.Response.StatusCode; - await CallEnrichDiagnosticContextAsync(httpContext); - LogCompletion(httpContext, collector, statusCode, elapsedMs, null); + logger = _logger ?? Log.ForContext(); + level = _getLevel(httpContext, elapsedMs, null); + LogCompletion(httpContext, collector, statusCode, elapsedMs, logger, level, null); } catch (Exception ex) // Never caught, because `LogCompletion()` returns false. This ensures e.g. the developer exception page is still // shown, although it does also mean we see a duplicate "unhandled exception" event from ASP.NET Core. - // We do not call _enrichDiagnosticContextAsync> here because we cannot do that in the filter and do not - // want to unwind the stack by rethrowing the exception. - when (LogCompletion(httpContext, collector, 500, GetElapsedMilliseconds(start, Stopwatch.GetTimestamp()), ex)) + // The elapsedMs is required for calculating the level and for LogCompletion. + // The level is required in the finally block. + when ((elapsedMs = GetElapsedMilliseconds(start, Stopwatch.GetTimestamp())) >= 0 + && (level = _getLevel(httpContext, elapsedMs, ex)) >= 0 + && LogCompletion(httpContext, collector, 500, elapsedMs, logger, level, ex)) { } finally { + await CallEnrichDiagnosticContextAsync(httpContext, logger, level); collector.Dispose(); } } - async Task CallEnrichDiagnosticContextAsync(HttpContext httpContext) + async Task CallEnrichDiagnosticContextAsync(HttpContext httpContext, ILogger? logger, LogEventLevel level) { - if (_enrichDiagnosticContextAsync != null) + try + { + logger ??= Log.ForContext(); + if (!logger.IsEnabled(level)) return; + + if (_enrichDiagnosticContextAsync != null) + { + await _enrichDiagnosticContextAsync.Invoke(_diagnosticContext, httpContext); + } + } + catch { - await _enrichDiagnosticContextAsync.Invoke(_diagnosticContext, httpContext); + // we want to avoid throwing exceptions in the logging pipeline, so we just swallow them here } } - bool LogCompletion(HttpContext httpContext, DiagnosticContextCollector collector, int statusCode, double elapsedMs, Exception? ex) + bool LogCompletion(HttpContext httpContext, DiagnosticContextCollector collector, int statusCode, double elapsedMs, ILogger? logger, LogEventLevel level, Exception? ex) { - var logger = _logger ?? Log.ForContext(); - var level = _getLevel(httpContext, elapsedMs, ex); + logger ??= Log.ForContext(); if (!logger.IsEnabled(level)) return false; From 6a3730c875e9e4d130ff14b3bf1dae44b1864d22 Mon Sep 17 00:00:00 2001 From: Hilmar Bunjes Date: Thu, 28 Sep 2023 13:20:36 +0200 Subject: [PATCH 3/3] Fix wrong initialization of logger in case an exception occurs in _next --- src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs index c24ef5e..13b2e68 100644 --- a/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs +++ b/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs @@ -57,7 +57,7 @@ public async Task Invoke(HttpContext httpContext) var start = Stopwatch.GetTimestamp(); var collector = _diagnosticContext.BeginCollection(); - ILogger? logger = null; + var logger = _logger; var level = LogEventLevel.Information; // only used if _getLevel throws an exception double elapsedMs;