Abundant `UpgradeRequestCanceled` in the logs

[Deilan]

Describe the bug

Using as a direct proxy. Having abundant UpgradeRequestCanceled in the logs. Could be a symptom of misconfiguration or code flaw?

Log message:

2021-09-17 16:18:11.712 +03:00 [INF] "UpgradeRequestCanceled": Copying the upgraded request body was canceled.
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.GetResult(Int16 token)
   at System.Net.Http.HttpConnection.ReadAsync(Memory`1 destination)
   at System.Net.Http.HttpConnection.RawConnectionStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpConnection.RawConnectionStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
   at Yarp.ReverseProxy.Forwarder.StreamCopier.CopyAsync(Boolean isRequest, Stream input, Stream output, IClock clock, CancellationToken cancellation)

To Reproduce

Code:

public void ConfigureServices(IServiceCollection services)
{
    services.AddHttpProxyServices();
}

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
    if (!env.IsDevelopment())
    {
        app.UseHsts();
    }
    app.UseHttpsRedirection();
    app.UseRouting();
    app.UseEndpoints(builder =>
    {
        builder.MapHttpProxy("/{**catch-all}", "http://localhost:8080");
    });
}

public static IEndpointConventionBuilder MapHttpProxy(this IEndpointRouteBuilder builder, string pattern, string destinationUri)
{
    // Configure our own HttpMessageInvoker for outbound calls for proxy operations
    var httpClient = new HttpMessageInvoker(new SocketsHttpHandler
    {
        UseProxy = false,
        AllowAutoRedirect = false,
        AutomaticDecompression = DecompressionMethods.None,
        UseCookies = false,
    });

    return builder.Map(pattern, async httpContext =>
    {
        var httpForwarder = httpContext.RequestServices.GetRequiredService<IHttpForwarder>();
        await httpForwarder.SendAsync(httpContext, destinationUri, httpClient);
    });
}

public static class HttpProxyServiceCollectionEx
{
    public static IServiceCollection AddHttpProxyServices(this IServiceCollection services)
    {
        services.AddHttpForwarder();

        return services;
    }
}

Further technical details

• .NET Core 3.1.14
• Yarp.ReverseProxy 1.0.0-preview.12.21451.3
• Windows 10 version 20H2

[Tratcher]

@MihaZupan have you seen this in your recent testing?

[MihaZupan]

No, though they were all simple scenarios (1 connection at a time)

[adityamandaleeka]

@Deilan Can you provide a sample client/server that demonstrates this in addition to the proxy logic you provided above?

[karelz]

Triage: We should check logs for WebSockets if it is common.

@Deilan would you be able to test it on latest bits (RC1)? We should have more detailed logs there + some issues were fixed. Thanks!

[Deilan]

I will try to reproduce the issue in a similar environment using the latest version. I'm on a long vacation now, so it will not be very soon though.

[MihaZupan]

info: Yarp.ReverseProxy.Forwarder.HttpForwarder[48]
      UpgradeResponseCanceled: Copying the upgraded response body was canceled.
      System.Threading.Tasks.TaskCanceledException: The operation was canceled.
         at System.Net.Http.CancellationHelper.ThrowOperationCanceledException(Exception innerException, CancellationToken cancellationToken)
         at System.Net.Http.HttpConnection.RawConnectionStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
         at Yarp.ReverseProxy.Forwarder.StreamCopier.CopyAsync(Boolean isRequest, Stream input, Stream output, IClock clock, ActivityCancellationTokenSource activityToken, CancellationToken cancellation)

or

info: Yarp.ReverseProxy.Forwarder.HttpForwarder[48]
      UpgradeResponseCanceled: Copying the upgraded response body was canceled.
      System.Threading.Tasks.TaskCanceledException: The operation was canceled.
       ---> System.IO.IOException: The read operation failed, see inner exception.
       ---> System.ObjectDisposedException: Cannot access a disposed object.
      Object name: 'SslStream'.
         at System.Net.Security.SslStream.<ThrowIfExceptional>g__ThrowExceptional|138_0(ExceptionDispatchInfo e)
         at System.Net.Security.SslStream.DecryptData(Int32 frameSize)
         at System.Net.Security.SslStream.ReadAsyncInternal[TIOAdapter](TIOAdapter adapter, Memory`1 buffer)
         --- End of inner exception stack trace ---
         at System.Net.Security.SslStream.ReadAsyncInternal[TIOAdapter](TIOAdapter adapter, Memory`1 buffer)
         at System.Net.Http.HttpConnection.ReadAsync(Memory`1 destination)
         at System.Net.Http.HttpConnection.RawConnectionStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
         --- End of inner exception stack trace ---
         at System.Net.Http.HttpConnection.RawConnectionStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
         at Yarp.ReverseProxy.Forwarder.StreamCopier.CopyAsync(Boolean isRequest, Stream input, Stream output, IClock clock, ActivityCancellationTokenSource activityToken, CancellationToken cancellation)okenSource activityToken, CancellationToken cancellation)

or

info: Yarp.ReverseProxy.Forwarder.HttpForwarder[48]
      UpgradeResponseCanceled: Copying the upgraded response body was canceled.
      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.Security.SslStream.EnsureFullTlsFrameAsync[TIOAdapter](TIOAdapter adapter)
         at System.Net.Security.SslStream.ReadAsyncInternal[TIOAdapter](TIOAdapter adapter, Memory`1 buffer)
         at System.Net.Http.HttpConnection.ReadAsync(Memory`1 destination)
         at System.Net.Http.HttpConnection.RawConnectionStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
         --- End of inner exception stack trace ---
         at System.Net.Http.HttpConnection.RawConnectionStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
         at Yarp.ReverseProxy.Forwarder.StreamCopier.CopyAsync(Boolean isRequest, Stream input, Stream output, IClock clock, ActivityCancellationTokenSource activityToken, CancellationToken cancellation)

I'm seeing quite a few of these when testing against Blazor. Whenever you close a tab / navigate away, the WebSocket connection will be forcefully closed by the browser (it will send a close, but won't wait for the server to do the same). Yarp is correct here in reporting the error.

In our WebSocketsTelemetry code, we would attribute this case as ClientGracefulClose.
Related discussion: #1237 (comment)

[Tratcher]

It's interesting all of those errors complain about the response body reads when it was the client that disconnected and the request body reads or response writes that should have noticed. All of the above were triggered by the RequestAborted CancellationToken, right? We could clarify that in the error messages.

[Deilan]

@Deilan would you be able to test it on latest bits (RC1)? We should have more detailed logs there + some issues were fixed. Thanks!

@karelz As of 1.0.0, after switching to IHttpForwarder, I don't see UpgradeRequestCanceled entries in logs anymore.

[karelz]

Triage: Looks like resolved per info about. Closing.