diff --git a/HANDOFF-f1.md b/HANDOFF-f1.md new file mode 100644 index 0000000..31c1401 --- /dev/null +++ b/HANDOFF-f1.md @@ -0,0 +1,89 @@ +# Handoff — the `test_dev.ml` "never bound agent.sock" flake + +## Root cause + +`test_dev.ml`'s first block checked `Sys.file_exists agent_sock` without having completed a single +round-trip on the daemon socket, so nothing had ordered the check after the bind. + +The evidence is in `lib/dev.ml`: + +- `merged_setup` (lib/dev.ml:2264) binds and listens on the **dev** socket (`Unix.bind ls` at + lib/dev.ml:2300) and returns. The program's main thread — the thread that calls `agent/start`, + which is what binds `agent.sock` (`vendor/agent/flan_agent.c:1097` `flan_agent_start`) — only runs + *after* `merged_setup` returns. +- So the test's `await (fun () -> Sys.file_exists sock)` (test/test_dev.ml:76) says nothing about + `agent.sock`, and `connect sock` (test/test_dev.ml:82) succeeds off the **listen backlog** without + anyone having accepted: `merged_serve` (lib/dev.ml:2311) does not reach `accept_loop` until after + its own `await ~ms:10000 (fun () -> Sys.file_exists t.agent)` (lib/dev.ml:2322). +- The comment at lib/dev.ml:2314-2320 states the ordering outright. + +There is a **second race on the same path**, which the timings confirmed. The test unlinks +`agent.sock` immediately after the check (test/test_dev.ml, `Unix.unlink agent_sock`). Both the test +and `merged_serve` poll that path at 5ms. When the test won and unlinked first, `merged_serve` burned +its full 10s timeout and printed the "does it call (agent/start ...)?" warning before accepting — the +test still passed, ~10s slower. Measured: failing runs clustered at ~24s, passing runs at ~30-36s. + +## What changed + +One file: `test/test_dev.ml`. The existing `describe` request and its status check were **moved up** +to sit immediately before the `agent_sock` existence check (and removed from their old position a few +lines below). No new sleep, no lengthened timeout, no change to `lib/dev.ml`. + +A completed reply proves `merged_serve` got past its `await` — i.e. it has *already observed* +`agent.sock` — which makes the existence check deterministic and puts the unlink safely after that +observation, killing both races at once. + +The genuine-failure property is preserved: if a program really never binds, `merged_serve` warns +after 10s and accepts anyway, the reply arrives, and the existence check fails as it should. + +## Verified + +Run as `./test_dev.exe` from `_build/default/test`, serially, whole binary, detecting the flake by +grepping stdout for `never bound`: + +- **Before: 2/8 runs failed (25%)** — matches the rate NEXT.md records. Failing runs 24.7s and 24.0s; + passing runs 30.0-36.0s (the 10s stall described above). +- **After: 0/10 runs failed (0%)**, and every run landed in the fast band, 17.0-26.7s — the 10s stall + band is gone as well, which is the independent confirmation that the second race is also closed. + +Run counts are small (8 and 10) because the session was cut short for budget; each run is ~25s. A +longer sweep was **not measured**. + +`dune test --root .` was run twice after the change. The second run was green. The first run reported +`1 failure(s)` with `FAIL the daemon never listened` — see item 1 below. + +## What remains + +1. **Identify and fix the other "the daemon never listened" flake.** It appeared once in one of two + post-change full `dune test` runs and is *not* test_dev's first block (that block is 0/10 under + the new code, and its own message is distinct). The message text is emitted from + `test/test_emacs.ml:50` and `test/test_repl.ml:71` with exactly that wording; `test/test_dev.ml`'s + other daemons all use qualified wording ("the break daemon…", etc.), so the culprit is almost + certainly `test_emacs` or `test_repl`. Re-run `dune test --root .` in a loop and capture per-binary + output to disambiguate. Likely the same class of bug — a bounded `await` on a socket path under + parallel-dune CPU contention — but that is a hypothesis, not a finding. Pre-existing: it did not + appear in the pre-change full run, but one observation each way proves nothing. +2. **Decide whether `merged_serve`'s 10s warning path deserves a test.** Nothing currently exercises + lib/dev.ml:2322-2326 (a program that never calls `agent/start`). It was reachable only by accident + here, via the unlink race that is now closed. +3. **Confirm the fix at the rate NEXT.md claims** with a longer sweep (40+ runs) if the 0/10 is + considered too thin, then delete the "One flaky test, measured rather than suspected" section from + `NEXT.md` (around line 138). That section was deliberately **left untouched** — it should be + removed by whoever confirms the fix, not by the change that made it. + +## Tried and rejected + +- **Wrapping the check in the file's `await` helper** (`await (fun () -> Sys.file_exists agent_sock)`). + It looks like the obvious fix and it is wrong: it makes the test observe the file at the *earliest* + possible instant, which makes it *more* likely to win the unlink race against `merged_serve` and + more likely to trigger the silent 10s stall. Do not reintroduce it. +- **Lengthening any timeout.** Not needed; the ordering was missing, not the time. + +## Environment note for whoever picks this up + +Running `_build/default/test/test_dev.exe` directly requires the dune-copied deps +(`test/programs/*.flan`) to be present in `_build`. A bare `dune build --root .` does **not** copy +them — every daemon then dies with `Sys_error("programs/dev-loop.flan: No such file or directory")` +and all eleven blocks report "never listened". Run `dune build --root . @test/runtest` once first to +populate `_build/default/test/programs/`. Also run the loop **strictly serially**: the socket names +under `$TMPDIR` are fixed (`flan-devtest-*.sock`), so parallel runs collide and manufacture failures. diff --git a/test/test_dev.ml b/test/test_dev.ml index a4d71d9..c5bba88 100644 --- a/test/test_dev.ml +++ b/test/test_dev.ml @@ -125,6 +125,17 @@ let () = (Printf.sprintf "flan-dev-%d" pid)) "agent.sock" in + (* A completed reply is what makes the check above deterministic, so + [describe] is asked here rather than below. Connecting proves nothing: + the listener is bound by [merged_setup], and the program's main thread + — which is what calls [agent/start] — only runs after that returns, so + a connect lands in the backlog. [merged_serve] waits for the agent + socket before it accepts at all, so a reply having arrived means it has + already seen the path bound. Asking after the unlink instead would be + the same race from the other side: unlinking before [merged_serve] + looks makes it wait out its full timeout and warn. *) + let r = request c "(:op \"describe\")" in + if status r <> "ok" then fail "describe: %s" (status r); if not (Sys.file_exists agent_sock) then fail "the merged program never bound %s" agent_sock else (try Unix.unlink agent_sock with Unix.Unix_error _ -> ()); @@ -142,10 +153,6 @@ let () = lines () >= n) in - (* describe: what the daemon believes about the program it launched. *) - let r = request c "(:op \"describe\")" in - if status r <> "ok" then fail "describe: %s" (status r); - (* [defs] is its own op rather than more fields on [describe], because [describe] is what an editor polls to drain the program's output. It carries what eldoc, completion and find-definition each need: a kind,