Signalr version 8.0.5 - If I have even one connected client, shutdown of the app is 30 seconds

[alkampfergit]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

This is probably a duplicate of #53165 . Our application, whenever there is at least one client connected needs 30 seconds from when the Asp.NET core receve the IsClosing from when the app is closed.

This is really annoying because we have software running as windows service, and having this long timeout sometimes generates problem.

We took the timing with IHostedLifecycleService and whenever there is a client connected the time between closing and closed is always 30 seconds (with a difference of max 100 milliseconds).

We are using version 8.0.5, and issue #53165 is closed so I'm expecting not to have this problem.

Expected Behavior

When I shutdown my asp.net core application I do not want signalr block the shutdown for 30 seconds, because it causes problem.

I'm expecting also the possibility to force signalr to close everything and letting the application shutdown correctly.

Steps To Reproduce

I do not have a minimal reproduction, it happens always on our software.

Exceptions (if any)

No response

.NET Version

8.0.404

Anything else?

No response

[BrennanConroy]

Show server logs please, similar to what is in the issue you linked to
#53165 (comment)

[alkampfergit]

Ok here is what happened, this is the output of the console

[10:11:42 INF][Jarvis.Host.Support.WebAppLifecycleManagerHostedService] ################### StopAsync completed in 7180 ms.
[10:11:42 WRN][Orleans.Messaging] Dropping message Request [S10.0.0.39:40101:90666655 sys.svc.user.95B6CAE6/10.0.0.39:40101@90666655]->[S10.0.0.39:40101:90666655 management/0] Orleans.Runtime.IManagementGrain.GetRuntimeStatistics(Orleans.Runtime.SiloAddress[]) #5815 since this silo is blocking application messages
[10:12:04 INF][Microsoft.AspNetCore.Routing.EndpointMiddleware] Executed endpoint '/notification'
[10:12:04 INF][Microsoft.AspNetCore.Routing.EndpointMiddleware] Executed endpoint '/chat'
[10:12:04 INF][Microsoft.AspNetCore.Hosting.Diagnostics] Request finished HTTP/2 CONNECT https://jarvis-uniquehost.codewrecks.com/notification?id=ewhvNu2JeTu1Jf3oaH3qRg - 200 null null 29973.9655ms
[10:12:04 INF][Microsoft.AspNetCore.Hosting.Diagnostics] Request finished HTTP/2 CONNECT https://jarvis-uniquehost.codewrecks.com/chat?id=ARw59xut9nTlSsFXjp_orw - 200 null null 29974.0106ms
[10:12:04 INF][Microsoft.AspNetCore.Server.Kestrel] Connection id "0HN85ALL3T7BF", Request id "0HN85ALL3T7BF:00000035": the application completed without reading the entire request body.
[10:12:04 INF][Microsoft.AspNetCore.Server.Kestrel] Connection id "0HN85ALL3T7BF", Request id "0HN85ALL3T7BF:00000037": the application completed without reading the entire request body.
[10:12:04 INF][Jarvis.Host.Support.WebAppLifecycleManagerHostedService] ###################  StoppedAsync completed in 30015 ms.
[10:12:04 INF][Jarvis.Host.Support.WebAppLifecycleManagerHostedService] ################### OnStopped called in 30017 ms.

The first line shows that we closed all of our components after 7180 ms from when the IHost received CTRL+C (mainly is orleans), then I have no log up to 30017 ms when all other logs arrives. As you can see we have logs of our two endpoints for signalr /notification and /chat

I've uploaded trace file where I trace evertying that happened in signalr and asp.net

trace_extended20241115.log

Edit: Actually I've solved sending to all client a special message on closing that forces clients to disconnect. Whit this code the application shutsdown at 7 seconds, not waiting the full 30 seconds of signalr.

        this.connection.on("ForceDisconnect", ()=> {
            console.log("ForceDisconnect notification signalr");
            this.connection.stop();
        });

[BrennanConroy]

I see WebAppLifecycleManagerHostedService in your logs, is this an IHost/IWebHost implementation and does it implement IHostApplicationLifetime? SignalR uses IHostApplicationLifetime.ApplicationStopping to trigger connection disconnects.

If that doesn't help figure out the problem, could you enable trace logs for kestrel, hosting, signalr, and http.connections?

[alkampfergit]

The WebAppLifecycleManagerHostedService is a simple IHostedLifecycleService that is used to detect application closing and closing all of the services of our application gracefully. Internally it uses IHostApplicationLifetime to register The application stopping, and it is in that specific method that we send disconnect explicitly to signalr client. Without explicit shutdown, the application closes always in 30 seconds.

[BrennanConroy]

could you enable trace logs for kestrel, hosting, signalr, and http.connections?

Were you able to capture these logs?

[alkampfergit]

Sorry I had some problem these days, I'll check the issue as soon as possible, thanks Il mer 4 dic 2024, 00:41 dotnet-policy-service[bot] < ***@***.***> ha scritto:

…

Hi @alkampfergit <https://github.com/alkampfergit>. We have added the "Needs: Author Feedback" label to this issue, which indicates that we have an open question for you before we can take further action. This issue will be closed automatically in 7 days if we do not hear back from you by then - please feel free to re-open it if you come back to this issue after that time. — Reply to this email directly, view it on GitHub <#58947 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AACXREL56GXPIT4FTZ64LWL2DY6TJAVCNFSM6AAAAABRYTYVNCVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDKMJVHAYTANBXGI> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[alkampfergit]

@BrennanConroy

Attached is another file log, let me know if you need still more loggers.

trace_extended20241212.log

[BrennanConroy]

Thanks for the logs, this looks like an issue we discovered a couple weeks ago and are planning on fixing soon. The root cause is that when the app starts shutting down it triggers ApplicationLifetime.ApplicationStopping token which SignalR listens to and uses to close it's connections. Kestrel then runs and unbinds its connection listeners, but if there are new SignalR connections between when SignalR closes its connections and Kestrel unbinds the connection listener, those connections will succeed and block Kestrel finishing the close logic until the host timeout when it aborts the connections.

From your logs, it looks like immediately after the shutdown starts a new connection comes in. Likely because your clients have reconnection logic to retry immediately on close. A possible workaround (if you own the client code) is to make them wait a short amount of time before reconnection.

[10:01:39 DBG][Microsoft.Extensions.Hosting.Internal.Host] Hosting stopping <--- shutdown starts
[10:01:39 DBG][Microsoft.AspNetCore.Server.Kestrel.Http2] Trace id "0HN8QHE8EU5UM:00000013": HTTP/2 stream error ""INTERNAL_ERROR"". A Reset is being sent to the stream.
Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was aborted by the application.
[10:01:39 DBG][Microsoft.AspNetCore.Server.Kestrel.Http2] Trace id "0HN8QHE8EU5UM:0000000F": HTTP/2 stream error ""INTERNAL_ERROR"". A Reset is being sent to the stream.
Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was aborted by the application.
[10:01:39 DBG][Microsoft.AspNetCore.Http.Connections.Internal.Transports.WebSocketsTransport] Waiting for the application to finish sending data.
[10:01:39 DBG][Microsoft.AspNetCore.Http.Connections.Internal.Transports.WebSocketsTransport] Waiting for the application to finish sending data.
[10:01:39 DBG][Microsoft.AspNetCore.Http.Connections.Internal.Transports.WebSocketsTransport] Socket closed.
[10:01:39 DBG][Microsoft.AspNetCore.Http.Connections.Internal.Transports.WebSocketsTransport] Socket closed.
[10:01:39 DBG][Microsoft.AspNetCore.SignalR.HubConnectionHandler] OnConnectedAsync ending.
[10:01:39 DBG][Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager] Removing connection LjD7biz82bV7jGQ7V57BDg from the list of connections.
[10:01:39 INF][Microsoft.AspNetCore.Hosting.Diagnostics] Request starting HTTP/2 POST https://jarvis-uniquehost.codewrecks.com/chat/negotiate?negotiateVersion=1 - null 0 <---- new connection comes in

[alkampfergit]

Yes you are true, we heavily depend on signalr so clients after a disconnect, immediately try to reconnect. We solved in a simple way, when we want to close, we send a message to all clients to ask to disconnect , this seems to fix the issue Il gio 12 dic 2024, 18:53 Brennan ***@***.***> ha scritto:

…

Thanks for the logs, this looks like an issue we discovered a couple weeks ago and are planning on fixing soon. The root cause is that when the app starts shutting down it triggers ApplicationLifetime.ApplicationStopping token which SignalR listens to and uses to close it's connections. Kestrel then runs and unbinds its connection listeners, but if there are new SignalR connections between when SignalR closes its connections and Kestrel unbinds the connection listener, those connections will succeed and block Kestrel finishing the close logic until the host timeout when it aborts the connections. From your logs, it looks like immediately after the shutdown starts a new connection comes in. Likely because your clients have reconnection logic to retry immediately on close. A possible workaround (if you own the client code) is to make them wait a short amount of time before reconnection. [10:01:39 DBG][Microsoft.Extensions.Hosting.Internal.Host] Hosting stopping <--- shutdown starts [10:01:39 DBG][Microsoft.AspNetCore.Server.Kestrel.Http2] Trace id "0HN8QHE8EU5UM:00000013": HTTP/2 stream error ""INTERNAL_ERROR"". A Reset is being sent to the stream. Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was aborted by the application. [10:01:39 DBG][Microsoft.AspNetCore.Server.Kestrel.Http2] Trace id "0HN8QHE8EU5UM:0000000F": HTTP/2 stream error ""INTERNAL_ERROR"". A Reset is being sent to the stream. Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was aborted by the application. [10:01:39 DBG][Microsoft.AspNetCore.Http.Connections.Internal.Transports.WebSocketsTransport] Waiting for the application to finish sending data. [10:01:39 DBG][Microsoft.AspNetCore.Http.Connections.Internal.Transports.WebSocketsTransport] Waiting for the application to finish sending data. [10:01:39 DBG][Microsoft.AspNetCore.Http.Connections.Internal.Transports.WebSocketsTransport] Socket closed. [10:01:39 DBG][Microsoft.AspNetCore.Http.Connections.Internal.Transports.WebSocketsTransport] Socket closed. [10:01:39 DBG][Microsoft.AspNetCore.SignalR.HubConnectionHandler] OnConnectedAsync ending. [10:01:39 DBG][Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager] Removing connection LjD7biz82bV7jGQ7V57BDg from the list of connections. [10:01:39 INF][Microsoft.AspNetCore.Hosting.Diagnostics] Request starting HTTP/2 POST https://jarvis-uniquehost.codewrecks.com/chat/negotiate?negotiateVersion=1 - null 0 <---- new connection comes in — Reply to this email directly, view it on GitHub <#58947 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AACXREOKKHSQXUZCW63WA7T2FHEQ7AVCNFSM6AAAAABRYTYVNCVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDKMZZGYZDKNRSG4> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[noelex]

I'm also facing this issue after upgrading to .NET 9.0, but with gRPC server streaming calls. The shutdown of the server application will be blocked if there's any active server streaming call when the shutdown is initiated.

Even if I register to the IHostApplicationLifetime.ApplicationStopping signal in the streaming method and abort the method when shutdown is requested, the shutdown will still be blocked for about 30 seconds.

My workaround for this is to block the shutdown until all ongoing requests are finished, so that ASP.NET Core can start shutdown without being blocked by the streaming call:

internal interface IShutdownSignal
{
    void AddBlocker();
    void RemoveBlocker();
    CancellationToken ApplicationStopping { get; }
}

sealed class ShutdownSignal : IShutdownSignal, IDisposable
{
    private readonly CancellationTokenSource _cts = new();
    private readonly SemaphoreSlim _sem = new(1, 1);

    private long _blockers;

    public ShutdownSignal(IHostApplicationLifetime lifetime)
    {
        _logger = logger;
        lifetime.ApplicationStopping.Register(static (state) =>
        {
            var self = (ShutdownSignal)state!;
            self._cts.Cancel();
            self._sem.Wait();
        }, this);
    }

    public CancellationToken ApplicationStopping => _cts.Token;

    public void AddBlocker()
    {
        if (Interlocked.Increment(ref _blockers) == 1)
        {
            _sem.Wait();
        }
    }

    public void RemoveBlocker()
    {
        if (Interlocked.Decrement(ref _blockers) == 0)
        {
            _sem.Release();
        }
    }

    public void Dispose()
    {
        _cts.Dispose();
        _sem.Dispose();
    }
}

builder.Services.AddSingleton<IShutdownSignal, ShutdownSignal>();

await using var app = builder.Build();

var ss = app.Services.GetRequiredService<IShutdownSignal>();
app.Use(async (context, next) =>
{
    try
    {
        ss.AddBlocker();
        await next(context);
    }
    finally
    {
        ss.RemoveBlocker();
    }
});

private readonly IShutdownSignal _signal;

public override async Task ServerStream(RequestMessage request, IServerStreamWriter<ResponseMessage> responseStream, ServerCallContext context)
{
    using var cts = CancellationTokenSource.CreateLinkedTokenSource(context.CancellationToken, _signal.ApplicationStopping);
    await ServerStreamImpl(request, response, cts.Token);
}