SignalR server not sending keep-alive ping messages not sure why

[dazinator]

When clients connect to my hub I can see everything initially working:

dbug: Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[0]
      Request matched endpoint '/hubs/webnotifications'
dbug: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[0]
      Static files was skipped as the request already matched an endpoint.
dbug: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[0]
      Static files was skipped as the request already matched an endpoint.
info: Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler[0]
      Successfully validated the token.
dbug: Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler[0]
      AuthenticationScheme: Bearer was successfully authenticated.
info: Microsoft.AspNetCore.Authorization.DefaultAuthorizationService[0]
      Authorization was successful.
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint '/hubs/webnotifications'
dbug: Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionDispatcher[0]
      Establishing new connection.
dbug: Microsoft.AspNetCore.SignalR.HubConnectionHandler[0]
      OnConnectedAsync started.
dbug: Microsoft.AspNetCore.Http.Connections.Internal.Transports.WebSocketsTransport[0]
      Socket opened using Sub-Protocol: 'null'.
dbug: Microsoft.AspNetCore.SignalR.Internal.DefaultHubProtocolResolver[0]
      Found protocol implementation for requested protocol: json.
dbug: Microsoft.AspNetCore.SignalR.HubConnectionContext[0]
      Completed connection handshake. Using HubProtocol 'json'.
dbug: Hub.Server.Modules.WebNotifications.WebNotificationHub[0]
      User connected: 1

However on the client side (blazor wasm) I can see that after a while, it re-attempts the connection as it never receives a "keep-alive" ping from the server. This surfaces as my IRetryPolicy being invoked to connect again (and PreviousAttempts is always 0 as the connection always suceeds, it just it times out after a while due to no ping, so then re-connects)

On the client side (blazor wasm) I have configured the client connection like so:

                    var uri = new Uri(baseAddressUri, relativeHubUrl);
                    var tokenManager = sp.GetRequiredService<ITokenManager>();
                    var hubConnection = new HubConnectionBuilder()
                    .WithUrl(uri, options =>
                    {
                        options.AccessTokenProvider = async () => await tokenManager.GetJwtAccessTokenString();                     
                    })                    
                    .WithAutomaticReconnect(continuousRetryPolicy)                  
                    .Build();

                    hubConnection.ServerTimeout = TimeSpan.FromSeconds(30);
                    hubConnection.KeepAliveInterval = TimeSpan.FromSeconds(10);
                    return hubConnection;

On the server side things are a little more "non standard" as I am calling AddSignalR() in a child container built for the tenant, and MapHub() is called in a fork of the root IApplicationBuilder built for that tenant.

 var builder = s.AddSignalR((o) =>
                {
                    o.EnableDetailedErrors = _hostingEnvironment.IsDevelopment();
                    o.KeepAliveInterval = TimeSpan.FromSeconds(10);
                    o.ClientTimeoutInterval = TimeSpan.FromSeconds(60);
                });

I am able to issue messages from the server to the connected clients absolutely fine. So clients can connect, and they can receive messages. The only thing that doesn't appear to be working, is the thing that should be "pinging" the clients to keep them alive.

Based on these settings I would expect to see a Ping sent from the server close to every 10 seconds but I don't see any Ping messages being issued from the server at all..

I think this is something to do with the fact that SignalR services are being added to the child container, child IApplicationbuilder but I am not sure. I have looked through the code but it is not clear to me which class is responsible for sending Ping() messages to clients, and what it's dependencies are? Is anyone able to give me a pointer?

I have configured logging to trace level on the server (and client) for the following and there is no log message indicating any ping message being sent, and I can't see a ping in fiddler either.

         "Microsoft.AspNetCore.SignalR": "Trace",
        "Microsoft.AspNetCore.Http.Connections": "Trace"

[BrennanConroy]

What version of the client are you using? Can you see the client sending pings?

[dazinator]

@BrennanConroy

What version of the client are you using?

  <PackageReference Include="Microsoft.AspNetCore.SignalR.Client" Version="3.1.8" />

Can you see the client sending pings?

Not within the chrome network tab no. All I see is that client negotiates a connection via web socket. It then connects via web socket and those connections stay in a "pending" state (should they?") - here is the output, as you can see I am connecting to two different hubs here and they both exhibit the same problem:

Later on, after a period of no activity, I see my "retry policy" kick in on the client side, and the process repeats with the sae log output again - i.e the client negotiates a new connection. On the server on each attempt - I see the user is connected (The Hub's OnConnectedAsync method fires) and all looks well. However - it also appears that when the server is pushing messages to these "connected" clients - It is pushing 5 messages in a row. Only every other one makes it to the client. This behaviour appears consistent - Message 1, 3 and 5 are received by the client, message 2 and 4 never make it. On the server side I can see that all 5 messages are sent to the user via the hub and all looks fine from that perspective.

[BrennanConroy]

If you click on the websocket connection, you should be able to see a messages tab and see the json payloads

[dazinator]

I have just simplified it a bit, by removing one of the hubs. So now there is only a single hub, single hub connection - I am seeing identical behaviour:

1. No ping messages sent from client (however I a not sure this is actually relevent for websocket connections?)
2. When the client connection is started, I see the web socket connection in "pending" state in chrome network tab. On the server side, the hub OnConnectedAsync fires and the user connection all looks good.
3. After a period of time on the client, the existing websocket connection dies, the retry policy kicks in, and a new connection is created:

2. When pushing a sequence of messages from the server, only every other message makes it through to the connected user - I can see all of them being pushed via the hub to the connected client - can't see any obvious error output and not sure where else to look.

[dazinator]

If you click on the websocket connection, you should be able to see a messages tab and see the json payloads

Here are the messages from the 1st websocket connection which eventually terminates:

The client IRetryPolicy then kicks in and causes a new web socket connection to be created, which has the same issue - and same set of messages, before it terminates:

[dazinator]

The following hopefully shows more fully what I am seeing:

1. Websocket is created 22:12:17
2. I see some "{ "type": 6 }" messages being sent periodically - I assume those are the client keep alive messages?
3. On the server side, I pushed 5 "RecieveNotification" messages in a loop to the connected user.
4. I see the websocket connection only receives every other message - see below ids - 1117 and 1119 are missing.

After 4 - 5 mins, the websocket connection was closed, and the client IRetryPolicy then creates a new one with the same symptoms.

For this example, I had increased the timeouts on the server and the client a bit to give me some more time to capture what was going on. Server:

 o.KeepAliveInterval = TimeSpan.FromSeconds(120);
 o.ClientTimeoutInterval = TimeSpan.FromSeconds(240);

Client:

 hubConnection.ServerTimeout = TimeSpan.FromSeconds(240);
 hubConnection.KeepAliveInterval = TimeSpan.FromSeconds(15);     

The client side KeepAliveInterval is set to 15 seconds, and this ties up with the "{ "type": 6 }" messages I see are sent roughly every 15 seconds so I assume they must be the keep alive messages. However this doesn't prevent the connection from being closed for some reason by the client - and I can't see any "ping" messages coming from the server to the client.

[dazinator]

Thanks @davidfowl that helps. It seems it relies on IHostApplicationLifetime.Started in order to start that background timer. In my case, my tenant container is created after host startup, and signal r added to the child container so the host has already started - so i think it missed that event. I'll investigate a bit more and confirm but if that is what is happening then I should be able to workaround it pretty easily.

[dazinator]

Is it worth me submitting a PR to add a tiny bit of logic here:

aspnetcore/src/SignalR/common/Http.Connections/src/Internal/HttpConnectionManager.cs

Line 42 in f490dd2

appLifetime.ApplicationStarted.Register(() => Start());

which also would initiate the timer if IHostApplicationLifetime.ApplicationStarted was already true? I appreciate that wouldnt be the typical case.

Ignore me, I misread the api, there is no boolean property that returns if the application has already started.

[dazinator]

Ah ApplicationStarted is a CancellationToken so it should be possible to check if its already signalled via IsCancellationRequested() (to cover the case where the connection manager instance is actually created after the host has already started) and if so, initialise the timer immediately rather than register / wait for a callback... would you accept that as a PR @davidfowl or should I not bother with a PR for that - I accept this issue won't be applicable to many. I think there could be value in it making things a little bit more robust.

[davidfowl]

There's no PR required here that's how cancellation tokens work. https://source.dot.net/#System.Private.CoreLib/CancellationTokenSource.cs,573

[dazinator]

Haha oh yes thanks for the clarification! Something else must be happening in my scenario then! I'll continue to dig deeper.

[dazinator]

Ok so my issue turned out to be that I was not getting the same instance of IHostApplicationLifetime from the tenants child container as was registered in the application container - tenants were getting their own singleton instances of this. On those "per tenant" instances, they were never having the lifetime event called, and so the background ping method was never initiated.

https://github.com/dotnet/runtime/blob/6072e4d3a7a2a1493f514cdf4be75a3d56580e84/src/libraries/Microsoft.Extensions.Hosting/src/HostBuilder.cs#L215

This is something I'll need to fix in terms of how that service is resolved from child containers.

[dazinator]

Thank you @davidfowl and @BrennanConroy for your help getting to the bottom of this.