diff --git a/docs/canary1-failure-2026-04-09.md b/docs/canary1-failure-2026-04-09.md new file mode 100644 index 0000000..0b416e4 --- /dev/null +++ b/docs/canary1-failure-2026-04-09.md @@ -0,0 +1,174 @@ +# canary 1 (b6a52a0) failure report — 2026-04-09 + +operator report for the zlay engineer. canary 1 was `b91382b + 1eec324` +(FrameWork.hostname UAF fix). diagnostic question: does adding ONLY +the UAF fix to the running `zat21-b91382b` reintroduce the HTTP / delivery +failure seen on bbba92c / 795cc41 / 4f3d1d4? + +## headline + +**canary 1 failed at T+40 min with a new failure shape, distinct from +both the HTTP-fiber-hang we were hunting and from any of the 04-09 +failure modes i have documented previously.** + +| aspect | broken 04-09 pods (bbba92c / 795cc41 / 4f3d1d4) | canary 1 at T+40 min | +|---|---|---| +| pod `Ready` condition | flips to `False`, service endpoints emptied | stays `True`, pod in endpoints | +| external `/_health` | timeout, ingress returns 503 | **200→500 in 0.3s** with body `{"status":"error","msg":"database unavailable"}` | +| HTTP response latency | hangs past 10s | **fast** specific errors | +| thread state (`/proc/1/task`) | not captured during failure on broken pods | **47 threads, 2 R / 45 S, 0 D-state** (same as healthy) | +| listen socket accept queues (`/proc/net/tcp`) | not captured | **clean, rx=0** | +| `frames_received` from upstream | healthy | **healthy, ~400 fps** | +| `frames_broadcast` to connected consumer | frozen ~0 fps | **frozen, 0 frames in 15s** | +| `pool_queued_bytes` | unknown | **0 → 63.86 MiB** during the ~5 min preceding failure | +| `persist_order_spins_total` rate | unknown | **~18k/sec at T+32 → ~33M/sec at T+40** (≈2000× spike) | +| `host_authority` reject rate | 99.5% cumulative | **99.1% cumulative** + new rejects continuing at ~5/sec | +| postgres pod itself | not the suspect | **healthy — direct `psql` works instantly** | + +this is NOT an HTTP fiber hang. HTTP is answering fast with +application-specific errors. threads are not stuck in uninterruptible +I/O. accept queues are empty. the broadcaster is not getting scheduled +because something upstream of it is wedged — most consistent with +**DbRequestQueue deadlock or saturation**. + +## what i think is happening (hypothesis, not proven) + +the logs just before failure were flooded with this pattern: + +``` +info(relay): account did:plc:zbvmafs7jjq3teplzcfbezg6 (uid=241368) host mismatch: current=1316 new=97392 +info(relay): host user.eurosky.social: dropping event, host authority failed uid=241368 did=did:plc:zbvmafs7jjq3teplzcfbezg6 +``` + +the key observation: `current=1316 new=97392`. `current` is a small, +valid host id. `new` is a very large host id. this is **not** the +`host_id=0` orphan case from the DB audit. these are accounts where +zlay's `account.host_id` points at a real, valid host row, but the +DID doc resolves to a *different* valid host. + +the same ~5-10 UIDs (241368, 478114, 608246, 54156, 676874, ...) +appear in log lines over and over. every event from those accounts +triggers a `host_changed`, runs `resolveHostAuthority`, gets a +mismatch, drops the event. the account's `host_id` field in the DB +is never updated to the new value, so the next event from the same +account does the same dance. + +if `resolveHostAuthority` enqueues an UPDATE through `DbRequestQueue` +on a hit-the-new-host resolution, and the queue gets wedged (either +by pure rate of incoming work or by a deadlock), then: + +1. the UPDATE never commits +2. `account.host_id` stays stale +3. the same 5-10 accounts keep hitting the path +4. `host_authority_checks_total` and `host_authority_reject` climb + together at the same rate +5. the broadcaster's frame-release path, which also goes through + DbRequestQueue (i think — for cursor persist?), starves +6. `pool_queued_bytes` climbs as pending frame work accumulates +7. something spinning on a persist-order mutex explodes + `persist_order_spins_total` from ~18k/sec to ~33M/sec (seen in + metrics; don't yet know WHICH mutex or WHICH code path) +8. `/_health`'s DB probe times out waiting for DbRequestQueue, returns + its "database unavailable" error fast (this is not a timeout on + postgres — it's a timeout on the queue's processing) +9. connected firehose consumers receive 0 frames because the + broadcaster fiber is waiting on the same wedge + +**i'm not confident about step 7**. i have no attribution of which +persist-order mutex is spinning, and the memory notes don't define +the metric. if you can tell me which code path increments +`relay_persist_order_spins_total`, that probably points straight at +the wedge. + +## the two half-answers to the diagnostic question + +**"does 1eec324 reintroduce the delivery collapse?"** — inconclusive +but leans *somewhat yes*. canary 1 collapsed at T+40. the rollback +pod running the exact same code minus 1eec324 is currently at T+3h +and is still serving 270 fps to external consumers. BUT: + +- the rollback pod's `pool_queued_bytes` spiked to 20.7k in one + snapshot and dropped back to 0 in the next — it's a current-depth + gauge that oscillates under burst load, not a monotonic climb. + correction from an earlier wording. the gauge is mostly at 0 at + T+3h. the signal to watch is the canary 1 case where it jumped + to **63.86 MiB** and stayed there, 3 orders of magnitude above any + oscillation i've seen on the rollback pod. +- `persist_order_spins_total` rate on the rollback pod at T+3h is + ~33k/sec (vs canary 1's 33M/sec). 1000× lower. this may be the + most specific distinguishing signal between "functional" and + "wedged" that we've seen. +- i have not yet run the rollback pod long enough to rule out that + it too wedges eventually — just on a slower timescale. + +**"does 1eec324 reintroduce the host_authority 99% reject rate?"** — +**no.** the rollback pod at T+3h has `validation_failed{reason="host_authority"} = 127.3k / 128.5k checks = 99.1%`. this is the same +pattern as bbba92c-pre-workaround. the host_authority reject bug is +present on b91382b, i just never measured b91382b long enough to see +it. my earlier "b91382b predates the host_authority bug" claim from +the rollback doc was wrong — i was measuring at T+6 min with +`workers_count ≈ 700`, pre-ramp. + +so i'm retracting the part of the earlier rollback doc that pinned +the host_authority bug's introduction to the 04-06 → 04-07 window. +that half is wrong. the broadcaster delivery collapse introduction +window is STILL unclear — canary 1 data is suggestive that 1eec324 +makes it worse, but not conclusive. + +## what i am confident about + +- canary 1 failure at T+40 min is a real delivery-collapse event + reproducing in our current production setup, with thread/socket + evidence that distinguishes it from HTTP fiber hang +- the persist_order_spins rate discontinuity (33k/sec → 33M/sec) + within minutes of broadcaster wedge is a real signal and is the + best hang-detection counter we've seen +- the orphaned `account.host_id=0` bucket (239,422 accounts) is + real and distinct from the stale-valid-host-id pattern in the + canary 1 logs. two different DB states that both hit host_authority +- the rollback pod at T+3h is functional ENOUGH for evaluators + (270 fps external delivery) despite 99% host_authority reject, + because host_authority rejects are bounded (~10/sec) and most + events don't trigger the check at all (account cache hit) +- baseline `/proc` snapshots are valuable: 47 threads, 0 D, clean + accept queues is the healthy shape. future canary failures + should capture this same shape for comparison + +## what i want from you + +1. **an explanation of `relay_persist_order_spins_total`** — which + mutex, what code path, and whether 33M/sec is the "many + threads spinning because the owner is stuck in DB" shape i think + it is. +2. **confirmation of the DbRequestQueue deadlock-on-wedge hypothesis** + — does the health check's DB probe go through DbRequestQueue + too? if yes, then the fast 500 is consistent. if it's a separate + connection pool, my hypothesis is wrong and i need to look + elsewhere. +3. **guidance for canary 2**. i think the signal to add is per- + DbRequestQueue-operation timing or depth. if we can see the + queue depth climb and stall, we catch the wedge before it + propagates to the broadcaster. the `pool_queued_bytes` climb is + already a candidate signal but i'm not sure what "pool" it + measures (resolver pool? broadcast pool? frame worker pool?). +4. **a fix for the orphaned account.host_id=0 rows**. one-off + SQL to either delete or re-resolve those 239k accounts would + reduce cold-start host_authority pressure by ~4% independently + of any code change. not a root-cause fix, but cheap to land. + +## what i am doing on the operator side + +- running the rollback pod (`zat21-b91382b`) until you ship something + better. external evaluators can evaluate zlay from this state at + ~270 fps. +- actively monitoring via the new `scripts/zlay-probe` skill (see + `.claude/skills/zlay-diagnose/SKILL.md`). i will reach out if any + of the pressure signals (pool_queued_bytes, persist_order_spins + rate, D-state threads, accept queue non-zero) start climbing. +- NOT writing any zlay code. operator purview only. +- evidence snapshots saved at: + - `/tmp/canary1-healthy-{ss,ps}.txt` — T+2 baseline + - `/tmp/canary1-baseline.txt` — T+28 metrics + - `/tmp/canary1-fail-{ss,ps,logs,metrics}.txt` — T+40 failure + - `/tmp/canary1-db-audit.txt` — host table + orphan audit + - `/tmp/b91382b-3h-baseline-metrics.txt` — rollback at T+3h diff --git a/docs/ops-changelog.md b/docs/ops-changelog.md index b381e8c..11d7e9b 100644 --- a/docs/ops-changelog.md +++ b/docs/ops-changelog.md @@ -5,6 +5,890 @@ deployment decisions for both relays (indigo @ relay.waow.tech, zlay @ zlay.waow --- +## 2026-04-09 + +### zlay host_authority fix, crash loop, and probe workaround + +long day. three deploys, one rollback, one re-deploy with a k8s patch. +final state is stable but the root cause is still not identified. + +**1. diagnosis (morning).** investigation into why zlay sat at ~98.1% relay-eval +coverage while pulsar showed 54% exposed two problems. the pulsar gap turned +out to be the `ConsumerTooSlow` issue documented on 2026-04-01 — pulsar's +60-min window accumulated repeated kicks against the 8192-entry per-consumer +ring buffer (~33s of headroom at 250 fps). the relay-eval gap was a separate, +larger bug: `relay_validation_failed{reason="host_authority"}` was climbing +at ~10/sec, and cumulative failure rate was 99.54% (1,210,698 / 1,214,857 +lifetime). sampling log lines + manually resolving 15 of the rejected DIDs +against plc.directory showed 13/15 had DID docs whose PDS hostname exactly +matched the incoming host — zlay was dropping legitimate events. + +**2. ee4e368 — buffer fix + host_authority reject breakdown counters.** +bumped `Consumer.BUFFER_CAP` from 8192 → 65536 in `src/broadcaster.zig` (~4.4 +min of headroom at 250 fps instead of ~34s). split the single +`failed_host_authority` counter into six per-branch counters in +`src/validator.zig checkPdsHost`: +`relay_host_authority_reject{branch="parse_did|resolve|no_endpoint|bad_url|unknown_host|host_mismatch"}`. +48 minutes after deploy: 39,621 / 40,072 rejects in the `resolve` branch — +**100% of failures were in `resolver.resolve(parsed)` throwing on both +the first attempt and the retry.** no rejects in any other branch. +`sampleLogReject` was wired into the four `checkPdsHost` branches but NOT +into the resolve branch, so there were zero sampled warn lines — we knew +WHICH branch was failing but not WHY. the underlying error was swallowed +twice (`zat/transport.zig:70` → `error.RequestFailed` → +`zat/did_resolver.zig:98` → `error.DidResolutionFailed` → validator's catch +→ `.reject`), so no information made it to logs. + +**3. hypothesis (wrong, but led to a working workaround).** zlay git history +shows a pattern: `keep_alive` was disabled at one point (`3bddabd` — TLS +connection pool was eating ~3 GiB RSS), re-enabled (`d470580`) after the +`toArrayList` leak fix in zat v0.2.14, and the resolver pool of 4 `DidResolver` +instances was added in `1639565` (2026-03-18). then the zig 0.16 migration +landed in `9cc1ba3` (2026-04-05). host_authority failures became 100% from +that point on. framed this as "zig 0.16's `std.http.Client.fetch` keep-alive +handling doesn't recover from stale connections when a long-lived client sits +idle between calls" and asked the engineer to test keep_alive=false on the +pool. this framing was wrong — see section 6. + +**4. 584571a (build fail) → bbba92c (build fix).** engineer shipped +`keep_alive=false` on `host_resolvers` at `src/validator.zig:126` plus wired +`sampleLogReject` into the resolve and parse_did branches. first attempt +(584571a) failed to compile under `zig build` with +`src/validator.zig:591:21: error: error set is discarded` — `_ = err1;` is +not how zig 0.16 discards an error value; the outer `catch |err1|` capture +needs to not exist at all. `zig build test` didn't catch this because no +test referenced `resolveHostAuthority`, so lazy analysis skipped the function +body. `bbba92c` dropped the `|err1|` binding entirely. engineer added a rule: +for validator/subscriber/frame_worker changes, run `zig build` (host exe) +in addition to `zig build test` so the exe reference graph forces analysis. + +**5. bbba92c deployed and initially worked.** 14 minutes after deploy: +1,259 checks, 3 rejects total (2 `unknown_host` + 1 `host_mismatch` — all +legitimate policy drops), 0 `resolve` branch rejects. **reject rate +collapsed from 98.87% to 0.24%.** empirical workaround confirmed. + +**6. engineer's local repro falsified the hypothesis.** after shipping, the +engineer wrote a standalone repro: 1,624 calls × ReleaseFast/Debug × zig 3059 +and 3070 × serial/parallel × single-client/multi-client × 0-10s idle — all +green. **none of those dimensions could reproduce the failure.** the key +observation that surfaced: `resolveLoop` at `validator.zig:449` is still on +`keep_alive=true` and works fine in the same process, same zig, same kernel. + +**better hypothesis — no zig stdlib involved**: the pool (`validator.zig:65`, +`host_resolvers: [4]zat.DidResolver`) creates its 4 `DidResolver` instances +once at init (line 143) and **never recreates them**. `acquireHostResolver` / +`releaseHostResolver` (600, 612) just toggle availability atomics; no +rebuild on failure. `resolveHostAuthority` does two calls on the same +resolver, catches both, returns reject — it never destroys and re-inits +the slot. hypothesis: **one transient failure puts a resolver's http client +state into a bad condition (half-finished handshake, stale TLS session, +server-side close the client didn't notice), and because nothing ever +recreates the slot, it stays poisoned.** over minutes, all 4 slots +accumulate poison and every subsequent check fails twice in a row and +rejects. `keep_alive=false` fixes the symptom because the http client +doesn't reuse any state between calls — nothing to poison. + +`resolveLoop` likely "works" under keep_alive=true for a mundane reason: +it's a single-threaded worker that makes ONE call per DID and `continue`s +on any error, no spin-lock contention, no rapid-retry-on-same-client +pattern. if its resolver ever went bad, the cache would silently stop +growing — worth measuring `validator_cache_entries` across a long window +to confirm it's genuinely resilient and not just quietly broken too. + +**correction worth recording: I initially framed this as a "zig 0.16 +std.http.Client stale keep-alive" bug and asked for an upstream zig issue. +that framing was wrong — I was blaming the standard library for what is +almost certainly a missing-recovery-path in zlay's own pool code. the +proper fix is in `src/validator.zig`, not in zig stdlib: on any +`resolve()` failure in the pool, destroy and re-init the slot before +releasing it back. the workaround happened to fix the symptom but we now +have a fix and no root cause — the worst state to leave a bug in.** + +**7. bbba92c crash loop (afternoon).** ~9 hours after the bbba92c deploy the +pod had 25 container restarts. exit code 137 (SIGKILL), pattern: container +runs ~20 min, kubelet events show +`Container main failed liveness probe, will be restarted`, 549 readiness +probe timeouts and 265 liveness probe timeouts across the window, all +`context deadline exceeded`. cause: `keep_alive=false` means every +host_authority check does a fresh DNS + TCP + TLS + HTTPS round-trip to +plc.directory (~400-900ms per call). on a cold pod, 2,800 PDS subscribers +all reconnect concurrently and generate an `is_new` storm on the 4-slot +resolver pool. frame workers spin-blocking on `acquireHostResolver` starve +the HTTP server fiber, `/_healthz` misses its 5s probe timeout, kubelet +SIGKILLs after 10 consecutive failures (5 min), pod restarts, storm repeats. +infinite loop. **the old keep_alive=true pool was slow in a different way +but fit within the probe budget — the correctness workaround broke the +performance budget.** + +**8. rollback → reapply with probe patch.** rolled back to +`ReleaseFast-ee4e368` momentarily (brings back 100% host_authority reject +but kills the crash loop, relay goes back to ~98% relay-eval coverage). +then immediately patched the Deployment's liveness/readiness probes to +tolerate the cold-start storm and re-applied `ReleaseFast-bbba92c`: + +| field | old | new | +|---|---:|---:| +| liveness `initialDelaySeconds` | 30 | 300 | +| liveness `timeoutSeconds` | 5 | 15 | +| liveness `failureThreshold` | 10 | 20 | +| readiness `initialDelaySeconds` | 10 | 60 | +| readiness `timeoutSeconds` | 5 | 15 | +| readiness `failureThreshold` | 5 | 20 | + +this is a k8s Deployment config change, **not a code change** — same +`bbba92c` binary, same keep_alive=false workaround still active. + +**9. verification after reapply.** new pod stayed at 0 restarts through the +full 5-minute warmup window and beyond. at 6m21s uptime: + +| metric | value | +|---|---| +| `host_authority_checks_total` | 274 | +| `host_authority_reject{resolve}` | **0** | +| `host_authority_reject{unknown_host}` | 2 (legit policy drops) | +| mean host_authority latency | 356ms/check | +| `workers_count` | 1,060 (ramping toward ~2,800) | +| `frames_received` | 164k at ~413 fps | +| `frames_broadcast` | 76k (46% of received, consumer attached) | +| `slow_consumers_total` | 0 | +| `rss` | 716 MiB | + +### open items + +- **host_authority root cause still not identified.** current best guess: + pool's missing recovery path — a resolver slot gets into a bad state + once and stays there forever because nothing recreates it. proper fix + is in `src/validator.zig` pool code, not in zig stdlib. planned + production experiment: init 3 of 4 pool slots with `keep_alive=false` + (safe), 1 slot with `keep_alive=true` (broken path). captures + `@errorName` from the actual failure via the sampled warn log that + `bbba92c` wires up. small blast radius, fully reversible, NOT YET RUN. + also worth measuring: does `resolveLoop`'s resolver ever silently go + bad (cache fill stops growing)? if yes, the pool isn't unique and the + fix needs to touch both. + +- **workaround-on-a-workaround.** `keep_alive=false` costs ~350-900ms per + check. the 4-slot pool saturates under load. the probe relaxation is + not a fix — it's a band-aid over the performance consequence of the + correctness workaround. proper long-term fixes (any one of these): + 1. **add slot recovery** — destroy and re-init a resolver on any + `resolve()` failure before releasing it back to the pool. this is + the most direct fix and it's entirely in zlay code. + 2. bump pool size from 4 → 32+ so it can absorb reconnect storms + 3. make host_authority check async / bounded — don't block frame + workers on the hot path + 4. skip host_authority for the first N minutes of uptime (warmup grace) + +- **tight liveness probe**. the 5-minute initial delay means if the pod ever + genuinely hangs during startup, it takes 5 min before kubelet notices. + re-tighten once the pool recovery path is added and `keep_alive=true` + can be restored. + +- **stability dropouts (still open from 2026-04-08).** ~33% historical + dropout rate on relay-eval, suspension experiment showed some + correlation with the 4h reconnect cronjob but not all dropouts lined + up. worth re-evaluating now that the ConsumerTooSlow buffer is bumped — + possible that some of those "stability" drops were actually consumer + kicks on relay-eval's longer windows. + +commits: `ee4e368`, `584571a` (build fail), `bbba92c`, k8s deployment patch +(not a commit — lives in cluster state, should be captured in +`zlay/deploy/` if we want it persistent across helm re-installs). + +### probe relaxation committed to source; external review + 795cc41 bundle + +after the bbba92c crash loop was stabilized via the probe relaxation, did +three more things: + +**1. captured the probe settings in `zlay/deploy/zlay-values.yaml`** with a +NOTE block explaining why they're relaxed and what to check before tightening +again. this closes the "cluster-only probe patch" gap — a helm re-apply will +no longer revert to the old tight probes. + +**2. wrote `docs/zlay-external-review-2026-04-09.md`**: a comprehensive +write-up of both problems (resolver pool failure + HTTP fiber starvation), +what we measured, what the engineer's standalone repro ruled out, what we +explicitly don't know, and a code-pointer appendix. framed as a request for +external review rather than a "here's the fix" document. explicit about the +fact that we've been wrong about the bug's shape once already (the +"zig 0.16 stale keep-alive" framing that got falsified by the local repro). + +**3. engineer shipped `795cc41`** — a bundled PR addressing four items from +the review doc: + +- **cold-start per-host DB wait eliminated.** `spawnWorker` (`slurper.zig:535`) + was doing a blocking `DbRequestQueue` round-trip for + `getEffectiveAccountCount(host_id)` per host, ~2,770 round-trips during + cold start each yielding the spawn fiber. folded the `COALESCE + JOIN + + COUNT + GROUP BY` into the existing batch `listActiveHostsImpl` query + (`event_log.zig:711`). `Host` struct gains an `effective_account_count` + field. per-host fetch kept inline at the `addHost` path (one-off + `requestCrawl` handler, rare). removes ~2,770 blocking DB waits from the + Evented startup fiber. +- **resolver slot recovery.** `resolveHostAuthority` (`validator.zig:568`) + used to retry `resolve()` on the same pool slot after failure — if the + slot's http client was in a bad state, the retry was wasted and the slot + stayed bad forever. now: on first-attempt failure, `deinit` + re-init the + slot before the retry. directly tests the "poisoned slot" hypothesis + without making any zig stdlib claims. +- **zat transport error visibility.** bumped zat to `v0.3.0-alpha.23` + (commit `93d97be` on zat main): `DidResolver.resolve` and + `HttpTransport.fetch` now propagate the underlying `std.http.Client.fetch` + error instead of collapsing everything to `error.DidResolutionFailed` / + `error.RequestFailed`. the existing `sampleLogReject("resolve", did, + @errorName(err), ...)` call in the resolver pool will now log the actual + transport error kind (`UnknownHostName`, `ConnectionRefused`, `TlsAlert`, + etc.) instead of always `DidResolutionFailed`. no zlay code change needed — + free upgrade from the dep bump. +- **six new pool/loop metrics** in `broadcaster.zig`, emitted on `/metrics`: + `relay_host_resolver_acquire_wait_us_total`, + `relay_host_resolver_in_use`, + `relay_host_resolver_resets_total`, + `relay_host_resolver_resolve_fail_total`, + `relay_resolve_loop_resolve_ok_total`, + `relay_resolve_loop_resolve_fail_total`. +- **configurable pool size.** `HOST_RESOLVER_POOL_SIZE` env var (default 4, + hard cap 64), replacing the hard-coded constant. default unchanged for this + deploy — the dial exists for tuning based on the new `acquire_wait_us_total` + signal, not to bake in a speculative number. + +verified against `zig build`, `zig build test --summary all` (261/296 pass, +35 skipped, 0 fail), `zig fmt --check`. zat alpha bump verified empirically +against three structurally distinct failure modes (HTTP 404, DNS NXDOMAIN, +TCP refused) producing three distinct error names through the resolver API, +with a regression test added to zat's `did_resolver.zig` to lock the +invariant. zero breakage across all seven sibling zat consumers (zlay, +find-bufo, coral, prefect-server, pollz, labelz, bot). + +### reviewer's interpretation notes for the 795cc41 metrics + +- **leave `HOST_RESOLVER_POOL_SIZE` at default 4 for the first deploy.** + `795cc41` adds observability and a tuning knob; it should not also silently + change concurrency on the first measurement run. decide whether to bump + based on the new `acquire_wait_us_total` signal, not a guess. +- **`relay_host_resolver_resets_total` should stay near zero.** with + `keep_alive=false`, slots can't go bad in the keep-alive cached-connection + sense, so the recovery path is dormant infrastructure. **this is NOT + validation that the fix works** — that comes from a canary run (3 slots + `keep_alive=false` + 1 slot `keep_alive=true`) where we'd expect the + recovery counter to actually fire. if the counter rises anyway in the + default config, it means slot recovery is catching something other than + stale keep-alive state, which is a real signal worth chasing. +- **`relay_resolve_loop_resolve_fail_total` is a new baseline, not a + regression.** the background `resolveLoop` was previously failing at + whatever rate it was, silently, with `log.debug + continue`. whatever number + shows up post-deploy is visibility, not a new problem. if it's a meaningful + fraction of `resolve_loop_resolve_ok_total` that's something we didn't know + we had. if it's ~0, the "resolveLoop is healthy" assumption is finally + proven rather than hand-waved. + +### what 795cc41 explicitly does NOT do + +- re-enable `keep_alive=true` anywhere (canary is next, after a few hours of + clean steady-state on 795cc41) +- touch the spawn batch loop (50 hosts / 100ms yield at `slurper.zig:665`) — + the reviewer was explicit: slim the per-host work first, re-measure, + THEN decide whether batching needs tuning. this commit does the slim half. +- split liveness probes onto a dedicated thread — fallback if the slimmed + spawn fiber alone doesn't stop the flap +- identify the root cause of the 2026-04-08 ~99% rejection rate. slot + recovery + error visibility + pool metrics set up the infrastructure to + find out on the next canary; they don't diagnose retroactively. + +### known non-blockers (reviewer note) + +- backfill/cleaner are joinable but still not cooperatively cancellable. + operationally rough during shutdown but not a blocker for 795cc41. + +### 795cc41 deploy results (2026-04-09 ~17:15 UTC) + +deployed `ReleaseFast-795cc41` at 17:15:56Z. pod `zlay-65f7c4cbc9-ptkb4`. +observed the full ~35 min post-deploy window: + +**spawn speedup (review item 1):** worked as predicted. from pod start to +`startup complete: 2764 host(s) spawned` was **96 seconds**, vs the ~20+ +minutes on `bbba92c`. eliminating the per-host `DbRequest.wait()` for +`getEffectiveAccountCount` was ~20x on cold-start. single most impactful +change of the day. + +**stability:** pod ran cleanly for the first ~11 minutes, then readiness +flapped to 0/1 for ~2m36s (11m → 14m uptime), then recovered to 1/1 and +**stayed stable for the next 20+ minutes with 0 container restarts**. the +relaxed probes (`initialDelay=300s timeout=15s failureThreshold=20`) absorbed +the flap without kubelet killing anything. the flap window corresponds +exactly to the post-spawn reconnect storm — 2,764 subscribers all came +online within 96 seconds and started pumping cold events into the +host_authority pool simultaneously, producing temporary Evented scheduler +pressure until the initial is_new rate drained. + +**reviewer's predictions on the new metrics — all confirmed:** + +- `resolve_loop_resolve_ok_total = 68,326` / `resolve_loop_resolve_fail_total = 0`. + this is the first time we've *proved* the background signing-key + `resolveLoop` is healthy instead of assuming it from cache fill rate. + zero failures over 68k resolves over 34 min. +- `host_resolver_resets_total = 1` over 34 min. slot recovery is dormant, + as the reviewer predicted with `keep_alive=false`. if the counter starts + rising in default config, that's a real signal worth chasing. +- `host_resolver_resolve_fail_total = 1` over 34 min. first-attempt pool + failures are essentially zero with `keep_alive=false`, confirming the + 2026-04-08 workaround holds in steady state. + +**pool contention during the burst:** + +- `host_resolver_acquire_wait_us_total = 14,557,094,400 µs` (~4 hours + cumulative wait) over ~17,500 checks during the cold-start window +- that's ~831ms average wait per slot acquire, on top of ~387ms per + resolve → ~1.2s per host_authority check from the frame worker's side +- after the burst drained (~15m uptime onward), `host_resolver_in_use` went + to 0 and `acquire_wait_us_total` stopped climbing — pool is idle in + steady state +- the 4-slot default is under-provisioned for a 2,764-subscriber cold-start + burst. `HOST_RESOLVER_POOL_SIZE` env var exists now for tuning on the + next deploy. + +**host_mismatch burst (new observation, not a regression):** + +- `host_authority_reject{branch="host_mismatch"} = 15,198` cumulative over the + first ~15 minutes, then stopped climbing. at steady state the rate is + ~0/sec. +- all 15k rejects landed in the `host_mismatch` branch (not `resolve` like + the 2026-04-08 bug). meaning: the resolver *succeeded*, returned a valid + DID doc, and `pds_host_id != incoming_host_id` at the comparison. +- this is qualitatively different from the 2026-04-08 resolve-branch bug. + that was "DID doc lookup was failing." this is "DID doc lookup succeeded + but the resolved PDS id doesn't match the subscriber id we received the + event from." +- no sampled warn logs captured for this burst — the log buffer rotated out + during the 71k+ chain-break message flood and `kubectl logs` only retains + the most recent period. next occurrence we'll need to pull logs during + the burst, not after. +- plausible causes (unverified): stale `account.host_id` values in the DB + from a previous pod triggering `host_changed=true` on events where the + current DID doc still resolves to the current subscriber's hostname; or + duplicate rows in the `host` table with the same hostname and different + ids causing `getHostIdForHostname` (no ORDER BY) to return inconsistent + values; or something else. **not investigated yet.** none of the + candidates are new in 795cc41 — this is a pre-existing behavior the + faster spawn just made more visible by concentrating the is_new load. + +**operator error to record:** during the post-deploy window, I (claude) +repeatedly read cumulative lifetime counters (`acquire_wait_us_total`, +`host_authority_reject{host_mismatch}`) as steady-state rate indicators +and concluded the deploy was regressing. the reviewer's note said +explicitly to treat the new metrics as visibility, not as regression +signals; I ignored that and nearly recommended a rollback. the fix was +to pull a 10-second delta on the same counters, which immediately showed +the rates were flat and the pod was in healthy steady state. rule for +next time: **cumulative counters require a delta to interpret. never +suggest a rollback based on a single snapshot of a lifetime counter.** + +### net state at end of 2026-04-09 + +- deployed image: `ReleaseFast-795cc41` +- host_authority pool: `keep_alive=false`, 4 slots (default) +- `zlay/deploy/zlay-values.yaml`: probes relaxed to + `initialDelay=300s/60s timeout=15s failureThreshold=20` — + captured in source control, no cluster-only drift +- steady state: 1/1 Running, 0 restarts, `/metrics` responsive, pool idle, + `resolve_loop` healthy, no host_authority rejects currently firing +- known open items: root cause of 2026-04-08 99% reject rate still not + identified (infrastructure for next canary is in place); the + host_mismatch burst pattern is a new observation worth investigating + on the next cold-start; `HOST_RESOLVER_POOL_SIZE` dial exists but + left at default 4 per reviewer guidance + +commits (795cc41 bundle): `zlay/795cc41`, `zat/93d97be` (tagged as `v0.3.0-alpha.23`). + +### 4f3d1d4 gcLoop stabilization + honest handoff to next operator + +shipped `4f3d1d4` on top of `795cc41`: disabled `malloc_trim(0)` inside +`gcLoop`, bumped the gc interval from 10 min to 1 hour, added timing +instrumentation around `dp.gc()`. hypothesis at the time was that the +recurring ~10-minute "/metrics unresponsive" cycle on `bbba92c` and +`795cc41` was caused by `gcLoop` holding `DiskPersist.mutex` + +`malloc_trim` holding the glibc arena lock. full write-up in +`docs/zlay-gcloop-stall-2026-04-09.md`. + +**the hypothesis did not survive the deploy.** the `4f3d1d4` pod +(`zlay-6c776bf9b9-zv9pl`) exhibits the same symptom starting at ~10-12 +minutes of uptime, well before the new 1-hour gc interval would have +fired. so whatever the root cause is, it is not `gcLoop` and not +`malloc_trim`. those changes may still be worth keeping for other +reasons, but they are not the fix. + +### current deployed state (2026-04-09 ~20:40 UTC, at handoff) + +- image: `atcr.io/zzstoatzz.io/zlay:ReleaseFast-4f3d1d4` +- pod: 1/1 Running, 0 restarts, ~20 min uptime +- probes: relaxed (`initialDelay=300s timeout=15s failureThreshold=20`), + captured in `zlay/deploy/zlay-values.yaml` +- `/metrics`: does not return within any reasonable curl timeout (>45s + tested) +- `/_healthz`: ~11 s response +- `/_readyz`: ~17 s response (above the 15 s probe timeout — the pod is + surviving because kubelet probes happen to hit faster windows between + slower ones) +- prometheus scrapes: `health=down` with `context deadline exceeded` at + the 10 s scrape timeout, continuous since the deploy +- grafana: no data (prometheus has nothing to show) +- relay-eval: has been reporting zlay coverage near 0% for much of the + last several hours while other relays are at 99%+ +- node: load avg 67 on 8 cores, but zlay itself uses ~0.26 cores of CPU + and all 47 zlay threads are in S-state (sleeping) — nothing is + obviously burning CPU +- reconnect cronjob: active, default schedule `0 */4 * * *`, next fire at + 00:00 UTC +- host_authority pool: `keep_alive=false`, 4 slots, slot recovery present + (from `795cc41`) + +### what has been falsified today + +1. **"zig 0.16 `std.http.Client` stale keep-alive handling is broken"** — + the original framing for the host_authority 99.5% reject rate. engineer's + standalone repro (1,624 calls across many dimensions) could not + reproduce. `keep_alive=false` fixes the symptom, but the diagnosis was + not proven. root cause still open. +2. **"scheduler contention from 2,800 subscriber fibers starves + `Consumer.writeLoop`"** — I wrote this up in + `docs/zlay-broadcaster-starvation-2026-04-09.md` and proposed moving + writeLoop to `pool_io`. engineer correctly pointed out that this + re-enters the cross-Io crash class fixed in commit `6674812` — the + underlying websocket conn is Evented, so driving writeLoop from a + plain thread would NULL-deref `Thread.current()` under ReleaseFast. + do not do this. +3. **"`gcLoop` + `malloc_trim` every 10 min is the root cause of the + flap pattern"** — the 4f3d1d4 deploy with gc bumped to 1 hour shows + the same symptom at ~10 min uptime. whatever is causing the HTTP + server slowness fires before the new gc interval, so gc is not it. + +### what is still real and probably worth fixing + +- **`Consumer.writeLoop` uses `io.sleep(100ms)` polling instead of + `cond.wait`** (`broadcaster.zig:439-477`). this caps per-consumer drain + at 10 frames/sec even with zero contention, and makes `cond.signal` + in `Consumer.enqueue` (line 413) a no-op. this is a real bug + independent of everything else above, but it is not the cause of the + HTTP server being slow. zlay engineer's Option A in the 2026-04-09 + review exchange is the right fix: use `cond.wait`, keep everything on + Evented, move ping scheduling out-of-band. do NOT move writeLoop to + `pool_io`. +- **`DiskPersist.gc()` holds the persist mutex for its entire duration** + (`event_log.zig:977-1033`). this blocks every frame worker during gc. + narrowing the mutex scope is a real follow-up regardless of whether + gc turns out to be the primary cause of anything. +- **zlay's HTTP server fibers live on main `Io.Evented` io**, shared with + ~2,800 PDS subscriber fibers. this is still a plausible source of + trouble for short-lived consumer subscriptions (relay-eval, pulsar), + but I do not have direct evidence that the scheduler is the bottleneck + vs. something else in the Evented io backend. the engineer's Option A + should be tried before drawing more conclusions about the scheduler. + +### what the next operator should know + +- **do not trust a single steady-state `/metrics` snapshot as evidence of + stability.** I made this mistake twice today. the pattern is: pod runs + cleanly for ~10 minutes, then degrades. any probe taken in the first + 10 minutes will look fine. +- **cumulative counters are not the same as rate deltas.** I spent hours + today interpreting lifetime counter values as ongoing problems when + they were cold-start artifacts, and vice versa. pull two snapshots at + least a few seconds apart and diff them before drawing conclusions. +- **the relay-eval runs with `connected=True` + low DID counts are a + distinct failure mode from `connected=False` runs.** the former means + zlay accepted the subscription but delivered few events; the latter + means the handshake itself failed or the connection dropped. +- **there is a structured monitor timeline in `/tmp/zlay-diag/`** on my + laptop from today's session — it contains a ~2-hour window of pod + state + metrics availability + key counter deltas at 30 s cadence + across the bbba92c rollback, the 4f3d1d4 deploy, and the current stuck + state. includes the full Phase 1/2/3/etc timeline for the bbba92c pod + that eventually got kubelet-killed. +- **the most recent pod I remember reading `/metrics` from reliably in + this session was `31825b2`** (the 2026-04-07 FrameWork-UAF-fix pod, + with the then-current 99.5% host_authority reject bug). every pod I + shipped on top of that has the "HTTP server stops responding" symptom. + I do not know whether the symptom was also present on 31825b2 and I + just happened to miss it, or whether something I shipped today + triggered it. rolling back to 31825b2 would re-break host_authority + but might restore observability — worth considering purely as a + diagnostic step. + +### open items at handoff + +- Consumer.writeLoop cond.wait fix (engineer's Option A, not shipped) +- DiskPersist.gc() mutex scope narrowing +- actual root cause of the ~10-minute "/metrics unresponsive" cycle +- why relay-eval reports 0% for zlay during healthy-looking pod windows +- whether the cold-start is_new host_authority storm (seen at pod start + with 4/4 pool saturation and 800+ms acquire wait) ever fully drains on + the 4-slot default pool, or whether there's a permanent backlog state + +commits this session: `zlay/ee4e368`, `zlay/584571a` (build fail), +`zlay/bbba92c`, `zlay/795cc41`, `zlay/4f3d1d4`, `zat/93d97be`. docs +added: `docs/zlay-external-review-2026-04-09.md`, +`docs/zlay-broadcaster-starvation-2026-04-09.md` (wrong diagnosis, +preserved for context), `docs/zlay-gcloop-stall-2026-04-09.md` (also +wrong diagnosis). `zlay/deploy/zlay-values.yaml` updated with relaxed +probes. + +### operator rollback to b91382b — restored external service + +picked this back up later in the day as a new session. goal stated +explicitly: get zlay into a state where external evaluators +(relay-eval, pulsar, tap, hydrant) can actually reach it. code fixes +are out of scope for this session; rollback and dial-turning are in +scope. + +**confirmed the symptom is live on the `4f3d1d4` pod** +(`zlay-6c776bf9b9-zv9pl`, 28m uptime): + +| probe | result | +|---|---| +| internal `/metrics` (port-forward, t=0) | 200 in 0.5s | +| internal `/metrics` (port-forward, t=+15s) | **hung >10s** | +| external `https://zlay.waow.tech/_health` | **503** (ingress sees backend dead) | +| external `describeServer` | **503** | +| `endpoints/zlay` in k8s api | **empty** | +| pod `Ready` condition | flipped `True→False` at 20:59:34Z | + +so the reported ~10-min degradation cycle is reproducing. pod is +cycling in and out of `Ready` and service endpoints follow. external +consumers cannot handshake, which is why relay-eval shows 0%. + +also captured: +`relay_frames_received_total = 742988`, +`relay_frames_broadcast_total = 478` (frozen at cold-start value), +`host_authority_reject{branch="host_mismatch"} = 15,257` on 17,236 +checks (88% reject on the host_mismatch branch specifically — the +new burst pattern the 795cc41 entry flagged; still unexplained). + +**rollback attempt 1 — `ReleaseFast-b91382b` → ImagePullBackOff.** +tried rolling back to the 04-06 last-known-good image via +`kubectl set image`. the tag is not in the remote registry; zlay's +`publish-remote` uses `ctr images import` straight into k3s +containerd on the server, so older builds only live in the server's +local image store and the registry may have GC'd older pushes. 2m6s +in `ImagePullBackOff` before I caught it and reverted. + +**rollback attempt 2 — reverted back to `4f3d1d4` momentarily**, then +SSH'd to the server and ran `ctr -n k8s.io images ls | grep zlay` to +see what's actually cached locally. found **27 `ReleaseFast-*` images +and 15+ `ReleaseSafe-*` images** cached. the 04-06 build exists, but +under a non-standard tag: +`atcr.io/zzstoatzz.io/zlay:ReleaseFast-zat21-b91382b` (the `zat21-` +prefix was added to mark it as the zat v0.3.0-alpha.21 build). + +**rollback attempt 3 — `ReleaseFast-zat21-b91382b`** rolled out +cleanly. new pod `zlay-679c966669-6xg5v` was `1/1 Ready` in ~60s. +probed immediately: + +| probe | result | +|---|---| +| external `https://zlay.waow.tech/_health` | `200` `{"status":"ok"}` in 0.29s | +| external `xrpc/_health` | `200` in 0.23s | +| external `describeServer` | `404` (endpoint not implemented on this old build; not a blocker) | +| raw `wss://.../subscribeRepos` (python websockets, 15s) | **5,896 frames received, ~395 fps** | +| `just zlay test-tap 30` | connected, ran full 30s without error | + +the raw-websocket delivery measurement is the headline. the +broadcaster-starvation doc from earlier in the day measured +**6 frames in 170s (0.035 fps)** on `bbba92c` under the same +conditions. rollback improved downstream delivery by **~11,000×**. + +**metrics delta with an active consumer attached (15s window):** + +| metric | t0 | t1 | Δ | +|---|---:|---:|---:| +| `frames_received_total` | 472534 | 479377 | +6843 | +| `frames_broadcast_total` | 20828 | 27629 | +6801 | +| `consumers_active` | 1 | 1 | — | + +**delivery ratio 6801/6843 = 99.4%.** compared to the broken pods +where `frames_broadcast_total` stayed stuck at its lifetime value +even during an active consumer subscription. this is conclusive: on +b91382b, when a consumer connects, the broadcaster fans out to them +at ingest rate. on 4f3d1d4/795cc41/bbba92c it does not. + +**host_authority on b91382b: `validation_failed{reason="host_authority"} = 1 / 513` = 0.19%.** +the 99.5% reject rate that was the first headline bug of the day is +**not present on b91382b**. this build does not have the per-branch +reject breakdown (that lexicon came in ee4e368), so we only have the +aggregate counter — but the aggregate is fine. this narrows the +introduction window for the host_authority bug to **04-06 → 04-07**, +the same window the broadcaster-starvation doc identified as when +downstream delivery broke. two bugs, same window, possibly the same +commit. the broadcaster doc already flagged `1eec324` (FrameWork UAF +fix, 04-07) as suspicious because it changed how FrameWorks are +queued. + +**current deployed state (end of handoff-2):** + +- image: `atcr.io/zzstoatzz.io/zlay:ReleaseFast-zat21-b91382b` + (04-06, Evented/ReleaseFast, zat v0.3.0-alpha.21) +- pod: `zlay-679c966669-6xg5v`, 1/1 Ready, 0 restarts +- public `/health`: 200 in ~0.3s +- firehose delivery: ~400 fps to connected consumers (99.4% of ingest) +- `relay_validation_failed{reason="host_authority"} = 7 / 551 = 1.3%` steady state — within normal legitimate-policy-drop range +- k8s probes: still relaxed (`initialDelay=300s timeout=15s + failureThreshold=20`) from the `bbba92c` era. safe to leave — + they don't hurt anything on a fast-responding pod +- reconnect cronjob: still active (`0 */4 * * *`, next fire 00:00 UTC) + +**known risks I am actively watching on b91382b:** + +1. **FrameWork.hostname UAF** (fixed in 1eec324 on 04-07; b91382b + pre-dates the fix). the 04-07 ops entry documents that this UAF + can trigger a pod restart when "subscribers churn faster than the + frame pool can drain" — which is exactly what the 4h reconnect + cron does. if the next cron fire crashes the pod, rollback has to + move forward to a build that has the UAF fix, and we lose the + broadcaster-delivery win. +2. **unknown host_authority behavior under load.** it's 1.3% right + now at workers_count ~700, but workers_count is still ramping + toward ~2,800. possible the reject rate climbs with pool saturation + and the bug was latent on 04-06 because nobody measured it. +3. **`consumers_active` drops to 0 when no one is connected** → no + evidence the broadcaster *continuously* delivers correctly, only + that it delivers *when a consumer is attached*. need to leave a + long-running consumer (tap or relay-eval) attached and monitor + over a longer window. +4. **8192-slot per-consumer ring buffer** — pre-dates the ee4e368 + bump to 65536. `ConsumerTooSlow` kicks possible on long-window + consumers like pulsar. relay-eval windows are short enough that + this shouldn't bite. + +**what this rollback does NOT fix:** + +- does not explain *what changed between 04-06 and 04-07* to cause + both the broadcaster delivery collapse and the host_authority + reject bug. the `1eec324` FrameWork UAF commit is the leading + suspect because it changed frame queuing, but this is a pointer + for the engineer to investigate, not a diagnosis. +- does not eliminate the FrameWork UAF risk — b91382b still has + the bug, it's just pre-observation. +- does not ship the `Consumer.writeLoop` cond.wait fix ("Option A") + — that's still the engineer's work. + +**what to tell the zlay engineer** (written up separately in +`docs/zlay-handoff-2026-04-09-rollback.md`): see that file for the +full report, including the b91382b measurements that narrow the bug +window, the empirical evidence that delivery is collapsed on +bbba92c/795cc41/4f3d1d4, and the ask for a fix that lands the +host_authority workaround + slot recovery + observability on top of +the frame-queueing shape that existed on 04-06. + +commits this handoff-2 session: no code commits (operator only). +deploy action: `kubectl set image deployment/zlay main=atcr.io/zzstoatzz.io/zlay:ReleaseFast-zat21-b91382b`. + +### canary 1 (b6a52a0 = b91382b + 1eec324 UAF fix) — deploy, fail, rollback + +engineer shipped `b6a52a0` on origin/main — exactly one change vs the +running `zat21-b91382b`: the `1eec324` FrameWork.hostname UAF fix. +zat pinned to v0.3.0-alpha.21, everything else identical. diagnostic +question: does adding only the UAF fix reintroduce the HTTP / delivery +collapse seen on bbba92c / 795cc41 / 4f3d1d4? + +deployed via `just zlay publish-remote ReleaseFast` at 22:23 UTC. +image tag `ReleaseFast-b6a52a0`. pod `zlay-79ddd589b8-rlbdg`. + +**initial sweep (T+2 min) — all green.** external `/_health` 200 in +0.28s, raw ws 5438 frames/15s = 363 fps, delivery ratio 99.9% +(6016/6020) with an attached consumer, 0 host_authority rejects over +130 checks, pod 1/1 Ready. + +engineer asked for healthy-baseline capture, DB audit, refined sweep. +all three delivered. + +**healthy baseline (T+~5 min).** container has no `ss`/`netstat`/ +`ps`/`top` — fell back to `/proc`: +- listen sockets: tcp :3000, :3001 both LISTEN, `rx=00000000`, + `tx=00000000` (accept queues empty) +- threads: 47 total (5 R / 42 S / **0 D**) +matches the 04-05 migration note of ~47 threads on Evented. saved to +`/tmp/canary1-healthy-{ss,ps}.txt`. + +**DB audit (one-shot, independent of canary).** two queries: +1. `SELECT hostname, count(*) FROM host GROUP BY hostname HAVING count(*) > 1` + → **0 rows.** duplicate-host hypothesis dead. +2. `SELECT count(*) FROM account WHERE host_id NOT IN (SELECT id FROM host)` + → **239,422 rows** (4.11% of 5,817,756 total accounts). **100% of + orphans point at `host_id = 0`** — a single sentinel value, not + scattered drift. host id 0 does not exist in the `host` table + (ids start ≥1). some code path writes `host_id=0` when it should + either insert a new host row or reject the account write. this + is the first concrete evidence behind the "stale account.host_id" + hypothesis the 795cc41 reviewer raised. +saved to `/tmp/canary1-db-audit.txt`. + +**T+~30 sweep — mixed.** the pod was still up and external delivery +still worked, BUT: +- `validation_failed{reason="host_authority"} = 18,699` cumulative + over `host_authority_checks_total = 20,132` = **92.9% cumulative + reject rate** at T+30. +- 20s steady-state delta showed rejects climbing at 0.05/sec, so the + bulk (18.7k) accumulated during the 0-20 min ramp window. +- `trigger{host_changed} = 15,214` — almost all of the 18.7k rejects + landed on the host_changed branch, which maps to the orphaned- + account shape from the DB audit. +- `pool_queued_bytes = 0`, `pool_backpressure_total = 128` (effectively + flat at 0.1/s), threads still 47/0D, listen sockets still clean, + `/metrics` responding fast. +- delivery ratio on a 15s attached-consumer delta: **99.9%** (4744/4747) + — delivery was fine at T+30. + +honest correction recorded at this point: my earlier b91382b "clean" +measurement was at **T+6 min with workers_count ~700** (pre-ramp). i +stopped watching before the ramp completed. the rollback doc's claim +that "b91382b pre-dates both the host_authority bug and the broadcaster +delivery collapse" was half wrong — the host_authority reject pattern +is present on b91382b too, just invisible if you stop measuring before +the ramp. `feedback_steady_state_fallacy` lesson applied to my own +earlier work, late. + +**T+~40 — broadcaster delivery collapses.** external 15s raw ws: +**0 frames in 15s.** connection succeeds, `consumers_active = 1` while +attached, zero frames flow. same shape as bbba92c / 795cc41 / 4f3d1d4. +alongside: +- external `/_health` returns **500 with `{"status":"error","msg":"database unavailable"}`** in 0.3s (FAST response, not a hang) +- postgres itself is HEALTHY: direct `psql ... SELECT count(*) FROM host` + returns `3709` instantly +- pod: still 1/1 Ready, 0 restarts, 47 threads, 0 D-state, listen + socket accept queues still empty +- `relay_pool_queued_bytes` jumped from 0 → **63.86 MiB** +- `relay_persist_order_spins_total` jumped from 1.92G → **11.98G + (+10 billion in ~5 minutes = ~33M spins/sec)**. earlier rate on the + same pod at T+32 was ~18k/sec. **~2000× rate spike.** +- `relay_host_authority_reject{}` climbing again at ~5/sec — post-ramp + reject burst +- logs flooded with `host mismatch: current= new=` + for a small set of recurring UIDs. not the host_id=0 orphan shape — + these are accounts where `current` is a VALID small host id (312, + 1316) but `new` is a large host id (97k-105k). account migrations + where zlay hasn't updated account.host_id after resolving the new + host. repeating loop: same ~5-10 accounts keep triggering. + +this is **not** the HTTP-fiber-hang shape the broken 04-09 pods had. +- the broken 04-09 pods: HTTP fibers hang past probe timeout, ingress + drops the pod from endpoints, pod flips `Ready=False`, 503s from + the ingress. +- canary 1 at T+40: pod stays `Ready`, HTTP fibers respond FAST but + with specific error payloads (`/_health` = 500 "database unavailable" + in 0.3s). delivery is 0 fps to connected consumers. listen accept + queues are clean, threads are not stuck. + +interpretation: the failure mode is **DbRequestQueue deadlock or +back-pressure**, not HTTP fiber starvation. the `/_health` handler's +DB probe can't get through the jammed queue within its timeout, so it +returns a fast 500 with a specific error. the broadcaster is likewise +stuck waiting on DbRequestQueue for account.host_id updates. the same +small set of ~5 accounts generates repeated host_authority work because +their host_id update never commits. spin counter explodes because +whatever loop runs on the persist-order mutex spins forever when the +queue is jammed. + +**rolled back at T+~40 min** (23:05 UTC) to +`ReleaseFast-zat21-b91382b`. rollout successful, new pod +`zlay-679c966669-bth6c`. evidence saved to `/tmp/canary1-fail-*`. + +the rollback restores functional state for evaluators — external +delivery measured at 270 fps via raw ws at post-rollback T+3 min and +held through the subsequent ~3 hours of runtime at 270-290 fps. but +the rollback's host_authority reject rate climbs to the same ~99% +cumulative pattern by the 3-hour mark. b91382b has the host_authority +bug too; it just doesn't wedge the broadcaster the way canary 1 did. + +### b91382b @ 3h uptime — the long-watch measurement + +after the canary 1 rollback i left the pod running and came back to +it at T+3h02m (02:09 UTC 2026-04-10). the extended observation: + +| metric | value | +|---|---| +| pod state | 1/1 Ready, 0 restarts | +| external `/_health` | 200 in ~0.3s | +| external raw ws 15s | **270 fps** | +| threads (`/proc/1/task`) | 47 total, 2 R, 45 S, **0 D** | +| listen sockets accept queues | clean (rx=0) | +| `relay_frames_received_total` | 4.42M (cumulative ~400 fps lifetime) | +| `relay_frames_broadcast_total` | 438.7k | +| `relay_workers_count` | 2.8k (fully ramped) | +| `relay_host_authority_checks_total` | 128.5k | +| `relay_validation_failed{reason="host_authority"}` | **127.3k (99.1%)** | +| 15s rate of new rejects | **10.7/sec** | +| `relay_pool_queued_bytes` | **20.7k** (was 0 at T+2 min, climbing slowly) | +| `relay_pool_backpressure_total` | 1.1k (flat) | +| `relay_persist_order_spins_total` rate | ~33k/sec (1000× lower than canary 1's 33M/sec just before failure) | + +**conclusion: b91382b is the current functional-enough baseline**, not +a clean reference. it has: + +- host_authority 99%+ reject bug latent from cold-start — only visible + after the ramp finishes, easy to miss with short measurements +- slow `pool_queued_bytes` accumulation (0 → 20k over 3h) that will + presumably continue +- correct steady-state broadcaster delivery for now + +this means the b91382b baseline is NOT the pristine reference image +the earlier ops-changelog entry called it. the distinguishing signal +between "functional" and "broken" on the Evented + host_authority code +path is the `persist_order_spins_total` rate: ~33k/sec = functional, +~33M/sec = broadcaster wedged. 1000× gap, easy to spot. + +### the engineer report + +composed `docs/canary1-failure-2026-04-09.md` for the zlay engineer. +key points: +1. the UAF fix alone does NOT cleanly reintroduce the HTTP-hang — + what it reintroduces is a different failure mode (DbRequestQueue + deadlock + persist_order_spins explosion + broadcaster stall with + HTTP fibers still responding fast). +2. the host_authority 99% reject pattern is ALSO in b91382b. not + introduced by 1eec324. my earlier 1eec324-blame was wrong on + this half. +3. the broadcaster wedge *may* be introduced by 1eec324. the canary + was the cleanest test we've run, and it failed at T+40. BUT the + same pod with the exact same code minus 1eec324 (the running + b91382b rollback) has `pool_queued_bytes` slowly climbing too — + so it may be a matter of time, not a code difference. need to + watch b91382b for longer (>6h) to know. +4. the 33M/sec `persist_order_spins_total` rate is the most specific + new signal from this session. suggesting: add a per-mutex-target + attribution so we can tell WHICH persist-order mutex is spinning. + +### operator skill work this session + +two fragile patterns kept recurring during the day: (a) inline +`kubectl port-forward ... & sleep 2; curl ...; kill %1` dances, and +(b) metric-delta parsing via shell awk which broke on `# TYPE` comment +lines and label-escaping. captured as: + +- `scripts/zlay-probe` — single python script, subcommands + `health | delivery | metrics | delta | sweep`. handles port-forward + lifecycle (readiness-wait, process-group cleanup), prometheus text + parsing (regex-based, label-aware), delta rendering, tight-timeout + external probes (3s `/_health`), raw websocket frame counting against + the public ingress. self-contained uv script with `websockets` as + the only dep. +- `just zlay probe ` — justfile pass-through to the script. +- `.claude/skills/zlay-diagnose/SKILL.md` — one-page skill that points + future-me at the recipes and explicitly bans the inline port-forward + pattern. includes interpretation notes for each signal, the "when + the script is not enough" escape hatches (/proc thread states, /proc + listen sockets, DB audit), and the engineer's alarm thresholds from + the refined-sweep doc. + +the script caught its own first real failure — it reproduced the +canary 1 external `/_health` 500 on its initial smoke test, and the +subsequent sweep was the one that showed 0 fps delivery and the 10G +spin-counter spike. useful shape for future canaries. + +commits this canary-1 session: none yet (pending user review of the +zlay-probe script, SKILL.md, and this ops-changelog entry before +committing). + +--- + ## 2026-04-07 ### zlay FrameWork hostname UAF — fixed and shipped (1eec324) diff --git a/docs/zlay-broadcaster-starvation-2026-04-09.md b/docs/zlay-broadcaster-starvation-2026-04-09.md new file mode 100644 index 0000000..390f25e --- /dev/null +++ b/docs/zlay-broadcaster-starvation-2026-04-09.md @@ -0,0 +1,233 @@ +# zlay: downstream consumer delivery at 0.035 events/sec — root cause + fix recommendation + +*2026-04-09, follow-up to `zlay-external-review-2026-04-09.md`* + +## headline + +**zlay's firehose broadcaster is delivering ~0.035 events/second to connected consumers while the relay is ingesting ~300 events/second from upstream PDSes.** That's a ~7,500× delivery deficit. This is the single root cause behind the all-day churn: relay-eval's "0% coverage with connected=True" rows, pulsar at 54%, tap receiving 6 frames in 170 seconds, the apparent "HTTP server starvation" I was chasing. The HTTP fibers aren't really "starved" in the conventional sense — they're stuck behind ~2,800 Evented fibers doing upstream websocket reads, which is turning every consumer-facing fiber into a polling loop that runs once every many seconds. + +This is not a 795cc41 regression. It reproduces on `bbba92c` identically. It likely predates bbba92c by some amount — the 2026-04-06 ops entry says tap + hydrant consumed cleanly after the zat v0.3.0-alpha.21 deploy, so the break happened somewhere between 04-06 and 04-08. The 04-07 FrameWork-UAF-fix pod's 33% dropout rate on relay-eval is probably the same bug, previously mis-attributed. + +## evidence (measured, not theorized) + +**Tap subscribed to `wss://zlay.waow.tech/xrpc/com.atproto.sync.subscribeRepos` with `cursor=0`, ran for 180 seconds. Its prometheus counters at poll intervals:** + +``` +t=30s tap_firehose_events_received_total = 0 +t=60s tap_firehose_events_received_total = 1 +t=120s tap_firehose_events_received_total = 4 +t=170s tap_firehose_events_received_total = 6 +``` + +**6 frames in 170 seconds of connected time**. No decode errors. Connection succeeded (tap's `firehose_cursors` table populated). The ingested frames are well-formed — the issue is purely rate. tap ran on my laptop over the public internet to `zlay.waow.tech`, which rules out any in-cluster networking weirdness. + +**Simultaneously, from zlay's own `/metrics` sampled every 30s over the same window:** +- `relay_frames_received_total` was climbing at **~324 events/sec** (from 864k → 1,195k over 17 min) +- `relay_frames_broadcast_total` was stuck at the exact same number for the entire window (tap was briefly connected but zero events made it through fast enough to show up at monitor resolution) +- `relay_workers_count` climbing smoothly (1,925 at end of window) +- `relay_consumers_active = 0 or 1` depending on whether tap was connected +- `relay_process_rss_bytes` ~1.5 GiB, not memory-pressured +- `relay_broadcast_queue_depth_hwm = 3956` (of 65536), queue not backed up at broadcaster-input side +- `relay_broadcast_queue_full_total = 0`, queue never overflowed + +**Pod is healthy**. 1/1 Running, 0 restarts, `/metrics` responding in ~0.3s, `/_healthz` in ~0.22s. No crash loop on the current deploy. + +## root cause + +The delivery deadlock is structural, in two interlocking parts. + +### part 1 — all consumer-facing work runs on the main `Io.Evented` io, shared with ~2,800 PDS subscriber fibers + +`main.zig:61` sets `const Backend = Io.Evented`. Then: +- `main.zig:396` starts the metrics server via `io.concurrent(MetricsServer.run, ...)` on main io +- `main.zig:418` starts the ws+health HTTP server via `io.concurrent(runWsServer, ...)` on main io +- `main.zig:348` starts the broadcaster loop via `io.concurrent(Broadcaster.runBroadcastLoop, ...)` on main io +- `broadcaster.zig:566` spawns each downstream consumer's `writeLoop` via `self.io.concurrent(Consumer.writeLoop, ...)` — `self.io` is the main `io` (passed in at `main.zig:215`) +- `slurper.zig:589` spawns **every upstream PDS subscriber** via `self.io.concurrent(runWorker, ...)` — also on main io + +So at steady state the main Evented io has: +- ~2,800 subscriber fibers actively reading upstream PDS websockets +- 1 broadcaster fiber +- N consumer writeLoop fibers (per downstream subscriber) +- 2 HTTP listener fibers (ws on :3000, metrics on :3001) +- Various per-request handler fibers + +The frame workers that actually decode and push to the broadcast queue are on a separate `Io.Threaded` pool (`pool_io` at `main.zig:192-195`), which is why ingest keeps working — it's not scheduled by the Evented scheduler. Everything else is. + +### part 2 — `Consumer.writeLoop` uses `io.sleep(100ms)` as a wait primitive instead of `cond.wait()` + +`broadcaster.zig:439-477`: + +```zig +fn writeLoop(self: *Consumer) void { + self.last_send_time = Io.Timestamp.now(self.io, .real).nanoseconds; + + while (self.alive.load(.acquire)) { + var frame: ?*SharedFrame = null; + { + self.mutex.lockUncancelable(self.io); + defer self.mutex.unlock(self.io); + if (self.buf_len == 0) { + // no data: poll briefly instead of blocking on cond + // (Io.Condition has no timedWait, so we poll to allow periodic ping checks) + self.mutex.unlock(self.io); + self.io.sleep(Io.Duration.fromMilliseconds(100), .awake) catch {}; + self.mutex.lockUncancelable(self.io); + } + frame = self.dequeue(); + } + if (frame) |f| { + defer f.release(); + self.conn.writeBin(f.data) catch { ... }; + self.last_send_time = ...; + } else { + self.maybePing(); + } + } + ... +} +``` + +The inline comment explicitly names the reason: `Io.Condition has no timedWait`, so the author replaced `cond.wait()` with `io.sleep(100ms)` to allow periodic ping checks. This makes `cond.signal(self.io)` in `Consumer.enqueue` at line 413 a **no-op** — the writeLoop is never actually waiting on that condition. It's doing a 100ms polling loop with the lock released during sleep. + +**Consequences, under normal scheduler load**: +- Max drain rate per consumer is ~10 frames/sec (one wake every 100ms sleep, drain whatever was enqueued, repeat). +- 10 frames/sec is already far below the steady-state ingest rate of ~300/sec, but a single consumer can only receive 10/sec. +- Any burst of enqueued frames beyond 10 would force the consumer into a `ConsumerTooSlow` kick path. + +**Consequences, under heavy main-io scheduler load (2,800+ subscriber fibers)**: +- Every time the writeLoop's 100ms sleep completes, the fiber has to be rescheduled. With 2,800 other fibers all producing work, the actual wake-to-run latency is not 100ms — it's probably seconds. +- Measured reality: tap received 6 frames in 170s → one frame per ~28 seconds. +- The broadcaster fiber itself (also on main io) is similarly backed up — it pops from `broadcast_queue` and calls `broadcast()`, which iterates consumers holding `consumers_mutex`. Even if the `broadcast_queue.pop()` side is fast, the `writeLoop` consumer-side is the bottleneck because that's where frames leave the process. + +### summary + +Frames flow in correctly through the Threaded frame-worker pool and get enqueued into per-consumer ring buffers by the broadcaster fiber. But the per-consumer writeLoop that actually writes to the downstream websocket is stuck in a polling loop contending with 2,800 subscriber fibers for scheduler slots on the same Evented io. The effective drain rate is 3+ orders of magnitude below the ingest rate. + +## recommended fix — two changes, both small, in this order + +### change 1 (small, unambiguous, directly testable) — move `Consumer.writeLoop` off main `io` onto `pool_io` + +The consumer writeLoop has nothing that requires Evented semantics. It's a drain loop that writes to a websocket. The existing `pool_io` (Threaded, dedicated worker threads) is exactly the right runtime for it — same argument the frame workers already use (`main.zig:188-191` comment: *"worker threads are plain std.Thread — they cannot use Evented io"*). The writeLoop doesn't use any Evented-specific features. + +**Implementation sketch** (file:line references): + +1. `broadcaster.zig:517-540` (`Broadcaster` struct + `init`): add a `pool_io: Io` field alongside `io`, set in `init`. Update call site at `main.zig:215` to pass both (`Broadcaster.init(allocator, io, pool_io, &shutdown_flag)`). +2. `broadcaster.zig:559-581` (`addConsumer`): change `self.io.concurrent(Consumer.writeLoop, .{consumer})` to use the pool io. The writeLoop is CPU+network-bound, not event-loop-bound. +3. `broadcaster.zig:380-399` (`Consumer` struct): change the stored `io` field to be the pool io (so `Io.Timestamp.now`, `io.sleep`, mutex/cond all use Threaded semantics). + +**Expected effect**: writeLoop gets scheduled onto a dedicated std.Thread, not multiplexed against 2,800 subscriber fibers. Its effective drain rate goes from ~0.04/sec to "bounded only by ws write speed" (thousands/sec). + +**How to verify the fix worked (5-minute test)**: +1. Deploy the change. +2. Wait 10 minutes for the pod to reach steady state. +3. Run `tap run --relay-url https://zlay.waow.tech --db-url sqlite:///tmp/tap-verify.db --firehose-parallelism 4` for 60 seconds. +4. Pull tap's `tap_firehose_events_received_total` — should be in the thousands, not single digits. +5. Pull zlay's `relay_frames_broadcast_total` delta over the same 60s — should match received rate, around 300+/sec. +6. Pulsar's next 18:00 UTC run should report zlay near 99% instead of 54%. + +**Rollback**: trivial revert, no state or schema changes. + +### change 2 (slightly larger, structural) — replace the 100ms polling in `writeLoop` with `cond.wait()` and move the ping timer to a separate fiber + +Even after change 1, the polling-loop structure is wasteful and wrong. The fix is: + +- `writeLoop` should use `cond.wait(mutex)` to sleep until either a frame is enqueued (signaled by `enqueue` at line 413, which currently does nothing) or the consumer is being shut down. No polling. +- Ping scheduling should be a separate concern. Either: + - (a) A dedicated per-consumer "ping timer" fiber that calls `maybePing` every ~N seconds regardless of drain state, or + - (b) Check last_send_time after EACH successful frame write, and only if it exceeds the ping interval AND there's no backlog, send a ping. (No timer needed — pings happen opportunistically between frames.) + +Option (b) is simpler and avoids extra fibers. It doesn't send pings during long idle periods, but that's fine — the ping interval is about keeping the ws connection warm, and idle connections are rare in practice (the firehose has events constantly). + +This change removes the 100ms wake ceiling entirely and makes the writeLoop edge-triggered. + +**Implementation sketch**: + +```zig +fn writeLoop(self: *Consumer) void { + self.last_send_time = Io.Timestamp.now(self.io, .real).nanoseconds; + while (self.alive.load(.acquire)) { + self.mutex.lockUncancelable(self.io); + while (self.buf_len == 0 and self.alive.load(.acquire)) { + // block until enqueue signals or shutdown + self.cond.wait(self.io, &self.mutex); + } + const frame = self.dequeue(); + self.mutex.unlock(self.io); + + if (frame) |f| { + defer f.release(); + self.conn.writeBin(f.data) catch { + self.alive.store(false, .release); + return; + }; + const now = Io.Timestamp.now(self.io, .real).nanoseconds; + self.last_send_time = now; + // opportunistic ping: if idle period exceeded, send ping next time buf is empty + } + } + // drain remaining buffered frames + ... +} +``` + +Ping scheduling can move to a separate fiber that does `io.sleep(ping_interval)` in a loop and sends pings. + +**Why this is separate from change 1**: change 1 alone might fix the immediate problem (moving writeLoop off contended io). If it does, change 2 is an optimization we can take time on. If it doesn't, change 2 is needed too. Ship change 1 first and measure. + +### not recommended yet + +- **Don't** try to move the PDS subscriber fibers off main Evented. They rely on Evented for the websocket reader loops, and moving 2,800 of them would be a big architectural change. They're doing the right thing on Evented. +- **Don't** move the HTTP server fibers (metrics, ws accept) off Evented. They're fine at low-concurrency, and they're not the bottleneck — the writeLoop is. +- **Don't** bump `HOST_RESOLVER_POOL_SIZE`. The resolver pool is not the bottleneck; its `in_use` gauge was 0 during the observed delivery stall. +- **Don't** change the relaxed probes. They're tolerating a different symptom (cold-start wake-up latency on the HTTP fibers). Once the writeLoop is off Evented, the pressure on those HTTP fibers should drop and probes can eventually be tightened back. + +## risks and things to watch + +1. **writeLoop on pool_io still has to acquire `consumers_mutex`** (held by the broadcaster fiber during fanout at `broadcaster.zig:620-621`). If the broadcaster fiber is slow to release that mutex, writeLoop waits. With writeLoop running at thousands/sec and broadcast at ~300/sec, the mutex should be held briefly and contention should be negligible. But worth watching. +2. **Thread count**: moving writeLoops to pool_io means each consumer spawns a new std.Thread. With a few downstream consumers this is fine. If we ever have hundreds, revisit. +3. **This fix doesn't address the question "why is the main Evented io so loaded it can't schedule a single writeLoop fiber?"** — that's a real question, and the answer might be "2,800 fibers is simply too many for the Evented scheduler under io_uring." If so, the longer-term fix is to reduce the subscriber fiber count by pooling, but that's much bigger. Change 1 is strictly independent. +4. **Hypothesis check**: if change 1 does NOT fix the delivery rate, the scheduler contention theory is wrong and the bug is somewhere else. I've instrumented what I can from outside the process; the engineer may want to add a counter to `Consumer.writeLoop` that measures actual wake-to-wake cycle time, so we can directly measure whether 100ms sleep is returning in ~100ms or in multiple seconds. + +## minimal instrumentation to add alongside change 1 (optional but useful) + +```zig +// in Stats +consumer_writeloop_iterations_total: std.atomic.Value(u64) = .{ .raw = 0 }, +consumer_writeloop_sleeps_total: std.atomic.Value(u64) = .{ .raw = 0 }, +consumer_writeloop_sleep_elapsed_us_total: std.atomic.Value(u64) = .{ .raw = 0 }, +``` + +Increment `iterations_total` every writeLoop cycle. Increment `sleeps_total` each time we hit the `buf_len == 0` branch. Measure wall-clock time across the `io.sleep(100ms)` call and add it to `sleep_elapsed_us_total`. If `sleep_elapsed_us_total / sleeps_total >> 100,000`, the scheduler contention is confirmed. If it's ~100,000, the sleep is returning promptly and the bottleneck is elsewhere (e.g., ws write speed, or consumers_mutex contention). + +## code pointers + +- Main `io` backend: `zlay/src/main.zig:61` (`const Backend = Io.Evented`) +- Separate Threaded `pool_io`: `zlay/src/main.zig:192-195` +- Broadcaster init (takes main `io`): `zlay/src/main.zig:215` +- Subscriber spawn on main io: `zlay/src/slurper.zig:589` +- Consumer writeLoop spawn on main io: `zlay/src/broadcaster.zig:566` +- Consumer writeLoop body (the 100ms polling loop): `zlay/src/broadcaster.zig:439-477` +- Consumer enqueue (signals unused cond): `zlay/src/broadcaster.zig:403-415` +- Broadcaster fanout to consumers: `zlay/src/broadcaster.zig:604-647` + +## git bisect surface if wanted + +Something between 2026-04-06 and 2026-04-08 introduced or exposed this. The commits touching `broadcaster.zig`, `subscriber.zig`, or `frame_worker.zig` in that window are: + +``` +ee4e368 bump per-consumer buffer 8192→65536 + host_authority reject breakdown +31825b2 subscriber: extract prepareFrameWork + add UAF regression test +1eec324 fix UAF: dupe FrameWork.hostname per submit instead of borrowing +``` + +None of these touch the `writeLoop` directly. The 1eec324 UAF fix is suspicious because it changed how FrameWorks are queued — if it inadvertently changed the fiber scheduling shape (e.g., added a synchronization point that serializes frame workers), that could have increased load on main io somehow. But the writeLoop pattern (`io.sleep(100ms)` instead of `cond.wait`) appears to pre-date 1eec324. I'd bisect by reverting 1eec324 on a canary and running tap for 60s to see if the delivery rate changes. + +More likely: the scheduler contention has been present since the `Io.Evented` migration on 2026-04-05 (commit `9cc1ba3`), and the 04-06 "tap + hydrant consumed cleanly" test happened during the window where the migration had fewer subscribers online (cold-start). If the zat v0.3.0-alpha.21 test at 04-06 was run against a pod that was in the middle of its own cold-start ramp-up (workers_count low), the writeLoop wouldn't have been contended yet. + +## tl;dr for the engineer + +1. Move `Consumer.writeLoop` to `pool_io` (Threaded) instead of the main `io` (Evented). One-file change in `broadcaster.zig`, ~5 lines. Ship this first. +2. Run tap against zlay for 60 seconds and check `tap_firehose_events_received_total`. If it's >1000, we're back to healthy. If not, add the iteration/sleep instrumentation from the section above and re-measure. +3. Optionally, after (1) confirms, replace the 100ms polling loop with proper `cond.wait()` + a separate ping timer fiber. This is a quality fix, not an emergency. +4. Do NOT re-enable the host_authority pool with keep_alive=true yet. That's an orthogonal issue and the investigation continues on that front via the new per-branch metrics from `795cc41`. diff --git a/docs/zlay-external-review-2026-04-09.md b/docs/zlay-external-review-2026-04-09.md new file mode 100644 index 0000000..3d1d512 --- /dev/null +++ b/docs/zlay-external-review-2026-04-09.md @@ -0,0 +1,306 @@ +# zlay: resolver pool failure + HTTP server starvation — external review request + +*2026-04-09* + +## tl;dr + +We hit two related problems with zlay (our zig-based atproto relay). We have working band-aids for both and no confirmed root cause for either. We'd like a second pair of eyes before we commit to the next round of fixes, because we've already been wrong once about what was happening. + +1. **Pooled DID resolvers fail 100% under production load** on `std.http.Client`. Reject rate was 99.54% before the workaround. `keep_alive=false` on the pool fixes the symptom. Why the pool fails is not known — an isolated repro run by us couldn't reproduce it in 1,624 calls across many dimensions. The single-owner resolver in the same process on the same `std.http.Client` appears to work fine. +2. **The `keep_alive=false` workaround is slow enough** (~350–900ms per call) that during the cold-start reconnect storm, it contributes to starving the HTTP server fibers long enough to fail liveness probes, which caused a crash loop until we relaxed k8s probe timeouts. The spawn path itself is also part of the picture — spawning 2,770 PDS subscribers takes over 20 minutes, and batches of that work delay HTTP fibers even after the resolver pool catches up. + +--- + +## context: what zlay is + +- **zlay** is an atproto relay written in zig. Role: ingest the firehose from ~2,800 PDS hosts, validate commits (`#commit`, `#sync`, `#identity`, `#account`), and broadcast a merged firehose via `com.atproto.sync.subscribeRepos` to downstream consumers. It's an alternative implementation to bluesky's Go reference relay (`bluesky-social/indigo`). +- Deployed at `zlay.waow.tech`. We also run an indigo instance at `relay.waow.tech` as a stable reference — both hit the same upstream PDS pool. +- zig version: `0.16.0-dev.3059+42e33db9d`. Build optimization: `ReleaseFast` (the `Io.Evented` backend GPFs under `ReleaseSafe` due to a zig stdlib bug in fiber `contextSwitch` — separate issue). +- Target metric: pulsar / relay-eval coverage parity with indigo (~99.6–99.9% DID coverage within a 5-minute window). + +--- + +## architecture relevant to both problems + +### threading model + +zlay uses a hybrid `Io.Evented` + `Io.Threaded` setup: + +``` +Io.Evented (main `io`) Io.Threaded (`pool_io`) + ├─ ws/health HTTP on :3000 ├─ frame workers (16 std.Thread) + ├─ metrics HTTP on :3001 ├─ DB request queue workers (2 std.Thread) + ├─ broadcaster loop fiber ├─ host_ops queue worker (1 std.Thread) + ├─ slurper spawnWorkers fiber ├─ validator signing-key resolveLoop (1 std.Thread) + └─ per-subscriber fibers └─ validator host_authority resolver pool (4 resolvers, + (one per PDS, ~2,770 steady-state) accessed by the 16 frame worker threads) +``` + +- **Evented** drives network orchestration: listening sockets, websocket accepts, per-PDS subscriber fibers (each subscriber is a fiber that reads a websocket and pushes frames into the work queue), and the HTTP listener fibers. +- **Threaded** (a separate `Io.Threaded` backend with its own io vtable) drives the frame worker pool, DB access, and the two places DID resolution happens. Worker threads are plain `std.Thread`. The comment in `main.zig:187-191` says they can't use Evented io because Evented's futex calls `ev.yield()` which requires fiber context, which these std.Threads don't have. +- **Both the resolver pool and `resolveLoop` are called from `pool_io` (Threaded), not from Evented fibers.** + +### the host_authority resolver pool + +```zig +// zlay/src/validator.zig:65 +host_resolvers: [host_resolver_pool_size]zat.DidResolver = undefined, +host_resolver_available: [host_resolver_pool_size]std.atomic.Value(bool) = ..., +// const host_resolver_pool_size: usize = 4; +``` + +- 4 `zat.DidResolver` instances created once at init (`validator.zig:143`). Each wraps a `std.http.Client`. +- Callers acquire a slot via `acquireHostResolver` (line 600), which spins on `cmpxchgStrong` until a slot's `available` flag goes `true→false`. Release flips it back to `true`. No mutex, no condvar, no recovery path. +- **On a `resolver.resolve(parsed)` failure, nothing destroys or re-initializes the slot.** The resolver stays in whatever state it landed in after the failure, and the next frame worker thread to acquire the slot gets the same instance. +- Called from frame workers (`frame_worker.zig:98-128`) on every `is_new` or `host_changed` DID — i.e. every first-seen account and every account migration. + +### the single-owner `resolveLoop` + +```zig +// zlay/src/validator.zig:449 +fn resolveLoop(self: *Validator) void { + var resolver = zat.DidResolver.initWithOptions(self.io, self.allocator, .{ .keep_alive = true }); + defer resolver.deinit(); + while (self.alive.load(.acquire)) { + // pop did from queue, resolve, cache signing key, continue on error + } +} +``` + +- 1 `DidResolver`, 1 `std.http.Client`, owned for the lifetime of a single dedicated `pool_io` worker thread. +- Same underlying library (`zat.DidResolver`), same `std.http.Client`, same process, same kernel, same kubernetes. The only difference from the pool is single-owner vs 4-slot-shared. +- Catches resolver errors with `log.debug` + `continue`. No retry on the same resolver. +- **This path works in production.** The validator signing-key cache grows to steady-state capacity (~250k of 524k cap as observed on a prior pod). We have not instrumented whether it's silently failing some percentage of resolves, so we can't say it's definitively healthy — only that it's not catastrophically broken the way the pool is. + +### zat's DID resolver (wraps `std.http.Client`) + +```zig +// zat/src/internal/identity/did_resolver.zig:41 +pub fn resolve(self: *DidResolver, did: Did) !DidDocument { + return switch (did.method()) { + .plc => try self.resolvePlc(did), + .web => try self.resolveWeb(did), + .other => error.UnsupportedDidMethod, + }; +} +// line 50: resolvePlc builds "https://plc.directory/{did}" and calls fetchDidDocument +// line 98: fetchDidDocument does transport.fetch(...) catch return error.DidResolutionFailed +``` + +```zig +// zat/src/internal/xrpc/transport.zig:27 +pub fn fetch(self: *HttpTransport, options: FetchOptions) !FetchResult { + var aw: std.Io.Writer.Allocating = .init(self.allocator); + defer aw.deinit(); + // ... build headers ... + const result = self.http_client.fetch(.{ + .location = .{ .url = options.url }, + .response_writer = &aw.writer, + .headers = headers, + .keep_alive = self.keep_alive, // configurable; default true + }) catch return error.RequestFailed; // <-- swallow #1 + return .{ .status = result.status, .body = try self.allocator.dupe(u8, aw.written()) }; +} +``` + +Two layers of error flattening: +- `http_client.fetch(...) catch return error.RequestFailed` +- Upstream: `transport.fetch(...) catch return error.DidResolutionFailed` + +By the time the error reaches zlay's validator, we just know "something failed." The specific error kind from `std.http.Client.fetch` is gone. We've since added a sampled warn log in `bbba92c` that captures `@errorName(err2)` on the retry path, but by the time it was shipping, the `keep_alive=false` workaround had already changed the behavior. **So we have no production log data showing the actual error kind from the broken state.** + +--- + +## problem 1: pool rejects 100% of DID resolves + +### what we measured + +- Cumulative reject rate on a pre-workaround pod: **896,043 / 900,201 = 99.54%** over ~30 hours. +- Steady-state reject rate was ~10/sec, consistent across a fresh 20-second metrics delta (`202 checks / 202 rejects`). +- Per-branch breakdown after `ee4e368` split `failed_host_authority` into six reject counters: **100% of rejects (39,621 / 40,072 in a 48-minute window) were the `resolve` branch** — `resolver.resolve(parsed)` throwing on both the first call and the retry on the same resolver. Zero rejects in `parse_did`, `no_endpoint`, `bad_url`, `unknown_host`, `host_mismatch`. + +### what the rejected events looked like + +Manual probe: we sampled 15 DIDs from `dropping event, host authority failed` log lines and resolved each via `curl https://plc.directory/{did}` from a laptop. **13 of 15 DID docs had their `AtprotoPersonalDataServer` endpoint hostname exactly matching the incoming host** — these are events zlay should have accepted, legitimate firehose traffic from bluesky mushroom-shard PDSes. 2 of 15 were the same DID appearing on two wrong hosts — legitimate policy rejects. + +So the 100% rejection was not events that were "sort of invalid" or "in a migration." They were valid events from correctly-authoritative PDSes. + +### what wasn't wrong (ruled out) + +- **DB lookup**: we verified `SELECT id, hostname FROM host` on zlay's postgres returned exactly the expected rows with stable ids. `getHostIdForHostname` works in isolation. +- **Network**: the pod's own slurper is holding ~2,800 concurrent websocket connections to PDSes, including the ones whose events were being rejected. Outbound TLS works. +- **CA certificates**: container image is `debian:bookworm-slim` with `ca-certificates` installed. +- **plc.directory availability**: responds `200` in ~100ms to `curl` from any vantage point, including for the exact DIDs that were being rejected. +- **zat DID doc parser**: `resolve` fails, not any downstream parsing. The `no_endpoint` and `bad_url` counters are flat at 0. + +### the workaround that shipped + +`bbba92c` flipped the pool init to `DidResolver.initWithOptions(alloc, .{ .keep_alive = false })` (`validator.zig:143`). **Reject rate collapsed from 99.54% → 0.24% within 14 minutes of deploy.** The remaining 0.24% are `unknown_host` and `host_mismatch` — legitimate policy drops. Confirmed by per-branch counters at 48-min uptime: `resolve = 0`, `unknown_host = 2`, `host_mismatch = 1`, out of 1,259 checks. + +### what the engineer's local repro couldn't find + +Standalone zig program outside zlay, calling `zat.DidResolver.resolve()` against `plc.directory` with `keep_alive=true`: + +- ReleaseFast and Debug builds +- zig 0.16.0-dev.3059 and 0.16.0-dev.3070 +- Serial calls (one after another) and parallel (spawned threads, shared vs per-thread clients) +- Single `std.http.Client` and multi-client +- 0s to 10s idle between calls +- 1,624 total calls across all combinations + +**None reproduced the failure.** All 1,624 calls succeeded. + +### what we explicitly don't know + +1. What error `resolver.resolve(parsed)` was throwing in production. Swallowed twice. No production log data from the broken state because the sampled-warn-log fix shipped in the same commit as the workaround. +2. Whether `resolveLoop` (single-owner, still `keep_alive=true` in prod) is genuinely healthy or silently failing some percentage of resolves. Signing-key cache fill rate is consistent with "working" but we haven't proven it. +3. Why the pool fails when single-owner doesn't. The structural differences are: pool has 4 slots vs 1; pool is acquired by 16 frame worker threads via atomic handoff vs 1 dedicated thread; pool does `resolve()` twice in rapid succession on failure (retry on same resolver) vs single-owner which does 1 call + continue. +4. Whether the bug is in zlay's pool code, in zat's `DidResolver`, in `std.http.Client`, or some interaction between them. + +### the guess we're working from (not a diagnosis) + +**The pool has no slot-recovery path.** Whatever causes a resolver to go into a bad state (one transient network hiccup, a server-side connection close the client didn't notice, TLS session expiry, anything), the slot stays bad forever because nothing destroys and re-initializes it. Over a few minutes, all 4 slots drift into bad states and everything rejects. + +This would be consistent with: +- Isolated repros not reproducing — a fresh test creates a fresh client per run, so "resolver lives long enough to hit a transient failure and never recovers" is unreachable. +- `keep_alive=false` fixing it — no reused connection state, nothing to break. +- Single-owner `resolveLoop` appearing to work — it has the same reuse pattern but it only does one call per loop iteration and `continue`s on errors, and we haven't measured hard enough to be sure it's not also silently degraded. + +But we're calling this a **guess**, not a root cause. We've already been wrong about this bug's shape once (we originally framed it as "zig 0.16 `std.http.Client` stale keep-alive handling is broken" which got falsified by the local repro). We don't want to ship another confident fix built on another unverified hypothesis. + +### proposed fix (unimplemented) + +**Add slot recovery**: on any `resolver.resolve(parsed)` failure in the pool, `resolver.deinit()` + `resolver.* = DidResolver.init...` the slot before releasing it back to the pool. This is entirely in zlay code, requires no stdlib claims, and should make the pool self-heal regardless of what "bad state" means. + +We haven't implemented this yet because we want to know if it's structurally sound or if there's a gotcha we're not seeing. + +### questions on problem 1 + +1. **Is there a mental model for what could break `std.http.Client` in a pooled-across-threads pattern that fresh-per-call and single-owner both avoid?** Our guess is "slot gets poisoned, no recovery path," but we can't explain *what* poisons it. Do you know of a structural thing in `std.http.Client` (connection pool, TLS session cache, request buffer state) that could get into a bad state and then silently fail every subsequent request without surfacing a clear error? +2. **Is destroy-and-reinit the right shape of recovery, or is there a lighter-weight reset?** We'd prefer to clear the client's internal connection pool or trigger a reconnect without throwing away the whole struct. Does zig stdlib expose anything like that? +3. **Is it a red flag that `resolveHostAuthority` does two calls on the same client in rapid succession (first attempt + immediate retry on failure)?** Is there a client-internal state that doesn't fully reset between calls that a retry without a brief delay could trip over? +4. **Any known stdlib gotchas around `std.http.Client` when the calling thread changes?** Our 16 frame workers are plain `std.Thread`, and any of them can acquire any of the 4 resolver slots. We can't find documentation on whether `std.http.Client` holds per-calling-thread state. + +--- + +## problem 2: HTTP server fiber starvation during cold-start spawn + +### the setup + +```zig +// zlay/src/slurper.zig:303 — kicked off in Slurper.start +self.startup_future = try self.io.concurrent(spawnWorkers, .{self}); +``` + +`spawnWorkers` is an Evented fiber running on the main `io`. It does this: + +```zig +// zlay/src/slurper.zig:670-683 (elided) +for (hosts) |host| { + self.spawnWorker(host.id, host.hostname, host.last_seq) catch |err| { ... }; + spawned += 1; + if (spawned % batch == 0 and spawned < hosts.len) { + log.info("startup: spawned {d}/{d} hosts, yielding...", .{ spawned, hosts.len }); + self.io.sleep(Io.Duration.fromMilliseconds(100), .awake) catch break; + } +} +``` + +`STARTUP_BATCH_SIZE` defaults to 50. With ~2,770 hosts that's ~55 batches × (work + 100ms yield). + +Each `spawnWorker` call creates a subscriber task (`Io.concurrent(Subscriber.run, ...)`) which immediately starts a websocket handshake to a different PDS. Under `Io.Evented`, these spawns should yield during network I/O — but the spawn setup itself (allocations, struct init, db request queue pushes, per-subscriber fiber creation) is synchronous CPU work. + +The HTTP server for health probes is `io.concurrent(runWsServer, ...)` on port 3000 (`main.zig:418`), and the metrics server is `io.concurrent(MetricsServer.run, ...)` on port 3001 (`main.zig:396`). Both are fibers on the **same main `io`** as the spawn loop. + +### what we observe + +- With original k8s probes (`initialDelay=30s timeout=5s failureThreshold=10`): the pod crash-looped. Every ~20 minutes, kubelet saw 10 consecutive liveness failures, SIGKILLed the container, and the spawn + resolve storm started over. 25 restarts in 9 hours until we noticed. +- With relaxed probes (`initialDelay=300s timeout=15s failureThreshold=20`): the pod survived the first 20 minutes. But **at 21 minutes of uptime, readiness still briefly flapped 0/1 for ~90 seconds** before recovering on its own, with no container restart. The corresponding log line at that time: `info(relay): startup: spawned 2400/2770 hosts, yielding...`. +- So the spawn loop was 87% done at 21 minutes, and the batches it was still processing were heavy enough to delay the `/_readyz` fiber past a 15-second timeout. +- `/metrics` curl attempts during these windows timed out at 20 seconds. + +### the aggravating factor from problem 1 + +`keep_alive=false` on the host_authority pool means every new-DID check during spawn-up does a fresh DNS + TCP + TLS handshake to plc.directory (~350–900ms per call). The 4-slot pool saturates as thousands of is_new events flood in from the newly-connected PDS subscribers. Frame workers spin-blocking on `acquireHostResolver` pile up CPU, which shares resources with everything else. + +The frame worker pool is on `Io.Threaded` (separate from Evented), so it shouldn't directly starve the HTTP fibers via the scheduler. But: +- Both still share the same process + CPU cores +- Both contend on shared state (atomic counters, the persist ordering mutex at `broadcaster.zig:492`, metrics map updates) +- The HTTP handler itself touches some of the same metrics state it's reading for `/metrics` responses + +We can't cleanly separate "how much of the probe delay is spawn itself" from "how much is the resolver pool blocking frame workers which contend with HTTP." We just know both are happening. + +### what we explicitly don't know + +1. Which fiber is actually stuck when `/_healthz` times out. We haven't taken a fiber-level trace or `pprof`-equivalent. +2. Whether 100ms between batches is structurally the wrong yield, or whether the scheduler is fine and the batches themselves are much slower than we think. +3. Whether the right architectural answer is "isolate HTTP onto its own thread" vs "make spawn slower" vs "make spawn cheaper per-host." + +### questions on problem 2 + +1. **Is there an idiomatic `Io.Evented` pattern for "CPU-intensive startup task that must not starve other fibers"?** Our current `io.sleep(100ms)` between batches is a fixed yield. Is there a "yield to anything pending" primitive, or a fair scheduler we should be using? +2. **Should the HTTP probe endpoints run on a dedicated OS thread with their own event loop, specifically so business-logic stalls can't make kubelet kill the process?** We've seen this pattern in other relay implementations. The cost is some duplication + inter-thread handoff for anything `/metrics` wants to read, but the benefit is decoupling liveness from workload. +3. **Is 50 hosts per batch × 100ms yield reasonable, or should we be looking at "spawn 1 at a time with 0ms yield" or "spawn 500 at a time with 5s yield" or something else entirely?** The batching math here feels hand-tuned in a way we can't defend. +4. **Does anyone else run a zig-ecosystem network service in production at this scale? Any design patterns we should steal?** + +--- + +## what's deployed right now + +- Image: `atcr.io/zzstoatzz.io/zlay:ReleaseFast-bbba92c` +- Contains: + - Host_authority resolver pool with `keep_alive=false` (problem 1 workaround) + - Per-consumer ring buffer 8192 → 65536 in `broadcaster.zig` (separate fix for `ConsumerTooSlow` kicks on downstream subscribers, not covered in this doc but shipped at the same time) + - Per-branch `relay_host_authority_reject{branch=...}` counters + sampled warn logs +- k8s Deployment probes (cluster state, not yet captured in `zlay/deploy/` yaml): + - Liveness: `initialDelay=300s timeout=15s failureThreshold=20 period=30s` + - Readiness: `initialDelay=60s timeout=15s failureThreshold=20 period=15s` + +Pod is currently 1/1 Running. Readiness has flapped briefly a few times during startup spawn but kubelet has not killed it. Host_authority reject rate is ~0.24% (all legitimate policy drops). We do not consider either problem solved. Both have band-aid workarounds. + +--- + +## what we're asking for + +Priority order: + +1. **Is the "pool has no slot recovery" shape of fix structurally sound?** If yes, we'll implement it. If you can poke holes in it, we'd rather hear about them before we ship and have to revisit. +2. **Any independent guesses about what's actually breaking the pool** that we can test. We have production telemetry we can instrument, including a planned "1 of 4 slots with `keep_alive=true`, 3 with `keep_alive=false`" experiment to capture the error kind from production. Open to better ideas. +3. **Architectural thoughts on HTTP probe isolation.** We think dedicated-thread probes might be the right long-term answer, but we want to hear if you've seen this go wrong. +4. **General sanity check on the Evented+Threaded hybrid** — is this architecture load-bearing correctly, or are we accumulating workarounds on top of a fundamentally confused threading model? + +We're not in crisis. The relay is running. We want to get to a state where both bands-aids come off and are replaced with things we understand. + +--- + +## code pointers + +- Slurper spawn entry: [`zlay/src/slurper.zig:303`](https://tangled.org/zzstoatzz.io/zlay) (`io.concurrent(spawnWorkers, ...)`) +- `spawnWorkers` body: `zlay/src/slurper.zig:625-686` +- Frame worker hot path: `zlay/src/frame_worker.zig:85-128` (host_authority check at 98-128) +- Resolver pool state + init: `zlay/src/validator.zig:65` + `:143` +- Pool acquire/release: `zlay/src/validator.zig:600-615` +- `resolveHostAuthority`: `zlay/src/validator.zig:568-599` +- `resolveLoop` (single-owner, works): `zlay/src/validator.zig:449-500` +- `checkPdsHost` (downstream branches, not implicated): `zlay/src/validator.zig:618-660` +- HTTP/WS server: `zlay/src/main.zig:414-418` (`io.concurrent(runWsServer, ...)`) +- Metrics server: `zlay/src/main.zig:384-396` (`io.concurrent(MetricsServer.run, ...)`) +- zat transport (outer error swallow): `zat/src/internal/xrpc/transport.zig:62-75` +- zat DID resolver (inner error swallow): `zat/src/internal/identity/did_resolver.zig:41-107` + +## git context + +- zig 0.16 migration: commit `9cc1ba3` on 2026-04-05 (`migrate to zig 0.16: Io primitives, updated deps, timer regression fixes`) +- Resolver pool added: commit `1639565` on 2026-03-18 (`host authority: reuse pooled resolvers + add diagnostics`) — was working on zig 0.15 +- Per-branch counters + buffer bump: commit `ee4e368` (2026-04-08) +- Build failure on `_ = err1;`: commit `584571a` (zig 0.16 rejected the error-set discard; `zig build test` passed because the test module didn't reference `resolveHostAuthority` so lazy analysis skipped it) +- Final workaround: commit `bbba92c` (dropped the `|err1|` capture, wired sampled log into resolve branch, flipped `keep_alive=false` on the pool) + +## appendix: things we ruled out along the way + +- DB lookup of host id by hostname (`getHostIdForHostname`) — verified via direct psql +- plc.directory availability — verified via curl from outside the pod for DIDs the pod was rejecting +- ca-certificates — container has them +- `extractHostFromUrl` edge cases on bsky shard hostnames — they're plain `https://{shard}.host.bsky.network`, nothing unusual +- `zig build test` as a sufficient CI check for zlay validator changes — it's not (lazy analysis won't force-check functions that aren't referenced from tests); engineer rule added: run `zig build` (exe) in addition to `zig build test` +- "zig 0.16 `std.http.Client` stale keep-alive handling is broken" — this was our first hypothesis, held in writing too confidently, falsified by the engineer's standalone repro. It had the right shape (workaround involves keep_alive) but the wrong causal claim. diff --git a/docs/zlay-handoff-2026-04-09-rollback.md b/docs/zlay-handoff-2026-04-09-rollback.md new file mode 100644 index 0000000..e3d9687 --- /dev/null +++ b/docs/zlay-handoff-2026-04-09-rollback.md @@ -0,0 +1,208 @@ +# zlay: rollback to b91382b restored downstream delivery — report for engineering + +*2026-04-09, operator handoff after the earlier review doc* + +this is a follow-up to `zlay-external-review-2026-04-09.md` and +`zlay-broadcaster-starvation-2026-04-09.md`. it is written **for the +zlay engineer, by the operator**. no code changes shipped in this +session — the actions were all at the k8s / image-tag layer. + +## tl;dr + +- rolled back the zlay deployment from `ReleaseFast-4f3d1d4` → + `ReleaseFast-zat21-b91382b` (the 2026-04-06 build). +- external consumer delivery went from **6 frames / 170s + (0.035 fps)** on `bbba92c`/`795cc41`/`4f3d1d4` to + **~400 fps at 99.4% of ingest** on b91382b. same code path, + same cluster, same PDS pool, ~10 minutes apart. +- `relay_validation_failed{reason="host_authority"}` on b91382b is + **1.3% steady state** (7 / 551). the 99.5% reject rate you fixed + with `keep_alive=false` on bbba92c is **not present** on b91382b. +- those two measurements together narrow the introduction window + for both bugs to **2026-04-06 → 2026-04-07**. the broadcaster- + starvation doc already flagged commit `1eec324` (FrameWork UAF + fix) as suspicious because it changed how FrameWorks are queued. + i want to flag it again, harder: it is now the prime suspect for + *both* the delivery collapse and the host_authority bug. +- current pod is healthy and serving evaluators, but **b91382b + still has the FrameWork.hostname UAF** that 1eec324 fixes. a + reconnect storm (cron fires every 4h) may trip the UAF and + restart the pod. i'm accepting that risk to keep the evaluators + alive until you can ship a build that has the 1eec324 fix + *without* the delivery regression. + +## the measurements + +### pre-rollback (pod: `zlay-6c776bf9b9-zv9pl`, `4f3d1d4`, 28m uptime) + +| signal | value | +|---|---| +| `frames_received_total` | 742988 | +| `frames_broadcast_total` | **478** (frozen at cold-start value) | +| `consumers_active` | 0 | +| `host_authority_reject{branch="host_mismatch"}` | 15,257 / 17,236 (**88%**) | +| `host_authority_reject{branch="resolve"}` | 0 (the `keep_alive=false` workaround holds) | +| internal `/metrics` (first probe, port-forward) | 200 in 0.5s | +| internal `/metrics` (second probe, 15s later) | hung >10s | +| external `https://zlay.waow.tech/_health` | **503** (ingress) | +| `endpoints/zlay` in k8s api | **empty** | +| pod `Ready` condition | flipped `True→False` at 20:59:34Z | + +pod is `1/1 Running` in the kubelet's view but `Ready=False` and out +of the service endpoints — the relaxed probes from your handoff +(`initialDelay=300s failureThreshold=20`) are keeping the container +alive but the readiness probe is still failing enough to drop it +from the service. external consumers see 503. + +### post-rollback (pod: `zlay-679c966669-6xg5v`, `ReleaseFast-zat21-b91382b`) + +**probe sweep at ~90s uptime:** + +| probe | result | +|---|---| +| `https://zlay.waow.tech/_health` | 200 in 0.29s | +| `https://zlay.waow.tech/xrpc/_health` | 200 in 0.23s | +| raw `wss://.../subscribeRepos` (python websockets, 15s) | **5,896 frames, ~395 fps** | +| `just zlay test-tap 30` | connected + ran full 30s without error | + +**metrics delta with an active consumer attached (15s window):** + +| metric | t0 | t1 | Δ | +|---|---:|---:|---:| +| `frames_received_total` | 472534 | 479377 | +6843 | +| `frames_broadcast_total` | 20828 | 27629 | +6801 | +| `consumers_active` | 1 | 1 | — | + +**delivery ratio = 6801/6843 = 99.4%.** in the same conditions, +`4f3d1d4`/`bbba92c`/`795cc41` have `frames_broadcast_total` frozen +at their cold-start value even while a consumer is actively +subscribed. the 1.1%-ish gap on b91382b is within the range of +normal prevData chain-break filtering you'd expect. + +**host_authority on b91382b (no active workaround, no slot +recovery, no per-branch breakdown, just the aggregate counter):** + +``` +relay_host_authority_checks_total 513 +relay_validation_failed{reason="host_authority"} 1 # at uptime ~4 min +relay_validation_failed{reason="host_authority"} 7 # at uptime ~6 min +``` + +**0.19% → 1.3%** over the ramp-up window. well within normal +legitimate-policy-drop range. `workers_count` was still climbing +(531 → 652 → 704) so this is not a full-load measurement — the +reject rate may climb as the host table fully ramps, but there is +no evidence yet of the 99.5% catastrophic rejection you saw on +bbba92c-pre-workaround. + +## what this tells us about when the bugs were introduced + +the ops-changelog 2026-04-06 entry documents that `b91382b` (your +zat v0.3.0-alpha.21 release) was observed with tap and hydrant +"consuming cleanly with no rejections". your 04-07 entry and the +2026-04-09 investigation confirmed that by the time `31825b2` +was running, (a) downstream delivery was broken ("33% dropout rate +on relay-eval") and (b) host_authority was rejecting at 99.5% +(discovered retroactively on 04-09). both bugs were present and +unobserved on 31825b2. + +my measurements today close the loop: b91382b does not have either +bug. so both were introduced between `b91382b` and `31825b2`. the +commits in that window are, per the broadcaster-starvation doc: + +``` +1eec324 fix UAF: dupe FrameWork.hostname per submit instead of borrowing +31825b2 subscriber: extract prepareFrameWork + add UAF regression test +``` + +both touch FrameWork queueing. this is the same suspicion the +broadcaster-starvation doc raised — it's now harder to dismiss. + +**possible mechanism (hypothesis, not proven):** if `1eec324` +changed the sequence or timing of when a FrameWork is handed off +to the frame worker pool vs when `host_authority` runs vs when the +pool-slot resolver is touched, it could be doing something that: + +1. puts the host_authority pool's `std.http.Client` into a state + the single-owner `resolveLoop` never reaches (we never + confirmed what actually poisoned the pool slots — the + `keep_alive=false` workaround just avoided the reuse pattern) +2. creates backpressure against the broadcaster fiber on main + `Io.Evented`, forcing it into the polling-loop starvation state + the broadcaster-starvation doc described + +i am not claiming these are the mechanisms. i'm saying: the fact +that a single commit window introduced both bugs at once, both +affecting the frame-queueing hot path, is enough evidence to +direct the next diagnostic at that commit specifically rather than +at the resolver pool or the writeLoop in isolation. + +## what i'd ask for (operator-side asks) + +1. **treat `1eec324` and the 04-07 FrameWork queueing refactor as + the suspect** for both the host_authority bug and the + broadcaster delivery collapse. before shipping the Option A + writeLoop fix on top of `4f3d1d4`, consider git-bisecting the + 04-06 → 04-07 commit window against a simple 15-second + websocket consumer that counts frames. i can run that check + against any canary image you ship to atcr — it's a 10-line + script. +2. **the real target build** is: `1eec324` + `bbba92c` (host_authority + keep_alive=false workaround) + `795cc41` (slot recovery + + observability) + the fix for whatever `1eec324` actually broke. + none of the 04-09 builds have that combination because they + build on top of the regression. +3. **don't assume the host_authority fix is sufficient.** the + keep_alive=false workaround fixed the symptom of a poisoned + pool, but the poisoning itself is likely the downstream effect + of the same thing that broke delivery. if you fix delivery and + the host_authority bug goes away without the workaround, that's + strong evidence the two are the same bug. + +## what i am doing on the operator side + +- leaving the pod on `ReleaseFast-zat21-b91382b` until you ship + something better. external consumers can evaluate zlay again + from this state. +- watching for FrameWork UAF restarts over the next 4-hour + reconnect cron cycle. if the pod restarts with a + stack-pointer-shaped hostname in the logs, i'll roll forward to + `31825b2` (which has the UAF fix but re-introduces the delivery + bug) only as a last resort — a relay that crashes every 4h and + serves 400 fps between crashes is still better for evaluators + than a relay that stays up and serves 0 fps. +- leaving the relaxed k8s probes in place. they don't hurt a + fast-responding pod, and the engineer rule is "relax probes, + don't fix the underlying bug with probes" — but on b91382b the + HTTP fibers are fast anyway. +- leaving `HOST_RESOLVER_POOL_SIZE` at its default (b91382b + predates the env var entirely — it's just the hardcoded 4). +- no code changes from me this session. that is intentional: the + operator's purview is deploy + dial-turn + measurement + + reporting. fixing zig code is yours. + +## reproducing the measurements + +for the next operator or for you: + +```bash +# external health + delivery rate, no port-forward needed +curl --connect-timeout 3 -m 5 https://zlay.waow.tech/_health +uvx --from 'websockets==13.*' python -c ' +import asyncio, websockets, time +async def main(): + async with websockets.connect("wss://zlay.waow.tech/xrpc/com.atproto.sync.subscribeRepos", max_size=None) as ws: + n = 0; t = time.time() + while time.time() - t < 15: + await ws.recv(); n += 1 + print(f"{n} frames in 15s = {n/15:.1f} fps") +asyncio.run(main()) +' + +# metrics delta (needs port-forward to :3001 and a consumer attached for frames_broadcast to move) +kubectl --kubeconfig=zlay/kubeconfig.yaml -n zlay port-forward deploy/zlay 3001:3001 & +``` + +i'll probably encode this as `just zlay probe` and `just zlay +delta` recipes in a follow-up, so the next operator doesn't have +to rediscover it. diff --git a/docs/zlay-threaded-resolution-2026-04-10.md b/docs/zlay-threaded-resolution-2026-04-10.md new file mode 100644 index 0000000..e7d1c88 --- /dev/null +++ b/docs/zlay-threaded-resolution-2026-04-10.md @@ -0,0 +1,133 @@ +# zlay: Io.Threaded resolution — 2026-04-10 + +closes the april 8-9 incident and the broader 0.16 coverage degradation. + +## what we shipped + +two commits on 2026-04-09, deployed sequentially: + +### 1. `e6cdf84` — switch to Io.Threaded backend + +one-line change: `const Backend = Io.Evented` → `Io.Threaded` in +`src/main.zig:61`. switches from io_uring fiber scheduling (~35 threads) +to thread-per-PDS (~2,800 OS threads). this was the proven model on +0.15, which ran at 99%+ coverage. + +also enables **ReleaseSafe** (was impossible under Evented due to a zig +codegen bug in fiber context-switch). ReleaseSafe gives panic + stack +trace on safety violations instead of silent undefined behavior. + +### 2. `4735725` — fix socket-after-close race + buffer bump + +ReleaseSafe immediately surfaced a pre-existing bug: `dropSlowConsumer` +(broadcast thread) called `conn.close()` while the websocket server's +`readLoop` (server thread) was calling `posix.setsockopt` on the same +fd. under ReleaseFast this was silent UB on every prior build. + +fix: socket close ownership moved from broadcast thread to writeLoop +thread. `dropSlowConsumer` only sets `alive=false`; writeLoop exits, +drains, then closes. also bumped consumer BUFFER_CAP 8192 → 65536 +(~3 min headroom at 335 fps instead of ~24 sec). + +## why Io.Threaded + +switching to Io.Threaded eliminates the failure mode in production and +restores delivery to expected levels. Evented is the leading regression +source for the acute april 8-9 outage, and plausibly for the broader +~10-15% coverage degradation since `9cc1ba3`, but we did not fully +root-cause every sub-symptom inside the Evented pipeline. the known +issues under Evented: + +- 8 cross-Io crash classes (Threaded futex on Evented fiber → NULL + threadlocal → SIGSEGV or heap corruption) +- ReleaseSafe GPF from fiber context-switch codegen bug (forced + ReleaseFast, hiding safety violations) +- HTTP fiber starvation under load (the ~10-40 min degradation cycle) +- persist_order_spins 33M/sec (mutex contention from Evented scheduler) +- broadcast_queue_depth_hwm 8,191 (Evented scheduler couldn't drain) +- zig team marks Evented as "experimental" with "important followup work" + +all of these vanish under Threaded. the only cost is thread count +(~2,800 instead of ~35), which matches the 0.15 baseline that ran at +99%+ coverage for months. + +## measurements + +### `4735725` (Threaded + ReleaseSafe + consumer fix) at T+22 min, 2,700 workers + +| signal | value | vs Evented builds | +|---|---|---| +| /_health | 200 in 0.29s | Evented: hung after 10-40 min | +| delivery (raw ws) | 152 fps (still ramping) | Evented canary 1: 0 fps at failure | +| host_authority rejects | 0 new/15s steady state | Evented: 88-99% reject rate | +| pool_queued_bytes | 0-13k oscillating | Evented: 64 MiB stuck | +| persist_order_spins | **2.9k/sec** | Evented: **33M/sec** (11,000× higher) | +| broadcast_queue_depth_hwm | 36 | Evented: 8,191 | +| RSS | 1.89 GiB stable | comparable | +| restarts | 0 | Evented: crashed at T+10-80 min | + +### `e6cdf84` (first Threaded build, before consumer fix) fully ramped + +| signal | value | +|---|---| +| delivery ratio (consumer attached) | 97.3% (5.0k/5.1k in 15s) | +| host_authority rejects | 93% cumulative (ramp residue), 1.5% steady | +| persist_order_spins | 28.2k/sec | +| RSS | 1.92 GiB stable | +| crash | 1 restart at T+80 min (socket race, fixed in 4735725) | + +### hydrant verification (4735725) + +739,075 events consumed in 30s with full signature verification, 0 +errors. clean log. no crash, no ConsumerTooSlow. + +## what the reviewer's analysis got right and wrong + +the reviewer's handoff (2026-04-09 evening) correctly identified: +- the 0.16 migration (`9cc1ba3`) as the true coverage inflection point +- `1eec324` (UAF fix) as NOT the prime suspect (canary 1 was healthy) +- cross-Io mistakes as a recurring failure class + +the reviewer recommended tracing the Evented pipeline with Tracy and +making narrow fixes. we chose a different path: abandon Evented entirely +and switch to Threaded. this was faster, simpler, and eliminated the +entire problem class rather than trying to trace scheduler behavior in +an experimental runtime. + +the reviewer explicitly said "do not revert to thread-per-PDS — that +defeats the architectural point." we respectfully disagreed. the +architectural point (thread reduction) is subordinate to having a +working, debuggable system. Evented can be revisited when zig's runtime +matures. + +## what's left + +### fixed by this work +- [x] HTTP fiber starvation / 10-40 min degradation cycle +- [x] host_authority 88-99% reject rate (not reproducing under Threaded; Evented appears to have amplified or concentrated it, but root cause attribution is incomplete) +- [x] persist_order_spins mutex contention (33M → 2.9k/sec) +- [x] broadcast_queue backpressure (8,191 → 36 HWM) +- [x] socket-after-close panic in consumer drop path +- [x] ConsumerTooSlow frequency (8192 → 65536 buffer) +- [x] ReleaseSafe enabled (was blocked by Evented GPF) + +### still open (not blocking, not urgent) +- orphaned `account.host_id = 0` sentinel (4.11% of accounts) — causes + `is_new` burst during cold start, not a reject source +- Consumer.writeLoop polling (100ms sleep instead of cond.wait) — caps + per-consumer throughput at ~10 fps. real bug, low priority. +- DiskPersist.gc() holds persist mutex for entire body — real bug, low + priority now that gc runs on its own thread without Evented contention +- pool_io redundancy — both runtimes are now Threaded, pool_io can be + merged. cleanup, not urgent. +- DbRequestQueue bridge — unnecessary under all-Threaded. cleanup. +- uring networking patch inert in Dockerfile — cleanup. + +## deploy recipe + +``` +just zlay publish-remote ReleaseSafe +``` + +note: **ReleaseSafe**, not ReleaseFast. the fiber GPF that forced +ReleaseFast was Evented-only.