.NET 8 Global Exception Handler logs twice.

[siimonemoretti]

Description
As title suggests, using Global Exception handler logs twice on exceptions but not on simple logs. This happens both on console and file sink, so I don't think the issue is with the sink but rather on the Global Exception Handler.

Demo:

Here, logs are logged fine.

Here is the unexpected behaviour.

Reproduction

The appsettings.json:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning",
      "Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware": "None"
    }
  },
  "AllowedHosts": "*"
}

The program.cs:

using TestSerilogLogger;
 
using Serilog;
using Microsoft.AspNetCore.Http.HttpResults;

internal class Program
{
    private static void Main(string[] args)
    {
        Log.Logger = new LoggerConfiguration()
    .WriteTo
    .Console()
    .WriteTo.File("log.txt", rollingInterval: RollingInterval.Day)
    .CreateLogger();

        try
        {
            Log.Information("Starting web application");

            var builder = WebApplication.CreateBuilder(args);
            builder.Host.UseSerilog(); // <-- Add this line

            // Activate Global Exception Handler
            builder.Services.AddExceptionHandler<GlobalExceptionHandler>();
            builder.Services.AddProblemDetails();

            builder.Services.AddControllers();
            // Learn more about configuring Swagger/OpenAPI at https://aka.ms/aspnetcore/swashbuckle
            builder.Services.AddEndpointsApiExplorer();
            builder.Services.AddSwaggerGen();
      
            var app = builder.Build();

            // Configure the HTTP request pipeline.
            if (app.Environment.IsDevelopment())
            {

                app.UseSwagger();
                app.UseSwaggerUI();
            }

            app.UseHttpsRedirection();

            app.UseAuthorization();

            app.MapControllers();

            // All about exceptional handler and logging
            app.UseSerilogRequestLogging();
            app.UseStatusCodePages();
            app.UseExceptionHandler();


            var theEndPoint = app.MapGroup("/endpoint");

            app.MapGet("/GenerateLog", GenerateLog);
            app.MapGet("/GenerateFakeError", GenerateFakeError);

            app.Run();

            static IResult GenerateLog()
            { 
               Log.Information("Information");
               Log.Debug("Debug");
               Log.Warning("Warning");
               Log.Error("Error");
               Log.Fatal("Fatal");

                return Results.Ok();
            }
            static async Task<IResult> GenerateFakeError()
            {
                throw new Exception("Fake error");    
            }
        }
        catch (Exception ex)
        {
            Log.Fatal(ex, "Error during setup!");
        }
        finally
        {
            Log.CloseAndFlush();
        }
    }
}

The GlobalExceptoinHandler.cs:

using Microsoft.AspNetCore.Diagnostics;
using System.Diagnostics;

namespace TestSerilogLogger
{
    public class GlobalExceptionHandler(ILogger<GlobalExceptionHandler> logger) : IExceptionHandler
    {
        private readonly ILogger<GlobalExceptionHandler> logger = logger;


        public async ValueTask<bool> TryHandleAsync(
            HttpContext httpContext,
            Exception exception,
            CancellationToken cancellationToken)
        {
            var traceId = Activity.Current?.Id ?? httpContext.TraceIdentifier;
            logger.LogError(
                exception,
                "Could not process the request on machine {MachineName}. TraceID : {TraceID}",
                Environment.MachineName,
                traceId);

            var (statusCode, title) = MapException(exception);

            await Results.Problem(

                title: title,
                statusCode: statusCode,
                extensions: new Dictionary<string, object?>
                {
                     { "traceId" , traceId }
                }

             ).ExecuteAsync(httpContext);


            return true;
        }

        private static (int StatusCode, string Title) MapException(Exception exception)
        {
            return exception switch
            {
                ArgumentOutOfRangeException => (StatusCodes.Status400BadRequest, exception.Message),
                _ => (StatusCodes.Status500InternalServerError, "We made a mistake but we are working on it!")
            };

        }

    }
}

Expected behavior
Expected to see only one log event when an exception is thrown.

Relevant package, tooling and runtime versions

[deathchurch]

Isn't this issue already known when implementing IExceptionHandler and the workaround is setting the logging to None for ExceptionHandlingMiddleware

https://learn.microsoft.com/en-us/answers/questions/1618819/why-does-asp-net-core-log-an-unhandled-exception-w

"Logging": {
"LogLevel": {
"Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware": "None"
}

[siimonemoretti]

Yes, I forgot to show that I enabled that setting too.

[dimaios]

I've experienced the same behaviour and I don't know how to solve it.
Using the .NET 7 middlware strategy the logger works properly but applying the new .NET 8 Global Exception Handler Serilog is not the only logger that intercepts the exception. Other logs excluding the exception handling ( normal application behaviour ) are ok but when the code generates an exception it is logged twice.

[siimonemoretti]

LoggerTest.zip
Here I've created a demo solution that shows the problem. Invoking the WebAPI you'll see that the console shows the logging messages only once. When exception is thrown it is intercepted by the Global Exception Handler and logs the issue, but before that, another handler has still logged the same exception, generating a copy of the error message.

[cremor]

This looks like a duplicate of #341

[nblumhardt]

UseSerilogRequestLogging() has logged exceptions for a long time; adding a new exception handling mechanism (IExceptionHandler) hasn't changed that, the example given above is logging the exceptions twice because both the Serilog handler (vial UseSerilogRequestLogging()) and the registered global one are being hit.

Having a means to turn off exception logging in UseSerilogRequestLogging() would be the way to go. .NET 8 Global Exception Handler logs twice. #341 is tracking this so let's move the discussion and focus over there, so we can edge towards a configuration setting for it.

[FabianSSG]

Are we sure this is the same issue as #341. Because currently we are facing the problem of tripple logs. Like it is seen here and in the other issue.
The main difference is, the first log is [ERR] HTTP POST /User/UserLicense responded 500 in 1066.8046 ms #341
The second one is [ERR] An unhandled exception has occurred while executing the request. This issue
The third is from IExceptionHandler

We do not have "Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware": "None" set at the moment.

Edit: It seems to be the issue mentioned here dotnet/aspnetcore#54554
Edit: After some testing, pretty sure the reason is that Serilog doesn't actually support "None", so it doesn't get filtered. With Error/Fatal it would work. serilog/serilog#1049
The first exception we are getting is from the RequestResponseMiddleware, mentioned in the linked issue.