UseExceptionHandler causes Serilog to write uncaught exceptions twice into the request log.

[stevesw]

Description
When UseExceptionHandler is combined with UseSerilogRequestLogging, every time an uncaught exception occurs, two 500 error lines are written into the request log.

Reproduction
This sample code more or less follows what is posted in the README:

Program.cs:

using System;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Hosting;
using Serilog;
using Serilog.Events;

namespace SerilogDoubleLogging
{
    public class Program
    {
        public static int Main(string[] args)
        {
            Log.Logger = new LoggerConfiguration()
            .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
            .MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning)
            .Enrich.FromLogContext()
            .WriteTo.Console()
            .CreateLogger();

            try
            {
                Log.Information("Starting web host");
                CreateHostBuilder(args).Build().Run();
                return 0;
            }
            catch (Exception ex)
            {
                Log.Fatal(ex, "Host terminated unexpectedly");
                return 1;
            }
            finally
            {
                Log.CloseAndFlush();
            }
        }

        public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .UseSerilog()
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder.UseStartup<Startup>();
                });
    }
}

Startup.cs:

using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Serilog;

namespace SerilogDoubleLogging
{
    public class Startup
    {
        public Startup(IConfiguration configuration)
        {
            Configuration = configuration;
        }

        public IConfiguration Configuration { get; }

        // This method gets called by the runtime. Use this method to add services to the container.
        public void ConfigureServices(IServiceCollection services)
        {

            services.AddControllers();
        }

        // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
        public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
        {
            app.UseExceptionHandler("/error");

            app.UseSerilogRequestLogging();

            app.UseRouting();

            app.UseAuthorization();

            app.UseEndpoints(endpoints =>
            {
                endpoints.MapControllers();
            });
        }
    }
}

TestController.cs:

using System;
using Microsoft.AspNetCore.Mvc;

namespace SerilogDoubleLogging.Controllers
{
    [ApiController]
    public class TestController : ControllerBase
    {
        public TestController()
        {
        }

        [HttpGet]
        [Route("")]
        public IActionResult Test()
        {
            throw new Exception("Test");
        }

        [HttpGet]
        [Route("error")]
        public IActionResult Error()
        {
            return new JsonResult(new { message= "There was an error with your request." });
        }
    }
}

Running the project and then making a HTTP request to http://localhost:5000 results in the following entries being written into the log file:

[14:31:17 ERR] HTTP GET / responded 500 in 39.6844 ms
System.Exception: Test
   at SerilogDoubleLogging.Controllers.TestController.Test() in /Users/steve/Hindsight/Projects/test/csharp/SerilogDoubleLogging/SerilogDoubleLogging/Controllers/TestController.cs:line 17
   at lambda_method1(Closure , Object , Object[] )
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.SyncActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Serilog.AspNetCore.RequestLoggingMiddleware.Invoke(HttpContext httpContext)
[14:31:17 ERR] An unhandled exception has occurred while executing the request.
System.Exception: Test
   at SerilogDoubleLogging.Controllers.TestController.Test() in /Users/steve/Hindsight/Projects/test/csharp/SerilogDoubleLogging/SerilogDoubleLogging/Controllers/TestController.cs:line 17
   at lambda_method1(Closure , Object , Object[] )
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.SyncActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Serilog.AspNetCore.RequestLoggingMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
[14:31:17 ERR] HTTP GET / responded 500 in 18.3700 ms

Ignoring the stack traces, note that there are two different lines that both read HTTP GET / responded 500 in xx.xxxx ms, except the number of milliseconds differs.

Expected behavior
Since there was only a single HTTP request made and a single exception thrown, I would expect a single 500 error line to get written into the request log, not two. Why is the error line getting repeated? This makes things rather misleading when analyzing our logs.

Relevant package, tooling and runtime versions
Serilog 2.10.0, Serilog.AspNetCore 4.1.0, .NET 5.0

[nblumhardt]

Thanks for the note; this is currently expected behavior - since request logging middleware is part of the pipeline, it'll log whatever is happening at its point in the pipeline, including uncaught exceptions, and re-execution of the pipeline, if it's inside UseExceptionHandler().

This is in part because these two components have some overlapping features - the docs for UseExceptionHandler() state:

Adds a middleware to the pipeline that will catch exceptions, log them, reset the request path, and re-execute the request. The request will not be re-executed if the response has already started.

You can modify it by swapping the order of pipeline components:

            app.UseSerilogRequestLogging();

            app.UseExceptionHandler("/error");

[dario-l]

@nblumhardt The solution from above works for me. I have no any duplicated logs but... i loose ExceptionDetail on all ajax requests. 😢

This eliminates duplicated logs but on all ajax requests Serilog.AspNetCore.RequestLoggingMiddleware do not log ExceptionDetails

app.UseSerilogRequestLogging();
app.UseExceptionHandler("/error");

This causes duplicated logs.

app.UseExceptionHandler("/error");
app.UseSerilogRequestLogging();

I found this issue #298 but IDiagnosticContext.SetException(ex) is not available on public release packages. 😞

[nblumhardt]

Thanks for the note @dario-l. #292 is now ready to go, and integrates IDiagnosticContext.SetException(), so this shouldn't be far away now :-)