cov-ci: wall-clock-bounded tests fail under llvm-cov instrumentation on a loaded machine (false-failure class)

[hartsock]

Observation

just cov-ci failed twice in a row at the same place:

thread 'main' panicked at agent-bridle-tool-shell/tests/brush_real.rs:688:10:
a confined stdin-reader must not block on the operator terminal: Elapsed(())

That is confined_stdin_reader_gets_eof_not_the_operator_terminal, whose teeth
are a 10-second tokio::time::timeout wrapped around spawning a brush
worker and running /bin/cat.

It is not a defect in the code under test. The same test passes cleanly in
the same worktree uninstrumented (cargo test -p agent-bridle-tool-shell --no-default-features --features brush --test brush_real). Both failures were
under cargo llvm-cov on a developer machine that was heavily loaded at the
time (load average in the thousands, i/o-wait bound, several concurrent
workspace builds). The bound is losing a race with i/o wait, not detecting a
hang.

Why this deserves a fix rather than a re-run

The failure is indistinguishable from a real regression at the point of
reading it: an Elapsed panic on a test whose docstring says the timeout IS
the regression detector for "the child blocked on the operator terminal". A
reviewer who sees it in CI has no way to tell "the fd-0 fix regressed" from
"the runner was busy", and the honest response — re-run it — is exactly the
habit that hides real failures.

CI's coverage job is the same shape (instrumented, shared runner), so this is
not purely a local-machine artifact.

The class, not just the instance

Any test whose assertion is a wall-clock bound has this property. At least:

• brush_real.rs::confined_stdin_reader_gets_eof_not_the_operator_terminal (10s)
• brush_real.rs::confined_run_is_bounded_by_the_wall_clock_ceiling
• the #269 / AB-006 timeout-kill tests (real_timed_out_child_is_killed_and_never_writes_marker and the grandchild variant), which sleep past a deadline and assert a marker is absent

Note the repo already draws this line correctly for authority (no wall clock as a coordination primitive; caveats key on valid_for_generation). These
tests use wall-clock legitimately — they bound work — but the bounds were
chosen against an idle machine.

Options

1. Scale the bounds under instrumentation: multiply when a coverage/profile
   env var is present (LLVM_PROFILE_FILE is set by cargo llvm-cov), so the
   uninstrumented bound stays tight and the instrumented one stays honest.
2. Replace the bound with a causal oracle where one exists. The stdin test
   really asks "did the child get EOF", which a sentinel file or an explicit
   read() result answers without a clock; the timeout is only there to stop a
   hang. Both can coexist: assert the causal fact, keep a generous timeout as a
   hang-stop.
3. Serialise the coverage run (--test-threads), reducing self-inflicted load
   at the cost of wall-clock.

Preference: (2) where the test has a causal oracle available, (1) as the blanket
guard for the rest. Not fixing this in-flight — filed so it is not re-discovered
later as an unexplained flake.

[hartsock]

Second, independent instance — different crate, different worktree, same stage and same class (reported by the session running the #352/#354 merge train):

agent-bridle-mcp/tests/mcp_carried_coreutils.rs:79
default_mcp_shell_runs_carried_ls_and_denies_ungranted_external
panicked: timed out waiting for MCP response: Elapsed(())
error: Recipe `cov-ci` failed with exit code 101

That is a 20-second tokio::time::timeout around an MCP request/response over a spawned child's stdio, under llvm-cov, at load average 3544. Mine was a 10-second bound around a brush worker plus /bin/cat, failing 2/2 under coverage and passing clean uninstrumented in the same worktree.

Two wall-clock-bounded tests, two crates, two worktrees, both failing only under cov-ci on a saturated box. That moves this from "a flaky test" to "a property of the coverage lane": instrumentation plus contention inflates latency past bounds that were chosen against an idle machine.

Updated class list:

• brush_real.rs::confined_stdin_reader_gets_eof_not_the_operator_terminal (10s)
• brush_real.rs::confined_run_is_bounded_by_the_wall_clock_ceiling
• mcp_carried_coreutils.rs::default_mcp_shell_runs_carried_ls_and_denies_ungranted_external (20s)
• the AB-006: shell timeout does not terminate/reap the child process #269 / AB-006 timeout-kill tests

The operational rule both sessions have adopted meanwhile, worth writing down: while the machine is loaded, a wall-clock-bounded test failing is not evidence of a defect — discriminate by re-running that test uninstrumented before believing it. That is a workaround for humans, though, not a fix: CI's coverage job has the same shape, and a reviewer reading "cov-ci failed" cannot tell a real regression from a busy runner.

Adds a fourth option to the list above: exclude wall-clock-bounded tests from the coverage lane and assert them in the uninstrumented lane, where the bound is meaningful. That keeps each bound honest in exactly one place rather than making every bound generous everywhere.

[hartsock]

The mechanism is swap thrashing from concurrent linkers — not CPU saturation, and the load average is misleading

Measured on gnuc while a cov-ci gate was running. This corrects a premise several of us were reasoning from, including me.

The load average says 3420. It is not measuring what it appears to measure.

/proc/loadavg  ->  3420.53 3432.27 3356.13  runnable: 2/5649
vmstat         ->  runnable=1  blocked=20  iowait=67%  idle=22%

Only 1–2 of 5649 tasks are runnable and the CPU is 22% idle. Linux's load average counts uninterruptible-sleep (D-state) tasks, so thousands of threads blocked on page-in inflate it. It is a symptom, not a demand signal — and "the box is at load 3400, therefore everything is CPU-starved" is the wrong inference.

What is actually happening:

Swap:  5757 MB used of 8191   (70% consumed, 2434 MB free)
Top RSS:  rust-lld 1.2GB, rust-lld 1.1GB, rust-lld 1.1GB, rust-lld 1.1GB, rust-lld 1.1GB
iowait: 67%

Five concurrent rust-lld processes at ~1.1–1.2GB each, on a 30GB box, push it into swap. Once swapping, every wall-clock bound in the suite is racing page-in latency, which is why timeouts and not assertion failures are the signature.

This changes the remedy. The lever is not "fewer gates" but bounded link parallelism. Linking is the memory-hungry phase; cargo's -j / CARGO_BUILD_JOBS caps concurrent codegen+link units. A gate constrained to a handful of link jobs uses a fraction of the peak RSS and stays out of swap while running exactly the same checks — no bound relaxed, nothing skipped. That is worth trying before generous timeouts, because it fixes the cause rather than the symptom, and it applies to CI runners too, which are typically smaller than this box.

It also strengthens the case for the fourth option above (exclude wall-clock-bounded tests from the coverage lane): the coverage lane is memory-heavy and slow, so it is the worst place to assert a wall-clock property.

The ratio that should drive the default

Across one day on this train: six measurement-contamination artifacts against two real defects.

The two real defects were a silent 1<<20 descriptor-sweep clamp, and a test oracle that asked a shell whether a descriptor was closed (unsound in both directions — false alarm and false pass).

The six artifacts were: a global cargo target-dir letting two worktrees overwrite each other's test binary; concurrent cargo unlinking a test binary mid-gate (twice — once by an agent, once by me, ten seconds into a gate I was myself watching); a SHA handed to a native-test operator that had never reached the remote; a test helper that never built anything and graded whichever binary it found; and a push wrapper that piped through tail, reporting exit 0 while the push had failed.

Why the ratio is decision-relevant rather than colour: if most gate failures in a contended window are artifacts, then "re-run the whole gate" is the wrong first move and "re-run that one test uninstrumented" is the right one. It also argues for an artifact-until-discriminated prior on any wall-clock failure during a contended window — while being explicit that the same shortcut is exactly what lets a real regression be waved through as "just the box", so the discriminator must actually be run, not assumed.

One falsifiable, time-boxed disclosure so it does not decay into general doubt about a run: during push 3 of #352, I started cargo test in that worktree ~10 seconds into its own gate and killed it ~40 seconds later. Any missing-binary failure in that gate's first minute is mine and not real. Anything after that window is genuine.

Three artifact signatures that impersonate real bugs

• Recipe ... was terminated ... by signal 15 mid-cargo test — SIGTERM, not OOM (that would be SIGKILL).
• could not execute process ... (never executed) / No such file or directory — a sibling cargo recompiled and unlinked a binary the gate had already enumerated.
• Elapsed(()) on any tokio::time::timeout — a wall-clock bound losing to page-in latency.

None of the three is distinguishable from a real regression by reading the log.

[hartsock]

Natural experiment: the same gate, same box, same commands — passing once the linkers are gone

The swap mechanism above was measured correlation. This is the controlled comparison, and it came for free rather than from a code change.

Two consecutive runs of the identical pre-push gate on the identical box. The trees differ only by two docs-only commits touching no MCP or brush code. Same hook, same cov-ci stage, same llvm-cov instrumentation.

Run 2 — five rust-lld processes resident at 1.1–1.2GB each, 5.7GB swapped, runnable: 2/5649, iowait 67%:

default_mcp_shell_runs_carried_ls_and_denies_ungranted_external ... FAILED
  panicked: timed out waiting for MCP response: Elapsed(())
error: Recipe `cov-ci` failed with exit code 101

Run 3 — pgrep -c rust-lld = 0, r=5 b=2:

default_mcp_shell_runs_carried_ls_and_denies_ungranted_external ... ok
confined_stdin_reader_gets_eof_not_the_operator_terminal        ... ok
confined_run_is_bounded_by_the_wall_clock_ceiling               ... ok

All three members of the wall-clock class passed, under instrumentation, with no bound changed and no code touched. The only variable that moved was resident linker memory.

That is the discrimination this issue asks for, performed accidentally and cleanly: these tests do not fail because they are too tight in isolation, they fail because a memory-hungry concurrent phase pushes the box into swap and every deadline then races page-in. CARGO_BUILD_JOBS was held in reserve and deliberately not used, precisely so the run kept exactly one variable.

Practical consequence for the lane: the coverage job is both the most memory-hungry stage and the one asserting wall-clock properties, so it is the configuration most likely to fail for reasons unrelated to the change under test — while looking identical to a regression. Whichever remedy is chosen (bounded link parallelism, or moving these assertions out of the coverage lane), the fix belongs at the lane level rather than in each individual timeout.

A fourth artifact signature

Adding to the three above, from the same train:

• A process exit is not a result when its output went somewhere unreadable. Two git push invocations "exited" while the branch never moved — one because a | tail pipeline masked the real exit code (the wrapper reported success while PUSH_EXIT=1 sat inside the output), one because the SSH transport had been idled out by the long hook and the transfer died after the gate passed. In both cases the only thing that revealed the truth was an independent git ls-remote read-back.

The general rule: never treat an exit status as an outcome unless you can read what the operation actually printed — and for anything that publishes state, confirm the state at the destination rather than trusting the local result.