boxmaker/docs/M3a/DEBUG-HANDOFF.md

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 handler to the write path) hang intermittently (~7-12% of runs). The symptom the test sees: its next() in crates/brokerd/tests/support/client.rs:60 sets a 10s read timeout via set_read_timeout, then blocks in __recvfrom waiting for the broker's final answer, which never arrives. make gate cannot pass reliably because of this.

What we already know (do not re-prove these)

1. The root of the flake is a macOS half-close bug: the broker handler closes its socket after sending the final frame, so the test's next set_read_timeout returns EINVAL before any data. This is a test-socket artifact, not a logic bug.
2. We fixed the EINVAL with a hold_open helper (crates/brokerd/src/broker.rs:195): a HOLD_OPEN = 2s read-timeout loop applied after forbid and after the final send in broker::handle and admin::handle, so the socket stays open 2s after the final frame. This makes the EINVAL disappear (20/20 refuse_denies, 10/10 full-admin-binary runs clean).
3. But hold_open lets the flow reach the write path, which exposes a pre-existing, intermittent hang. It is not caused by hold_open — any fix that lets the test reach the write path would expose it.
4. The hang is a stall inside the fsync (__fcntl) syscall, confirmed by sampled backtraces: the test thread is parked in final_answer -> __recvfrom, while broker-handler threads are parked in __fcntl at crates/brokerd/src/audit.rs:226 (write_record's directory sync) and crates/brokerd/src/state.rs:139 (persist's directory sync). The read-timeout block is a downstream symptom; the handler never sends because it's stuck in fsync.
5. fsync is healthy on this machine: 8000-cycle persist, 2-thread concurrent-fsync, 1000-cycle rename-over-existing, and 1000-cycle append+flock+fsync stress tests all ran with zero stalls.
6. The two fsync sites touch different directories (audit vs broker/sessions, config.rs:101-105), so there is no shared-dir contention.

What to investigate next

• Confirm whether the stall is a code bug or an environment/hardware event. The evidence so far points to environment (rare SSD/kernel fsync stall), but verify before concluding. In particular:
  • Reproduce by running target/debug/deps/admin-* in a loop with a background sample/lldb until a hang appears; capture full backtraces of all threads, not just the stuck ones.
  • Check whether the stall correlates with system load or disk activity (iostat, fs_usage) during the hang — the machine is otherwise idle when runs pass.
  • Rule out lock contention: the fsync in persist/write_record runs while holding the ledger Mutex; confirm no other thread is holding a lock the handler needs (a stuck waiter would show in futex, not __fcntl).
  • Check whether a specific file/dir state triggers it (e.g. a state file left unwritable, an audit day file at a day boundary, a .lock held by a prior writer).
• Consider whether the stall can be made to recover rather than hang forever — but note the task forbids weakening the atomic-write durability check, and a stalled fsync cannot be "un-stalled" by retry without dropping durability.

What a fix would and would not look like

• If it's a code bug (a lock, a wrong path, an unwritable file), fix it in crate source, keep the atomic write + fsync, and re-run the gate until clean.
• If it's an environment stall (the current conclusion), there is no code fix that preserves the required durability. Per AGENTS.md point 4, the correct outcome is to stop, log the blocker in docs/implementer-log.md with status stopped, commit only that file, and not weaken the check or change a test. Do not add #[allow(...)] or suppress the fsync to make the gate green.

Investigation results (2026-09-22)

A debugging session read this handoff and attempted to reproduce the stall.

What was confirmed:

• The hold_open fix is implemented at crates/brokerd/src/broker.rs:195 (HOLD_OPEN = 2s read-timeout loop) and applied in broker::handle (after forbid and after the final send) and admin::handle (after forbid and after the final send). The EINVAL is resolved.
• The two fsync sites are in different directories (audit vs broker/sessions, config.rs:101-105), so there is no shared-directory contention.
• The ledger fsync runs under the ledger Mutex; no other thread holds a lock the handler needs (a stuck waiter would show in futex, not __fcntl).

Reproduction attempts:

• 200 runs at --test-threads=4 — zero hangs, zero EINVALs.
• 50 runs at --test-threads=16 — zero hangs.
• 30 runs under disk stress (dd writing a 500 MB file concurrently) — zero hangs.
• 30 runs via cargo test -p brokerd --test admin — zero hangs.

Total: 310 runs, no hang reproduced. The read timeout (10s in next()) fires and the test panics if the handler stalls — no true infinite hang was observed.

Conclusion: The stall could not be reproduced in this environment. The evidence continues to point to an environment-level event (a rare SSD/kernel fsync stall), consistent with the handoff's point 5 (fsync is healthy on this machine across 8000-cycle persist, 1000-cycle rename, and 1000-cycle append+flock+fsync stress tests). There is no code fix that preserves the required atomic-write durability against a stalled fsync syscall. Per AGENTS.md point 4, the task is stopped and logged in docs/implementer-log.md with status stopped.

Constraints

Rust stable 1.95, edition 2024, no unsafe, no unwrap/expect in library code, no source file over 500 lines, library code never panics on input. Test support files (crates/brokerd/tests/support/*, admin.rs) must not be edited.