aspnetcore icon indicating copy to clipboard operation
aspnetcore copied to clipboard

Framework does not handle Request cancellation properly

Open maxcherednik opened this issue 1 year ago • 11 comments

Is there an existing issue for this?

  • [X] I have searched the existing issues

Describe the bug

When a browser closes the connection during the active request, asp.net core raises the cancellation.

[HttpGet(Name = "GetWeatherForecast")]
    public async Task<IEnumerable<WeatherForecast>> Get(CancellationToken cancellationToken)
    {
        await Task.Delay(TimeSpan.FromSeconds(30), cancellationToken);
        /// return logic here
    }

As a result the log file is full of errors like this:

fail: Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware[1]
      An unhandled exception has occurred while executing the request.
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
         at WebApplication1.Controllers.WeatherForecastController.Get(CancellationToken cancellationToken) in /Users/maximcherednik/Projects/WebApplication1/WebApplication1/Controllers/WeatherForecastController.cs:line 32
         at lambda_method5(Closure , Object )
         at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.AwaitableObjectResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|20_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
         at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
         at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
         at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)
         at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)
         at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)

Similar question: https://stackoverflow.com/questions/69607456/unhandled-taskcancelledexception-when-request-is-aborted-by-client-in-asp-net-co

Expected Behavior

  1. Framework supposed to handle the 'OperationCancelledException' which was raised on a CancellationTokenSource as a reaction to the cancelled request.
  2. No error logging - there are no issues here, it is completely normal flow.
  3. Maybe you would like to log it as debug, but please no stack traces.

Steps To Reproduce

Run the code similar to this:

[HttpGet(Name = "GetWeatherForecast")]
    public async Task<IEnumerable<WeatherForecast>> Get(CancellationToken cancellationToken)
    {
        await Task.Delay(TimeSpan.FromSeconds(30), cancellationToken);
        /// return logic here
    }

Refresh the page several times while waiting.

Exceptions (if any)

No response

.NET Version

6.0.301

Anything else?

No response

maxcherednik avatar Oct 22 '22 17:10 maxcherednik

@Tratcher I think this should be handled in the ExceptionHandlerMiddleware, and maybe in the server implementations as well.

davidfowl avatar Oct 24 '22 21:10 davidfowl

if (operationCancelledException.CancellationToken == httpContext.RequestAborted) { /* less noisy */ }?

Tratcher avatar Oct 24 '22 21:10 Tratcher

Yep. Is returning 499 something standard? (I'll admit I haven't' seen that status code before).

davidfowl avatar Oct 24 '22 21:10 davidfowl

Returning 499? There's nothing to return, the request was aborted. What gets logged is the only question. It also depends on if the response has started or not.

Tratcher avatar Oct 24 '22 21:10 Tratcher

Triage: we can reduce the amount of logging for OperationCanceledException cases. If the check that @Tratcher mentioned above works with chained tokens, we can do that too.

This would have to happen in multiple places.

adityamandaleeka avatar Oct 24 '22 22:10 adityamandaleeka

Thanks for contacting us.

We're moving this issue to the .NET 8 Planning milestone for future evaluation / consideration. We would like to keep this around to collect more feedback, which can help us with prioritizing this work. We will re-evaluate this issue, during our next planning meeting(s). If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues. To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

ghost avatar Oct 24 '22 22:10 ghost

Returning 499? There's nothing to return, the request was aborted. What gets logged is the only question. It also depends on if the response has started or not.

You're right. There's no client to respond to 😄

davidfowl avatar Oct 24 '22 22:10 davidfowl

Depending on where in the pipeline this is handled setting the response code to 499 (or some other value) can make for nicer request logging output, as an example of where it might be useful even though there is nothing to respond to.

jmcgoldrick avatar Oct 26 '22 15:10 jmcgoldrick

@Tratcher @davidfowl I have dig into the code and below are my findings:

a) On line no 102 the exception is being logged when the browser close.

https://github.com/dotnet/aspnetcore/blob/04bb460447cc6b84ec88080a777b298ba70ce7d7/src/Middleware/Diagnostics/src/DeveloperExceptionPage/DeveloperExceptionPageMiddlewareImpl.cs#L94-L108

b) When I go to Implementation of this method it goes to the below file on line no 12. With LoggerMessageAttribute it log the error. Just Brainstorming where should I fix this ? LoggerMessageAttribute is in the Runtime Repository

https://github.com/dotnet/aspnetcore/blob/04bb460447cc6b84ec88080a777b298ba70ce7d7/src/Middleware/Diagnostics/src/DiagnosticsLoggerExtensions.cs#L8-L15

Note: When I go to definition it goes to below file (Autogenerated file): image

singh733 avatar Nov 03 '22 13:11 singh733

The UnhandledException log is not the one that emits the end-of-response data like status code. However, this is where we check HasStarted and decide if we should change the response to a 500. If we first check if the client has already disconnected we could consider changing the status to 499 for OCE's instead. We already have a similar check for BadHttpRequestException.

https://github.com/dotnet/aspnetcore/blob/04bb460447cc6b84ec88080a777b298ba70ce7d7/src/Middleware/Diagnostics/src/DeveloperExceptionPage/DeveloperExceptionPageMiddlewareImpl.cs#L104-L122

Tratcher avatar Nov 08 '22 23:11 Tratcher

@Tratcher Do we need to do something like this:

if (ex is BadHttpRequestException badHttpRequestException)
               {
                   context.Response.StatusCode = badHttpRequestException.StatusCode;
               }
               else if (ex is OperationCancelledException operationCancelledException)
               {
                   context.Response.StatusCode = operationCancelledException.StatusCode; //(499)
               }
               else
               {
                   context.Response.StatusCode = 500;
               }

  1. No error logging - there are no issues here, it is completely normal flow.

Also in this issue there is requirement of no error logging. But we are logging on line no 102. Please share your views.

https://github.com/dotnet/aspnetcore/blob/04bb460447cc6b84ec88080a777b298ba70ce7d7/src/Middleware/Diagnostics/src/DeveloperExceptionPage/DeveloperExceptionPageMiddlewareImpl.cs#L94-L108

singh733 avatar Nov 24 '22 10:11 singh733

@singh733 we'd also want to ensure that the OperationCancelledException was caused by the request aborting and not something else. See the discussion starting at https://github.com/dotnet/aspnetcore/issues/44697#issuecomment-1289621220

_logger.UnhandledException(ex); could be conditional based on RequestAborted, and instead log a message that an unhandled exception was caught for an aborted request, with the exception type and message, but not the whole stack trace.

DeveloperExceptionPageMiddleware is only one use case. Also consider, ExceptionHandlerMiddlewareImpl https://github.com/dotnet/aspnetcore/blob/04bb460447cc6b84ec88080a777b298ba70ce7d7/src/Middleware/Diagnostics/src/ExceptionHandler/ExceptionHandlerMiddlewareImpl.cs#L115-L121

Each server (Kestrel, HttpSys, IIS) will also have a catch like this: https://github.com/dotnet/aspnetcore/blob/04bb460447cc6b84ec88080a777b298ba70ce7d7/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs#L599-L602

Tratcher avatar Nov 30 '22 20:11 Tratcher

@Tratcher, There is no OperationCancelledException Exception right now . Should I need to create the OperationCancelledException same as BadHttpRequestException.

If yes, then a) How we get the CancellationToken property of OperationCancelledException because BadHttpRequestException does not have CancellationToken property.

See the discussion starting at https://github.com/dotnet/aspnetcore/issues/44697#issuecomment-1289621220

We need the CancellationToken property because of the upper comment

singh733 avatar Dec 07 '22 14:12 singh733

You mean there's no OperationCancelledException catch statement now? Yes, you'll need to add those. You won't be working with BadHttpRequestException.

Tratcher avatar Dec 07 '22 18:12 Tratcher

@Tratcher Below is the proposed Solution for DeveloperExceptionPageMiddlewareImpl

Please share your views.

 try
        {
            await _next(context);
        }
        catch (Exception ex)
        {
            if (ex is OperationCanceledException operationCanceledException && operationCanceledException.CancellationToken == context.RequestAborted)
            {
                // TODO: Better message
                _logger.LogDebug("Request aborted Exception");
            }
            else
            {
                _logger.UnhandledException(ex);
            }

            if (context.Response.HasStarted)
            {
                _logger.ResponseStartedErrorPageMiddleware();
                throw;
            }

            try
            {
                context.Response.Clear();

                // Preserve the status code that would have been written by the server automatically when a BadHttpRequestException is thrown.
                if (ex is BadHttpRequestException badHttpRequestException)
                {
                    context.Response.StatusCode = badHttpRequestException.StatusCode;
                }

                else if (ex is OperationCanceledException operationCancelException && operationCancelException.CancellationToken == context.RequestAborted)
                {
                    context.Response.StatusCode = 499;
                }
                else
                {
                    context.Response.StatusCode = 500;
                }

                await _exceptionHandler(new ErrorContext(context, ex));

singh733 avatar Dec 19 '22 18:12 singh733

Does operationCanceledException.CancellationToken == context.RequestAborted work if a linked cancellation token caused the failure? If not, if (ex is OperationCanceledException operationCanceledException && context.RequestAborted.IsCancellationRequested) might be the best option.

You should return; after the _logger.LogDebug("Request aborted Exception"); line, there's no need for further request processing if the request was aborted.

Tratcher avatar Dec 19 '22 19:12 Tratcher

Does operationCanceledException.CancellationToken == context.RequestAborted work if a linked cancellation token caused the failure? If not, if (ex is OperationCanceledException operationCanceledException && context.RequestAborted.IsCancellationRequested) might be the best option.

It doesn't and your suggestion is what we should be using.

davidfowl avatar Dec 19 '22 19:12 davidfowl

@Tratcher @davidfowl Below is the proposed Solution for DeveloperExceptionPageMiddlewareImpl

try
        {
            await _next(context);
        }
        catch (Exception ex)
        {
            if (ex is OperationCanceledException operationCanceledException && operationCanceledException.CancellationToken.IsCancellationRequested)
            {
                // TODO: Better message
                _logger.LogDebug("Request aborted");
                context.Response.StatusCode = 499;

                return;
            }

and For ExceptionHandlerMiddlewareImpl

 private async Task HandleException(HttpContext context, ExceptionDispatchInfo edi)
    {
        if (edi.SourceException is OperationCanceledException operationCanceledException && operationCanceledException.CancellationToken.IsCancellationRequested)
        {
            // TODO: Better message
            _logger.LogDebug("Request aborted");
            context.Response.StatusCode = 499;

            return;
        }

        _logger.UnhandledException(edi.SourceException);
        // We can't do anything if the response has already started, just abort.
        if (context.Response.HasStarted)
        {
            _logger.ResponseStartedErrorHandler();
            edi.Throw();
        }

        PathString originalPath = context.Request.Path;
        if (_options.ExceptionHandlingPath.HasValue)
        {
            context.Request.Path = _options.ExceptionHandlingPath;
        }
        try
        {

c) OperationCanceledException is already handled in kestrel. Do we need to make the following changes ?

image

d) I didn't see any ConnectionAbortedException(TaskCanceledException) in httpsys project. Would you please let me know in which files I need to change in HttpSys and IIS server ?

e) I have seen ConnectionAbortedException(TaskCanceledException) at many places. Do we need to take action on any other place.

image

singh733 avatar Dec 20 '22 18:12 singh733

if (ex is OperationCanceledException operationCanceledException && operationCanceledException.CancellationToken.IsCancellationRequested)

I think you missed the point here. operationCanceledException.CancellationToken.IsCancellationRequested should always be true when catching an OperationCanceledException. What we want confirm is if the OperationCanceledException is related to the request being aborted, context.RequestAborted.IsCancellationRequested.

context.Response.StatusCode = 499;

Always check if (context.Response.HasStarted) before trying to modify the response, otherwise it could throw.

OperationCanceledException is already handled in kestrel. Do we need to make the following changes ?

That's a ConnectionAbortedException and shouldn't be changed (what's it's log level?). What about OperationCanceledException's thrown by CancellationTokens? All the servers would need a specific check for OperationCanceledException that looks the same as ExceptionHandlerMiddlewareImpl.

Tratcher avatar Dec 29 '22 17:12 Tratcher

That's a ConnectionAbortedException and shouldn't be changed (what's it's log level?).

Log Level is Debug

b) Just Curious Do we need to handle both ConnectionAbortedException and OperationCanceledException, because ConnectionAbortedException is already inheriting OperationCanceledException. If yes, Then we need to handle OperationCanceledException after ConnectionAbortedException. Please share your views

image

singh733 avatar Jan 10 '23 17:01 singh733

This feels related to #45086 which is about ConnectionResetExceptions.

@Tratcher Do we want to do anything similar for IOExceptions that happen because of a request abort while reading the request body? It seems very similar because the exception is caused by a disconnecting client through no fault of the application. I'm not sure that MVC model binding is really special here.

halter73 avatar Feb 07 '23 21:02 halter73

The discussion around model binding is about control flow. Model binding is doing IO from Streams which can only report errors by throwing IOExceptions. Since these are expected from Streams, we should have model binding catch them and exit gracefully. We don't want to flow IOExceptions all the way up the stack when we can avoid it, that's expensive and unnecessary.

Having a backup check in the various exception handlers for this case isn't a bad idea, it would at least cut down on the log noise.

Tratcher avatar Feb 07 '23 22:02 Tratcher

Background and Motivation

@Tratcher mentions:

HTTP Status 499 is often used in logs when a client has disconnected before the response starts. It's an unofficial code created by nginx, but it has received broad recognition/adoption. https://learn.microsoft.com/en-us/azure/application-gateway/http-response-codes#499--client-closed-the-connection

Proposed API

namespace Microsoft.AspNetCore.Http;
 
/// <summary>
/// A collection of constants for
/// <see href="http://www.iana.org/assignments/http-status-codes/http-status-codes.xhtml" >HTTP status codes</see >.
/// </summary>
/// <remarks>
/// Descriptions for status codes are available from
/// <see cref="M:Microsoft.AspNetCore.WebUtilities.ReasonPhrases.GetReasonPhrase(Int32)" />.
/// </remarks>
public static class StatusCodes
{
+    public const int Status499ClientClosedRequest = 499;
}

Usage Examples

This API will mostly be used by framework code, but you could set it yourself so diagnostics from custom middleware see the 499 status code. You'd be unlikely to check if the response already has a 499 status code, since this would only be set automatically fairly late in the pipeline, but it is visible in some places like IHttpContextFactory.Return(HttpContext)

if (context.RequestAborted.IsCancellationRequested && !context.Response.HasStarted)
{
    context.Response.StatusCode = StatusCodes.Status499ClientClosedRequest;
}

Alternative Designs

Continue using 0 for this status code.

Risks

People could theoretically already be looking for status code 0 instead of 499 in their logs for this case, but it seems unlikely.

halter73 avatar Feb 08 '23 00:02 halter73

Thank you for submitting this for API review. This will be reviewed by @dotnet/aspnet-api-review at the next meeting of the ASP.NET Core API Review group. Please ensure you take a look at the API review process documentation and ensure that:

  • The PR contains changes to the reference-assembly that describe the API change. Or, you have included a snippet of reference-assembly-style code that illustrates the API change.
  • The PR describes the impact to users, both positive (useful new APIs) and negative (breaking changes).
  • Someone is assigned to "champion" this change in the meeting, and they understand the impact and design of the change.

ghost avatar Feb 08 '23 00:02 ghost

API Review Notes:

https://github.com/dotnet/aspnetcore/blob/105e1b2d91a6704a769a90ebd1e0a284805483b8/src/Http/Http.Abstractions/src/StatusCodes.cs#L236-L239

  • Do we plan on adding any other non-standard status codes? Maybe.
  • How do we come up with names like Status499ClientClosedRequest vs Status499ClientClosedConnection? We do our best and try to pick the clearest, most commonly used name.
  • @JamesNK asks "Do all status codes have a reason phrase? [Yes] If they all do then add one for consistency. On that topic, what about adding a unit test that uses reflection to loop over all statuses and verify they all have a reason phrase." @Tratcher doesn't think a test is necessary, but I don't think it'd be too difficult. We do something similar in our SniOptionsSelectorTests.CloneSslOptionsClonesAllProperties().
  • We currently use HTTP status 0 instead of 499 for this purpose, should we continue using that instead? This has the upside of not changing our request completed logs or any other behavior. However, I doubt anyone is relying on the request completed logs using a status code of "0". Or at least I hope not. And searching for "499 http status code" seems a little more helpful than "0 http status code".

API Approved as proposed!

namespace Microsoft.AspNetCore.Http;
 
public static class StatusCodes
{
+    public const int Status499ClientClosedRequest = 499;
}

halter73 avatar Feb 09 '23 18:02 halter73