Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unhandled exceptions are being logged before custom IExceptionHandler is being called #54554

Open
1 task done
AlOnestone01 opened this issue Mar 15, 2024 · 8 comments · May be fixed by #59074
Open
1 task done

Unhandled exceptions are being logged before custom IExceptionHandler is being called #54554

AlOnestone01 opened this issue Mar 15, 2024 · 8 comments · May be fixed by #59074
Assignees
Labels
area-middleware Includes: URL rewrite, redirect, response cache/compression, session, and other general middlesware
Milestone

Comments

@AlOnestone01
Copy link

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

@dotnet-issue-labeler dotnet-issue-labeler bot added the area-web-frameworks *DEPRECATED* This label is deprecated in favor of the area-mvc and area-minimal labels label Mar 15, 2024
@OskarKlintrot
Copy link

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
Copy link
Member

@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?

@captainsafia captainsafia added this to the Discussions milestone May 8, 2024
@captainsafia captainsafia added area-middleware Includes: URL rewrite, redirect, response cache/compression, session, and other general middlesware and removed area-web-frameworks *DEPRECATED* This label is deprecated in favor of the area-mvc and area-minimal labels labels May 8, 2024
@JamesNK
Copy link
Member

JamesNK commented May 9, 2024

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
Copy link

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.

@JamesNK JamesNK self-assigned this Jul 3, 2024
@axylophon
Copy link

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
Copy link

Sylvain2703 commented Oct 16, 2024

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
Copy link
Member

JamesNK commented Oct 16, 2024

It’s too late to do it in 9.

We can look at changing it in 10.

@andy1547
Copy link

andy1547 commented Oct 17, 2024

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area-middleware Includes: URL rewrite, redirect, response cache/compression, session, and other general middlesware
Projects
None yet
Development

Successfully merging a pull request may close this issue.

8 participants