Queues, workers and the jobs that fail twice

A customer received the same dispatch notification four times. Worse, a different customer was charged twice for one order. Both came from the same misunderstanding: that a queue delivers each job once.

The symptom

[2016-11-08 14:02:11] queue.INFO: Processing: ChargeOrder {"order":8841,"attempt":1}
[2016-11-08 14:02:41] queue.ERROR: ChargeOrder failed: cURL timeout after 30s
[2016-11-08 14:03:11] queue.INFO: Processing: ChargeOrder {"order":8841,"attempt":2}
[2016-11-08 14:03:19] queue.INFO: Processed:  ChargeOrder {"order":8841}

# and at the gateway
14:02:39  charge 4900 TRY  order 8841  SUCCESS
14:03:18  charge 4900 TRY  order 8841  SUCCESS

The first attempt succeeded at the gateway and the response never arrived. From the worker’s point of view it failed; from the customer’s bank statement it did not.

Why it happens

Every queue worth using guarantees at-least-once delivery, and the phrase is a warning rather than a feature. The broker cannot distinguish a worker that died before doing the work from one that died after doing it and before acknowledging, so it must assume the former — which means the latter produces a duplicate.

Exactly-once delivery is not available at any price. The problem has to be solved in the consumer.

The fix

A natural key and a unique constraint

class ChargeOrder implements ShouldQueue
{
    public function handle(Gateway $gateway, Payments $payments)
    {
        // the database decides, not the application
        $attempt = $payments->beginOnce($this->orderId);

        if ($attempt === null) {
            return;   // already charged, or being charged. done.
        }

        $receipt = $gateway->charge($this->orderId, $this->cents, $attempt->idempotencyKey);

        $payments->complete($attempt, $receipt);
    }
}

CREATE TABLE payment_attempts (
  order_id         BIGINT UNSIGNED NOT NULL,
  idempotency_key  CHAR(36) NOT NULL,
  status           ENUM('pending','complete','failed') NOT NULL,
  PRIMARY KEY (order_id)          -- one attempt per order, enforced
) ENGINE=InnoDB;

The primary key does the work. beginOnce() is an INSERT that either succeeds or violates the constraint, and the violation is the answer rather than an error. Checking with a SELECT first reintroduces the race in a smaller window, which is the version that passes review and fails in production.

The idempotency key is passed to the gateway as well, so even a duplicate that gets past everything is rejected at the far end. Two independent mechanisms, because this is the one that costs money.

Backoff and the dead letter table

class ChargeOrder implements ShouldQueue
{
    public $tries = 5;

    public function backoff($attempt)
    {
        return random_int(0, (2 ** $attempt) * 10);   // jittered
    }

    public function failed(Exception $e)
    {
        // runs once, after the last attempt
        FailedCharge::record($this->orderId, $e);
        Ops::alert('charge exhausted retries', array('order' => $this->orderId));
    }
}

The jitter is not decoration. A gateway outage fails every queued charge at the same moment, and without it every retry lands simultaneously — so the recovering service is hit by the entire backlog at once and fails again.

failed() is where the job goes when the retries are exhausted, and its only job is to make sure a human finds out. A failed-jobs table nobody has alerted on is an archive of problems nobody knows about.

Workers that do not serve stale code

A long-running worker holds the application in memory, which is the reason it is fast and the reason it keeps running the code it booted with. A deploy that reloads PHP-FPM does nothing to it.

; /etc/supervisor/conf.d/queue.conf
[program:shop-queue]
command=php /var/www/shop/current/artisan queue:work --sleep=3 --tries=5 --max-jobs=1000
autorestart=true
numprocs=4
stopwaitsecs=60
user=deploy

# part of every deploy, after the symlink swap
$ php artisan queue:restart
$ sudo supervisorctl restart shop-queue:*

queue:restart signals workers to exit gracefully after the current job; supervisor starts them again on the new release. stopwaitsecs has to exceed the longest job or supervisor kills a worker mid-charge, which is exactly the scenario the idempotency work above exists to survive — but it should not be routine.

Verifying it worked

The assertion is that running a job twice produces one outcome, and it belongs in the test suite because this is not something to verify once.

public function testChargingTwiceChargesOnce()
{
    $gateway = $this->spy(Gateway::class);
    $job     = new ChargeOrder($this->order->id, 4900);

    $job->handle($gateway, app(Payments::class));
    $job->handle($gateway, app(Payments::class));   // the duplicate

    $gateway->shouldHaveReceived('charge')->once();
}

The queue that quietly stopped

Every failure so far has been a job that ran twice. The other one is a job that never ran at all, and it is harder to notice because there is nothing in the log — no error, no retry, just a queue getting longer.

# depth, and the age of the oldest job — the second one matters more
redis-cli LLEN queues:default
redis-cli LINDEX queues:default -1 | python -c 
  'import sys,json;print(json.load(sys.stdin)["pushedAt"])'

Depth alone is a poor signal: a queue with four thousand items that drains in a minute is healthy, and one with three items that have been there since Tuesday is not. Age of the oldest job is the number to alert on.

queue.default.depth        412      ok
queue.default.oldest_age   4s       ok
queue.charges.depth        3        ok
queue.charges.oldest_age   9h 41m   CRITICAL

The cause that afternoon was four supervisor workers all exited and not restarted, because stopwaitsecs was shorter than a job that had begun holding a lock — supervisor killed them, and the restart raced the lock and lost. Nothing in the application logged anything, because from its point of view nothing happened.

What this costs

Every job now needs a natural key, and some genuinely do not have one — “send the weekly digest” is not identified by anything in the payload. Those need a synthetic key generated at dispatch and carried in the job, which is more machinery than the job itself.

There is also a new operational surface: four supervisor processes per server, a failed-jobs table to triage, and a deploy step that can be forgotten. Forgetting queue:restart produces the worst class of bug available — old code running against a new schema, silently, for as long as nobody notices.