Duplicate error messages with Serilog ASP.NET Core

ASP.NET Core 5 Razor Pages using Serilog

UseStatusCodePagesWithReExecute works as expected and re-executes a page after it goes to my /CustomError page.

How to suppress Serilog logging of the 2nd call to the re-executed page?

// program.cs
public static void Main(string[] args)
{
    Log.Logger = new LoggerConfiguration()
        // if only do warning, then will get duplicate error messages when an exception is thrown, then again when re-executed
        // we do get 2 error message per single error, but only 1 stack trace
        .MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Fatal)
        .Enrich.FromLogContext()
        .WriteTo.Console()
        .CreateLogger();

    try
    {
        Log.Information("Starting up");
        CreateHostBuilder(args).Build().Run();
    }
    catch (Exception ex)
    {
        Log.Fatal(ex, "Application start-up failed");
    }
    finally
    {
        Log.CloseAndFlush();
    }
}

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

and then

public class Startup
{
    public void ConfigureServices(IServiceCollection services)
    {
        // snip
    }

    public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
    {
        if (env.IsDevelopment())
        {
            app.UseDeveloperExceptionPage();
        }
        else
        {
            app.UseExceptionHandler("/CustomError");
        }

        app.UseStaticFiles(); 

        // https://khalidabuhakmeh.com/handle-http-status-codes-with-razor-pages
        // https://andrewlock.net/retrieving-the-path-that-generated-an-error-with-the-statuscodepages-middleware/
        app.UseStatusCodePagesWithReExecute("/CustomError", "?statusCode={0}");

        app.UseRouting();

        // don't want request logging for static files so put this serilog middleware here in the pipeline
        app.UseSerilogRequestLogging(); // <- add this

        app.UseAuthentication();
        app.UseAuthorization();

        app.UseCookiePolicy(new CookiePolicyOptions { MinimumSameSitePolicy = SameSiteMode.Strict });

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

and then

// CustomError.cshtml.cs
[ResponseCache(Duration = 0, Location = ResponseCacheLocation.None, NoStore = true)]
[IgnoreAntiforgeryToken]
public class CustomErrorModel : PageModel
{
    public int? CustomStatusCode { get; set; }

    public void OnGet(int? statusCode = null)
    {
        var feature = HttpContext.Features.Get<IStatusCodeReExecuteFeature>();

        // a non 500 eg 404
        // this can be non page requests eg /js/site-chart.js
        // feature can be null when a 500 is thrown
        if (feature != null)
        {

            //Log.Warning($"Http Status code {statusCode} on {feature.OriginalPath}");
            CustomStatusCode = statusCode;
            return;
        }

        // a 500
        // relying on serilog to output the error
        //var exceptionHandlerPathFeature = HttpContext.Features.Get<IExceptionHandlerPathFeature>();

        // integration tests can call a page where the exceptionHandlerPathFeature can be null
        CustomStatusCode = 500;

        // somewhere else is emitting the Log.Error stacktracke
        //Log.Error($"Exception is {exceptionHandlerPathFeature.Error}");

        //OriginalPath = exceptionHandlerPathFeature.Path;
        //Exception exception = exceptionHandlerPathFeature.Error;
    }

    public void OnPost()
    {
        Log.Warning( "ASP.NET failure - maybe antiforgery. Caught by OnPost Custom Error. Sending a 400 to the user which is probable");
        Log.Warning("Need to take off minimumlevel override in Program.cs for more information");
        CustomStatusCode = 400;
    }
}

Duplicate log entries for errors eg 404 - ideally only want 1

Update

Thanks to Alan's answer below I've put the SerilogRequestLogging at the start of configure.

 public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
 {

      app.UseSerilogRequestLogging(); 

      if (env.IsDevelopment())
      {
           app.UseDeveloperExceptionPage();
      }
      else
      {
           app.UseExceptionHandler("/CustomError");
      }

      app.UseStaticFiles(); 

      app.UseStatusCodePagesWithReExecute("/CustomError", "?statusCode={0}");

      // snip..
}

This gives 2 ERR messages in the log:

Which I'm fine with.

There is probably a way to merge the 2 ERR entries, but this is simple. Also the 2 entries are for different concepts. Requests and Exceptions.

It may be possible to give each log entry a RequestId as the boilerplate Error.cshtml.cs gives.

RequestId = Activity.Current?.Id ?? HttpContext.TraceIdentifier;

But hey, this solution is good enough for me. Thanks Alan!

Solution

Short answer:

To prevent duplicate logging in this case, you can place UseSerilogRequestLogging() before UseStatusCodePagesWithReExecute() in your Configure method:

    app.UseSerilogRequestLogging();
    app.UseStatusCodePagesWithReExecute("/CustomError", "?statusCode={0}");

Long answer:

According to the ASP.NET documentation, the order used to build middlewares matters:

The order that middleware components are added in the Startup.Configure method defines the order in which the middleware components are invoked on requests and the reverse order for the response. The order is critical for security, performance, and functionality.

Now, according to Serilog documentation, UseSerilogRequestLogging will only process components that appear after in the middleware pipeline.

With that in mind, I noticed that on the Startup class, you added your UseSerilogRequestLogging middleware after UseStatusCodePagesWithReExecute.

UseStatusCodePagesWithReExecute documentation says it does two things:

Returns the original status code to the client.

Generates the response body by re-executing the request pipeline using an alternate path.

In other words, when you get an error, it seems Serilog is unaware that the second request was internally generated by a previous middleware, so it will log both:

the original request
the second one, created by the execution of the alternate path (/CustomError)

Step-by-step, this is what would happen in the request pipeline when a GET request hits the StatusCode400 endpoint:

Request flow: UseStatusCodePagesWithReExecute -> Serilog -> StatusCode400 endpoint (error happens here)
Response flow: UseStatusCodePagesWithReExecute (error status code, so re-execution kicks in) <- Serilog (logs request) <- StatusCode400 endpoint
Re-execution request flow: UseStatusCodePagesWithReExecute -> Serilog -> CustomError endpoint (no error now, but re-execution preserves the HTTP status code)
Re-execution response flow: UseStatusCodePagesWithReExecute <- Serilog (logs request) <- CustomError endpoint

Therefore, if you don't want to have duplicate log messages, you can place the Serilog middleware before the re-execution one, so it will process only one request coming from it (the second one):

Request flow: Serilog -> UseStatusCodePagesWithReExecute -> StatusCode400 endpoint (error happens here)
Response flow: Serilog <- UseStatusCodePagesWithReExecute (error status code, so re-execution kicks in) <- StatusCode400 endpoint
Re-execution request flow: Serilog -> UseStatusCodePagesWithReExecute -> CustomError endpoint (no error now, but re-execution preserves the HTTP status code)
Re-execution response flow: Serilog (logs request) <- UseStatusCodePagesWithReExecute <- CustomError endpoint