serilog / serilog-aspnetcore

Serilog integration for ASP.NET Core
Apache License 2.0
1.28k stars 202 forks source link

.NET 8 Global Exception Handler logs twice. #374

Closed siimonemoretti closed 2 days ago

siimonemoretti commented 2 weeks ago

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: immagine (1) Here, logs are logged fine.

immagine (2) 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 immagine

deathchurch commented 1 week ago

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 commented 1 week ago

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

dimaios commented 1 week ago

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 commented 1 week ago

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 commented 3 days ago

This looks like a duplicate of #341

nblumhardt commented 2 days ago

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. https://github.com/serilog/serilog-aspnetcore/issues/341 is tracking this so let's move the discussion and focus over there, so we can edge towards a configuration setting for it.