Control the handling of TaskCanceledException and other exceptions

[anders-dev1]

What should we add or change to make your life better?

Our setup

We use YARP as a gateway from our frontend client to the backend services, with communication via gRPC-web.

The suggestion

We encounter an issue when the client leaves a page while streaming data from a backend service through the YARP proxy. YARP throws a TaskCanceledException in this scenario. No error is thrown or logged by the backend service. We expect this exception to be thrown, as it usually is when a task is canceled. However, it is currently not possible to catch and handle the exception with YARP. This is problematic for us because YARP logs the exception, which then gets caught by our analytics.

We have attempted to add middleware to address this issue, but we have been unable to stop the logging of the exception.

Changing the log level to not log errors is not a viable solution as we may miss other important errors.

We suggest one of the following solutions:

1. Add a configuration flag to toggle the logging of TaskCanceledException since it is an expected exception.
2. Make it possible for the consumer of YARP to decide how to handle exceptions. This may be achievable if we can catch it in middleware.

Why is this important to you?

This is important to us as we don't want to log expected exceptions, which then gets reported by our analytics.

[Tratcher]

Please share the full log and stack trace you're concerned about.

Add a configuration flag to toggle the logging of TaskCanceledException since it is an expected exception.

We have a policy against customizing log levels, it doesn't scale.

Make it possible for the consumer of YARP to decide how to handle exceptions. This may be achievable if we can catch it in middleware.

This is more plausible.

[anders-dev1]

Sure, here is the stacktrace:

System.Threading.Tasks.TaskCanceledException: The operation was canceled.
---> System.IO.IOException: Unable to read data from the transport connection: The I/O operation has been aborted because of either a thread exit or an application request..
---> System.Net.Sockets.SocketException (995): The I/O operation has been aborted because of either a thread exit or an application request.
--- End of inner exception stack trace ---
 at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
 at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource<System.Int32>.GetResult(Int16 token)
 at System.Net.Http.HttpConnection.ReadAsync(Memory`1 destination)
 at System.Net.Http.HttpConnection.ChunkedEncodingReadStream.ReadAsyncCore(Memory`1 buffer, CancellationToken cancellationToken)
 --- End of inner exception stack trace ---
 at System.Net.Http.HttpConnection.ChunkedEncodingReadStream.ReadAsyncCore(Memory`1 buffer, CancellationToken cancellationToken)
 at Yarp.ReverseProxy.Forwarder.StreamCopier.CopyAsync(Stream input, Stream output, Int64 promisedContentLength, StreamCopierTelemetry telemetry, ActivityCancellationTokenSource activityToken, Boolean autoFlush, CancellationToken cancellation)

And the whole log entry (changed RequestPath as i can't show deails of what we are working on):

{
"@t":"2023-07-18T07:14:28.1538081Z",
"@mt":"{error}: {message}",
"@x":"
System.Threading.Tasks.TaskCanceledException: The operation was canceled.
---> System.IO.IOException: Unable to read data from the transport connection: The I/O operation has been aborted because of either a thread exit or an application request..
 ---> System.Net.Sockets.SocketException (995): The I/O operation has been aborted because of either a thread exit or an application request.
 --- End of inner exception stack trace ---
 at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
 at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource<System.Int32>.GetResult(Int16 token)
 at System.Net.Http.HttpConnection.ReadAsync(Memory`1 destination)
 at System.Net.Http.HttpConnection.ChunkedEncodingReadStream.ReadAsyncCore(Memory`1 buffer, CancellationToken cancellationToken)
 --- End of inner exception stack trace ---
 at System.Net.Http.HttpConnection.ChunkedEncodingReadStream.ReadAsyncCore(Memory`1 buffer, CancellationToken cancellationToken)
 at Yarp.ReverseProxy.Forwarder.StreamCopier.CopyAsync(Stream input, Stream output, Int64 promisedContentLength, StreamCopierTelemetry telemetry, ActivityCancellationTokenSource activityToken, Boolean autoFlush, CancellationToken cancellation)
",
"error":"ResponseBodyCanceled",
"message":"Copying the response body was canceled.",
"EventId":{"Id":48, "Name":"ForwardingError"},
"SourceContext":"Yarp.ReverseProxy.Forwarder.HttpForwarder",
"RequestId":"0HMS7BQ8709RD:000000DF",
"RequestPath":"/servicename/streamendpoint",
"ConnectionId":"0HMS7BQ8709RD"
}

Thanks for your help 😃

[AliJP]

We have the same problem with our application. So most of our exception logs are TaskCanceledExceptions logged by Yarp. It would be great if you gave the user the ability to decide which error should be logged or not.
Our stack trace is not the same. I would paste that in here, so it might help you:
Type:

System.Threading.Tasks.TaskCanceledException

Error:

RequestCanceled

Message:

The request was canceled before receiving a response.

Parsed Stack trace

[
  {
    "method": "System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess",
    "level": 0,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification",
    "level": 1,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Threading.Tasks.TaskCompletionSourceWithCancellation`1+<WaitWithCancellationAsync>d__1.MoveNext",
    "level": 2,
    "line": 0,
    "assembly": "System.Net.Http, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
  },
  {
    "method": "System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw",
    "level": 3,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess",
    "level": 4,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification",
    "level": 5,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Net.Http.HttpConnectionPool+<GetHttp2ConnectionAsync>d__80.MoveNext",
    "level": 6,
    "line": 0,
    "assembly": "System.Net.Http, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
  },
  {
    "method": "System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw",
    "level": 7,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess",
    "level": 8,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification",
    "level": 9,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Net.Http.HttpConnectionPool+<SendWithVersionDetectionAndRetryAsync>d__84.MoveNext",
    "level": 10,
    "line": 0,
    "assembly": "System.Net.Http, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
  },
  {
    "method": "System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw",
    "level": 11,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess",
    "level": 12,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification",
    "level": 13,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Net.Http.DiagnosticsHandler+<SendAsyncCore>d__8.MoveNext",
    "level": 14,
    "line": 0,
    "assembly": "System.Net.Http, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
  },
  {
    "method": "System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw",
    "level": 15,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess",
    "level": 16,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification",
    "level": 17,
    "line": 0,
    "assembly": "System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e"
  },
  {
    "method": "Yarp.ReverseProxy.Forwarder.HttpForwarder+<SendAsync>d__6.MoveNext",
    "level": 18,
    "line": 0,
    "assembly": "Yarp.ReverseProxy, Version=1.1.1.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
  }
]

[MihaZupan]

Triage:

• We agree that most errors that occur as a result of the client disconnecting are not directly actionable by the proxy, and therefore less useful and potentially drowning out logs about real issues.
• We do not believe adding options to control how each exception is logged is a scalable solution.
• We are open to removing exceptions that result due to the client disconnecting from logs, or to moving them to a separate event with a higher verbosity level.

[jakebanks]

+1 for this, we are also seeing these as noise in our telemetry unfortunately

cc @ChintanRaval

[MihaZupan]

Now that we moved these logs from Information to Warning, this has become a lot more annoying - #2340.
Moving this one out of backlog.

[hesperanca]

+1 Same here. I get a notification on my mobile when there are exceptions raised by the servers. We have a multitenant SAAS tool and I'm getting pinged when our SPA client app cancels a request (e.g. when a customer paginates quickly through lists on our client app).

[MihaZupan]

#2503 is moving RequestCanceled, RequestBodyCanceled, and UpgradeRequestCanceled to a new debug-level log.