flan/docs/handoffs/HANDOFF-devtest-noise.md

122 lines
7.5 KiB
Markdown

# Handoff — the linker error `dune test` prints on every run
Branch: `dev-loop`, worktree `agent-a4f73ab1c6726fdc2`. Scope is the `dev-robust` fixture and the noise it makes;
nothing else in the suite is touched.
## The question
Every `dune test --root .` prints, twice:
```
/usr/bin/ld: cannot open output file /tmp/build_*_dune/flan-devtest-robust.cache/flan-macros-*.so.*: Permission denied
clang: error: linker command failed with exit code 1
```
`HANDOFF-x86-rt.md` section 4 says this is inside the `dev-robust` fixture and deliberate. That has been quoted
forward without ever being checked. The brief names two possibilities: the failure is deliberate and only *looks*
like a broken toolchain, or it is accidental and the fixture has been proving less than it claims.
## The answer: deliberate, and the read is confirmed at the source
`test/test_dev.ml`, the block starting "A build that fails is a refusal, not the end of the session" (~line 2805):
- The fixture gives the daemon a cache directory of its own — `FLAN_CACHE_DIR=<tmp>/flan-devtest-robust.cache`,
with any inherited `FLAN_CACHE_DIR` filtered out of the environment first.
- Before each step that must fail it runs `Unix.chmod rcache 0o500`, and afterwards `0o700`. A read-only,
non-writable cache directory is exactly why `ld` cannot open its output there.
- The two failing steps are the `eval-expr` one (C-x C-e) and the `eval` one carrying a `defmacro` (C-c C-c) —
which is why the message appears **twice** per run, and why the count matches.
So this is possibility 1. The property — a failed build leaves the session standing — is genuinely under test.
## The actual defect, which is narrower
The daemon is spawned with `Unix.stderr` as its stderr, so it inherits the test binary's. `Build.run` shells out
with `Sys.command`, which does not capture anything, so clang's and ld's own words go straight through to the
terminal. Its *stdout* already goes to a log file nobody reads (`rout`), and the comment there says as much; its
stderr was simply never given the same treatment.
The result is four lines of what reads like a broken toolchain on a passing run. A real linker failure in that spot
today would be invisible.
## What was done
Three changes, all in `test/test_dev.ml` and all inside the `dev-robust` block. The lever that causes the failure
is untouched: the existing comment's argument that a read-only cache is "the one lever that reaches the macro module
and nothing else" is right, and swapping it for a different cause would mean re-proving that the new one does not
leak into other builds. The channel was the defect, not the cause.
1. **The daemon gets a stderr of its own**`rerr = tmp "robust.err"`, passed to `create_process_env` where
`Unix.stderr` used to be, the same treatment its stdout already had.
2. **That log is reprinted, contents and not path, only when a step in this block failed.** The count is taken
against `rfailures`, a snapshot of `!failures` at block entry, because `failures` is the whole file's and an
earlier block's failure is not a reason to reprint this daemon's expected complaints. The path itself would be
useless: `rerr` lives under dune's per-run `TMPDIR`, which is gone before anyone reads the run.
3. **The fixture says so in its own voice**, one line, before the daemon starts, naming the directory it is about
to make read-only so the reader can match it against the linker's own words. The wording deliberately contains no
`error`, `Error` or `FAIL`, because the reader it is written for is scanning for exactly those words. The reprint
header names that signature rather than a count, because a step that fails *before* either chmod window leaves no
deliberate failure in the log at all, and a header promising two of them would be the wrong diagnosis NEXT.md
warns about.
`test/dune` was **not** touched, and neither was anything under `lib/`. The whole change is in `test/test_dev.ml`
and this file.
## Measured, before and after
Both from a full `dune test --root .`, exit 0 either way.
| | before | after |
|---|---|---|
| `cannot open output file` lines | 2 | **0** |
| `clang: error: linker command failed` lines | 2 | **0** |
| a line saying the failure is deliberate | none | **1** |
The "before" row is from a full, uncached `dune test`, which inventoried the whole suite: **exactly two
occurrences**, both sitting immediately after `flan dev: ... dev-robust.flan ready on ...`, which places them in
this block and nowhere else. So there is no second site quietly doing the same thing and fixing `test_dev.ml` fixes
all of it. (The run's log has been deleted rather than left in the tree; the count is the claim, and it is
reproducible by reverting the two commits below and running the suite.)
The "after" row is from a run where dune replayed most targets from cache — cached actions do not reprint their
output, so the *suite-wide* zero rests on the baseline's inventory rather than on that run. What the after-run does
establish directly is the part that matters: `test_dev` itself reran fresh, and produced none.
Two informational lines from this daemon — `flan dev: built dev-robust.flan in 1937ms` and its `ready on` — now go
to the log with the rest of its stderr rather than to the terminal. Its siblings still print theirs. That is a small
inconsistency and the right side of the trade: the whole point is that this daemon's stderr is a channel nobody
should be reading on a green run.
## Verified
- `dune test --root .` exit 0, and the four lines are gone. `test_dev` alone: `dev: all tests passed`, exit 0.
- **The reporting half was verified by breaking the test on purpose**, which is the part a green run cannot show:
a fix that silences unconditionally and a fix that reports-on-failure produce identical output when everything
passes. The `Some "16"` expectation was temporarily changed to a value it cannot match, the block failed, and the
captured stderr — the linker's own words — was reprinted under its header. Then reverted.
Baseline not regressed, all three measured after the change:
- `dune test --root .` — exit 0.
- `spike/x86/survey.sh`**101 MATCH / 0 DIFFER / 0 REFUSED / 0 NOX86**, 36 skipped (28 does-not-compile, 6 no-main,
2 runs-forever).
- `spike/x86/cells.sh`**4/4**, exit 0.
One thing not to re-derive: a first attempt at the survey came back `SURVEY_EXIT=143` with a bare `Terminated`. That
was the harness killing the process group of a long background command, not a survey failure and nothing to do with
this change — nothing under `lib/` was touched. Re-run detached under `setsid` it is 101/0/0. A `143` from that
script means it was signalled; read it as "run it again", not as a regression.
## One stale note left behind, deliberately not edited
`HANDOFF-x86-rt.md` section 4 still tells the next lane that `dune test` prints those four lines as an environment
note. That is no longer true. It is not corrected here because another lane holds that file and a conflict costs
more than the sentence is worth — but a lane that reads it and goes hunting for the noise will not find any.
## Open questions
- `Build.run` reports only `(exit N)` to the caller; clang's actual words reach the terminal and nothing else. The
fixture asserts the reply "carries the compiler's message" but only checks for the substring `(exit `, so an
editor attached to a real `flan dev` sees a bare exit status and no diagnostic. Widening `Build.run` to capture
and forward stderr would fix that, and is out of this lane's scope — recorded here so it is not lost.