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.
90 lines
5.6 KiB
Markdown
90 lines
5.6 KiB
Markdown
# 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.
|