Postmortem: A supervisor Package Upgrade Left Two Horizons Running

Nobody deployed anything. No alert fired, no job failed, no log line was written. A routine supervisor package upgrade restarted supervisord, and when it came back a complete set of Horizon workers was still on the box — draining the same queues, with no supervisor above them and no process manager that knew they existed.

This is the writeup. The root cause is two defaults that are each defensible on their own and catastrophic together: Horizon's fast_termination, and the KillMode=process that Debian and Ubuntu ship in the supervisor systemd unit.

What happened#

The application runs Horizon under supervisord on a Debian host, in a completely ordinary arrangement: one [program:horizon] block, autorestart=true, a generous stopwaitsecs, and a handful of supervisors with a 60-second worker timeout.

The supervisor package was upgraded and that lead to restart of the service. The same is happening upon systemctl restart supervisor.

When it came back up, the queues were being worked by two populations of processes: the fresh tree supervisord had just started, and the previous generation's workers, still finishing the jobs they had been holding when the upgrade landed.

Impact#

Nothing failed, and that is the uncomfortable part. Every layer reported success: apt exited zero, systemd marked the unit active, supervisord logged stopped then spawned, and Horizon's dashboard showed a healthy master with the expected supervisors. The exposure is entirely in the overlap:

• Worker concurrency doubles for the duration. Whatever your maxProcesses figures were tuned against — CPU count, database connection pool, memory headroom — is briefly served by twice as many processes.
• Rate limits and third-party integrations see double the traffic. A queue deliberately pinned to a single worker so an upstream API is never called concurrently is, for that window, called concurrently. Limiter state keyed per worker does not save you here; there are simply two of everything.
• The orphans are uncommandable. Horizon routes pause, continue, terminate and stop-job through the owning supervisor's Redis command list. The orphans name a supervisor that no longer exists, so nobody consumes those commands. A stop-job issued from the dashboard against one of these workers sits in Redis forever while the job runs to completion, and the UI reports success.
• They run the previous release's code. Not a factor in this incident, since no deploy was involved — but the same mechanism during a deploy leaves old code executing against a freshly migrated schema.

In the normal case the overlap is self-limiting: the orphans were signalled, so each finishes its current job and exits. The window is your longest in-flight job. In the failure mode described in the second branch below, it is not self-limiting at all.

Root cause#

Two defaults, from two different projects, neither wrong in isolation.

1. fast_termination => true#

The whole feature is one method. When a supervisor is told to terminate it signals its workers, then decides whether to stay and watch:

// Laravel\Horizon\Supervisor::terminate()
$this->processPools->each(function ($pool) {
    $pool->processes()->each(function ($process) {
        $process->terminate();          // SIGTERM to each worker
    });
});

if ($this->shouldWait()) {
    while ($this->processPools->map->runningProcesses()->collapse()->count()) {
        sleep(1);                       // ...the drain loop
    }
}

$this->exit($status);

protected function shouldWait()
{
    return ! config('horizon.fast_termination') ||
        app(CacheFactory::class)->get('horizon:terminate:wait');
}

With the flag on, the drain loop is skipped and the supervisor exits immediately. Note what it does not do: it does not kill the workers, shorten their jobs, or make anything finish sooner. It only stops waiting.

fast_termination does not speed up shutdown. It declares shutdown finished while it is still happening.

That is the flag's documented purpose and it is a reasonable trade for deploys. The problem is that it makes a claim to the layer above — "the program has stopped" — that is not true, and that layer acts on it.

2. KillMode=process in the shipped systemd unit#

# /usr/lib/systemd/system/supervisor.service  (Debian/Ubuntu, supervisor 4.2.5)
[Service]
ExecStart=/usr/bin/supervisord -n -c /etc/supervisor/supervisord.conf
ExecStop=/usr/bin/supervisorctl $OPTIONS shutdown
ExecReload=/usr/bin/supervisorctl -c /etc/supervisor/supervisord.conf $OPTIONS reload
KillMode=process
Restart=on-failure
RestartSec=50s

KillMode decides which processes systemd signals when a unit stops. The default, control-group, signals every process in the unit's cgroup — which for this unit would include the entire Horizon tree. KillMode=process narrows that to the main process only: supervisord itself.

For supervisord that is a defensible choice. supervisord is a process manager with its own opinions about how and in what order its children should stop; having systemd fire SIGKILL into the cgroup underneath it would defeat every stopwaitsecs in the config. The setting exists so supervisord's shutdown logic is authoritative.

But it is only safe if supervisord's shutdown logic is correct. KillMode=process is systemd delegating cleanup to supervisord; fast_termination is Horizon lying to supervisord about whether cleanup finished. Put them together and there is no layer left that both knows the truth and has the authority to act on it.

systemd trusted supervisord to clean up. supervisord trusted Horizon's master to have cleaned up. The master had been told not to bother.

The worse branch: when ExecStop doesn't complete#

Everything above assumes ExecStop ran to completion. It does not always. If supervisorctl shutdown fails — the socket is gone, the config moved, the Python modules were mid-upgrade — or if the stop simply outlives TimeoutStopSec (systemd's default is 90 seconds, and the shipped unit does not override it), systemd escalates to SIGKILL against the main process. With KillMode=process, that SIGKILL goes to supervisord and to nothing else.

supervisord dies without stopping anything.

Two complete, fully functional Horizon installations, both registered in Redis, both processing the same queues on the same host. The old master has PPID 1 and no reason to ever stop: it was never asked to terminate, its supervisors are happily monitoring their workers, and its workers are happily draining jobs. It will still be there tomorrow, and every subsequent supervisor restart adds another one.

This branch is the one that produces permanently surviving workers, and it is the reason the fix cannot be "turn off fast_termination" alone. That change fixes the first branch. Only the systemd side fixes this one.

Why none of our safeguards fired#

stopwaitsecs=3600 never engaged#

This is the setting everyone reaches for, and it was already set to an hour. It did nothing, because stopwaitsecs is how long supervisord waits before resorting to SIGKILL — and supervisord was never waiting. The master genuinely exited, voluntarily, after two seconds. A generous stopwaitsecs protects against a master that needs more time than it is given. Our master needed less time than it should have taken.

horizon:purge was not scheduled#

Horizon ships a reconciler for precisely this class of problem, and we were not running it. That is the single largest process failure in this incident, and it gets its own section below, because using it correctly requires understanding what it can and cannot see.

Remediation#

Four changes, in the order they matter.

1. 'fast_termination' => false#

// config/horizon.php
'fast_termination' => false,

This is what closes the first branch. With stopwaitsecs=3600 already in place, supervisord will now wait out the drain instead of being told it has finished. The stop takes as long as the longest in-flight job and the worker count never exceeds what was provisioned.

2. A systemd drop-in for the supervisor unit#

This is the change that closes the second branch, and it is the one we were missing entirely. Do not edit /usr/lib/systemd/system/supervisor.service — the next package upgrade will overwrite it, which is exactly the event we are hardening against. Ship a drop-in:

# /etc/systemd/system/supervisor.service.d/override.conf

[Service]
# The shipped unit sets KillMode=process, so systemd signals only supervisord
# and leaves every Horizon process in the cgroup running. "mixed" keeps the
# graceful part -- SIGTERM still goes to supervisord alone, so its own
# stopwaitsecs logic stays authoritative -- but escalates the final SIGKILL to
# the whole cgroup, so nothing survives the unit going away.
KillMode=mixed

# ExecStop is bounded by TimeoutStopSec, whose default is 90s. A Horizon drain
# is bounded by the worker timeout, so this must exceed it with room to spare;
# otherwise systemd SIGKILLs supervisord mid-drain and we are back to orphans.
TimeoutStopSec=300

$ systemctl daemon-reload
$ systemctl show supervisor -p KillMode -p TimeoutStopUSec
KillMode=mixed
TimeoutStopUSec=5min

KillMode=mixed is the right setting rather than control-group precisely because it preserves the reason the shipped unit chose process: the initial SIGTERM still goes to supervisord alone, so supervisord remains in charge of the graceful path and every stopwaitsecs in the config is still honoured. Only the last-resort SIGKILL — the point at which graceful shutdown has already failed and there is nothing left to protect — is widened to the whole cgroup.

TimeoutStopSec matters more than it looks. It is the ceiling on ExecStop, so with the default 90 seconds and a drain bounded by a 60-second worker timeout you are inside the limit — but not by much, and the margin shrinks every time someone raises a job's timeout. Setting it explicitly, above the worst-case drain, is what stops the first branch from silently degrading into the second.

3. Schedule the backstop#

// routes/console.php
Schedule::command('horizon:purge')->everyMinute();

Covered in full below.

The backstop, in detail#

horizon:purge is Horizon's reconciler for orphaned processes. It is genuinely good and we should have been running it. It is also narrower than its name suggests, and the difference between what it catches and what it misses is exactly the difference between the two branches of this incident. Worth understanding properly rather than scheduling and hoping.

How it decides what is an orphan#

The whole judgement is two set operations in ProcessInspector:

// Laravel\Horizon\ProcessInspector

public function current()
{
    return array_diff(
        $this->exec->run('pgrep -f [h]orizon'),        // every Horizon-looking pid
        $this->exec->run('pgrep -f horizon:purge')     // ...except this command itself
    );
}

public function monitoring()
{
    return collect(app(SupervisorRepository::class)->all())
        ->pluck('pid')                                             // registered supervisors
        ->pipe(function ($processes) {
            $processes->each(function ($process) use (&$processes) {
                $processes = $processes->merge($this->exec->run("pgrep -P {$process}"));
            });                                                    // ...and their children
            return $processes;
        })
        ->merge(Arr::pluck(app(MasterSupervisorRepository::class)->all(), 'pid'))
        ->all();                                                   // ...and registered masters
}

public function orphaned()
{
    return array_diff($this->current(), $this->monitoring());
}

In words: everything on the box that looks like Horizon, minus everything the Redis registry can account for. A process is an orphan if no registered supervisor claims it as a child and it is not a registered master. That is precisely the signature of our first branch — workers whose supervisor de-registered and exited — which is why purge would have caught it.

It works in two phases, and both matter#

// Laravel\Horizon\Console\PurgeCommand

public function purge($master, $signal = SIGTERM)
{
    $this->recordOrphans($master, $signal);          // phase 1

    $expired = $this->processes->orphanedFor(
        $master, $this->supervisors->longestActiveTimeout()
    );

    collect($expired)->each(function ($processId) use ($master, $signal) {
        $this->components->task("Process: $processId", function () use ($processId, $signal) {
            exec("kill -s {$signal} {$processId}");   // phase 2
        });

        $this->processes->forgetOrphans($master, [$processId]);
    });
}

Phase 1 records the current orphan set and signals it immediately. The recording goes into a Redis hash keyed by master name, using HSETNX so the first time a pid was seen as orphaned is preserved across sweeps, and HDELing any pid that is no longer orphaned:

// Laravel\Horizon\Repositories\RedisProcessRepository::orphaned()
$shouldRemove = array_diff($this->connection()->hkeys($key = "{$master}:orphans"), $processIds);

if (! empty($shouldRemove)) {
    $this->connection()->hdel($key, ...$shouldRemove);
}

$this->pipeline(function ($pipe) use ($key, $time, $processIds) {
    foreach ($processIds as $processId) {
        $pipe->hsetnx($key, $processId, $time);      // first observation wins
    }
});

Phase 2 is the escalation. It asks which pids have been on that list longer than longestActiveTimeout() — the maximum timeout across your registered supervisors, i.e. the longest a worker is allowed to spend on one job — and signals those again. The logic is that a worker given a polite SIGTERM should have finished its job and exited within its own timeout; one that has not is stuck, not busy.

The default signal is SIGTERM for both phases#

--signal defaults to SIGTERM and applies to both phases, which makes the escalation less of an escalation than it appears — a process that ignored the first SIGTERM will generally ignore the second. That matters more than it sounds, because a worker blocked in a syscall is exactly the case phase 2 exists for: PHP dispatches asynchronous signals between VM instructions, so a process parked in a blocking socket read never gets to run its handler. We measured one of these surviving 139 seconds against a 60-second job timeout, ignoring both SIGTERM and the worker's own SIGALRM.

If you want phase 2 to actually be terminal, say so — and understand that you are killing a job mid-flight:

Schedule::command('horizon:purge --signal=SIGKILL')->everyMinute();

We run the SIGTERM default and alert on the phase-2 output instead, on the grounds that a process that needs SIGKILL is a process we want to look at rather than silently discard. Either choice is defensible; drifting into one by not reading the flag is not.

Four things it cannot do#

It is a no-op when no master is registered. The command iterates registered master names and purges per-master:

foreach ($masters->names() as $master) {
    if (Str::startsWith($master, MasterSupervisor::basename())) {
        $this->purge($master, $signal);
    }
}

No registered master means the loop body never runs. That rules out the placement people reach for first — a pre-start deploy hook, "clean up before we bring Horizon back" — which is precisely when it does nothing. It has to run alongside a live Horizon, from the scheduler, which in turn means your cron entry for schedule:run has to be working. A silently broken scheduler makes this backstop silently absent.

It cannot see a duplicate tree. This is the important limitation and the reason it is a backstop rather than the fix. In the second branch, the old master and its supervisors are all still registered in Redis, so monitoring() accounts for every one of their workers and orphaned() comes back empty. Those processes are not orphans by this definition — they belong to a Horizon that should not exist. Purge is scoped to processes whose owner has disappeared, not to owners that are illegitimate.

The orphan clock resets whenever Horizon restarts. The hash is keyed {master-name}:orphans, and the master name carries that random token. A pid recorded under web-1-Vf68:orphans is invisible to a sweep running under web-1-YzD4. Phase 2's "has been orphaned for longer than the worker timeout" is therefore measured from the current master's lifetime, not the pid's — so a restart storm can keep resetting the escalation clock on a process that never dies.

pgrep -f [h]orizon matches on the whole command line. Anything with the string "horizon" in its arguments is a candidate for being signalled: a tail -f horizon.log, a script named horizon-deploy.sh, an editor with the config file open, a grep in someone's shell history loop. Only horizon:purge itself is explicitly excluded. On a shared box, or one where operators habitually tail the Horizon log, that is worth a moment's thought before scheduling it with --signal=SIGKILL.

Where it sits in the defence#

The honest summary: horizon:purge covers exactly one of the four, and it happens to be the one we hit first. Schedule it, but do not let it stand in for the configuration fixes — two of these rows have no backstop at all.

Detection#

The reason this ran undetected is that no individual signal was abnormal. What we watch now:

# Count the tree. Compare against what your provisioning actually declares.
pgrep -af 'artisan horizon' | wc -l

# The permanent-leak signature: more than one master token.
redis-cli --scan --pattern 'horizon:master:*'

# The orphan signature: a worker whose parent is init.
ps -eo pid,ppid,etime,cmd | awk '$2 == 1' | grep 'horizon:work'

# Which supervisor does each worker think it belongs to...
pgrep -af 'horizon:work' | grep -o 'supervisor=[^ ]*' | sort | uniq -c

# ...and do those supervisors still exist?
redis-cli --scan --pattern 'horizon:supervisor:*'

Two mismatches to alert on. A --supervisor= value on a running worker with no matching horizon:supervisor:* key is a temporary orphan. More than one distinct master token under horizon:master:* is the permanent leak, and it will not resolve on its own. Both are cheap to check on an interval and neither requires anything to have failed first.

What we took from it#

Package upgrades are deploys. Nothing in our deployment pipeline ran, nobody was on call for it, and the change was to a package we think of as inert infrastructure. Any package whose postinst restarts a service is a production change; unattended-upgrades makes it an unattended one.

A setting that is correct for one failure can be inert for another. stopwaitsecs=3600 was set deliberately, by someone who had thought about shutdown, and it protected against a real problem — a master that needs more time than it is given. It simply had no bearing on a master that took less time than it should have. Having thought about a class of failure is not the same as having covered the instance you get.

Check what the layer above yours believes. The whole incident is a chain of trust with one broken link: systemd trusted supervisord to clean up its children, supervisord trusted the master's exit to mean the program had stopped, and the master had been configured not to wait long enough to know. Each hand-off was reasonable. Nobody had written down what the layer above was assuming.

Reproduce before you fix. Our first hypothesis was the well-known shell-wrapped command problem, which we did not have. Building a container that reproduced the real timings took under an hour and turned a plausible story into a measured one — including the discovery of the second, permanent branch, which we would not have found by reasoning and which the first fix alone would not have closed.

If you want the mechanics of Horizon's shutdown cascade in more depth, the troubleshooting guide covers the process tree and the signals that move through it. If your queues are backing up rather than duplicating, that is usually a balancing problem instead. And Skyline's per-queue pausing and dashboard operations exist partly so that routine interventions do not require bouncing the process tree at all — the safest supervisor restart is the one you did not need.