From 407d7b226f09d065f51ad99e8ba067ca6605439f Mon Sep 17 00:00:00 2001 From: zzstoatzz Date: Wed, 5 Aug 2026 03:24:59 -0500 Subject: [PATCH] =?UTF-8?q?docs:=20overnight=20=E2=80=94=20prod=20failure?= =?UTF-8?q?=20reproduced=20deterministically,=20root=20cause=20still=20ope?= =?UTF-8?q?n?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-Authored-By: Claude Fable 5 --- .../HANDOFF-2026-08-04-zio-backend.md | 79 +++++++++++++++++++ 1 file changed, 79 insertions(+) diff --git a/docs/handoffs/HANDOFF-2026-08-04-zio-backend.md b/docs/handoffs/HANDOFF-2026-08-04-zio-backend.md index b32b25f..7f7b181 100644 --- a/docs/handoffs/HANDOFF-2026-08-04-zio-backend.md +++ b/docs/handoffs/HANDOFF-2026-08-04-zio-backend.md @@ -319,3 +319,82 @@ themselves are not completing, so start there. the churn harness plus the new gauges surfaced it in 20 minutes. ## soak result for this candidate + +--- + +# 2026-08-05 overnight: the prod failure REPRODUCED (root cause still open) + +## the headline + +**The prod failure now reproduces deterministically on the test box, with +zero consumers, in minutes.** A fresh relay at ~1,700 upstream connections +starves its accept paths: `/metrics` on :3001 answers roughly **1 probe in +12** (3s timeout), :3000 likewise, while ingest stays healthy (`relay_seq` +advancing, hosts still connecting) and the loop thread sits at only ~50% CPU. +That is the 2026-08-04 prod signature — both ports mostly-deaf, process +alive, ingest continuing, scrapes intermittent with the occasional lone +success. + +This is the thing we did not have before: a failure we can trigger on +demand instead of waiting for prod. + +## ruled out, with evidence + +- **epoll watch exhaustion** — `max_user_watches` is 3,639,251. Off by three + orders of magnitude. +- **arm failures** — `zio_poller_arm_failures_total` stayed 0 throughout. + Nothing fails to register. +- **CPU saturation** — loop thread ~36–50%, not pegged. +- **consumer fan-out** — reproduced with ZERO consumers attached. +- **the fiber leak** — real (see below) but not causal; reproduction happens + with the leak fixed. + +## two real bugs found and fixed on the way + +1. **fibers stranded on closed fds** (zio, `71a66ba` + regression test + `41a83f1`). zio never overrode `netClose`; the kernel drops closed fds + from the epoll set without an event, so any fiber parked on one waited + forever — one leaked fiber per connection under churn, identified by the + new `zio_fiber_starts` histogram as the websocket server's per-connection + handler. The test fails (hangs) without the fix and passes with it. +2. **ready-queue starving the poller** (zio, `d6d77b7`). `step()` drained + the ready queue to empty and skipped `poller.wait()` whenever anything was + runnable, so a busy fiber population could stop io delivery entirely. Real + bug, and it matches the symptom shape — but measured A/B on the box it + only moved accept probes from **0/12 to 1/12**. It is not the main cause. + +## the open question (start here tomorrow) + +Why is the accept fiber serviced only ~once per 45s when the loop thread is +half idle and nothing fails to arm? + +Two possibilities, and they are distinguishable with one counter each: + +- **the listener's event is never delivered** → instrument `Epoll.wait` to + count events delivered per token/fd, or specifically for the listener fds. +- **the event is delivered but the fiber waits in the ready queue** → + instrument the accept fiber's wakeups (count + timestamp of last wake, + exported as a gauge). + +That single discriminator decides between a poller-delivery bug and a +scheduler-fairness bug, and neither is guesswork once the counter exists. + +Worth a look while there: `max_batch` is 256 against ~1,800 armed fds, and +`Epoll.wait` computes `cap = min(out.len / 2, raw.len)`. Whether the kernel's +ready-list ordering can starve a rarely-ready fd (the listener) behind +constantly-ready ones is untested. + +## caveat on the starvation fix + +`d6d77b7` also made the startup ramp visibly slower (~575 conns at 4 min vs +~1,700 before). The always-poll-with-zero-timeout path may be spinning. It +should be measured properly, and possibly reworked to poll with a short +non-zero timeout, before it goes anywhere near prod. + +## bottom line for the canary decision + +Do **not** ship the canary yet. The failure prod hit is now reproducible and +still unexplained; two contributing bugs are fixed but the primary cause is +not. The instrumentation, the forensics script, and the reproduction harness +(`/root/repro.py` pattern: hold N consumers, probe a NEW connection every +20s) are all in place to finish this quickly with a rested head. -- 2.51.2