diff --git a/HANDOFF-devtest-noise.md b/HANDOFF-devtest-noise.md new file mode 100644 index 0000000..feb2384 --- /dev/null +++ b/HANDOFF-devtest-noise.md @@ -0,0 +1,121 @@ +# 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=/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. diff --git a/test/test_dev.ml b/test/test_dev.ml index 6b62062..0e13557 100644 --- a/test/test_dev.ml +++ b/test/test_dev.ml @@ -2829,7 +2829,22 @@ let () = outlive a sequence with several cold clang drivers in it, which is what programs/dev-robust.flan is for. *) let rsock = tmp "robust.sock" and rout = tmp "robust.out" in + (* This daemon gets a stderr of its own, which none of the others needs. + [Build.run] shells out with [Sys.command], so a clang driver's own words + go to whatever stderr it inherited — and the two failures below are + deliberate, so on a *passing* run the suite was printing + "cannot open output file ... Permission denied" and "linker command + failed" straight to the terminal. Four lines of what reads like a broken + toolchain, on every run, for years of handoffs. Noise that is always + there stops being read, and a real linker failure in this spot would + have been invisible behind it. So it goes to a file, and the file is + reprinted below only if a step in this block actually failed. *) + let rerr = tmp "robust.err" in let rcache = tmp "robust.cache" in + (* Counted from here, not from zero: [failures] is the whole file's, and a + failure in an earlier block is not a reason to reprint this daemon's + expected complaints. *) + let rfailures = !failures in let rec rm_rf path = match Sys.is_directory path with | true -> @@ -2853,12 +2868,25 @@ let () = @ [ "FLAN_CACHE_DIR=" ^ rcache ]) in let rfd = Unix.openfile rout [ Unix.O_WRONLY; Unix.O_CREAT; Unix.O_TRUNC ] 0o600 in + let refd = Unix.openfile rerr [ Unix.O_WRONLY; Unix.O_CREAT; Unix.O_TRUNC ] 0o600 in + (* Said out loud, because the alternative is a reader deciding for + themselves what a linker complaint in a test run means. Deliberately no + "error" or "FAIL" in the wording: the reader this line is for is + scanning for exactly those words. *) + print_endline + (Printf.sprintf + "dev: two builds below are made to fail on purpose — the robustness \ + fixture holds its own cache directory (%s) read-only, so the linker \ + cannot write its output there. The compiler's complaints go to a \ + log and are reprinted only if a step actually goes wrong." + rcache); let rpid = Unix.create_process_env flan [| flan; "dev"; "programs/dev-robust.flan"; "-s"; rsock |] - renv Unix.stdin rfd Unix.stderr + renv Unix.stdin rfd refd in Unix.close rfd; + Unix.close refd; if not (listening ~pid:rpid rsock) then begin fail "the robustness daemon %s" !listen_why; (try Unix.kill rpid Sys.sigkill with Unix.Unix_error _ -> ()) @@ -3026,8 +3054,28 @@ let () = (try ignore (Unix.waitpid [] rpid) with Unix.Unix_error _ -> ()); (try Unix.chmod rcache 0o700 with Unix.Unix_error _ -> ()); rm_rf rcache; + (* Its contents rather than its name: [rerr] is under dune's per-run + TMPDIR, which is gone by the time anyone reads the run. *) + if !failures > rfailures then begin + (* True on every path through the block, which the obvious wording is + not: 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 a wrong diagnosis — the thing NEXT.md says costs more + than no message. So it names the signature rather than a count. *) + print_endline + "dev: the robustness daemon's stderr follows. Any linker failure in \ + it that names the read-only cache directory above is one of the \ + deliberate ones; anything else is not."; + match open_in_bin rerr with + | ic -> + let n = in_channel_length ic in + print_string (really_input_string ic n); + flush stdout; + close_in ic + | exception Sys_error e -> Printf.printf " (unreadable: %s)\n" e + end; List.iter (fun f -> try Sys.remove f with Sys_error _ -> ()) - [ rsock; rout ]; + [ rsock; rout; rerr ]; List.iter (fun f -> try Sys.remove f with Sys_error _ -> ()) [ sock; out; bsock; bout ];