Exception middlewares introduce duplicates of error.type diagnostic tags in some situations

[hacst]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

In some specific situations exceptions can cause the Microsoft.AspNetCore.Hosting,http.server.request.duration metric to duplicate error.type tags. One such situation is throwing an exception in a handler after a websocket connection is closed, but there might be others.

This is devastating if downstream systems cannot handle tag duplication. E.g. with prometheus once tags are duplicated scraping fails completely, marking the service as down in prometheus. The only way to recover from this is restarting the service (until the issue reoccurs).

I found open-telemetry/opentelemetry-dotnet#5199 reported against OTEL which sounds like it might describe the same problem caused in other ways.

Expected Behavior

Regardless of in which situation an exception is thrown, the tags on the metrics should not be duplicated. Looking at the code this seems to be the intent of the implementation to begin with.

Steps To Reproduce

1. Run the example application below using dotnet run

var builder = WebApplication.CreateBuilder(args);
var app = builder.Build();
app.UseExceptionHandler(options => {}); // Exception handling middleware introduces duplicate tag
app.UseWebSockets();

app.MapGet("/", async (HttpContext context, CancellationToken ct) =>
{
    if (context.WebSockets.IsWebSocketRequest)
    {
        using var ws = await context.WebSockets.AcceptWebSocketAsync();
        await ws.CloseAsync(System.Net.WebSockets.WebSocketCloseStatus.NormalClosure, "done", ct);
        throw new InvalidOperationException("Throw after websocket request completion to produce the bug");
    }
});
app.Run();

2. Attach using dotnet-counters collect -n DuplicateTagRepro Microsoft.AspNetCore.Hosting (or any other tooling that allows seing the Microsot.AspNetCore.Hosting metrics.
3. Use a websocket client to request the endpoint. E.g. wscat --connect localhost:5221/
4. Observe that metrics now show Microsoft.AspNetCore.Hosting,http.server.request.duration metrics with duplicated error.type=System.InvalidOperationException tags

E.g. Microsoft.AspNetCore.Hosting,http.server.request.duration (s)[error.type=System.InvalidOperationException;error.type=System.InvalidOperationException;error.type=System.InvalidOperationException;http.request.method=GET;http.response.status_code=101;http.route=/;network.protocol.version=1.1;url.scheme=http;Percentile=50]

You will see one duplication per exception middleware. E.g. when running in Development mode the automatically added developer exception middleware will introduce another duplication.

Exceptions (if any)

As expected (and correct), triggering the exception causes one or more exceptions related to unhandled exceptions:

fail: Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware[1]
      An unhandled exception has occurred while executing the request.
      System.InvalidOperationException: Throw after websocket request completion
         at Program.<>c.<<<Main>$>b__0_1>d.MoveNext() in C:\dev\experiments\DuplicateTagRepro\Program.cs:line 20
      --- End of stack trace from previous location ---
         at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.<Invoke>g__Awaited|10_0(ExceptionHandlerMiddlewareImpl middleware, HttpContext context, Task task)
         at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.HandleException(HttpContext context, ExceptionDispatchInfo edi)
         at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.<Invoke>g__Awaited|10_0(ExceptionHandlerMiddlewareImpl middleware, HttpContext context, Task task)
         at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddlewareImpl.Invoke(HttpContext context)

fail: Microsoft.AspNetCore.Server.Kestrel[13]
      Connection id "0HN2U17KD956D", Request id "0HN2U17KD956D:00000001": An unhandled exception was thrown by the application.
      System.InvalidOperationException: Throw after websocket request completion
         at Program.<>c.<<<Main>$>b__0_1>d.MoveNext() in C:\dev\experiments\DuplicateTagRepro\Program.cs:line 20
      --- End of stack trace from previous location ---
         at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.<Invoke>g__Awaited|10_0(ExceptionHandlerMiddlewareImpl middleware, HttpContext context, Task task)
         at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.HandleException(HttpContext context, ExceptionDispatchInfo edi)
         at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.<Invoke>g__Awaited|10_0(ExceptionHandlerMiddlewareImpl middleware, HttpContext context, Task task)
         at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddlewareImpl.Invoke(HttpContext context)
         at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddlewareImpl.Invoke(HttpContext context)
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)

.NET Version

8.0.200 or 9.0.100-preview.3.24204.13

Anything else?

I reproduced this in dotnet 8.0.200 and the current preview 9.0.100-preview.3.24204.13.

At least one part in this duplication seems to be the unexpected presence of the exception in HostingMetrics.RequestEnd
https://github.com/dotnet/aspnetcore/blob/8486d31e24f30e3fa1809a95699a0adc16f448d7/src/Hosting/Hosting/src/Internal/HostingMetrics.cs#L72C1-L77C14
The comment there states, that if ExceptionHandlerMiddleware or DeveloperExceptionMiddleware is used, the exception variable should be null. However this is not the case with the reproducer above.

Other instances of the tag are introduced in the ExceptionHandlerMiddlewareImpl in

aspnetcore/src/Middleware/Diagnostics/src/ExceptionHandler/ExceptionHandlerMiddlewareImpl.cs

Line 130 in 8486d31

DiagnosticsTelemetry.ReportUnhandledException(_logger, context, edi.SourceException);

and DeveloperExceptionPageMiddlewareImpl in

aspnetcore/src/Middleware/Diagnostics/src/DeveloperExceptionPage/DeveloperExceptionPageMiddlewareImpl.cs

Line 128 in b83e1e1

DiagnosticsTelemetry.ReportUnhandledException(_logger, context, ex);

Which call DiagnosticsTelemetry.ReportUnhandledException which adds the error.type tag into the IHttpMetricsTagsFeature Tags list. This is later given to HostingMetrics.RequestEnd as customTag entries.

This way a single record can have three identical error.type entries. One for each middleware and one by the RequestEnd function.

[amcasey]

That seems bad. @JamesNK may have thoughts on how we expected to handle this.

[JamesNK]

Fix here: #55211

[nsentinel]

Is there any way to make similar changes for .NET 9? At least Preview 7 still has duplicate tags, in .NET 8 this problem no longer exists.

[JamesNK]

This was fixed for both. If you're still getting duplicate tags then please file a new issue and include a reproduction of the issue if possible.

[nsentinel]

@JamesNK Yes, there are nuances, a different case indeed, although the outcome is very similar. I described the situation here: #57558