A backend worker died under load after a notifying POST (blocking calls in async handlers?) #841

Closed
opened 2026-09-26 14:38:45 +00:00 by claude-bot · 7 comments
Collaborator

Seen twice during lane 7's journey runs (#733) on a loaded machine, where another stack was using about 2 GB of Docker's 7 GB. A backend worker died ("Child process died", then an nginx 502) right after a POST that notifies: a discussion reply, and a session confirm.

Uvicorn 0.52's 5-second worker health check killed a worker whose event loop had blocked. The suspicion is synchronous Celery .delay() or Redis calls made inside async request handlers on the notify path. Under load, these block the loop past the health-check window.

A related symptom: J1's keyboard project began losing an Enter while a page was still arriving, 2 of 5 runs after lane 7, where it had been 6 of 6 before. The test now waits for the heading, which may be hiding an app-side race.

To do:

  • find blocking calls on async paths: notify, enqueue, and Redis publishes;
  • move them off the loop, with run_in_threadpool or an async client;
  • add a test or a load harness that catches a blocked loop.

Refs #733, #726.

Seen twice during lane 7's journey runs (#733) on a loaded machine, where another stack was using about 2 GB of Docker's 7 GB. A backend worker died ("Child process died", then an nginx 502) right after a POST that notifies: a discussion reply, and a session confirm. Uvicorn 0.52's 5-second worker health check killed a worker whose event loop had blocked. The suspicion is synchronous Celery `.delay()` or Redis calls made inside async request handlers on the notify path. Under load, these block the loop past the health-check window. **A related symptom:** J1's keyboard project began losing an Enter while a page was still arriving, 2 of 5 runs after lane 7, where it had been 6 of 6 before. The test now waits for the heading, which may be hiding an app-side race. **To do:** - find blocking calls on async paths: notify, `enqueue`, and Redis publishes; - move them off the loop, with `run_in_threadpool` or an async client; - add a test or a load harness that catches a blocked loop. Refs #733, #726.
Author
Collaborator

Seen again (2026-09-26), in J4 phone's Notes step during lane 7's integration run. Three session-page requests all came back 502 at the same moment, after about 5.5 s. That matches a worker death. Backend memory in the next run was sampled at about 345–352 MiB of the container's 512 MiB limit, so running out of memory is also possible, alongside the 5 s health check. The final run, with nothing else on Docker, was green.

**Seen again (2026-09-26),** in J4 phone's Notes step during lane 7's integration run. Three session-page requests all came back 502 at the same moment, after about 5.5 s. That matches a worker death. Backend memory in the next run was sampled at about 345–352 MiB of the container's 512 MiB limit, so running out of memory is also possible, alongside the 5 s health check. The final run, with nothing else on Docker, was green.
Author
Collaborator

Picking this up (2026-09-26) on fix/841-blocking-loop. Evidence first:

  • uvicorn's health-check mechanics;
  • an inventory of blocking calls on async paths;
  • a repro with a slow or paused Redis.

Then a single off-loop helper for Celery publishes and sync Redis, plus a regression guard.

Picking this up (2026-09-26) on `fix/841-blocking-loop`. Evidence first: - uvicorn's health-check mechanics; - an inventory of blocking calls on async paths; - a repro with a slow or paused Redis. Then a single off-loop helper for Celery publishes and sync Redis, plus a regression guard.
Author
Collaborator

Findings (2026-09-26). The fix for the real blocking is in #850; the worker kills are still unexplained.

1. A blocked loop can't trip uvicorn's health check.

  • In uvicorn 0.52.4 (supervisors/multiprocess.py), the health-check pong is answered by a separate thread (always_pong), not the event loop. The parent polls each worker with a 5 s timeout and logs "Child process [pid] died" when it kills one. That same line is logged for any death.
  • Two experiments under --workers 2:
    • time.sleep(12) in an async def freezes the loop but releases the GIL. It was not killed.
    • A single C call holding the GIL for more than 5 s was killed at 5.17 s, and nginx showed a 502.
  • The real enqueue path with Redis paused froze a worker for 26 s with no kill, because socket waits release the GIL.
  • So: sync publishes froze workers (fixed in #850), but they didn't cause the "Child process died" events.

2. The best hypothesis for the kills (medium confidence, not reproduced): memory stalls in the Docker VM.

  • The ~5.5 s 502 timing matches a health-check kill, which needs the whole process unscheduled or the GIL held for more than 5 s.
  • There was no kernel OOM kill: oom_kill 0 since boot.
  • The VM has heavy swap and memory-pressure history:
    • about 5.5 GB swapped out;
    • 2M major faults;
    • PSI memory full at 657 s.
  • A worker thrashing on page-ins while holding the GIL, e.g. during GC, fits that, and it also fits "the unloaded run was green".
  • A proper repro needs VM-wide contention, which would have hit another agent's journey stack.

Follow-ups, not done:

  • e2e: UVICORN_TIMEOUT_WORKER_HEALTHCHECK=15 and/or more mem_limit for the backend (it's 512m). Sample docker stats and /proc/pressure/memory during a journeys run to confirm.
  • Async Redis clients (app/redis_pool.py, the ad-hoc aioredis.from_url calls) have no socket timeouts. A paused Redis hangs that request indefinitely (not the loop).
  • notify() could stop enqueueing further recipients after the first broker failure. Each one still costs up to ~8 s during an outage, now off the loop.
  • J1's lost Enter: a frozen worker can lengthen "page still arriving", but it can't drop a keypress. Any race is frontend-side.

Leaving this open for the kill hypothesis and the follow-ups.

**Findings (2026-09-26). The fix for the real blocking is in #850; the worker kills are still unexplained.** **1. A blocked loop can't trip uvicorn's health check.** - In uvicorn 0.52.4 (`supervisors/multiprocess.py`), the health-check pong is answered by a **separate thread** (`always_pong`), not the event loop. The parent polls each worker with a 5 s timeout and logs "Child process [pid] died" when it kills one. That same line is logged for any death. - Two experiments under `--workers 2`: - `time.sleep(12)` in an `async def` freezes the loop but releases the GIL. It was **not** killed. - A single C call holding the GIL for more than 5 s **was** killed at 5.17 s, and nginx showed a 502. - The real enqueue path with Redis paused froze a worker for 26 s with **no** kill, because socket waits release the GIL. - **So:** sync publishes froze workers (fixed in #850), but they didn't cause the "Child process died" events. **2. The best hypothesis for the kills (medium confidence, not reproduced): memory stalls in the Docker VM.** - The ~5.5 s 502 timing matches a health-check kill, which needs the whole process unscheduled or the GIL held for more than 5 s. - There was no kernel OOM kill: `oom_kill 0` since boot. - The VM has heavy swap and memory-pressure history: - about 5.5 GB swapped out; - 2M major faults; - PSI memory `full` at 657 s. - A worker thrashing on page-ins while holding the GIL, e.g. during GC, fits that, and it also fits "the unloaded run was green". - A proper repro needs VM-wide contention, which would have hit another agent's journey stack. **Follow-ups, not done:** - **e2e:** `UVICORN_TIMEOUT_WORKER_HEALTHCHECK=15` and/or more `mem_limit` for the backend (it's 512m). Sample `docker stats` and `/proc/pressure/memory` during a journeys run to confirm. - **Async Redis clients** (`app/redis_pool.py`, the ad-hoc `aioredis.from_url` calls) have no socket timeouts. A paused Redis hangs that request indefinitely (not the loop). - **`notify()`** could stop enqueueing further recipients after the first broker failure. Each one still costs up to ~8 s during an outage, now off the loop. - **J1's lost Enter:** a frozen worker can lengthen "page still arriving", but it can't drop a keypress. Any race is frontend-side. Leaving this open for the kill hypothesis and the follow-ups.
Author
Collaborator

Picking up two of the follow-ups (1 Oct), on fix/841-redis-timeouts:

  1. Socket timeouts on the async Redis clients, from one place in app/redis_pool.py, with every ad-hoc from_url site converted. Blocking reads (pub/sub, stream consumers) keep no read timeout or a longer one, and a timeout takes the same path a Redis outage already does at each site.
  2. notify() stops enqueueing after the first broker failure in one call, while still writing every in-app row and without letting one bad payload stop the others.

Not doing, because they are the owner's call: the backend's mem_limit (512m in docker-compose.yml) and uvicorn's worker health-check timeout. The worker kills have not been seen since the CI runner's capacity was raised on 29 Sep; today's eight full CI runs were all green. If they stay away, the remaining hypothesis (memory stalls in a contended Docker VM) is an environment matter, and this issue can close when these two land.

Picking up two of the follow-ups (1 Oct), on `fix/841-redis-timeouts`: 1. **Socket timeouts on the async Redis clients**, from one place in `app/redis_pool.py`, with every ad-hoc `from_url` site converted. Blocking reads (pub/sub, stream consumers) keep no read timeout or a longer one, and a timeout takes the same path a Redis outage already does at each site. 2. **`notify()` stops enqueueing after the first broker failure** in one call, while still writing every in-app row and without letting one bad payload stop the others. Not doing, because they are the owner's call: the backend's `mem_limit` (512m in `docker-compose.yml`) and uvicorn's worker health-check timeout. The worker kills have not been seen since the CI runner's capacity was raised on 29 Sep; today's eight full CI runs were all green. If they stay away, the remaining hypothesis (memory stalls in a contended Docker VM) is an environment matter, and this issue can close when these two land.
Author
Collaborator

Correction to my last comment: "eight full CI runs, all green" overstated it. Today's count, checked: four PR runs green (#986, #987, #989, #992) and two of main's push runs green (after #987 and #989); main's run after #986 was cancelled when the next push superseded it, and one is running now. No worker deaths in any of them. The scheduled Dependency Audit did fail this morning, for unrelated reasons (#995).

Correction to my last comment: "eight full CI runs, all green" overstated it. Today's count, checked: four PR runs green (#986, #987, #989, #992) and two of main's push runs green (after #987 and #989); main's run after #986 was cancelled when the next push superseded it, and one is running now. No worker deaths in any of them. The scheduled Dependency Audit did fail this morning, for unrelated reasons (#995).
Author
Collaborator

The two code follow-ups are merged in #1002 (1 Oct, main c95fe032):

  • Redis clients have timeouts, held in one place (app/redis_pool.py): 2 s to connect, 10 s for a reply. Ten and not two because on an async client the wait is measured on the event loop, so a loop stall would otherwise fail session lookups. The live recording-status stream, the one blocking reader, keeps no read timeout. A guard test fails if a module builds a Redis client without them.
  • notify() stops enqueueing after the first broker connectivity failure in a call, still writes every in-app row, and doesn't let one bad payload stop the others.

What is left is the owner's: whether to raise the backend's mem_limit (512m in docker-compose.yml) or uvicorn's worker health-check timeout. The kills this issue was opened for haven't been seen since the CI runner's capacity was raised on 29 Sep. Leaving this open for that call.

The two code follow-ups are merged in #1002 (1 Oct, main c95fe032): - Redis clients have timeouts, held in one place (`app/redis_pool.py`): 2 s to connect, 10 s for a reply. Ten and not two because on an async client the wait is measured on the event loop, so a loop stall would otherwise fail session lookups. The live recording-status stream, the one blocking reader, keeps no read timeout. A guard test fails if a module builds a Redis client without them. - `notify()` stops enqueueing after the first broker connectivity failure in a call, still writes every in-app row, and doesn't let one bad payload stop the others. **What is left is the owner's:** whether to raise the backend's `mem_limit` (512m in `docker-compose.yml`) or uvicorn's worker health-check timeout. The kills this issue was opened for haven't been seen since the CI runner's capacity was raised on 29 Sep. Leaving this open for that call.
Author
Collaborator

Closing, by the owner's answer to Q160 (O35), 2026-10-05: "Close it: it has not come back."

  • The code follow-ups were merged in #1002.
  • The kills have not been seen since the runner's capacity was raised.
  • The backend's memory is now handled where it is actually tight:
    • the import moves to the worker (#1054, the owner's answer to Q153);
    • pictures are bounded before they are opened (#1074, #1087).

Reopen if a backend worker dies under load again.

**Closing, by the owner's answer to Q160 (O35), 2026-10-05: "Close it: it has not come back."** - The code follow-ups were merged in #1002. - The kills have not been seen since the runner's capacity was raised. - The backend's memory is now handled where it is actually tight: - the import moves to the worker (#1054, the owner's answer to Q153); - pictures are bounded before they are opened (#1074, #1087). Reopen if a backend worker dies under load again.
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
rbrooks/Quest-Board#841
No description provided.