Lab CI flake: a hung in-scenario command hangs the whole gate silently for 6 min (no exec timeout + all-or-nothing TAP) #88

New issue

Closed

opened 2026-07-03 10:17:36 +00:00 by vxfemboy · 2 comments

vxfemboy commented

2026-07-03 10:17:36 +00:00

(Migrated from github.com)

Symptom

Intermittently, one lab gate in the lab CI job fails with zero stdout and the message The job running on runner ... has exceeded the maximum execution time of 6 minutes (the per-step timeout). It has hit different gates on different runs (deception in the C1c Part-A run, flow/flow-sflow on the main post-#83 run and on #87). It always passes on re-run. check is unaffected; only lab flakes.

Root cause (confirmed in code)

Two independent harness defects combine to make a single hung child command an invisible 6-minute hang:

No per-command execution timeout. netns::run (crates/blackwall-lab/src/exec/netns.rs:9) executes every one-shot command via Command::output(), which blocks until the child exits with no upper bound. Asserts funnel through it: assert_cmd (exec/proc.rs:56) runs sh -c "<cmd>", and several gates use cmd="cargo test --offline -p <crate> --test <name> …" as the assert. wait_until's deadline (exec/proc.rs:25) is only checked between probe iterations — a single blocking .output() call is never interrupted. So one command that never exits hangs the whole lab test until the CI step timeout (6 min) SIGKILLs the process.
All-or-nothing TAP output. report.rs (:92) accumulates the entire TAP document into a String and prints it only after the run completes. A hang mid-run therefore emits nothing — no TAP version 13, no per-step lines — which is why the failure is a silent 6-minute wall with no diagnostic.

Why it's intermittent

The command that hangs is almost certainly cargo test --offline, blocking on the shared Cargo build-directory lock target/debug/.cargo-lock. Cargo prints Blocking waiting for file lock on build directory to stderr (never stdout) and waits indefinitely when another cargo process holds the lock. Gates run sequentially, but several gates spawn a long-lived run daemon that is itself a cargo test process holding that lock; if teardown races (daemon not fully reaped before the next gate's assert cargo starts), the next gate's cargo blocks forever. This matches every observed property: transient, zero stdout, and hitting whichever gate happens to run next.

Fix plan

(primary) Bound command execution. Convert netns::run from .output() to spawn() + poll try_wait() against a deadline (default ~60s, well under the 6-min CI step timeout); on timeout, kill the child's process group (set process_group(0) at spawn, kill(-pgid, SIGKILL)) and return a LabError::Exec("command timed out …") carrying any partial stderr. A hung command then fails its step fast with a clear reason instead of hanging the job. Add a test: sh -c 'sleep 30' under a 1s bound returns a timeout error in ~1s.
(diagnostics) Stream TAP incrementally. Emit TAP version 13 + the plan line up front and each step's result as it completes (line-buffered), so a future hang shows exactly which step stalled and how far the run got. Keep the JUnit artifact unchanged.
(root cause) Stop running cargo inside scenarios. The lab job already pre-builds all test binaries in its build step. Have gates invoke the pre-built test binary directly (locate it once via cargo test --no-run --message-format=json) so no in-scenario cargo ever contends on .cargo-lock. This removes the lock-contention trigger entirely.

Primary + diagnostics are a small, self-contained lab-hardening increment; the root-cause item is a larger follow-on.

## Symptom Intermittently, one lab gate in the `lab` CI job fails with **zero stdout** and the message `The job running on runner ... has exceeded the maximum execution time of 6 minutes` (the per-step timeout). It has hit different gates on different runs (deception in the C1c Part-A run, `flow`/flow-sflow on the main post-#83 run and on #87). It always passes on re-run. `check` is unaffected; only `lab` flakes. ## Root cause (confirmed in code) Two independent harness defects combine to make a single hung child command an invisible 6-minute hang: 1. **No per-command execution timeout.** `netns::run` (`crates/blackwall-lab/src/exec/netns.rs:9`) executes every one-shot command via `Command::output()`, which blocks until the child exits with no upper bound. Asserts funnel through it: `assert_cmd` (`exec/proc.rs:56`) runs `sh -c "<cmd>"`, and several gates use `cmd="cargo test --offline -p <crate> --test <name> …"` as the assert. `wait_until`'s deadline (`exec/proc.rs:25`) is only checked *between* probe iterations — a single blocking `.output()` call is never interrupted. So one command that never exits hangs the whole `lab test` until the CI **step** timeout (6 min) SIGKILLs the process. 2. **All-or-nothing TAP output.** `report.rs` (`:92`) accumulates the entire TAP document into a `String` and prints it only after the run completes. A hang mid-run therefore emits **nothing** — no `TAP version 13`, no per-step lines — which is why the failure is a silent 6-minute wall with no diagnostic. ## Why it's intermittent The command that hangs is almost certainly `cargo test --offline`, blocking on the shared Cargo build-directory lock `target/debug/.cargo-lock`. Cargo prints `Blocking waiting for file lock on build directory` to **stderr** (never stdout) and waits indefinitely when another cargo process holds the lock. Gates run sequentially, but several gates spawn a long-lived `run` daemon that is itself a `cargo test` process holding that lock; if teardown races (daemon not fully reaped before the next gate's assert cargo starts), the next gate's cargo blocks forever. This matches every observed property: transient, zero stdout, and hitting whichever gate happens to run next. ## Fix plan - **(primary) Bound command execution.** Convert `netns::run` from `.output()` to `spawn()` + poll `try_wait()` against a deadline (default ~60s, well under the 6-min CI step timeout); on timeout, kill the child's **process group** (set `process_group(0)` at spawn, `kill(-pgid, SIGKILL)`) and return a `LabError::Exec("command timed out …")` carrying any partial stderr. A hung command then fails its *step* fast with a clear reason instead of hanging the job. Add a test: `sh -c 'sleep 30'` under a 1s bound returns a timeout error in ~1s. - **(diagnostics) Stream TAP incrementally.** Emit `TAP version 13` + the plan line up front and each step's result as it completes (line-buffered), so a future hang shows exactly which step stalled and how far the run got. Keep the JUnit artifact unchanged. - **(root cause) Stop running `cargo` inside scenarios.** The `lab` job already pre-builds all test binaries in its build step. Have gates invoke the pre-built test binary directly (locate it once via `cargo test --no-run --message-format=json`) so no in-scenario cargo ever contends on `.cargo-lock`. This removes the lock-contention trigger entirely. Primary + diagnostics are a small, self-contained lab-hardening increment; the root-cause item is a larger follow-on.

vxfemboy commented

2026-07-06 23:10:22 +00:00

(Migrated from github.com)

The flow-live gate is worse than an intermittent flake — it wedges past GitHub's step timeout-minutes. Root cause: the flow-sflow-live scenario spawns hsflowd (an external daemon), which inherits the CI step's redirected stdout (exec … >lab-gate.log); the open pipe keeps the step's process group alive even after sudo timeout kills lab test, so GitHub's step-timeout kill doesn't reap it and the step never terminates. That hung the whole lab job to its job cap on 3+ consecutive main runs, starving every gate after it (deception-syncookie, -v6, xdp never ran).

Disabled the gate in CI (if: false) in the timeout PR so the rest of the suite runs; the scenario still works locally. Proper fix for this issue: ensure the lab reaps daemons like hsflowd into the scenario's process group (the deception run daemons already teardown by pgid — extend that to hsflowd), and/or close/redirect the daemon's inherited stdout so it can't hold the step open. Then re-enable the CI gate.

The flow-live gate is worse than an intermittent flake — it **wedges past GitHub's step `timeout-minutes`**. Root cause: the `flow-sflow-live` scenario spawns `hsflowd` (an external daemon), which inherits the CI step's redirected stdout (`exec … >lab-gate.log`); the open pipe keeps the step's process group alive even after `sudo timeout` kills `lab test`, so GitHub's step-timeout kill doesn't reap it and the step never terminates. That hung the whole `lab` job to its job cap on 3+ consecutive `main` runs, starving every gate after it (deception-syncookie, -v6, xdp never ran). Disabled the gate in CI (`if: false`) in the timeout PR so the rest of the suite runs; the scenario still works locally. **Proper fix for this issue:** ensure the lab reaps daemons like `hsflowd` into the scenario's process group (the deception `run` daemons already teardown by pgid — extend that to hsflowd), and/or close/redirect the daemon's inherited stdout so it can't hold the step open. Then re-enable the CI gate.

vxfemboy commented

2026-07-07 14:11:00 +00:00

(Migrated from github.com)

Re-enabling flow-live under the #137 teardown fix confirmed its wedge is a separate, in-step mechanism (not the cross-gate orphan residue #137 fixed): with #137's teardown hardening in place, flow-live STILL wedged in CI (~25min on a 6min step). So hsflowd holds the CI step's stdout pipe open during the step, past GitHub's timeout-minutes kill, so the step never finalizes — independent of teardown. Passes locally (no wedge there).

Dedicated fix needed: guarantee hsflowd cannot inherit/hold the runner's stdout/stderr pipe — e.g. spawn it with setsid + all fds redirected to files//dev/null and </dev/null, and confirm no child of the lab test process retains fd 3/4 (the exec 3>&1 4>&2 saved runner pipe) . Kept quarantined until then. The other three #137 gates (deception-resilience, flowspec, flowspec-auto) are re-enabled and being verified in CI now.

Re-enabling flow-live under the #137 teardown fix confirmed its wedge is a **separate, in-step** mechanism (not the cross-gate orphan residue #137 fixed): with #137's teardown hardening in place, flow-live STILL wedged in CI (~25min on a 6min step). So hsflowd holds the CI step's stdout pipe open *during* the step, past GitHub's `timeout-minutes` kill, so the step never finalizes — independent of teardown. Passes locally (no wedge there). **Dedicated fix needed:** guarantee hsflowd cannot inherit/hold the runner's stdout/stderr pipe — e.g. spawn it with `setsid` + all fds redirected to files/`/dev/null` and `</dev/null`, and confirm no child of the `lab test` process retains fd 3/4 (the `exec 3>&1 4>&2` saved runner pipe) . Kept quarantined until then. The other three #137 gates (deception-resilience, flowspec, flowspec-auto) are re-enabled and being verified in CI now.