A reply is the ordering the socket check was missing
test_dev's first block checked for agent.sock without having completed a round-trip, so nothing put the check after the bind. merged_setup binds the dev socket and returns; the main thread calls agent/start only after that, and a connect lands in the backlog because merged_serve does not accept until it has seen agent.sock itself. 2 runs in 8 failed. Moving the describe up in front of the check supplies the ordering: a reply arriving means merged_serve is past its own await, so it has already observed the path. That closes the second race too — unlinking before merged_serve looked made it wait out its full ten seconds and warn, which is the ten seconds separating the passing runs from the failing ones. 0 in 10 after, and every run in the fast band.
This commit is contained in:
parent
344e571c8c
commit
f80a7a98e7
89
HANDOFF-f1.md
Normal file
89
HANDOFF-f1.md
Normal file
@ -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.
|
||||
@ -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,
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user