On October 20, right after a deploy, I ran our queue-count command. The registry of started jobs in our main queue listed 27 jobs. No worker was running any of them. Every one had been killed by a deploy.
The next morning, a worker died while cleaning up after four jobs killed by that morning's deploy. It was idle, so no job was lost, and the pool started a new one. Following that crash led back to a line we thought we had fixed in May.
Some context. I run engineering at GoodBarber, an app platform. Our AI app builder writes the code of an app section from a description, and each generation runs as a job on a pool of RQ workers: rq 2.12, started with django-rq's rqworker-pool, with the tasks declared through django-tasks. It all runs in Docker Compose on two hosts, and a deploy takes the containers down, then brings the new image up. This post is about what those deploys were doing to the workers and the four fixes we shipped on October 22. The same deploy changed what the jobs are made of: our queue stopped carrying pickle.
PID 1 was bash
Our worker containers run a short shell script. Until October 22, it ended like this:
exec python manage.py rqworker-pool \
--job-class django_tasks_rq.Job \
--num-workers "${NUM_WORKERS}" \
${QUEUES} \
2>&1 | tee -a "${LOGFILE}"
The exec is there so that Python replaces the shell and receives the signals. In a pipeline, it can't. Bash runs each side of a pipe in a subshell, so the exec replaced a subshell, and the script's own bash stayed PID 1 of the container, waiting for both sides of the pipeline to finish.
docker stop sends SIGTERM to PID 1. Our bash ignored it and passed nothing on, so nothing happened until the 15 seconds of stop_grace_period ran out. Then Docker sent SIGKILL, and every process in the container died with it. Every stop ended that way, and so did every deploy.
The fix gives the log a tee of its own and lets Python take the script's place:
exec > >(tee -a "${LOGFILE}") 2>&1
exec python manage.py rqworker-pool \
--job-class django_tasks_rq.Job \
--num-workers "${NUM_WORKERS}" \
${QUEUES}
Each worker service in the compose file also got init: true:
command: ./deploy/common/rqworker.sh
init: true
stop_grace_period: 15s
With it, Docker's small init process (tini) is PID 1. It hands SIGTERM to its child, now the Python process, and it reaps orphans. Python as PID 1 wouldn't, and a pool does leave orphans: when a worker is killed, the work horse it forked for a job is handed to PID 1.
The history is the uncomfortable part. On May 28, we pushed two commits eleven minutes apart. The first cut the workers' grace period from 60 seconds to 15. Its message said deploys sat about 60 seconds in "Stopping" because the pool "stays blocked in Redis BLPOP until the grace expires, even when no jobs are in flight". The second removed a bash -c wrapper from the compose commands, with the right diagnosis: bash in PID 1 doesn't forward SIGTERM. It counted on each script's own exec to make the real process PID 1. The worker's exec sat in a pipeline, and as you'll see below, the web script had none. Bash moved from the wrapper to the shebang and stayed PID 1. The BLPOP explanation stayed in a comment above stop_grace_period for almost five months.
We never checked what PID 1 was after the change. It takes one command:
docker exec <container> cat /proc/1/comm
Before the fix, the answer on our workers was bash.
The new test doesn't take the script's word for it either. It runs the real script with a fake python and sends SIGTERM to the script. It passes only if the fake python has become the script's own process and exits on the signal with its own exit code. All three of its cases fail on the old script.
Now that SIGTERM arrives, the pool stops its workers: an idle worker exits at once, and its scheduler gives back its lock. A job still running when the 15 seconds end still dies in the SIGKILL, and our generations take between 85 and 500 seconds, so a deploy still kills every generation in flight.
The web container had the same bug, and uWSGI has its own idea of SIGTERM
The script of our web container started uWSGI without exec. Bash stayed PID 1 and ignored SIGTERM, so uWSGI was killed at the end of Compose's default 10-second stop timeout. The comment above it in the compose file described an exec the script didn't have.
Adding exec wasn't enough. We measured each variant in our image, with two 5-second requests in flight when docker stop arrived:
| Script | What docker stop got |
|---|---|
no exec (before) |
10.3 s, exit code 137: SIGKILL |
exec uwsgi |
uWSGI 2.0 treats SIGTERM as a "brutal reload": it reloaded its workers, cut both requests, and the stop still ended in SIGKILL |
exec and --die-on-term
|
2.4 s, exit code 0, both requests cut |
exec and --hook-master-start "unix_signal:15 gracefully_kill_them_all"
|
4.7 s, exit code 0, both requests got their 200 |
We kept the last line. A request that fits in the stop timeout is now served to the end, and a longer one still dies in the SIGKILL.
Its test had a trap of its own. The first version sent SIGTERM half a second after starting a 2-second request. Under load, the signal could land before the request had entered the application, and the test failed for nothing, or after the request had ended, and the test passed without ever stopping uWSGI mid-request. The test application now writes a file as soon as a request enters it, and the test waits for that file before it sends the signal.
The job nobody was running
A SIGKILL leaves traces in Redis. RQ keeps a registry of started jobs for each queue, stored under rq:wip:<queue>. When a worker dies in the middle of a job, the job's entry stays there with nothing behind it, and once the entry expires, a maintenance pass is supposed to mark the job as failed and run its failure callback.
That maintenance pass was what crashed. django-rq's rqworker-pool builds its queues with our job class, but RQ's WorkerPool, which it starts, passes each child only the queue names, and the child rebuilds the queues with RQ's base Job class, whatever --job-class says. The cleanup reads abandoned jobs with the queue's job class. Our jobs come from django-tasks, whose RQ backend registers a failure callback that reads job.task_result, an attribute only its own Job subclass has. Read as a base Job, every abandoned job made the callback raise:
AttributeError: 'Job' object has no attribute 'task_result'
The error escaped the worker's loop. The child died with the job still marked "started", and the queue's maintenance lock stayed taken for 15 minutes, until the next child ran the same cleanup and died on the same job. As long as those entries were there, we lost a worker about every quarter of an hour. The workers were idle each time, so no job was lost, and the pool replaced them. Our workaround was to delete the entries by hand after each deploy, with a ZREMRANGEBYSCORE on rq:wip:default.
The fix is a few lines in a mixin on our worker class. It gives the child's queues the worker's job class, as RQ does when a worker is handed queue names:
class PoolWorkerMixin:
def __init__(self, queues, *args, **kwargs):
super().__init__(queues, *args, **kwargs)
for queue in self.queues:
queue.job_class = self.job_class
An abandoned job is now failed the way RQ intends: its callback runs, and the job moves from the started registry to the failed one. The manual cleanup isn't needed anymore.
The scheduler that took almost 14 minutes to come back
The SIGKILL left one more thing behind. Every child of the pool starts RQ's scheduler, but only the one holding the queue's scheduler lock actually runs it. The lock is a Redis key, rq:scheduler-lock:<queue>, that lives 61 seconds and is refreshed every second. A scheduler killed along with its worker leaves the key to expire on its own.
RQ 2.12 tries the lock again when a worker starts, which right after a restart is too early since the dead lock is still there, and after that only during maintenance: every 10 minutes, which an idle worker checks between two waits of 405 seconds. We measured it in our image. After a docker kill and a restart, a job due a few seconds later left the scheduled registry 815 seconds after the kill. Retries and the jobs we chain on a timer all waited that long after any deploy that ended in SIGKILL, which until then meant every deploy.
The same mixin now tries the lock every 10 seconds while its worker has no scheduler running: between short waits when the worker is idle, and at the 30-second heartbeat of the job it watches when it's busy. It never takes a lock that a live scheduler holds, and it stops trying once the worker has been asked to stop, otherwise a busy worker could grab the lock during the grace period and leave it to the SIGKILL. With the patch, the same job left 64 seconds after the kill, 3 seconds after the dead lock expired. With the pool's only slot busy, it left after 67 seconds.
Then we changed what the jobs are made of
The four fixes went out on the morning of October 22. The same deploy turned on a change we had prepared a few days earlier: the queue stopped carrying pickle.
RQ serializes jobs with pickle by default, and unpickles a job before anything checks what it is. With pickle, anything that can write to the Redis a worker reads from can make that worker run code. JSON closes that. It can't be rolled out gradually, though: a job can only be read in the format it was written in, and a worker reads every job in its queues with a single serializer.
A few choices shaped the switch.
-
No fallback reader. Trying JSON first and pickle when it fails would have kept
pickle.loadson whatever Redis holds, which is exactly what we were removing. So the switch happens with the queues drained, and a job left in pickle fails without being read. -
The worker takes its serializer from the queue.
rqworkerandrqworker-poolhave a--serializeroption that defaults to pickle. With two settings that have to agree, every job fails the first time they don't, so our worker class reads the serializer from the queue's configuration and ignores the flag. The queues the pool rebuilds also come with RQ's default serializer, pickle, so the same class sets the configured one on each of them, as the mixin above does for the job class. A test builds a pool child exactly the way RQ does and checks both. -
A strict serializer instead of RQ's JSON one. RQ's JSON serializer silently turns integer keys into strings, because that's what
json.dumpsdoes. Ours refuses what JSON would change or can't carry: non-string keys, bytes, NaN, infinities, UUIDs, datetimes. Tuples are the one exception it lets through, as lists, since django-tasks already normalizes arguments that way. Its error names where the value is and its type, never the value itself. - A test that reads every enqueue site. It parses our code to find the 22 places in 15 files that enqueue a task, then round-trips each argument through JSON. A new task or a new call site fails the test until someone adds it.
Review caught the trap we had missed. When a scheduled job comes due, RQ writes it back, metadata included, as it moves it to the queue. A job scheduled in pickle before the switch has metadata that JSON can't read, which RQ keeps as raw bytes, and writing that back raises. The whole batch of due jobs is then never written, and the scheduler process dies, again at every restart. One leftover job would have held back every job due with it. Our scheduler now moves such jobs to the failed registry first, without reading them, before RQ queues the rest.
The stats command had a trap too. In RQ, counting a registry runs its cleanup first, and django-rq's rqstats builds its registries without the queue's serializer, so running it could unpickle whatever an expired entry holds. We count our queues with a small management command of our own that never reads a job.
The switch itself took a short checklist. Clear the abandoned entries, then wait until the count command reports every queue drained, with nothing queued, started, deferred or scheduled. Turn the setting on and build once. Deploy both hosts back to back, because between the two deploys, a job written in one format and read by a worker of the other fails without running. After the deploy, the queues reported the JSON serializer, and the first check of the logs found no DeserializationError and no traceback. Both hosts showed zero abandoned started jobs and zero overdue scheduled jobs.
A race in the deploy script
The deploy script had a race of its own. It runs docker compose down -v, which removes the volumes our two web containers share, and the next up -d recreates them empty. Docker copies the image's files into an empty named volume when a container that mounts it starts, and both containers started at the same moment. We first saw the failure on October 12 and wrote it down as unrelated to the code. At 15:19 on October 22, one of the two containers hit failed to mkdir …/_data/admin: file exists and up -d stopped there. The host ran without a single container for three minutes, until the deploy was launched again. Replayed locally with the old script, the race broke 2 deploys out of 20.
The fix starts one web container alone right after down -v, then the rest. Docker only copies into an empty volume, so the second container finds the files already there, and 60 local deploys out of 60 went through. It reached production on the morning of October 26. The deploy script runs git pull on its own repository, and bash keeps executing the copy of the script it opened before the pull. On the second host, that old copy hit the race one last time, and the run after it, on the new script, started all six containers.
What a deploy still breaks
A generation running during a deploy still dies. The pool now gets SIGTERM and waits for the job, but a generation needs minutes and the grace period is 15 seconds. A grace period longer than our slowest generation, around 500 seconds, would save it, and every docker stop could then take more than eight minutes.
What I'd check in your own setup
- Run
docker exec <container> cat /proc/1/common every container that runs jobs or serves requests. If it printsbashorsh,docker stopmost likely ends in SIGKILL there. Atrapin the script won't save it: bash runs a trap only after the foreground command returns, so the process would have to run in the background behind await.execis simpler. - Look for
execinside a pipeline.exec cmd | tee logdoesn't replace the shell. - After a deploy, count the entries in your started-job registries that no live worker is running. Each one is a job the deploy killed.
- If you run uWSGI 2.0, check what it does with SIGTERM before you rely on it to stop.
- If your deploy script updates itself with
git pull, its first run after a change is still the old script.
If your jobs run for minutes, what happens to them when you deploy: do you drain the queue first, or let them die and retry?
Top comments (8)
The exec inside a pipeline detail is easy to miss, and your test that checks the real script rather than trusting the script is a strong idea. For the long running generations that still die on deploy, would you rather drain the queue before a deploy or make those jobs resumable, given that they are paid model calls?
Thanks. Today it's neither: the deploy kills the generation, the user runs it again, and the calls the first run made are paid for nothing.
For deploys, I'd rather drain: a call that finishes is the only call we pay for once. Since the fix, the pool already stops taking jobs on SIGTERM and waits for the one it's running. The catch is our deploy script, which takes everything down before it brings anything up: a grace period longer than our slowest generation would keep the whole host down for up to eight minutes. Resuming I'd keep for the deaths we don't schedule, and a model call cut halfway leaves nothing to resume from.
Draining makes sense when a finished call is paid for only once, since a killed generation wastes the first attempt entirely. How do you decide the cutoff when a slow generation is close to finishing, given that a longer grace period could keep the whole host down for up to eight minutes?
The
cat /proc/1/commcheck is a great habit, we've been bitten by the same thing with shell entrypoints that wrap the real process. One thing we'd look at after this fix is the relationship between stop_grace_period and your longest job. With RQ's warm shutdown the worker finishes its current job, so a 15 second grace still kills anything that runs longer. Do you requeue interrupted jobs on startup, or rely on the job registry to surface them?Thanks, you're pointing at exactly the part we haven't fixed.
To your question: today nothing requeues them. Since the fix, RQ's own cleanup fails an abandoned job the way it should and runs its failure callback, so the started registry no longer fills up with jobs nobody runs. That keeps RQ's books straight, but it isn't what the user sees. Each running generation holds a Redis key with a 90-second expiry, and the worker keeps renewing it. When the page checks on a generation, if that key is gone and the generation is more than 180 seconds old, the generation is marked as failed. So a generation killed by a deploy shows up as failed within about three minutes while the page is open, and the user runs it again.
How do you handle yours: do you requeue on startup? Our jobs are paid model calls, so the part I'd want to be sure of is never running one twice.
The /proc/1/comm check is the best part. If it prints bash, the rest of the story writes itself.
Thanks! I'll be honest, this was the first time I'd run into this problem. I knew
execwas there to hand the signals to the real process, and I had never seen it quietly do nothing inside a pipeline. Working out why turned out to be the most interesting part of the whole fix.One follow-up if you run the check after a fix like ours: with
init: true, it doesn't printpythonanymore, it printsdocker-init, the tini that Docker bundles. The question then moves one level down: is the child of PID 1 your process, or a shell?docker top <container>shows that from the host, even in an image withoutps.Good point on docker-init. If /proc/1/comm prints that instead of python, the next check is what sits under it, and docker top shows that from the host.