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

Framework does not handle Request cancellation properly #44697

Closed
1 task done
maxcherednik opened this issue Oct 22, 2022 · 25 comments · Fixed by #46330
Closed
1 task done

Framework does not handle Request cancellation properly #44697

maxcherednik opened this issue Oct 22, 2022 · 25 comments · Fixed by #46330
Assignees
Labels
api-approved API was approved in API review, it can be implemented area-networking Includes servers, yarp, json patch, bedrock, websockets, http client factory, and http abstractions area-web-frameworks *DEPRECATED* This label is deprecated in favor of the area-mvc and area-minimal labels help wanted Up for grabs. We would accept a PR to help resolve this issue
Milestone

Comments

@maxcherednik
Copy link

Is there an existing issue for this?

  • 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

@Tratcher Tratcher added area-web-frameworks *DEPRECATED* This label is deprecated in favor of the area-mvc and area-minimal labels and removed area-runtime labels Oct 24, 2022
@davidfowl
Copy link
Member

davidfowl commented Oct 24, 2022

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

@Tratcher
Copy link
Member

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

@davidfowl
Copy link
Member

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

@Tratcher
Copy link
Member

Tratcher commented Oct 24, 2022

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.

@adityamandaleeka
Copy link
Member

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 adityamandaleeka added this to the .NET 8 Planning milestone Oct 24, 2022
@ghost
Copy link

ghost commented Oct 24, 2022

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.

@adityamandaleeka adityamandaleeka added the help wanted Up for grabs. We would accept a PR to help resolve this issue label Oct 24, 2022
@davidfowl
Copy link
Member

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 😄

@jmcgoldrick
Copy link

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.

@singh733
Copy link
Contributor

singh733 commented Nov 3, 2022

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

public async Task Invoke(HttpContext context)
{
try
{
await _next(context);
}
catch (Exception ex)
{
_logger.UnhandledException(ex);
if (context.Response.HasStarted)
{
_logger.ResponseStartedErrorPageMiddleware();
throw;
}

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

internal static partial class DiagnosticsLoggerExtensions
{
// ExceptionHandlerMiddleware & DeveloperExceptionPageMiddleware
[LoggerMessage(1, LogLevel.Error, "An unhandled exception has occurred while executing the request.", EventName = "UnhandledException")]
public static partial void UnhandledException(this ILogger logger, Exception exception);
// ExceptionHandlerMiddleware
[LoggerMessage(2, LogLevel.Warning, "The response has already started, the error handler will not be executed.", EventName = "ResponseStarted")]

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

@Tratcher
Copy link
Member

Tratcher commented Nov 8, 2022

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.

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
{
context.Response.StatusCode = 500;
}

@singh733
Copy link
Contributor

singh733 commented Nov 24, 2022

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

public async Task Invoke(HttpContext context)
{
try
{
await _next(context);
}
catch (Exception ex)
{
_logger.UnhandledException(ex);
if (context.Response.HasStarted)
{
_logger.ResponseStartedErrorPageMiddleware();
throw;
}

@Tratcher
Copy link
Member

@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 #44697 (comment)

_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

_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();
}

Each server (Kestrel, HttpSys, IIS) will also have a catch like this:

catch (Exception ex)
{
Log.LogWarning(0, ex, CoreStrings.RequestProcessingEndError);
}

@singh733
Copy link
Contributor

singh733 commented Dec 7, 2022

@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 #44697 (comment)

We need the CancellationToken property because of the upper comment

@Tratcher
Copy link
Member

Tratcher commented Dec 7, 2022

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

@singh733
Copy link
Contributor

@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));

@Tratcher
Copy link
Member

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.

@davidfowl
Copy link
Member

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.

@singh733
Copy link
Contributor

singh733 commented Dec 20, 2022

@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

@Tratcher
Copy link
Member

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.

@singh733
Copy link
Contributor

singh733 commented Jan 10, 2023

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

@halter73
Copy link
Member

halter73 commented Feb 7, 2023

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.

@Tratcher
Copy link
Member

Tratcher commented Feb 7, 2023

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.

@halter73
Copy link
Member

halter73 commented Feb 8, 2023

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 halter73 added the api-ready-for-review API is ready for formal API review - https://github.com/dotnet/apireviews label Feb 8, 2023
@ghost
Copy link

ghost commented Feb 8, 2023

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.

@halter73
Copy link
Member

halter73 commented Feb 9, 2023

API Review Notes:

/// <summary>
/// HTTP status code 419.
/// </summary>
public const int Status419AuthenticationTimeout = 419; // Not defined in any RFC

  • 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 halter73 added api-approved API was approved in API review, it can be implemented and removed api-ready-for-review API is ready for formal API review - https://github.com/dotnet/apireviews labels Feb 9, 2023
@Tratcher Tratcher self-assigned this Feb 16, 2023
@ghost ghost locked as resolved and limited conversation to collaborators Mar 18, 2023
@amcasey amcasey added area-networking Includes servers, yarp, json patch, bedrock, websockets, http client factory, and http abstractions and removed area-runtime labels Aug 25, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
api-approved API was approved in API review, it can be implemented area-networking Includes servers, yarp, json patch, bedrock, websockets, http client factory, and http abstractions area-web-frameworks *DEPRECATED* This label is deprecated in favor of the area-mvc and area-minimal labels help wanted Up for grabs. We would accept a PR to help resolve this issue
Projects
None yet
Development

Successfully merging a pull request may close this issue.

9 participants