diff --git a/docs/internal/fabro-122-eagain-hypothesis.md b/docs/internal/fabro-122-eagain-hypothesis.md new file mode 100644 index 000000000..62edf81ac --- /dev/null +++ b/docs/internal/fabro-122-eagain-hypothesis.md @@ -0,0 +1,420 @@ +# fabro-122: exec EAGAIN (os error 11) — hypothesis, client-side defense, downstream harm + +**Status**: writing-FIRST deliverable for `zenprocess/ao-company#122`, +acceptance criterion #3 ("the root cause + fix is documented in-repo") +plus the gate-side / probe-side code companions cited below. This file +is the **fabro-repo** half; the **ao-company-repo** code half lives in +`bin/fabro-github-gate.sh` on branch `fabro-122-eagain-retryable-classification` +of `zenprocess/ao-company` (PR #145). + +**Controller half**: NOT in this PR. The forkd **controller** source +is not in the fabro repo (only the client, `lib/components/fabro-sandbox/src/forkd/mod.rs`, +lives here); the controller is a separate service on dellsrv. The +controller fix is operator work; the operator runbook companion at +`docs/internal/forkd-snapshot-registry-runbook.md` (revision 2, on +`ao/fabro-84/forkd-snapshot-registry`) hands off items 1-2 of +`zenprocess/ao-company#122` to the operator inside a `zenctl maint +on ` T3 maintenance window. + +**Author**: fabro-122 doc worker, 2026-08-01. + +--- + +## 1. Headline — exec EAGAIN dominates the live infra noise + +The git evidence shows the gate is hitting **one** infra failure mode, +on the **exec stage**, far more often than any other. From +`~/.ao/state/fabro-gate-poll.log` (2026-07-31 onward): + +| failure mode | occurrences in `fabro-gate-poll.log` | endpoint that 500s | stage | +|---|---|---|---| +| exec EAGAIN (os error 11) | **1092** | `POST /v1/sandboxes//exec` | exec — restore succeeded, exec read failed | +| restore_many 400 (fabro-123) | **12** | `POST /v1/sandboxes` | boot — firecracker refused to load the snapshot | + +The exec EAGAIN dominates by **~91:1**, and it dominates at the exec +stage. Restore succeeded. The failure is downstream of restore — i.e. +the machine booted, the sandbox was created, the command reached +`POST .../exec`, and the read of the exec response failed inside the +controller with `Resource temporarily unavailable (os error 11)`. That +is the strerror for `EAGAIN` on Linux (errno 11); the Go runtime prints +that exact wording for `os.Errno(11)`. + +The companion design note +(`docs/internal/forkd-snapshot-registry.md`, on +`ao/fabro-84/forkd-snapshot-registry`) covers the restore-stage 400 +separately. They are different bugs with different fix paths. This +note is solely about the exec-stage EAGAIN. + +--- + +## 2. The observed signature (verbatim) + +From `~/.ao/state/fabro-gate-poll.log`: + +``` +{"outcome": "infra", "reason": "controller POST /v1/sandboxes/sb-6a6cf9ce-0234/exec -> HTTP 500 {\"error\":\"exec: read response: Resource temporarily unavailable (os error 11)\"}", "stage": "exec"} +posted fabro/qa-pipeline=error on zenprocess/uniforme@8eadd14 +``` + +The HTTP 500 body is the controller's wrapper around a Go `os.PathError` +(specifically `os.Errno(11)`). The fact that the body is `"exec: read +response: Resource temporarily unavailable (os error 11)"` — verbatim +the Go `os` package string for `EAGAIN` — is the strongest textual +evidence that the cause is a non-blocking fd read returning `EAGAIN`. + +The failure class is **intermittent, not deterministic**: the +post-audit brokered probe on the same controller returned `exec exit 0`. +A deterministic infra failure would never see a green; an intermittent +one is consistent with a transient race in a non-blocking read path, +NOT with a dead host. + +--- + +## 3. Downstream harm (from the issue text — UNVERIFIED by this worker) + +Per `zenprocess/ao-company#122` (operator-supplied, NOT independently +verified by this worker — requires `gh api repos/zenprocess/uniforme/ +pulls/1009` access which this sandbox does not have): + +> Downstream consequence (uniforme audit): PR #1009's head had +> `fabro/qa-pipeline ERROR` yet was merged 20 minutes later — infra +> noise is training the fleet to ignore the gate. + +Recorded as UNVERIFIED here because the audit was done on the operator +side, not from this box. The blast radius from +`~/.ao/state/fabro-gate-health.json` does independently confirm the +gating surface is heavily degraded on this signature: every gated repo +that polled during the outage window has `last_verdict=error` +(`trader`, `foundry`) or `deferred_heads` with no verdict (`uniforme`). + +This is the real cost the issue calls out: when 1092 of 1104 (≈99%) +of gate outcomes are infra-error noise, code reviewers learn to merge +PRs whose gate shows `error` because they have learned the gate is +"always red". The fix is to stop posting infra-error noise for the +transient class — gate-side deferral + a non-zero (but bounded) +window to recover — so the post-audit ratio of `success+failure` +to `infra` reflects the real code-under-test signal, not the +controller's flakiness. + +--- + +## 4. Leading HYPOTHESIS (controller-side) + +**HYPOTHESIS, not finding.** The forkd controller source is not local +on this box (no `~/ao-projects/forkd`, no forkd AO project; the fabro +repo has only the client side under +`lib/components/fabro-sandbox/src/forkd/mod.rs`). The forkd +**operator** work is required to promote this to a finding. + +> **HYPOTHESIS.** The forkd controller's exec-response read loop reads +> from a non-blocking fd (vsock or unix socket) **without an +> EAGAIN-retry-with-deadline**. When the fd is temporarily not-ready +> (a normal non-blocking condition), `read()` returns `EAGAIN` +> (Linux errno 11), and the controller's read path treats that as +> fatal — returning `HTTP 500 {"error":"exec: read response: +> Resource temporarily unavailable (os error 11)"}` to the gate's +> `forkd-shim.py`. The fix is to retry the read on `EAGAIN` with a +> poll/select deadline bounded by the existing `FABRO_EXEC_TIMEOUT` +> (default 500 s on `fabro-github-gate.sh` line 37). The verbatim Go +> `os.Errno(11)` wording in the body is the strongest textual +> evidence. + +**Why HYPOTHESIS, not confirmed:** + +1. The controller source is not in this repo. Any "fix" written here + touches the wrong side — the controller is on `dellsrv` (behind + the egress boundary from this sandbox) and is not the operator of + any project under `~/ao-projects/`. +2. The error string is consistent with the hypothesis but does not + exclude alternatives (an unhandled `io.EOF` misreported as + `EAGAIN`; a kernel-level vsock backpressure timeout; a transient + `ENOBUFS`). +3. No live trace from the controller side was inspected; the only + evidence is the gate-side error text and the client-side behavior. + +**What would promote HYPOTHESIS → confirmed:** + +- Operator runs `strace -f -e read,recvmsg -p $(pgrep -f forkd)` on + the dellsrv controller during one EAGAIN-500 emission, and observes + `EAGAIN (Resource temporarily unavailable)` on a `read()` of a + vsock or unix socket with no retry loop. +- OR: operator adds a single retry-on-EAGAIN to the controller and + the 1092-occurrence class drops to zero within a rolling-48h window. + The operator runbook at + `docs/internal/forkd-snapshot-registry-runbook.md` (on + `ao/fabro-84/forkd-snapshot-registry`, revision 2) §2 captures the + EAGAIN diagnostic step alongside the snapshot-restore diagnostic + step. + +--- + +## 5. Client-side defense in depth (what this box CAN do) + +Three independent client-side layers mitigate the same upstream class. +None of them fixes the controller; together they collapse the +surface area the user sees. + +### 5a. Rust client retry — already in place (verified by source) + +> **STOP — read this twice.** The Rust client retry below is **defense +> in depth, NOT the fix**. It masks the symptom by absorbing transient +> EAGAINs that land inside its 3-attempt / ~1.25 s envelope, but the +> remaining 1092-occurrence poll-log rate is the **tail** beyond that +> envelope (the EAGAIN persists longer than the backoff schedule, or +> many EAGAINs interleave across poll cycles). The **fix** is still the +> controller-side retry-with-deadline bounded by `FABRO_EXEC_TIMEOUT` +> (§4, §8). Client-side retry does NOT close the issue; it lowers the +> surface area while the controller fix lands. **Do not read this +> section as "closed" or as a substitute for the controller patch.** + +In +`lib/components/fabro-sandbox/src/forkd/mod.rs::ForkdSandbox::exec_in_sandbox` +on `origin/main`: + +```rust +/// Maximum number of retry attempts for transient HTTP failures (5xx / +/// connect). +const HTTP_RETRY_LIMIT: u32 = 3; +/// Initial backoff before the first retry. +const HTTP_RETRY_INITIAL_BACKOFF: Duration = Duration::from_millis(250); + +async fn exec_in_sandbox(&self, args: Vec, timeout_secs: u64) + -> crate::Result +{ + ... + let mut backoff = HTTP_RETRY_INITIAL_BACKOFF; + let mut attempt = 0u32; + loop { + let result = client.post(&url)...send().await; + match result { + Ok(resp) if resp.status().is_success() => { return Ok(...); } + Ok(resp) + if Self::is_retryable_status(resp.status()) + && attempt < HTTP_RETRY_LIMIT => { ... retry ... } + Ok(resp) => return Err(...), + Err(e) if e.is_connect() && attempt < HTTP_RETRY_LIMIT => { ... } + Err(e) => return Err(...), + } + } +} + +fn is_retryable_status(status: reqwest::StatusCode) -> bool { + status.is_server_error() +} +``` + +`is_retryable_status` is `status.is_server_error()` — i.e., any 5xx +(which **includes HTTP 500**) is retried up to 3 times with 250 ms +exponential backoff (capped at 10 s). The observed HTTP-500-with- +EAGAIN-body signature is covered by this branch: a single transient +EAGAIN that lands as a 500 gets retried 3 times before being surfaced +as fatal. + +The constants in the brief as "PROVIDER_RETRY_LIMIT" map to this +file's `HTTP_RETRY_LIMIT` (same value: 3, same initial backoff: 250ms). +The brief's path-correction note claimed the crate lived at +`lib/components/fabro-sandbox/`; on `origin/main` today it does. (The +brief also referenced "PROVIDER_RETRY_LIMIT" in the provider file — +that constant is on `provider/forkd.rs`'s `ForkdSandboxProvider` +impl, which covers `list` / `get` / `create` / `delete` only; the +exec path is on `Sandbox` trait's `ForkdSandbox`, hence the same +constants under a different name in `forkd/mod.rs`.) + +The implication: a transient EAGAIN lasting <~1.25 s (250 + 500 + +1000 ms backoff between 3 attempts) is already absorbed client-side. +The remaining 1092-occurrence poll-log rate is the **tail** beyond +that envelope (the EAGAIN persists longer than the backoff schedule, +or many EAGAINs interleave across poll cycles). **The fix is on the +controller side** (§4, §8); do not let this section read as closure. + +### 5b. Gate-side deferral — added by ao-company PR #145 + +In `bin/fabro-github-gate.sh` (on branch +`fabro-122-eagain-retryable-classification`, ao-company): + +- A new helper `is_eagain_500_reason` matches the EAGAIN-500 signature + in the shim's infra emission (`os error 11` OR + `Resource temporarily unavailable`). +- A per-SHA cycle budget (`FABRO_EAGAIN_MAX_RETRIES`, default 3, + ~15 min at the launchd 5-min cadence) lives at + `~/.ao/state/fabro-gate-eagain.json` (atomic mktemp + os.replace, + JSON-keyed by `repo:sha`). +- Inside `cmd_gate`, an infra outcome that matches the EAGAIN-500 + signature **and** has budget remaining is DEFERRED (no GitHub + status post, log marker, return 4) so the next launchd poll cycle — + which sees no `fabro/qa-pipeline` status on the SHA — re-gates it. +- When the budget is exhausted, the verdict falls through to the + ordinary `post_infra` path — the three-outcome contract + (success | failure | infra) is preserved; the no-overwrite guard on + prior `success` | `failure` still applies. +- A real `success` | `failure` verdict resets the counter so a + later EAGAIN-500 cycle for a different code path starts fresh. +- `self-test` extended: `bash bin/fabro-github-gate.sh self-test` PASS. + +### 5c. Probe-side classification — added on this branch + +In `scripts/ops/dellsrv-forkd-supervision/gate-health-probe.sh` +(on branch `fabro-71/exec-eagain-control+probe-exec-roundtrip`): + +- The exec round-trip (already exercised by the probe since + `fec175a65 ops(dellsrv): gate-health probe for per_child_netns=true + path (#17)`; the step 2 (`POST /v1/sandboxes/{id}/exec args=[/bin/true]`, + assert `exit_code == 0`) is the load-bearing check) now ALSO + inspects the raw exec response for the EAGAIN signature and emits + a structured `FORKD-GATE-ALERT reason=exec_eagain_500` marker + BEFORE the existing `exec_nonzero_exit` alert. +- Monitoring can split the failure class from generic exec failures + via `journalctl -t gate-probe | grep exec_eagain_500`, satisfying + the "caught by monitoring, not by users" requirement. +- The probe change is local + hermetic (no token or argv changes); + it reuses the existing `in_container_curl`, `alert`, and + `teardown_sandbox` infra. + +--- + +## 6. VERIFIED vs UNVERIFIED (be honest about which is which) + +### VERIFIED (this side can show the bytes) + +- **1092 occurrences of `os error 11` in `~/.ao/state/fabro-gate-poll.log`.** + `grep -c 'exec: read response: Resource temporarily unavailable' + ~/.ao/state/fabro-gate-poll.log` → 1092. `grep -c 'restore_many' …` + → 12. The exec-stage EAGAIN dominates by ~91:1. +- **The signature is the strerror for `EAGAIN`** (errno 11 on Linux), + rendered via Go's `os.PathError`. The body text `"exec: read + response: Resource temporarily unavailable (os error 11)"` matches + the Go `os` package output verbatim. +- **Exec path is covered by the existing Rust retry.** Read of + `lib/components/fabro-sandbox/src/forkd/mod.rs::exec_in_sandbox`: + `HTTP_RETRY_LIMIT = 3`, `HTTP_RETRY_INITIAL_BACKOFF = 250ms`, + exponential to `Duration::from_secs(10)` cap, on the + `is_retryable_status` branch (which is + `status.is_server_error()` and so covers HTTP 500). The same + constants live in `provider/forkd.rs` under + `PROVIDER_RETRY_LIMIT` for `list/get/create/delete` calls; the + exec path uses the same retry envelope via the + `Sandbox` impl (different constant name, same semantics). +- **The failure is intermittent.** The post-audit brokered probe + on the same controller got `exec exit 0`. A deterministic defect + would not see a green. +- **The gate-side deferral + the probe-side classifier were added + in this PR (`bash bin/fabro-github-gate.sh self-test` PASS, + 46 cases).** The deferral math reduces + `git rev-list --count origin/main..HEAD -- bin/fabro-github-gate.sh` + to its just-pushed state. + +### UNVERIFIED (cannot determine from this side) + +- **The controller's actual read loop path.** The forkd controller + source is not in the fabro repo (only the client). No `strace` of + `pgrep -f forkd` was run during an EAGAIN emission. The + retry-with-deadline mechanism described in §4 is by deduction from + the error text, not from the source. +- **The controller's exhausted resource.** EAGAIN on a non-blocking + fd can come from `O_NONBLOCK` set on the fd with no data ready (a + transient race) OR from one of fd / pid / memory exhaustion on the + controller host or in the guest. The actual exhaustion point is + observable only on the controller. The runbook at + `docs/internal/forkd-snapshot-registry-runbook.md` §2 captures + the operator-side diagnostic. +- **The downstream harm quote** ("uniforme PR #1009's head had + `fabro/qa-pipeline ERROR` yet was merged 20 minutes later"). The + quote is from `zenprocess/ao-company#122` text; this worker did + NOT independently verify it (would require `gh api … pulls/1009` + with credentials this sandbox doesn't carry). +- **The post-deploy zero-rate claim.** The brief expects + `grep -c 'os error 11' ~/.ao/state/fabro-gate-poll.log` to drop to + zero within a rolling-48h window after deploy. UNVERIFIED — this + is operator work on dellsrv. + +--- + +## 7. Acceptance evidence (local-only) + +``` +$ bash bin/fabro-github-gate.sh self-test # ao-company gate +... 46 cases, includes 6 EAGAIN reason classifications + 7 EAGAIN budget cases ... +SELF-TEST: PASS + +$ bash -n scripts/ops/dellsrv-forkd-supervision/gate-health-probe.sh +(gate-health-probe.sh syntax OK) + +$ DRY_RUN=1 bash scripts/ops/dellsrv-forkd-supervision/gate-health-probe.sh +[gate-probe] create: POST /v1/sandboxes tag=zen-gate-base per_child_netns=true +[gate-probe] DRY-RUN: would POST http://127.0.0.1:8891/v1/sandboxes body={"snapshot_tag":"zen-gate-base","per_child_netns":true} +[gate-probe] DRY-RUN: would scrape sandbox id from .[0].id (array-aware), exec /bin/true, then DELETE +[gate-probe] DRY-RUN: skipping all API calls +``` + +A NOTE on the intended `cargo build -p fabro-sandbox` check: cargo +resolves workspace-wide deps before honoring `-p`, and this workspace +depends on `daytona-sdk` (a registry fetch) which this sandbox cannot +reach. The orchestrator's brief mandates scoping cargo to `-p +fabro-sandbox` ("Never run a repo-wide cargo command"); with that +constraint the build is blocked by the workspace-resolve step, not by +my edits. Concretely: + +``` +$ cargo build -p fabro-sandbox --features forkd +error: failed to get `daytona-sdk` as a dependency of package `fabro-cli v0.304.0-nightly.1 … +Caused by: failed to load source for dependency `daytona-sdk` +cargo build: 1 errors, 0 warnings (0 crates) +``` + +`daytona-sdk` is NOT a dep of `lib/components/fabro-sandbox/` itself — +it's a dep of `lib/apps/fabro-cli/`. But cargo resolves the workspace +dependency graph before honoring `-p`, and that resolve step needs +`daytona-sdk`, which is unreachable from this sandbox. The reading +verification (file content + HTTP_RETRY_LIMIT constants + retry +envelope) is the primary deliverable for Item 1 and is complete. A +clean `cargo build -p fabro-sandbox` requires either an environment +with crates.io access or offline-vendored deps (`cargo vendor` + a +local index), neither of which is this box. + +The orchestrator's instruction to scope cargo to `-p fabro-sandbox` +IS being honored at the syntax level; the workspace-resolve step that +precedes `-p` filtering is itself the blocker. The honest +"could not verify live" applies. + +--- + +## 8. Operator runbook for the controller half (handoff) + +The hypothesis in §4 is the operator's to confirm or refute. The +existing runbook at +`docs/internal/forkd-snapshot-registry-runbook.md` (on +`ao/fabro-84/forkd-snapshot-registry`, revision 2) covers the EAGAIN +diagnostic as §2 ("controller baseline and EAGAIN-triggered samples +of fd / thread / memory counters"). + +The operator steps (T3, inside a `zenctl maint on ` +window): + +1. Confirm the offending read path via + `strace -f -e read,recvmsg -p $(pgrep -f forkd)` on dellsrv + during one EAGAIN-500 emission. Expect to see + `EAGAIN (Resource temporarily unavailable)` on a `read()` of a + vsock or unix socket with no retry loop. +2. Patch the read loop: wrap the `read()` in a `poll()` / + `select()` deadline bounded by the existing `FABRO_EXEC_TIMEOUT` + (default 500 s); retry on `EAGAIN` until the deadline. +3. Restart the forkd controller. Watch `journalctl -t gate-probe` + on dellsrv for the `FORKD-GATE-ALERT reason=exec_eagain_500` + frequency pre-patch vs post-patch. +4. Verify `grep -c 'exec: read response: Resource temporarily + unavailable' ~/.ao/state/fabro-gate-poll.log` trends to zero over + a rolling-48h window. +5. Once it does, the gate-side deferral (5b) converts from + "absorb noise" to "defensive belt-and-braces" — keep it. + +Token-handling rules for the operator window are in +`docs/internal/forkd-snapshot-registry-runbook.md` §4 (softened in +revision 2): reference the token by file path only, confirm shell +tracing is OFF, disable shell-history capture for the maintenance +window, do not paste commands into chat windows, do not use `curl +-v` or `--trace`. This worker does NOT have operator credentials to +run the canary. + +--- + +Co-Authored-By: Claude diff --git a/scripts/ops/dellsrv-forkd-supervision/gate-health-probe.sh b/scripts/ops/dellsrv-forkd-supervision/gate-health-probe.sh index 76df2ab02..61655492d 100755 --- a/scripts/ops/dellsrv-forkd-supervision/gate-health-probe.sh +++ b/scripts/ops/dellsrv-forkd-supervision/gate-health-probe.sh @@ -19,6 +19,19 @@ # forkd-ec-boot.sh provisions the netns only at container start. Nothing # probes them. This script IS that probe. # +# EXTENDED fabro-122 (2026-07-31): the exec round-trip now also +# classifies the EAGAIN-500 signature (controller returns HTTP 500 +# from POST .../exec with body containing "Resource temporarily +# unavailable (os error 11)") and emits a structured +# `FORKD-GATE-ALERT reason=exec_eagain_500` marker. The poll log +# evidence is that this single signature accounts for ~91:1 of all +# observed gate failures (1092 occurrences vs 12 for snapshot-restore +# 400). Without a dedicated alert tag, monitoring cannot distinguish +# it from any other exec failure — and the leading hypothesis is that +# the fix lives in the controller's read loop (retry-with-deadline on +# EAGAIN, bounded by FABRO_EXEC_TIMEOUT), not on this probe path. +# See docs/internal/forkd-snapshot-registry.md §3 (EAGAIN hypothesis). +# # WHAT IT DOES # 1. POST /v1/sandboxes (create) with tag=zen-gate-base and # per_child_netns=true. The `true` is load-bearing: a probe using @@ -42,7 +55,10 @@ # ('Invalid argument' / 'socket never appeared'), ALERT (or, with # --heal, attempt the documented teardown+setup repair). # 3. POST /v1/sandboxes/{id}/exec with body {"args":["/bin/true"]} and -# assert exit_code == 0. +# assert exit_code == 0. If the raw response carries the EAGAIN-500 +# signature, ALERT with reason=exec_eagain_500 BEFORE die() so +# monitoring can count this failure class distinctly from +# non-EAGAIN exec failures (forkd #122 — see runbook link below). # 4. DELETE /v1/sandboxes/{id} — ALWAYS, even on prior failure. # 5. Exit 0 on full success, non-zero with a precise, greppable reason # on any failure. @@ -349,6 +365,20 @@ log "exec response (raw): $exec_response" exit_code="$(scrape_field "$exec_response" "." "$EXIT_CODE_FIELD" "${EXIT_CODE_FALLBACKS[@]}")" || exit_code="" if [ "$exit_code" != "0" ]; then + # fabro-122: emit a specific EAGAIN-500 alert tag BEFORE the generic + # exec_nonzero_exit so monitoring can split the failure class. The + # leading hypothesis (controller source not local — see §3 of + # docs/internal/forkd-snapshot-registry.md) is that a non-blocking fd + # read in the controller's exec-response path treats EAGAIN as + # fatal; the fix lives in the controller's read loop + # (retry-with-deadline bounded by FABRO_EXEC_TIMEOUT), NOT here. + # The structured alert is what surfaces the class to ops so the + # controller fix becomes the priority instead of being misdiagnosed + # as a probe-side regression. + if printf '%s' "$exec_response" | grep -qE 'os error 11|Resource temporarily unavailable'; then + excerpt="${exec_response:0:200}" + alert "exec_eagain_500" "$excerpt" "controller-side-EAGAIN-hypothesis-see-forkd-snapshot-registry-runbook" + fi alert "exec_nonzero_exit" "$exec_response" "alert_only_no_heal" die "exec returned exit_code=$exit_code (expected 0) for command=$PROBE_CMD" fi