Merge pull request #271 from angularsen/agl/diagnostic-exception

Log exception set in IDiagnosticContext

Author: nblumhardt

src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs

@@ -86,7 +86,7 @@ bool LogCompletion(HttpContext httpContext, DiagnosticContextCollector collector
             // Enrich diagnostic context
             _enrichDiagnosticContext?.Invoke(_diagnosticContext, httpContext);
 
-            if (!collector.TryComplete(out var collectedProperties))
+            if (!collector.TryComplete(out var collectedProperties, out var collectedException))
                 collectedProperties = NoProperties;
 
             // Last-in (correctly) wins...
@@ -98,7 +98,7 @@ bool LogCompletion(HttpContext httpContext, DiagnosticContextCollector collector
                 new LogEventProperty("Elapsed", new ScalarValue(elapsedMs))
             });
 
-            var evt = new LogEvent(DateTimeOffset.Now, level, ex, _messageTemplate, properties);
+            var evt = new LogEvent(DateTimeOffset.Now, level, ex ?? collectedException, _messageTemplate, properties);
             logger.Write(evt);
 
             return false;

src/Serilog.AspNetCore/Serilog.AspNetCore.csproj

@@ -30,7 +30,7 @@
 
   <ItemGroup>
     <PackageReference Include="Serilog" Version="2.10.0" />
-    <PackageReference Include="Serilog.Extensions.Hosting" Version="4.2.0" />
+    <PackageReference Include="Serilog.Extensions.Hosting" Version="4.2.1-dev-00092" />
     <PackageReference Include="Serilog.Sinks.Console" Version="4.0.1" />
     <PackageReference Include="Serilog.Sinks.File" Version="5.0.0" />
     <PackageReference Include="Serilog.Sinks.Debug" Version="2.0.0" />

test/Serilog.AspNetCore.Tests/SerilogWebHostBuilderExtensionsTests.cs

@@ -9,6 +9,7 @@
 using Microsoft.AspNetCore.Hosting;
 using Microsoft.AspNetCore.Mvc.Testing;
 using Microsoft.AspNetCore.Builder;
+using Microsoft.AspNetCore.Http;
 using Serilog.Filters;
 using Serilog.AspNetCore.Tests.Support;
 
@@ -65,7 +66,51 @@ public async Task RequestLoggingMiddlewareShouldEnrich()
             Assert.True(completionEvent.Properties.ContainsKey("Elapsed"));
         }
 
-        WebApplicationFactory<TestStartup> Setup(ILogger logger, bool dispose, Action<RequestLoggingOptions> configureOptions = null)
+        [Fact]
+        public async Task RequestLoggingMiddlewareShouldEnrichWithCollectedExceptionIfNoUnhandledException()
+        {
+            var diagnosticContextException = new Exception("Exception set in diagnostic context");
+            var (sink, web) = Setup(options =>
+            {
+                options.EnrichDiagnosticContext += (diagnosticContext, _) =>
+                {
+                    diagnosticContext.SetException(diagnosticContextException);
+                };
+            });
+
+            await web.CreateClient().GetAsync("/resource");
+
+            var completionEvent = sink.Writes.First(logEvent => Matching.FromSource<RequestLoggingMiddleware>()(logEvent));
+
+            Assert.Same(diagnosticContextException, completionEvent.Exception);
+        }
+
+        [Theory]
+        [InlineData(false)]
+        [InlineData(true)]
+        public async Task RequestLoggingMiddlewareShouldEnrichWithUnhandledExceptionEvenIfExceptionIsSetInDiagnosticContext(bool setExceptionInDiagnosticContext)
+        {
+            var diagnosticContextException = new Exception("Exception set in diagnostic context");
+            var unhandledException = new Exception("Unhandled exception thrown in API action");
+            var (sink, web) = Setup(options =>
+            {
+                options.EnrichDiagnosticContext += (diagnosticContext, _) =>
+                {
+                    if (setExceptionInDiagnosticContext)
+                        diagnosticContext.SetException(diagnosticContextException);
+                };
+            }, actionCallback: _ => throw unhandledException);
+
+            Func<Task> act = () => web.CreateClient().GetAsync("/resource");
+
+            Exception thrownException = await Assert.ThrowsAsync<Exception>(act);
+            var completionEvent = sink.Writes.First(logEvent => Matching.FromSource<RequestLoggingMiddleware>()(logEvent));
+            Assert.Same(unhandledException, completionEvent.Exception);
+            Assert.Same(unhandledException, thrownException);
+        }
+
+        WebApplicationFactory<TestStartup> Setup(ILogger logger, bool dispose, Action<RequestLoggingOptions> configureOptions = null,
+            Action<HttpContext> actionCallback = null)
         {
             var web = _web.WithWebHostBuilder(
                 builder => builder
@@ -80,24 +125,29 @@ WebApplicationFactory<TestStartup> Setup(ILogger logger, bool dispose, Action<Re
                     .Configure(app =>
                     {
                         app.UseSerilogRequestLogging(configureOptions);
-                        app.Run(_ => Task.CompletedTask); // 200 OK
+                        app.Run(ctx =>
+                        {
+                            actionCallback?.Invoke(ctx);
+                            return Task.CompletedTask;
+                        }); // 200 OK
                     })
                     .UseSerilog(logger, dispose));
 
             return web;
         }
 
-        (SerilogSink, WebApplicationFactory<TestStartup>) Setup(Action<RequestLoggingOptions> configureOptions = null)
+        (SerilogSink, WebApplicationFactory<TestStartup>) Setup(Action<RequestLoggingOptions> configureOptions = null,
+            Action<HttpContext> actionCallback = null)
         {
             var sink = new SerilogSink();
             var logger = new LoggerConfiguration()
                 .Enrich.FromLogContext()
                 .WriteTo.Sink(sink)
                 .CreateLogger();
 
-            var web = Setup(logger, true, configureOptions);
+            var web = Setup(logger, true, configureOptions, actionCallback);
 
             return (sink, web);
         }
     }
-}
+}