diff --git a/docs/M3a/DEBUG-HANDOFF.md b/docs/M3a/DEBUG-HANDOFF.md index c1e5d84..73e9ce0 100644 --- a/docs/M3a/DEBUG-HANDOFF.md +++ b/docs/M3a/DEBUG-HANDOFF.md @@ -1,5 +1,38 @@ # Debug handoff: brokerd admin-test hang (m3a branch) +## Resolution (2026-09-22, design model) + +Resolved. The conclusions below are wrong and are kept only as the record of the investigation. +There is no fsync stall. The failure is a macOS rule about socket options, and it was in loopd's +production code as well as in the test client. + +- **The cause.** macOS refuses every socket option with `EINVAL` once the peer has closed (XNU + `sosetoptlock`, `bsd/kern/uipc_socket.c`: both `SS_CANTRCVMORE` and `SS_CANTSENDMORE` set), + even while unread data is still buffered and readable. Linux never refuses. Anything that sets a + read timeout before each read therefore fails on macOS as soon as the peer has sent its last + bytes and closed. Measured directly: after a peer writes and closes, `setsockopt(SO_RCVTIMEO)` + returns `EINVAL` on the Mac and succeeds on Talos, and the following read returns the data on + both. +- **It was never intermittent.** At `2408e2c` the admin test failed 40 runs of 40 on the Mac, + every one at `client.rs:60` with `os error 22`, and passed 40 of 40 on Talos. The work before + this handoff ran on Talos (Linux); the handoff and `hold_open` were done on the Mac. +- **It was also a production bug.** loopd set a read timeout before every read in `BrokerPort` + (`Deadline::read`) and in the HTTP client used for llama-server. On the Mac, twelve loopd test + binaries failed with `os error 22`; `make gate` never reached them because `cargo test` stops at + the first failing binary, which was brokerd's `admin`. +- **The "fsync stall" was a misread profile.** On macOS `File::sync_all` is + `fcntl(F_FULLFSYNC)`, so every sync shows as `__fcntl`. It costs about 4 ms here (p50 4.1 ms, + max 8.5 ms over 600 calls), and the admin binary does hundreds, so each run takes 2 to 9 s on + the Mac against under 1 s on Talos, where the test directories are on tmpfs. A sample catches + threads there because that is where the time goes, not because they are stuck. With `hold_open` + in place, 170 admin runs on the Mac and 50 on Talos, and 10 to 20 runs of every brokerd test + binary on each host, had no hang and no failure. +- **The fix.** `loopd::socket::set_read_timeout` takes that one refusal as success on Apple + targets (a socket shut in both directions cannot block on a read), and both loopd call sites use + it (`00a85c1`). The brokerd test client does the same (`d7009dc`, and in + `docs/plans/M3a/files/`). `hold_open` is removed (`57dc789`); it only hid the test client's + problem, and it kept every handler thread for up to 2 s after its final frame. + ## The bug On the `m3a` branch, the brokerd admin tests (and any brokerd test that runs a full broker diff --git a/docs/implementer-lessons.md b/docs/implementer-lessons.md index 4eecb51..3b2a819 100644 --- a/docs/implementer-lessons.md +++ b/docs/implementer-lessons.md @@ -28,6 +28,7 @@ How it is used: | I10 | If a tool you were told to use does not exist, stop and say so. Do not invent a command in its place. | Laguna as coordinator ran `opencodec`, which does not exist, and then diagnosed its own typo. | yes | | | I11 | A rule about one path applies to every path that does the same thing. If a task says "release X before the final frame", every final frame counts, including the error frames written earlier in the function. | M2b finding 1. | yes | | | I12 | A file that exists but cannot be read is an error. Only a file that does not exist may be treated as absent. | M2b finding 3. | yes | | +| I13 | Before calling a failure "environmental", measure the thing you blame, and name the machine, OS and file system the evidence came from. A sample that shows a thread inside a system call shows where the time goes, not that the call is stuck. | M3a stop before task 20: an fsync "stall" was blamed from `__fcntl` frames that were ordinary 4 ms `F_FULLFSYNC` calls on the Mac, and the real cause, a macOS socket rule, went unfixed. | no | | ## Tips for writing tasks @@ -50,6 +51,7 @@ How it is used: | T15 | Running the whole plan through `tools/run-plan.sh` worked: ten tasks, one commit each, unattended, in about three hours. Keep the TUI closed while it runs; a second message into the driver's session starts a second agent on the same tree. | M2b run, 2026-09-18. | | T16 | When a task prescribes the fix, check that it compiles against the types as they are, in the reference tree, before handing it over. A fix that cannot be written as described pushes the implementer outside the listed paths. | M2b task 11: "`unwrap_or_else` with a fixed valid id" had no non-panicking form outside `proto`; the implementer added `Default` to `SessionId` and reported it. | | T17 | Match the check to the risk. A full reference for intricate logic whose writing debugs the spec (state machines, concurrency); a naive oracle inside the test for decision logic; a compiling skeleton (`todo!()` bodies under the real signatures) for plumbing. Record what each check exposed, and let the record decide what the next milestone gets. | Across M1 to M2b the references caught no implementer defect. They caught task defects (T16) and missed what they shared with the tests (T5). Decision of 2026-09-18. | +| T18 | The gate runs on two platforms, Talos (Linux) and the Mac (macOS), and they differ where the tests touch the OS: sockets, file sync, `/tmp`. Accept a task only when the gate passes on both. Code that sets a socket option after the peer may have closed breaks on macOS only. | M3a: `BrokerPort`, the HTTP client and the brokerd test client passed on Talos and failed on the Mac from task 13 on; it was found only when the gate was first run on the Mac. | ## What worked and should be kept diff --git a/docs/implementer-log.md b/docs/implementer-log.md index da9b0bb..ee84f2f 100644 --- a/docs/implementer-log.md +++ b/docs/implementer-log.md @@ -293,3 +293,20 @@ orchestrator and the workers (workers with thinking off); the commit trailer sti 01 and 02 come out almost identical to it (`wire.rs` differs in one line), which is expected: their task files give the types verbatim, so the likeness shows nothing either way. The review will say more. + +### M3a, the stop before task 20 ("brokerd admin fsync stall") — reviewed 2026-09-22 by the design model (Claude) + +The two `stopped` rows for this (`M3a/20-22` and `DEBUG-HANDOFF.md`) reached the wrong conclusion, +and the fix they committed hid the bug instead of fixing it. The stop itself was right: the gate +failed and the cause was not understood. `docs/M3a/DEBUG-HANDOFF.md` now opens with the resolution. + +| # | Severity | Owner | Finding | Fix | +|---|---|---|---|---| +| 1 | high | implementer (M3a/17) | `BrokerPort` and the HTTP client set a read timeout before every read. macOS refuses that with `EINVAL` once the peer has closed, so a response that arrived just before the close was reported as an outage. Twelve loopd test binaries failed on the Mac; none on Talos. | `loopd::socket::set_read_timeout` (`00a85c1`) | +| 2 | medium | task (M3a/13) | The given test client `next()` does the same, so every admin test that reads a second frame failed on the Mac (40 of 40 runs at `2408e2c`). | Fixed in the crate and in `docs/plans/M3a/files/` (`d7009dc`) | +| 3 | medium | implementer (debugging) | `hold_open` put a workaround for the test client into the handlers: each connection was held for up to 2 s after its final frame, and bytes the peer sent in that time were dropped. | Removed (`57dc789`) | +| 4 | medium | implementer (debugging) | The "fsync stall" was not measured. The sampled `__fcntl` frames are `F_FULLFSYNC`, which is how `sync_all` works on macOS and costs about 4 ms each; the claimed 7 to 12% hang did not appear in 270 runs on two hosts. The row says the tests ran on "this machine" without naming it, and Talos (Linux, tmpfs `/tmp`) and the Mac behave differently here. | Tips I13 and T18 | + +After the fixes, `make gate` passes on Talos. On the Mac, fmt, clippy, every test and the gate +scripts pass; `cargo deny` is not installed there, so the gate itself stops at that step. Tasks 20 +to 22 are no longer blocked.