Unhandled exceptions are being logged before custom IExceptionHandler is being called

[AlOnestone01]

Is there an existing issue for this?

• 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: #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.