reverse-proxy icon indicating copy to clipboard operation
reverse-proxy copied to clipboard
verified publisher icon microsoft

Control the handling of TaskCanceledException and other exceptions

Open anders-dev1 opened this issue 2 years ago • 7 comments

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.

anders-dev1 avatar Jul 17 '23 07:07 anders-dev1

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.

Tratcher avatar Jul 17 '23 15:07 Tratcher

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 😃

anders-dev1 avatar Jul 18 '23 07:07 anders-dev1

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"
  }
]

AliJP avatar Aug 18 '23 15:08 AliJP

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.

MihaZupan avatar Aug 31 '23 14:08 MihaZupan

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

cc @ChintanRaval

jakebanks avatar Nov 22 '23 05:11 jakebanks

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

MihaZupan avatar Jan 24 '24 14:01 MihaZupan

+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).

hesperanca avatar Mar 25 '24 14:03 hesperanca