Record the resolution of the M3a "fsync stall": a macOS socket rule
The handoff and the two stopped rows blamed an environment fsync stall. The cause was macOS refusing socket options after the peer closes, in loopd and in the brokerd test client. The handoff now opens with the resolution, the log gets a review note (the stopped rows are kept as written), and the lessons gain I13 (measure what you blame, and name the machine) and T18 (the gate must pass on Talos and on the Mac). Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
@@ -1,5 +1,38 @@
|
|||||||
# Debug handoff: brokerd admin-test hang (m3a branch)
|
# 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
|
## The bug
|
||||||
|
|
||||||
On the `m3a` branch, the brokerd admin tests (and any brokerd test that runs a full broker
|
On the `m3a` branch, the brokerd admin tests (and any brokerd test that runs a full broker
|
||||||
|
|||||||
@@ -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 | |
|
| 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 | |
|
| 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 | |
|
| 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
|
## 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. |
|
| 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. |
|
| 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. |
|
| 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
|
## What worked and should be kept
|
||||||
|
|
||||||
|
|||||||
@@ -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:
|
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
|
their task files give the types verbatim, so the likeness shows nothing either way. The review
|
||||||
will say more.
|
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.
|
||||||
|
|||||||
Reference in New Issue
Block a user