Fetching both starter packs at once froze both backend workers; uvicorn killed them (prod, 4.6.0) #1239

New issue

Closed

opened 2026-10-26 23:29:18 +00:00 by claude-bot · 2 comments

claude-bot commented

2026-10-26 23:29:18 +00:00

Collaborator

What happened (prod, 4.6.0, 2026-10-26)

The owner fetched both starter packs from Admin → Content packs and got "import failed". Quest Board then stopped responding for about a minute and seemed to sign them out and back in.

Timeline (backend and worker logs, UTC)

23:25:07 Both packs were fetched from the v4.6.0 release in the same second: open5e-srd.qbpack (341 KB) and pf2e-orc.qbpack (2,145,955 B).
Right after: Waiting for child process [8] / Child process [8] died, and the same for [9]. No POST response was ever logged for either request.
23:25:34–39 New workers started.
23:25:41 The first GET /api/me after the restart returned 500: redis.exceptions.TimeoutError: Timeout connecting to server in get_session. A stack trace went to the log (the response body is the generic 500). This is the likely cause of the sign-out flicker.
23:26:21 The owner retried pf2e on its own. It was queued, and the worker finished at 23:26:54: status: active, 2 warnings, pack d5ba2049-….
The open5e pack has not been retried.

Cause

Memory is ruled out: the backend cgroup's memory.events shows max 0, oom 0 and oom_kill 0, and peak use was 470 MiB of 512 MiB.

The log lines are uvicorn 0.52.4's supervisor killing hung workers. multiprocess.py pings each worker, and a worker that misses timeout_worker_healthcheck (5 s) gets process.kill() and then "Child process … died". Both workers blocked their event loops at once on synchronous, CPU-bound pack work done inside async routes:

open5e (≤ SYNC_IMPORT_BYTES, 2 MiB) imports fully inside the request: import_from_path, parsing 998 records plus writes.
pf2e is just over the threshold, so it takes the queued path. That path still calls _prepare_system → read_meta → read_pack in the request, which parses the whole pack.

With both running at once, neither worker answered the 5 s ping, so both were killed and every in-flight request was dropped. Alone, the pf2e read finished in time.

Fix (to decide)

Keep CPU-bound pack parsing off the event loop: asyncio.to_thread, or have read_meta read only the manifest rather than every record. Alternatively, always queue URL and starter imports to the worker.
Look at why a failed /api/me (500) during a restart reads to the UI as signed out. A 5xx should not look like a 401.
Optionally, retry the Redis connection on the first session read after startup.
Add a test that a large sync import doesn't hold the loop, e.g. a loop-lag probe.

## What happened (prod, 4.6.0, 2026-10-26) The owner fetched both starter packs from Admin → Content packs and got "import failed". Quest Board then stopped responding for about a minute and seemed to sign them out and back in. ## Timeline (backend and worker logs, UTC) - **23:25:07** Both packs were fetched from the v4.6.0 release in the same second: `open5e-srd.qbpack` (341 KB) and `pf2e-orc.qbpack` (2,145,955 B). - **Right after:** `Waiting for child process [8]` / `Child process [8] died`, and the same for `[9]`. No POST response was ever logged for either request. - **23:25:34–39** New workers started. - **23:25:41** The first `GET /api/me` after the restart returned **500**: `redis.exceptions.TimeoutError: Timeout connecting to server` in `get_session`. A stack trace went to the log (the response body is the generic 500). This is the likely cause of the sign-out flicker. - **23:26:21** The owner retried pf2e on its own. It was queued, and the worker finished at 23:26:54: `status: active`, 2 warnings, pack `d5ba2049-…`. - **The open5e pack has not been retried.** ## Cause Memory is ruled out: the backend cgroup's `memory.events` shows `max 0`, `oom 0` and `oom_kill 0`, and peak use was 470 MiB of 512 MiB. The log lines are uvicorn 0.52.4's supervisor killing **hung** workers. `multiprocess.py` pings each worker, and a worker that misses `timeout_worker_healthcheck` (5 s) gets `process.kill()` and then "Child process … died". Both workers blocked their event loops at once on synchronous, CPU-bound pack work done inside `async` routes: - **open5e** (≤ `SYNC_IMPORT_BYTES`, 2 MiB) imports fully inside the request: `import_from_path`, parsing 998 records plus writes. - **pf2e** is just over the threshold, so it takes the queued path. That path still calls `_prepare_system` → `read_meta` → `read_pack` in the request, which parses the whole pack. With both running at once, neither worker answered the 5 s ping, so both were killed and every in-flight request was dropped. Alone, the pf2e read finished in time. ## Fix (to decide) 1. Keep CPU-bound pack parsing off the event loop: `asyncio.to_thread`, or have `read_meta` read only the manifest rather than every record. Alternatively, always queue URL and starter imports to the worker. 2. Look at why a failed `/api/me` (500) during a restart reads to the UI as signed out. A 5xx should not look like a 401. 3. Optionally, retry the Redis connection on the first session read after startup. 4. Add a test that a large sync import doesn't hold the loop, e.g. a loop-lag probe.

claude-bot commented

2026-10-26 23:31:03 +00:00

Author

Collaborator

Owner, 26 Oct 2026: both starter packs are now imported on prod (one at a time). The fix is logged here for later and is not scheduled; leave it until the owner picks it up.

claude-bot added this to the v4.7.0 - Browse the Rules milestone

2026-10-27 17:38:53 +00:00

claude-bot commented

2026-10-30 19:23:03 +00:00

Author

Collaborator

Picked up for v4.7.0 (2026-10-30), on branch fix/1239-pack-fetch-off-loop: no pack parsing on the event loop in any request path (asyncio.to_thread, or a manifest-only read_meta), and only a 401 from /api/me reads as signed out (not a 5xx or a network failure), with tests on both sides.

Picked up for v4.7.0 (2026-10-30), on branch `fix/1239-pack-fetch-off-loop`: no pack parsing on the event loop in any request path (`asyncio.to_thread`, or a manifest-only `read_meta`), and only a 401 from `/api/me` reads as signed out (not a 5xx or a network failure), with tests on both sides.