RequestLoggingMiddleware assumes HTTP status 500 for all exceptions which is not correct

[cremor]

Description
RequestLoggingMiddleware logs all exceptions with HTTP status code 500 even if the actual status code sent to the client is a different one.

Reproduction

1. Use app.UseSerilogRequestLogging();
2. Have throw new BadHttpRequestException("Test"); in an API controller action method.
3. Call the method.
4. See the log output "HTTP GET /api/test responded 500 in 55.9105 ms"
5. See that the actual status code received by the client is 400.

Expected behavior
RequestLoggingMiddleware should use the actual HTTP status code in the log message.

Relevant package, tooling and runtime versions
Serilog.AspNetCore 7.0.0 on .NET 7

Additional context
I think in this special case the HTTP status code is set by the DeveloperExceptionPageMiddlewareImpl. But there might be other cases/middlewares that affect the status code.

ASP.NET Core 8 will improve the default exception handling middlewares for cancellation, see dotnet/aspnetcore#46330
As you can see in that PR, cancelled requests will then use the status code Status499ClientClosedRequest.

ASP.NET Core 9 will allow user code to determine the returned status code, see https://github.com/dotnet/core/blob/main/release-notes/9.0/preview/preview7/aspnetcore.md#exceptionhandlermiddleware-option-to-choose-the-status-code-based-on-the-exception

[nblumhardt]

Some exploration around how to support this would be welcome; seems like a great improvement to make, if it can be done 👍

[hbunjes]

I don't think this can be achieved. As every middleware can change the result code (as DeveloperExceptionPageMiddlewareImpl does) we cannot know at this point which status code will be returned finally.

You can also use a middleware that catches an Exception which is not relevant for the caller and still returns a 200/OK message. The 500 status code is just a good guess in this case.

[airbreather]

I think in this special case the HTTP status code is set by the DeveloperExceptionPageMiddlewareImpl. But there might be other cases/middlewares that affect the status code.

ASP.NET Core 8 will improve the default exception handling middlewares for cancellation, see dotnet/aspnetcore#46330 As you can see in that PR, cancelled requests will then use the status code Status499ClientClosedRequest.

This is why I came here. I (of course) agree that no middleware can predict what other middlwares in the pipeline will do eventually, but with this specific detail from the "Additional context", RequestLoggingMiddleware is in an awkward place now where I seem to be given a choice between:

• a little extra log spam per request from the default logging middleware
• reduced log spam per request from this middleware, but a LOT of log spam for each canceled request
• pick either of those and then write my own custom middleware that addresses its own drawbacks

As a power user, I'm happy to app.UseSerilogRequestLogging(); and then immediately follow it up with some variant of what was done in dotnet/aspnetcore#46330, but it seems like things might go a bit more smoothly if this line

serilog-aspnetcore/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs

Line 61 in 68f2f3d

await _next(httpContext);

were, itself, wrapped in the same kind of try/catch?

Edit to add: or, probably better, a clone of this block

serilog-aspnetcore/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs

Lines 66 to 71 in 68f2f3d

	catch (Exception ex)
	// Never caught, because `LogCompletion()` returns false. This ensures e.g. the developer exception page is still
	// shown, although it does also mean we see a duplicate "unhandled exception" event from ASP.NET Core.
	when (LogCompletion(httpContext, collector, 500, GetElapsedMilliseconds(start, Stopwatch.GetTimestamp()), ex))
	{
	}

that catches the same exceptions that dotnet/aspnetcore#46330 does, then logs them (status code 499), then doesn't rethrow?

[sommmen]

I think in this special case the HTTP status code is set by the DeveloperExceptionPageMiddlewareImpl. But there might be other cases/middlewares that affect the status code.
ASP.NET Core 8 will improve the default exception handling middlewares for cancellation, see dotnet/aspnetcore#46330 As you can see in that PR, cancelled requests will then use the status code Status499ClientClosedRequest.

This is why I came here. I (of course) agree that no middleware can predict what other middlwares in the pipeline will do eventually, but with this specific detail from the "Additional context", RequestLoggingMiddleware is in an awkward place now where I seem to be given a choice between:

* a little extra log spam per request from the default logging middleware

* reduced log spam per request from this middleware, but a LOT of log spam for each canceled request

* pick either of those and then write my own custom middleware that addresses its own drawbacks

As a power user, I'm happy to app.UseSerilogRequestLogging(); and then immediately follow it up with some variant of what was done in dotnet/aspnetcore#46330, but it seems like things might go a bit more smoothly if this line

serilog-aspnetcore/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs

Line 61 in 68f2f3d

await _next(httpContext);

were, itself, wrapped in the same kind of try/catch?

Edit to add: or, probably better, a clone of this block

serilog-aspnetcore/src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs

Lines 66 to 71 in 68f2f3d

	catch (Exception ex)
	// Never caught, because `LogCompletion()` returns false. This ensures e.g. the developer exception page is still
	// shown, although it does also mean we see a duplicate "unhandled exception" event from ASP.NET Core.
	when (LogCompletion(httpContext, collector, 500, GetElapsedMilliseconds(start, Stopwatch.GetTimestamp()), ex))
	{
	}

that catches the same exceptions that dotnet/aspnetcore#46330 does, then logs them (status code 499), then doesn't rethrow?

I'm running into the same issue, having a lot of TaskCanceledException log spam. Aditionally you have the annoying '... Cancelled by user.' SqlException for later.

[nblumhardt]

Just chiming in with another workable option; since ASP.NET Core completes the Activity corresponding to each request after all middleware has run, using https://github.com/serilog-tracing/serilog-tracing and Instrument.AspNetCoreRequests() can achieve similar output to this middleware, but should produce a more accurate final status code.

[scottfavre]

As a work around, if you catch exceptions in a middleware after RequestLoggingMiddleware and set the exception in the DiagnosticContext, then the Serilog middleware will do the right thing and

1. log the exception
2. use whatever HTTP status code you've already set

This may not work with error pages, I haven't tried it

public class ExceptionHandlingMiddleware( RequestDelegate next, DiagnosticContext diagnosticContext )
{
	public async Task Invoke( HttpContext context )
	{
		try
		{
			await next( context );
		}
		catch ( Exception ex )
		{
			var response = await BuildResponseAndSetStatusCode( context, ex );

			diagnosticContext.SetException( ex );
			// don't rethrow the exception
		}
	}

	private async Task BuildResponseAndSetStatusCode(HttpContext context, Exception exception)
	{
	/* handle the error */ 
	}

And during startup:

// this order ensures that `ExceptionHandlingMiddleware` gets the chance to manage the error and set a status code before serilog sees it
app.UseSerilogRequestLogging();
app.UseMiddleware<ExceptionHandlingMiddleware>();

[kevinharing]

Joining in, because I'm surprised to see that in .net 8 when the clients disconnects, the response code is set to 499, but serilog happily logs a 200 response code in the requestloggingmiddleware.

[cremor]

Seems like this will get more complicated. ASP.NET Core 9 will allow user code to determine the returned status code, see https://github.com/dotnet/core/blob/main/release-notes/9.0/preview/preview7/aspnetcore.md#exceptionhandlermiddleware-option-to-choose-the-status-code-based-on-the-exception

I don't know if there is any way how this could be supported in RequestLoggingMiddleware. But if no automatic solution is possible, then maybe it would be a good idea to offer the same StatusCodeSelector setting?

[nblumhardt]

Mirroring that setting sounds reasonable @cremor 👍 - thanks for the heads-up.

[cremor]

Although I think it should be possible to just inject IOptions<ExceptionHandlerOptions> into RequestLoggingMiddleware.