Unhandled exceptions are being logged before custom IExceptionHandler is being called

[AlOnestone01]

Is there an existing issue for this?

• [X] I have searched the existing issues

Describe the bug

When using a custom IExceptionHandler an unhandled exception is being logged (e.g. to console) before the custom exception handler is being called. The exception is being logged with the message:

An unhandled exception has occurred while executing the request

This happens in ExceptionHandlerMiddlewareImpl.cs in the method private async Task HandleException(HttpContext context, ExceptionDispatchInfo edi): DiagnosticsTelemetry.ReportUnhandledException(_logger, context, edi.SourceException);

After that the custom IExceptionHandler is being called.

Expected Behavior

If there is a custom IExceptionHandler registered, it is being called without logging anything before. In the IExceptionHandler the developer can decide if and how to log the unhandled exception.

Steps To Reproduce

Minimalistic project for reproduction: https://github.com/AlOnestone01/custom-exception-handling

1. Implement custom IExceptionHandler
2. Register the handler: builder.Services.AddExceptionHandler<GlobalExceptionHandler>();
3. Register the middleware: app.UseExceptionHandler();
4. Implement an endpoint that throws an exception

Exceptions (if any)

No response

.NET Version

8.0.202

Anything else?

Sample output of the minimalistic project: exception-log.txt

dotnet --info: .NET SDK: Version: 8.0.202 Commit: 25674bb2f4 Workload version: 8.0.200-manifests.8cf8de6d

Runtime Environment: OS Name: Windows OS Version: 10.0.19045 OS Platform: Windows RID: win-x64 Base Path: C:\Program Files\dotnet\sdk\8.0.202\

.NET workloads installed: There are no installed workloads to display.

Host: Version: 8.0.3 Architecture: x64 Commit: 9f4b1f5d66

.NET SDKs installed: 8.0.202 [C:\Program Files\dotnet\sdk]

.NET runtimes installed: Microsoft.AspNetCore.App 6.0.28 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 7.0.17 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 8.0.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.NETCore.App 6.0.28 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 7.0.17 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 8.0.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.WindowsDesktop.App 6.0.28 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 7.0.17 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 8.0.3 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

Other architectures found: x86 [C:\Program Files (x86)\dotnet] registered at [HKLM\SOFTWARE\dotnet\Setup\InstalledVersions\x86\InstallLocation]

Environment variables: Not set

global.json file: Not found

[OskarKlintrot]

This is a confusing behaviour giving the example in the docs. In that example implementation of IExceptionHandler logs the exception, which in reality will result in logging the exception twice.

[captainsafia]

@AlOnestone01 Thanks for reporting this issue!

This change in behavior is a result of some work we did in .NET 8 to add support for metrics to ASP.NET Core. The docs that @OskarKlintrot references in his comments haven't been updated to reflect this change in behavior.

@JamesNK Assuming this behavior change is intentional, did we author a breaking change notice here?

[JamesNK]

Is this a change in behavior? I looked at the PR that added DiagnosticsTelemetry.ReportUnhandledException method. The exception was already logged.

https://github.com/dotnet/aspnetcore/pull/46834/files#diff-307cb43e0f10bb8837662fc645a7e0cacaefb6560bdba0cdc8e9648bed392fac

The only difference is error.type tag is added to the http metric, but that's brand new.

Update:

Ok, I looked into this more and IExceptionHandler is new in .NET 8: https://github.com/dotnet/aspnetcore/pull/47923. I wasn't involved with it so it's new to me.

I guess the request here is if an IExceptionHandler returns true from TryHandleAsync then the built-in middleware logging shouldn't happen. I think some people would want the built in exception, and some people would want to be able to turn it off, so a setting makes sense here. Should the default behavior change? IExceptionHandler was only introduced in .NET 8 so this would be a break from just that version.

I'm going to move this into 9.0 milestone. I don't know if there is time, but we should consider addressing this.

[emyklebost]

Just to add to this issue: A Diagnostic Event will always be sent by the default ExceptionHandler, regardless of if it is "handled" by an IExceptionHandler or not, this will result in the Exception showing up as an unhandled exception in e.g. Application Insights. Don't know if this is intended behavior or not, but something to address if the implementation is changed to not log when a IExceptionHandler was able to handle it.

[axylophon]

I can confirm the problem. I disabled the Log for Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware to mitigate the log issue. The IExceptionHandler should control the logging.

The Application Insights topic is also an issue. Depending on the IExceptionHandler outcome the exception should be added to Application Insights instead for all possible exceptions.

[Sylvain2703]

Hi! Is there any news regarding this issue? Can a fix (with or without a setting to control this behavior) be included in .NET 9?

In my opinion, this is a major problem for the adoption of IExceptionHandler (including the exception handler lambda), because as its name suggests, it allows to handle exceptions! So finding An unhandled exception has occurred while executing the request in logs is clearly bad, especially when a custom IExceptionHandler handles it by returning true from the TryHandleAsync method.

As mentioned by @JamesNK, changing this behavior in .NET 9 would be nice to only break with .NET 8.

Should the default behavior change? IExceptionHandler was only introduced in .NET 8 so this would be a break from just that version.

Also, disabling logs from Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware is really a poor workaround since the same logger is also used to report other errors.

[JamesNK]

It’s too late to do it in 9.

We can look at changing it in 10.

[andy1547]

Note if using Serilog rather than Microsoft logger, the configuration for disabling is:

"Serilog": {
    "MinimumLevel": {
      "Override": {
        // disable default exception logging
        "Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware": "Fatal",
      }
    }

In our case, we wanted to treat some thrown exceptions as client errors and others as server errors, returning 400-499 / 500-599 status codes respectively. Disabling the in-built logging to only log server errors inside of IExceptionHandler was necessary to avoid spamming the logs.

One could take the stance that all exceptions should be logged and instead an IActionResult should be explicitly returned for client errors. Our stack made use of various service layers (that have no knowledge of ASP.NET Core) that throw validation errors (that should be treated as client errors). Duplicating this validation logic or adding a try/catch around each of these calls was infeasible. The other approach was introducing an IExceptionFilter (ran for just MVC pipeline) for handling client thrown exceptions, returning an IActionResult. However, we decided against this approach as using both IExceptionFilter and a IExceptionHandler together added complexity (we prefer to have all exception handling done in a single place).

Funnily we actually had the reverse issue of not logging explicitly returned ObjectResult 500-599 status codes. The workaround was adding logging in an IAlwaysRunResultFilter.