Joseph Ferano 6de6c079b0 What the "never listened" flake actually was, written where it was hunted

Two lanes were sent after a contention race on a socket path. There is
none.  The sentence came from three sites and not the two HANDOFF-f1.md
named — test_dev.ml:77 checks the *dev* socket with exactly that wording,
in the same block whose *agent* socket check was fixed — and the cause is
a bound too short for a build: flan dev links the whole program before it
binds, ~600ms warm, measured at 6.5s here and 6.6-6.8s by the lane that
fixed it, against a 5000ms await in test_dev.ml and 8000ms in the other
two.  Build.cachedir sits under dune's per-run TMPDIR, so that build is
cold on every invocation and the failure is not occasional at all.  The
fix landed on another branch; nothing in this commit touches a test.

The agent.sock ordering fix it does confirm: 30 sequential full dune test
runs, 0 failures, no "never bound" in any log — so NEXT.md's "One flaky
test, measured rather than suspected" section, left standing for whoever
confirmed it, goes.

HANDOFF-f1.md's "lengthening any timeout" bullet is qualified rather than
deleted.  It was true of the agent.sock check and read as a rule, and
reading it as a rule is what kept this open for a second lane.

2026-09-13 13:12:17 +07:00

6.6 KiB

Raw Blame History

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

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.

Closed since: the other "the daemon never listened", which was not a race at all

The previous item 1 sent two lanes after a contention race. There is none, and the reading it was built on was wrong twice over:

The wording is not unique to test_emacs.ml:50 and test_repl.ml:71. test/test_dev.ml:77 — the dev socket check in the same first block this handoff fixed the agent socket check in — emitted exactly the daemon never listened as well. Three sites, not two, which is why a sighting in a full-run log could not be attributed.
The cause is a bound that is too short for a build, not a race. flan dev does an llc-and-link of the whole program before it binds its socket, so the await covers a build. Warm and idle that is ~600ms; under dune's own parallelism it was measured at 6.5s here and at 6.6s and 6.8s by the lane that fixed it — against a 5000ms await in test_dev.ml and 8000ms in the other two. Nothing about it is occasional; it reproduces whenever the build is cold, and Build.cachedir sits under dune's per-run TMPDIR, so the object cache starts empty on every dune test invocation.

Fixed on another branch: all three awaits now wait a minute, bounded by the existing watchdog rather than by a guess, and test_dev.ml carries a named listening helper so the reason is written once for its thirteen daemons.

Two measurements from this lane that stand whatever else changes: 30 sequential full dune test runs, 0 failures and no never bound in any of them — the agent.sock ordering fix above is confirmed at a sweep wide enough to close item 3 of the old list, so NEXT.md's "One flaky test, measured rather than suspected" section is deleted. The reproduction that came after it, on the 31st run, was the dev socket at test_dev.ml:77, with built dev-loop.flan in 6525ms sitting four lines below the FAIL in the same log — which is what turned the hypothesis into the finding above.

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 — for the agent.sock check. Not needed there; the ordering was missing, not the time. This does not generalise, and reading it as a rule cost two lanes: the socket-appears checks above are a wait for a build, and there lengthening the bound was exactly the fix. See the section before this one.

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.

6.6 KiB Raw Blame History

Handoff — the test_dev.ml "never bound agent.sock" flake