Wolverine instance graceful shutdown

[AlexandreBossard]

Is your feature request related to a problem? Please describe.

When using container orchestration (like k8s, cloud-run, aspire, etc) during version roll-out deployment, new instances are spun-out while the old ones are gracefully shut down.

When handling HTTP requests, traffic is routed to the new instances while inflight requests have grace period to complete until they are forcefully interrupted.

We would like to know how wolverine is supposed to handle shutdown request. The only piece of doc we found is lacking the intended process followed by a sunsetting wolverine instances, especially regarding in flight and long running messages. Also, are CancellationTokens passed to handlers leveraged or not ? We have not found any occurrences of IHostApplicationLifetime.ApplicationStopping in the wolverine code base.

Describe the solution you'd like

Documentation of what is supposed to happen, guarantees wolverine provides, and/or the steps an implementer should take to achieve a graceful shutdown.

For the process itself, we expect the graceful shutdown process to be something as the following:

• On receiving SIGTERM, stop pulling messages from the transport inbox
• Let the inflight handlers complete
• After a configurable timeout, abort all remaining handlers
• Release wolverine node messages assignation (set it to zero)
• Flush the outbox to the transport
• Dies

This should guarantees smooth instance sunsetting, and no messages lost nor stale.

Describe alternatives you've considered

None, N/A.

Additional context

The ASP.Net documentation on graceful shutdown has lot of good information and examples.

[jeremydmiller]

@AlexandreBossard I'll take a longer look at this, but Wolverine is already trying to do every single thing you listed.

Except that Wolverine is depending on IHost.StopAsync() being called. That's something to look at I guess.

[AlexandreBossard]

Here my very simplified and very contrived example:

Program.cs

using JasperFx;
using Services;
using Wolverine;
using Wolverine.Postgresql;

var builder = WebApplication.CreateBuilder(args);
builder.Services.AddWolverine(opts =>
{
    opts.Policies.UseDurableLocalQueues();
    var pgsqlPersistance = opts.PersistMessagesWithPostgresql(
        builder.Configuration.GetConnectionString("SolidDB")!
    );
});
builder.Host.ConfigureHostOptions(opts => opts.ShutdownTimeout = TimeSpan.FromSeconds(5));

builder.Services.AddHostedService<LifetimeWatcher>();
builder.Services.AddLogging();

var app = builder.Build();
return await app.RunJasperFxCommands(args);

BackgroundTask.cs

using JasperFx.Core;
using Wolverine;

namespace Services;

public sealed record Ping(int Number);

public static class PingHandler
{
    public static void Handle(Ping ping, ILogger logger, CancellationToken cancellationToken)
    {
        logger.LogWarning(
            "Received Ping #{Number} with token cancellation {Token}",
            ping.Number,
            cancellationToken.IsCancellationRequested
        );
    }
}

internal sealed class LifetimeWatcher : BackgroundService
{
    private readonly ILogger logger;
    private readonly IHostApplicationLifetime applicationLifetime;
    private readonly IServiceProvider serviceProvider;

    public LifetimeWatcher(
        IHostApplicationLifetime applicationLifetime,
        ILogger<LifetimeWatcher> logger,
        IServiceProvider serviceProvider
    )
    {
        this.logger = logger;
        this.applicationLifetime = applicationLifetime;
        this.serviceProvider = serviceProvider;
    }

    protected override async Task ExecuteAsync(CancellationToken stoppingToken)
    {
        applicationLifetime.ApplicationStarted.Register(
            o =>
            {
                logger.LogError("[DEBUG] ApplicationStarted");
            },
            null
        );
        applicationLifetime.ApplicationStopping.Register(
            o =>
            {
                logger.LogError(
                    "[DEBUG] ApplicationStopping, with token cancellation {IsCancellationRequested}",
                    stoppingToken.IsCancellationRequested
                );
                // Thread.Sleep(5.Seconds());
            },
            null
        );
        applicationLifetime.ApplicationStopped.Register(
            o =>
            {
                logger.LogError(
                    "[DEBUG] ApplicationStopped, with token cancellation {IsCancellationRequested}",
                    stoppingToken.IsCancellationRequested
                );
            },
            null
        );

        using var timer = new PeriodicTimer(TimeSpan.FromSeconds(1));
        var counter = 0;

        try

        {
            do
            {
                await using var scope = serviceProvider.CreateAsyncScope();
                var bus = scope.ServiceProvider.GetRequiredService<IMessageBus>();
                await bus.SendAsync(new Ping(counter++));
            } while (await timer.WaitForNextTickAsync(applicationLifetime.ApplicationStopped));
        }
        catch (OperationCanceledException)
        {
            logger.LogWarning("[DEBUG] I'm dying {IsCancellationRequested}", stoppingToken.IsCancellationRequested);
            await Task.Delay(5.Seconds());
        }
    }
}

If you launch the following program you will see something akin to

[...]
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: http://localhost:5026
fail: Services.LifetimeWatcher[0]
      [DEBUG] ApplicationStarted
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: /Users/alex/workbox/staging/Solid
warn: Services.Ping[0]
      Received Ping #0 with token cancellation False
info: Services.Ping[104]
      Successfully processed message Services.Ping#08de7f75-48d7-4294-6edd-5b6eb2400000 from local://services.ping/
^Cfail: Services.LifetimeWatcher[0]
      [DEBUG] ApplicationStopping, with token cancellation False
info: Microsoft.Hosting.Lifetime[0]
      Application is shutting down...
warn: Services.Ping[0]
      Received Ping #1 with token cancellation False
info: Services.Ping[104]
      Successfully processed message Services.Ping#08de7f75-496e-6ed0-6edd-5b6eb2400000 from local://services.ping/
warn: Services.Ping[0]
      Received Ping #2 with token cancellation False
info: Services.Ping[104]
      Successfully processed message Services.Ping#08de7f75-4a07-145a-6edd-5b6eb2400000 from local://services.ping/
warn: Services.Ping[0]
      Received Ping #3 with token cancellation False
info: Services.Ping[104]
      Successfully processed message Services.Ping#08de7f75-4a9f-64a8-6edd-5b6eb2400000 from local://services.ping/
warn: Services.Ping[0]
      Received Ping #4 with token cancellation False
info: Services.Ping[104]
      Successfully processed message Services.Ping#08de7f75-4b37-e700-6edd-5b6eb2400000 from local://services.ping/
warn: Services.Ping[0]
      Received Ping #5 with token cancellation False
info: Services.Ping[104]
      Successfully processed message Services.Ping#08de7f75-4bd0-a5ee-6edd-5b6eb2400000 from local://services.ping/
info: Wolverine.Transports.ListeningAgent[0]
      Stopped message listener at stub://replies/
warn: Services.Ping[0]
      Received Ping #6 with token cancellation False
info: Services.Ping[104]
      Successfully processed message Services.Ping#08de7f75-4c69-1f7c-6edd-5b6eb2400000 from local://services.ping/
info: Wolverine.Transports.ListeningAgent[0]
      Stopped message listener at dbcontrol://5a9ee0ac-fd4b-4716-9a2d-9c6171a367d6/
info: Wolverine.Postgresql.PostgresqlMessageStore[0]
      Reassigned 1 incoming messages from 21 and endpoint at local://services.ping/ to any node in the durable inbox
warn: Services.LifetimeWatcher[0]
      [DEBUG] I'm dying True
fail: Services.LifetimeWatcher[0]
      [DEBUG] ApplicationStopped, with token cancellation True

Because of the builder.Host.ConfigureHostOptions(opts => opts.ShutdownTimeout = TimeSpan.FromSeconds(5));, the host delays the stopping mechanism, but the ApplicationStopping event is triggered by the ApplicationHost.

What we can see is that messages are emitted, which is normal here since we are not reacting to the cancellation token willingly. But we can see the message are still processed by wolverine. I would expect them to stay in the inbox and not be picked up as soon as the SIGTERM/ApplicationStopping event is triggered.

I understand the example is a bit misleading here because of the background task, but it is here to represent an external transport (RabbitMQ, postgres) submitting messages. I would expect wolverine to stop picking them up too and leaving them on the transport, as soon the shutdown process is launch.

[jeremydmiller]

@AlexandreBossard There's some follow up work coming. And regardless of that PR, I'll do another thorough manual review before pushing this later today or my evening