SignalR: Client awaiting long running server method leads to timeout on server-side

[Apollo3zehn]

Describe the bug

I have a small setup where a C# client invokes a server method without parameters, simply waiting for an URL to return (both are v3.0.0-preview5). In my test setup, the server works on that zip file for 100s. During the call, the server prepares a zip file and returns a link to that file once finished. The server frequently sends status updates to the client.

With logs enabled on both sides and also using wireshark, I can see that the client sends pings regularly. However, if I get the source code right, the server does not process these pings due to the pending await call. The following happes:

• after 30s, the server detects that no new message was received but continues without complains (I think this is intended)
• after 60s, the server detects again that no frame was received and tries to abort the connection, but the invoked method continues to run. At this point, the client is not receiving status updates anymore from the server.
• after 90s, the server detects again that no frame was received and tries to abort the connection, but the invoked method continues to run
• after 100s, the invoked method returns, and the connection is actually aborted. OnDisconnectedAsync is called. On the client side, the error "A task was cancelled" appears.

I am not sure if this is by design (i.e. 'don't use async/await for very long running methods'), or if this is a bug, since the pings from the client are not processed.

If it is by design, what is the recommended alternative, when a client needs to wait for a long running methods?

To Reproduce

Hub content:

using Microsoft.AspNetCore.SignalR;
using System;
using System.Threading.Tasks;

namespace WebApplication1
{
    public class Broadcaster : Hub<IBroadcaster>
    {
        public Task<string> GetUrl()
        {
            int counter = 0;

            return Task.Run(async () =>
            {
                for (int i = 0; i < 100; i++)
                {
                    await Task.Delay(TimeSpan.FromSeconds(1));
                    await this.Clients.Client(this.Context.ConnectionId).SendProgress(counter, "Progress");
                    counter += 1;
                }

                return "url";
            });
        }
    }
}

Callback interface:

using System.Threading.Tasks;

namespace WebApplication1
{
    public interface IBroadcaster
    {
        Task SendProgress(double percent, string message);
    }
}

Client:

 _connection.On("SendProgress", (double percent, string message) =>
{
    Console.WriteLine($"{percent,3:0}%: {message}\n");
});

var url = await _connection.InvokeAsync<string>("GetUrl");

Expected behavior

I would expect that during an active connection where the client sends ping messages and server sends status updates, the connection is not cancelled.

Additional context

Include the output of dotnet --info

.NET Core SDK (gemäß "global.json"):
 Version:   3.0.100-preview5-011568
 Commit:    b487ff10aa

Laufzeitumgebung:
 OS Name:     Windows
 OS Version:  10.0.17763
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\3.0.100-preview5-011568\

Host (useful for support):
  Version: 3.0.0-preview5-27626-15
  Commit:  61f30f5a23

.NET Core SDKs installed:
  2.1.602 [C:\Program Files\dotnet\sdk]
  2.2.203 [C:\Program Files\dotnet\sdk]
  3.0.100-preview5-011568 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.2.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.2.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.0.0-preview5-19227-01 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.2.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.0.0-preview5-27626-15 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.WindowsDesktop.App 3.0.0-preview5-27626-15 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

[analogrelay]

I am not sure if this is by design (i.e. 'don't use async/await for very long running methods'), or if this is a bug,

This wouldn't be by-design. You should definitely be using await here ;).

I can repro this using your sample code (repo: https://github.com/anurse/longmethodrepro). I get the following logs on the server:

dbug: Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher[1]
      Received hub invocation: InvocationMessage { InvocationId: "1", Target: "GetUrl", Arguments: [  ], StreamIds: [  ] }.
dbug: Microsoft.AspNetCore.SignalR.HubConnectionContext[9]
      Client timeout (30000ms) elapsed without receiving a message from the client. Closing connection.

The client gets:

info: Microsoft.AspNetCore.Http.Connections.Client.Internal.WebSocketsTransport[11]
      WebSocket closed by the server. Close status NormalClosure.
dbug: Microsoft.AspNetCore.Http.Connections.Client.Internal.WebSocketsTransport[4]
      Receive loop stopped.
trce: Microsoft.AspNetCore.SignalR.Client.HubConnection[42]
      Waiting on Connection Lock in ReceiveLoop (/_/src/SignalR/clients/csharp/Client.Core/src/HubConnection.cs:1093).
trce: Microsoft.AspNetCore.SignalR.Client.HubConnection[20]
      Releasing Connection Lock in ReceiveLoop (/_/src/SignalR/clients/csharp/Client.Core/src/HubConnection.cs:1102).
dbug: Microsoft.AspNetCore.Http.Connections.Client.HttpConnection[4]
      Disposing HttpConnection.
dbug: Microsoft.AspNetCore.Http.Connections.Client.Internal.WebSocketsTransport[8]
      Send loop stopped.
info: Microsoft.AspNetCore.Http.Connections.Client.Internal.WebSocketsTransport[6]
      Transport is stopping.
dbug: Microsoft.AspNetCore.Http.Connections.Client.Internal.WebSocketsTransport[2]
      Transport stopped.
info: Microsoft.AspNetCore.Http.Connections.Client.HttpConnection[6]
      HttpConnection Disposed.
dbug: Microsoft.AspNetCore.SignalR.Client.HubConnection[46]
      Canceling all outstanding invocations.
trce: Microsoft.AspNetCore.SignalR.Client.HubConnection[13]
      Removing pending invocation 1.
trce: Microsoft.AspNetCore.SignalR.Client.Internal.InvocationRequest.NonStreaming[2]
      Invocation 1 disposed.
trce: Microsoft.AspNetCore.SignalR.Client.HubConnection[11]
      Shutting down connection.

Unhandled Exception: System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Microsoft.AspNetCore.SignalR.Client.HubConnection.InvokeCoreAsyncCore(String methodName, Type returnType, Object[] args, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.SignalR.Client.HubConnection.InvokeCoreAsync(String methodName, Type returnType, Object[] args, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.SignalR.Client.HubConnectionExtensions.InvokeCoreAsync[TResult](HubConnection hubConnection, String methodName, Object[] args, CancellationToken cancellationToken)
   at Client.Program.Main(String[] args) in C:\Code\anurse\Scratch\longmethodrepro\Client\Program.cs:line 35
   at Client.Program.<Main>(String[] args)

A couple things of note:

• It always happens around 60 seconds
• The client appears to be continuing to send pings, a Fiddler trace showed pings occurring every 15 seconds.
• The server appears to be erroneously believing that the client has timed out.

We'll investigate further!

[analogrelay]

After some discussion with @BrennanConroy this is somewhat expected behavior because you are returning the long-running Task from your Hub method and we block the processing loop based on that Task. We're looking at changing that behavior in #5351

As a workaround, you could pass this work off to a background service of some kind that uses IHubContext to send progress back to the client. Note: If you kick off a background process (and don't return that Task from your hub method) you can't call this.Clients from that background process. You have to use IHubContext, since the Hub will be disposed and become invalid while your background process is running.

[analogrelay]

Going to close this since it is "expected" in the current implementation and we have #5351 tracking an improvement that should resolve this issue.

In general, I would recommend not having such a long-running non-streaming Hub method and using the background service behavior I suggested above. Your Task.Run isn't really doing anything here since you're returning the task to us to await, so your hub method is exactly equivalent to the following (in fact, the only difference is that your code ends up being slower since it has to reenter the thread-pool queue). There's no need to jump off the current thread if you're just going to block the outer task waiting for the inner one to finish.

using Microsoft.AspNetCore.SignalR;
using System;
using System.Threading.Tasks;

namespace WebApplication1
{
    public class Broadcaster : Hub<IBroadcaster>
    {
        public async Task<string> GetUrl()
        {
            int counter = 0;

            for (int i = 0; i < 100; i++)
            {
                await Task.Delay(TimeSpan.FromSeconds(1));
                await this.Clients.Client(this.Context.ConnectionId).SendProgress(counter, "Progress");
                counter += 1;
           }

           return "url";
        }
    }
}

[Apollo3zehn]

Thank @anurse for investigation. I switched now to a background service which handles the request to not block the hub for a long time. I no longer run into timeouts.

But more convenient would be to simply await the result :)

[analogrelay]

But more convenient would be to simply await the result :)

Definitely agree. #5351 will make that work better since we won't be blocking the message loop on running the Hub.

Another super hacky way you could do this is with the streaming support, since we don't block the message loop on those requests. You can just stream only a single item back :). It's a big hack though and a breaking change to your Client if you switch back and forth between streaming and non-streaming.