flan/HANDOFF-f1.md
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

107 lines
6.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. **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.