The flake was SIGPIPE, and the handoff says how it was caught
This commit is contained in:
parent
ff2bd1da12
commit
82ca001683
@ -1,8 +1,11 @@
|
||||
# The `test_emacs` flake
|
||||
# The `test_emacs` flake — SIGPIPE, and a socket that outlived its process
|
||||
|
||||
**Closed.** It was neither of the two mechanisms this repository had seen
|
||||
before. It was a third: `SIGPIPE`.
|
||||
|
||||
## The symptom
|
||||
|
||||
One run of `dune test --root .` exited 1; the next run on the same tree exited 0.
|
||||
One run of `dune test --root .` exited 1; the next on the same tree exited 0.
|
||||
|
||||
```
|
||||
FAIL the client notices a stop nobody asked about
|
||||
@ -10,51 +13,130 @@ One run of `dune test --root .` exited 1; the next run on the same tree exited 0
|
||||
Error: error ("flan dev: cannot reconnect to /tmp/build_997a01_dune/flan-emacs-dev.sock: make client process failed: Connection refused, ...")
|
||||
```
|
||||
|
||||
## What the error text already rules out
|
||||
## Which mechanism it was
|
||||
|
||||
Two mechanisms have produced something like this here before: a genuine
|
||||
listen/connect ordering bug, and a five-second await against a cold
|
||||
`llc`-and-link. Neither fits this text, and the reason is in the branches:
|
||||
Neither of the two named in the brief.
|
||||
|
||||
- **A 20s poll deadline that simply expired** leaves the connection *live*.
|
||||
The two `FAIL`s would print and `flan-dev-restarts` would then succeed.
|
||||
There would be no `Error:` line at all.
|
||||
- **The daemon exiting** — the child program finishing, `serve` returning
|
||||
`closed`, or any OCaml exception — runs `Fun.protect`'s finally in
|
||||
`Dev.two_process`, which unlinks the socket. The client then takes the
|
||||
`(not (file-exists-p ...))` branch and says *"nothing is listening on ...;
|
||||
start `flan dev program.flan` again"*. A different message.
|
||||
- **`Connection refused`** on a unix socket needs the path to exist *and* no
|
||||
socket in listen state behind it. In `two_process` (lib/dev.ml:2514-2526)
|
||||
`bind` and `listen` are adjacent, nothing else ever creates that path, and
|
||||
the only close of the listening fd is in the same finally that unlinks. So
|
||||
it is reachable essentially one way: **the daemon died without running its
|
||||
finally — that is, it was killed by a signal.**
|
||||
- **Not a listen/connect ordering bug.** `bind` and `listen` are adjacent in
|
||||
both `Dev.two_process` and `Dev.merged_setup`, nothing else creates that
|
||||
path, and the connection that failed was one that had already been working
|
||||
for forty checks.
|
||||
- **Not a timeout too short for a cold build.** That failure mode is now
|
||||
reproducible on demand (see *The tick budget* below) and it produces an
|
||||
entirely different message.
|
||||
- **It was `SIGPIPE`.** The daemon answers an editor by calling `Wire.send`,
|
||||
which is `Unix.write_substring`. Nothing in the OCaml half of the daemon
|
||||
ignored `SIGPIPE`, so a reply written into a socket whose reader had gone
|
||||
killed the process outright. In the merged one-process build that process is
|
||||
the program, the compiler and the listener at once — so the program died
|
||||
without ever reporting a stop (the two `FAIL`s), and the socket file was left
|
||||
on disk with nothing accepting on it (`Connection refused` on a path that
|
||||
plainly exists). One event, all three lines.
|
||||
|
||||
The machine was loaded (several compiler lanes building at once) and `/tmp`
|
||||
filled to 100% the day before, so the OOM killer is the first candidate.
|
||||
It is not a contrived shape. `flan-dev--live-connection` reopens a dead
|
||||
connection, Emacs tears the old process down when it does, and a reply
|
||||
already on its way out lands in the gap. `flan_agent.c` had reached the same
|
||||
conclusion from the other side years ago and passes `MSG_NOSIGNAL`; the half
|
||||
written in OCaml never got the same treatment.
|
||||
|
||||
## The plan
|
||||
## How it was reproduced
|
||||
|
||||
1. Fix the observability first. `test_emacs.ml` throws away the one fact that
|
||||
discriminates: the cleanup `waitpid` matches `| _ -> true` and drops the
|
||||
status, and the temporary files are removed *before* the exit code is
|
||||
checked, so the program's output is gone by the time anyone looks.
|
||||
2. Reproduce by running `_build/default/test/test_emacs.exe` in a loop under
|
||||
artificial load, recording the daemon's wait status, `df /tmp` and
|
||||
`dmesg | tail` each iteration.
|
||||
3. Fix the mechanism the evidence names.
|
||||
4. Sweep the siblings — `test_repl.ml`, `test_dev.ml`, `test_cider.ml`. What
|
||||
they share with `test_emacs.ml` is the discarded wait status, not a missing
|
||||
connect retry: they already have retrying `connect` helpers.
|
||||
A client that sends one request and closes before the reply arrives:
|
||||
|
||||
## Open questions
|
||||
```
|
||||
daemon DIED after 1 hit-and-run connections
|
||||
daemon wait status: 141 (128+13=141 is SIGPIPE)
|
||||
socket file left behind: YES
|
||||
and a fresh client gets:
|
||||
[Errno 111] Connection refused
|
||||
```
|
||||
|
||||
That is the reported failure, exactly, in under a second and every time. With
|
||||
the fix, 300 such connections leave the daemon serving.
|
||||
|
||||
The reproduction is now a check in `test_dev.ml`, in the robustness daemon's
|
||||
block: eight hit-and-run connections, then a request proving the session is
|
||||
still there and still knows what it installed. Against the parent of the fix it
|
||||
fails with `killed by SIGPIPE`.
|
||||
|
||||
## The fix
|
||||
|
||||
`lib/dev.ml`, three parts:
|
||||
|
||||
1. `ignore_sigpipe ()` where the listening socket is bound — in both
|
||||
`two_process` and `merged_setup`. Ignored rather than handled, because
|
||||
`serve` already treats a failed write as a closed connection.
|
||||
2. The reply write is guarded. An `exception` case on a `match` covers the
|
||||
*scrutinee*, not the branch body, so the `EPIPE` that ignoring the signal
|
||||
produces went straight past the two handlers below it and out of the accept
|
||||
loop — which ended the session just as surely, only quietly. Without this
|
||||
the first fix converts `SIGPIPE` into `flan dev: Unix.Unix_error(EPIPE)` and
|
||||
the daemon still stops.
|
||||
3. The socket is unlinked on the ways out the daemon does not control as well
|
||||
as the one it does: an `atexit` in the merged `main` for `exit(3)`, which is
|
||||
what `flan_rt.c`'s `rt_die` takes on any runtime trap; by hand in
|
||||
`flan_agent.c`'s `die_now`, and in `main`'s `_exit(rc)` fallback, both of
|
||||
which skip the `atexit` chain deliberately. A stale socket can now only come
|
||||
from a `SIGKILL`.
|
||||
|
||||
`emacs/flan-dev.el`: a refusal on a path that exists is reported as a leftover
|
||||
socket rather than as `Connection refused`. The raw message is what sent two
|
||||
investigations here the wrong way.
|
||||
|
||||
`test/test_emacs.ml` and `test/test_repl.ml`: the daemon's wait status is kept
|
||||
instead of discarded, and the program's output is read *before* the temporary
|
||||
files are removed rather than after. The old order deleted the evidence and
|
||||
then printed the exit code — which is why nobody could tell, twice running,
|
||||
whether the daemon had exited or been killed.
|
||||
|
||||
## The sibling call sites
|
||||
|
||||
Four files are in this family and the answer differs for each:
|
||||
|
||||
- `test_dev.ml` and `test_repl.ml` drive the same daemon, so `lib/dev.ml`'s fix
|
||||
covers them. Neither had a separate copy of the bug.
|
||||
- `test_cider.ml` has **no daemon and no running program** — it drives the
|
||||
inspector and break buffer from fixtures. It is not in this family at all,
|
||||
despite the name.
|
||||
- `test_emacs.ml` was the only one whose harness destroyed the evidence before
|
||||
reading the exit code; `test_repl.ml` had the same ordering and is fixed too.
|
||||
|
||||
So: one bug, one site, three harnesses — not the three-way split the last one
|
||||
had.
|
||||
|
||||
## The tick budget — a second hazard, and not this one
|
||||
|
||||
`test/programs/dev-repl.flan` ran `(dotimes [i 4000] (agent/wait 5) ...)`: a
|
||||
twenty-second program under a two-minute test, and `test_emacs` drives one
|
||||
daemon through the whole run. On a loaded machine the client can still be
|
||||
working when the program reaches its last tick.
|
||||
|
||||
This is real and it is reproducible — sweep the budget and the same two
|
||||
break-loop checks fail at 165, 175 and 185 ticks — but it is **not** the flake
|
||||
above, because it fails honestly: `the program exited; restart flan dev` at one
|
||||
budget, `nothing is listening on ...` at another. Never `Connection refused`.
|
||||
That is what ruled it out.
|
||||
|
||||
Raised to 24000, which is what `dev-robust.flan` already uses for the same
|
||||
reason. The 600s watchdogs are what actually bound the run.
|
||||
|
||||
## Verification
|
||||
|
||||
- `dune test --root .` — three runs, 232 checks, 0 failures, exit 0 each time.
|
||||
All three under sixteen busy loops; two of them alongside a running
|
||||
`spike/x86/survey.sh`.
|
||||
- `spike/x86/survey.sh` — 103 MATCH / 0 DIFFER / 0 REFUSED.
|
||||
|
||||
## Open questions for the author
|
||||
|
||||
- `lib/cimport.ml:1138` still spells its own `cachedir` under `$TMPDIR`, which
|
||||
NEXT.md:694 flags as the last remnant of the cold-cache bug. Another lane
|
||||
holds that file. It is both a per-run cold cache and a plausible filler of
|
||||
`/tmp`.
|
||||
|
||||
## Status
|
||||
|
||||
Stub. Investigation in progress.
|
||||
holds that file. Folding it onto `Build.cachedir` is still a one-line change.
|
||||
- `Build.cachedir` is now under `XDG_CACHE_HOME`, which means it is **shared**
|
||||
between concurrently running lanes rather than private per dune run. The
|
||||
writes are `tmp`-then-`rename`, so nothing can read a half-written object,
|
||||
and nothing in this investigation pointed at it. Noted only because "several
|
||||
compiler lanes at once" is now a condition the suite is expected to survive.
|
||||
- `runtime/flan_dev.c:51` reaches `abort()` on a full name table, and `abort`
|
||||
runs neither the `atexit` chain nor anything else. It is a 4096-name limit
|
||||
and no test comes near it, so it is left as it is.
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user