A queue worker that stops cleanly

A routine deploy at 14:20 restarted the queue workers, and one of them was eleven seconds into a job that charges a card and then creates an order. The charge had happened. The order had not. The customer noticed before we did.

The symptom

$ journalctl -u app-worker --since '14:19' --until '14:22'
14:20:02 Stopping app-worker...
14:20:02 app-worker[8814]: Processing: AppJobsCapturePayment
14:20:11 app-worker[8814]: State 'stop-sigterm' timed out. Killing.
14:20:11 app-worker[8814]: Main process exited, status=9/KILL

# nine seconds. the job takes up to forty.

$ mysql -Nse "SELECT COUNT(*) FROM charges c
  LEFT JOIN orders o ON o.charge_id = c.id
  WHERE o.id IS NULL AND c.created_at > '2021-02-01'"
3

Three orphaned charges over five weeks, all within seconds of a deployment. The pattern is only visible once you look for it, and nothing in the logs says “a job was killed” — the process simply stops existing.

Why it happens

A supervisor sends SIGTERM, waits a grace period, then sends SIGKILL. The default grace period is ninety seconds in systemd and ten in Docker, and neither is derived from anything about the workload — they are defaults chosen for processes that stop quickly.

A worker that does not handle SIGTERM at all dies at the first signal, mid-job, with no opportunity to finish. A worker that handles it but takes longer than the grace period dies at the second one, which cannot be caught.

The fix

The handler, which stops taking work

final class Worker
{
    private bool $shouldQuit = false;

    public function listenForSignals(): void
    {
        pcntl_async_signals(true);

        pcntl_signal(SIGTERM, fn () => $this->shouldQuit = true);
        pcntl_signal(SIGINT,  fn () => $this->shouldQuit = true);
    }

    public function daemon(): void
    {
        $this->listenForSignals();

        while (true) {
            if ($this->shouldQuit) {
                return;      // between jobs. never inside one.
            }

            $this->runNextJob();
        }
    }
}

pcntl_async_signals is what makes this work without a tick declaration and is the piece that people writing this by hand in PHP 5 remember as much harder. The handler sets a flag and does nothing else — doing work in a signal handler is how you get a worker that dies in a more interesting way.

The check happens between jobs rather than inside one, which is the whole design. A job that takes forty seconds will take up to forty more seconds to stop, and that is the number the grace period has to accommodate.

Making the grace period match the longest job

[Service]
ExecStart=/usr/bin/php /app/artisan queue:work --max-time=3600
KillSignal=SIGTERM
TimeoutStopSec=120        # > the longest job, with margin
Restart=always
RestartSec=5

services:
  worker:
    stop_signal: SIGTERM
    stop_grace_period: 120s

# and the job timeout must be BELOW it, or the worker is
# killed while a job it would have abandoned is running:
#   queue:work --timeout=90

Three numbers have to be ordered and they live in three files: the job timeout, the worker’s own stop timeout, and the supervisor’s grace period. Getting them out of order produces a worker killed while cleanly abandoning a job, which is the worst of both.

The longest job is a number somebody has to know, and on this system it was not documented — it was measured by querying the job durations for a week. That measurement is worth keeping as a metric, because the grace period silently becomes wrong when a job gets slower.

Idempotency, because the handler is not enough

A clean shutdown covers the deploy case and not the machine losing power, the container being evicted, or the process being killed by the OOM killer. The job has to be safe to run twice regardless.

public function handle(PaymentGateway $gateway): void
{
    // the gateway's own idempotency key, derived from
    // something stable — not from a random value
    $charge = $gateway->charge(
        $this->order->paymentToken(),
        $this->order->total(),
        idempotencyKey: "order-{$this->order->id}-capture",
    );

    // and the local half, in one transaction
    DB::transaction(function () use ($charge) {
        $this->order->markCaptured($charge->reference());
    });
}

Deriving the key from the order id rather than generating one means a retry sends the same key and the gateway returns the original charge. That is the fix for the actual incident; the shutdown handling reduces how often it is needed.

The gateway call and the local write are still two systems, so a crash between them leaves a charge with no local record — which the derived key makes recoverable rather than duplicated. A reconciliation job comparing gateway charges to local records is what closes the remaining gap, and it should exist regardless.

The deploy that waits

set -euo pipefail

# tell the workers to finish and exit
php artisan queue:restart

# and then actually wait, rather than assuming
for i in $(seq 1 24); do
  [ "$(pgrep -cf 'artisan queue:work' || true)" -eq 0 ] && exit 0
  sleep 5
done

echo 'workers did not stop within 120s' >&2; exit 1

queue:restart sets a flag in the cache that workers check between jobs, which is a cooperative shutdown that does not depend on signals reaching the right process. It is the mechanism that works when the worker is behind a process manager that would restart it immediately.

Waiting and failing loudly is what turns “the deploy probably finished the jobs” into a fact. A deploy that proceeds while workers are still running is the same incident with better intentions.

Verifying it worked

# a load test with a deploy in the middle
$ ./bin/enqueue-test-jobs 500 &
$ sleep 10 && ./deploy.sh
$ wait

$ mysql -Nse 'SELECT COUNT(*) FROM test_job_results'
500        # none lost, none duplicated

$ journalctl -u app-worker --since '10 min ago' | grep -c KILL
0

# and the orphan check, as a scheduled assertion
$ php artisan reconcile:charges --since='1 day'
0 charges without an order

Enqueuing five hundred jobs and deploying halfway through is the test that would have caught the original bug, and it is worth automating because the failure only appears under concurrency. Counting results rather than checking for errors is the assertion — a lost job produces no error anywhere.

The reconciliation command running on a schedule is the standing check. It found nothing after the fix and it found the original three when run against history, which is how the incident was scoped in the first place.

What this costs

A deploy that takes up to two minutes longer, every time, because it waits for the longest possible job. That is a real cost on a team deploying six times a day and it is the price of not truncating work. Splitting long jobs into shorter ones is the way to reduce it and is a larger change than it sounds.

The job timeout is now a real constraint rather than a number nobody looked at. A job that grows past it is killed cleanly instead of running forever, which is better and is still a failure — so the duration needs a metric and an alert before it becomes an incident. Three numbers in three files, kept in the right order by a comment, is the fragile part of the arrangement and the one most likely to break silently.