test(cli): widen the headless capture timing gap instead of the bound

[junhoyeo]

Problem

The three headless_capture_* tests in crates/tokscale-cli/tests/cli_tests.rs assert wall-clock bounds measured around a full tokscale process spawn, so every measurement includes process startup. The bounds were placed inside gaps narrower than the startup cost on a loaded windows-latest runner, so they measured runner speed rather than the behaviour they are named for.

All three failed on the windows-latest leg of run 31196968982 (job 93170461116) with the behaviour under test entirely correct — exit code 17 passed through, 124 returned for the killed child, captured stdout matched — and only the elapsed assertions red:

fast failure waited too long: 11.0576809s                  (bound: < 8s)
fast success waited too long: 11.16815s                    (bound: < 8s)
slow command timeout duration was unexpected: 21.173129s   (bound: >= 10s && < 18s)

Since #1068 made that leg a hard gate, this is a merge blocker that fires on changes unrelated to the code under test.

Why the gap and not the bound

Raising the bounds again cannot work at the old constants.

The two fast tests exist to prove the parent did not wait for its 10s TOKSCALE_NATIVE_TIMEOUT_MS, so the discriminating signal is 10 seconds while the measured startup noise was ~11 seconds. There is no value between "returned immediately" and "waited for the deadline" left to place a bound on.

The slow test's upper bound had already been widened once for exactly this reason — 14s to 18s, after failing at 14.83s in job 92167428621, in a comment noting the bound "was measuring runner speed rather than the behaviour this test is named for". It has now failed at 21.17s, which is past the child's own 20s sleep. At that point the bound can no longer separate "the parent killed the child at its deadline" from "the parent outlived the child", which is the one thing it exists to do, so raising it to 22s would keep the test green while making it vacuous.

So this widens the gap between the two outcomes until the signal dominates the noise, rather than widening the bound until it stops firing.

Changes

TOKSCALE_NATIVE_TIMEOUT_MS becomes a per-test parameter of headless_capture_command, because the fast and slow tests need the parent's deadline on opposite sides of the child's runtime and a single shared constant cannot serve both.

Test	Parent deadline	Child	Bound	Headroom
fast_success / fast_nonzero	10s → 60s	exits immediately	< 8s → < 30s	27s above a healthy run, 30s below the failure mode
slow_command_times_out	10s (unchanged)	20s → 120s sleep	>= 10s && < 18s → >= 10s && < 60s	50s above the deadline, 60s below the child's sleep

The slow test's lower bound stays at the parent's own deadline. It is exact by construction — the child cannot exit on its own before then, so anything faster means the parent gave up early.

Every behavioural assertion is untouched: exit code 17 for fail, 124 for slow, and the byte-for-byte stdout comparisons against captured ok / captured fail with no trailing newline. The existing reasoning in the comments is extended rather than replaced, including fake_codex.rs's module doc, which now explains why the sleep must exceed the parent's timeout by a wide margin rather than merely exceed it.

The trade-off is that a genuinely hung parent now takes up to 60s to be reported instead of 10s. That is clearly preferable to a gate that blocks unrelated PRs.

Verification

cargo test -p tokscale-cli --test cli_tests headless_capture on an M-series Mac:

test headless_capture_fast_nonzero_preserves_exit_code ... ok
test headless_capture_fast_success_does_not_wait_for_timeout ... ok
test headless_capture_slow_command_times_out ... ok

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 150 filtered out; finished in 14.47s

Run individually, the fast tests take 3.22s and 3.55s and the slow test 13.99s — the same order as before, so the change costs no wall-clock time in the passing case.

Full package suite is green: cargo test -p tokscale-cli → 1023 unit + 153 integration passed, 0 failed. cargo fmt --all -- --check and cargo clippy -p tokscale-cli --all-targets are clean.

Red-green evidence

Each bound was checked to still fire, by temporarily sabotaging run_capture_command in crates/tokscale-cli/src/main.rs and reverting afterwards. The sabotages are deliberately narrow so the timing assertion is the one that fails, not the exit-code assertion.

Parent always sits on its deadline before reaping the child, exit code still passed through (thread::sleep(timeout) before the wait loop) — both fast tests red:

fast success waited too long: 63.215592334s
fast failure waited too long: 63.227539042s
test result: FAILED. 1 passed; 2 failed; ... finished in 63.24s

Parent enforces its deadline 90s late, still reporting 124 (deadline + Duration::from_secs(90)) — the slow test's upper bound red:

slow command timeout duration was unexpected: 103.410889333s
test result: FAILED. 0 passed; 1 failed; ... finished in 103.41s

Parent gives up immediately instead of waiting for its deadline (let deadline = Instant::now();) — the slow test's lower bound red:

slow command timeout duration was unexpected: 3.187209875s
test result: FAILED. 0 passed; 1 failed; ... finished in 3.19s

All three sabotages were reverted and crates/tokscale-cli/src/main.rs is byte-identical to main in this branch; no production code is changed.

Closes #1078

---

Summary by cubic

Stabilizes headless_capture_* CLI tests by widening the timing gap and refining the deadline check to subtract startup overhead and resample only when needed. Prevents false CI failures on windows-latest; no production code changed.

• Bug Fixes
  • Made TOKSCALE_NATIVE_TIMEOUT_MS per-test; fast tests use 60s with < 30s, slow test keeps 10s with >= 10s && < 60s.
  • Increased fake_codex slow sleep to 120s via FAKE_CODEX_SLOW_SLEEP_SECS; trade-off: a hung parent can take up to 60s to report.
  • Added headless_capture_timeout_fires_near_its_deadline: subtracts a fast baseline (min of 2) from a timed-out run and asserts 10s ± 5s; resamples the timed-out run only when it reads too long, taking the min to filter one-off spikes.

^{Written for commit b527b71. Summary will update on new commits.}

[vercel]

The latest updates on your projects. Learn more about Vercel for GitHub.

1 Skipped Deployment

Project	Deployment	Actions	Updated (UTC)
tokscale	Ignored	Preview	Aug 9, 2026 2:39am

[cubic-dev-ai]

No issues found across 2 files

_{Re-trigger cubic}

[junhoyeo]

Pinning the deadline itself, not just "the parent killed the child"

A review of this PR found a real gap in it, so here is the follow-up: 59e1cd1.

Widening the gap fixed the flake, but it gave something up. headless_capture_slow_command_times_out now accepts [10s, 60s) for a 10s deadline, and that window can no longer tell whether the timeout fired anywhere near where it was configured to. A regression that made the effective deadline 50s would still kill the 120s child, still return 124, and still land inside the window — it would ship green. The old <18s bound did catch that class; it just could not survive an 11s runner.

Assert on the difference, because startup is common-mode

The new test, headless_capture_timeout_fires_near_its_deadline, measures a fast baseline run and a timed-out run in the same test on the same machine and asserts on their difference. Everything paid outside the deadline — process spawn, dynamic linking, argument parsing, settings load, spawning and reaping the stand-in on PATH — is paid by both runs and cancels.

The numbers from the failure that forced the bound open (run 31196968982, job 93170461116) are the argument for it. Against a configured 10s deadline:

fast_success 11.16815s    fast_fail 11.0576809s    slow 21.173129s

slow - fast_success = 10.0050s
slow - fast_fail    = 10.1154s

Every absolute number there is ~11s away from anything a fixed threshold could use — the startup overhead alone is longer than the deadline being measured, which is why no absolute bound survived. The differences recover the deadline to within 0.12s, on the very runner that was too slow for a bound of any width. The ~11s of startup noise is not something the new assertion tolerates; it is something it subtracts away.

One thing the design had to learn the hard way

The overhead is only common-mode in steady state, and the first spawn in the test is not. Measured locally, the first tokscale spawn costs 3.5–6.1s while every spawn after it costs ~45ms. Subtracting a cold baseline from a warm timed-out run charges that one-off to the deadline: a first draft of this test failed exactly that way, reporting a 3.96s deadline for a 10s configured one because its single baseline sample happened to cost 6.09s.

So the baseline is the minimum of two fast samples. Elapsed-time noise is one-sided — nothing makes a run finish faster than the work it has to do — so the smaller sample is the better estimate of the floor, and one unlucky sample no longer moves it. With that in place the measurement is stable:

baseline=42.532958ms  slow=10.038495042s  measured=9.995962084s
baseline=38.663542ms  slow=10.035906833s  measured=9.997243291s
baseline=40.114167ms  slow=10.033497666s  measured=9.993383499s
baseline=38.701333ms  slow=10.020296875s  measured=9.981595542s

Within 20ms of the configured 10s across repeated runs, and it stays green under 2x CPU oversubscription (20 busy loops on 10 cores).

Tolerance: configured ± 5s, i.e. [5s, 15s]

Generous, because the worst residual ever measured is the 0.12s above on a loaded windows-latest runner and warm local runs land within ~50ms — 5s is roughly forty times the worst of those, so this should not become the next bound to be widened. Meaningful, because it is the largest tolerance that still fails when the effective deadline grows by half. Widening it past 5s is a change of meaning, not of margin.

Red/green proof

Temporarily scaling the deadline inside run_capture_command, then reverting:

Injected regression	headless_capture_slow_command_times_out	headless_capture_timeout_fires_near_its_deadline
timeout * 5 (50s effective)	passes	FAILS — measured 49.977642376s ... accepted 5s..=15s
timeout * 8 / 5 (16s effective)	passes	FAILS — measured 15.986997208s ... accepted 5s..=15s
none (reverted)	passes	passes

The first row is precisely the scenario the review raised: the coarse window happily reports success while the deadline is five times what it was configured to be, and the new assertion says so with the numbers in the failure message.

Why not a unit test on run_capture_command directly

It was considered — run_capture_command takes timeout: Duration and main.rs already has a mod tests, so a direct call would exclude tokscale's own process startup entirely rather than subtracting it. Two reasons it lost:

1. CARGO_BIN_EXE_fake_codex is only set for integration tests, so a unit test needs a cross-platform sleeping child it can name without guessing at a target directory. The existing fixture comments avoid exactly that guess, and the alternatives (sleep, timeout /t, powershell -Command Start-Sleep) are either missing or awkward on Windows, which is the platform this whole thread of failures came from.
2. More importantly, a direct call passes a Duration in and so cannot see the path where a deadline regression is most likely to appear: TOKSCALE_NATIVE_TIMEOUT_MS → Settings::get_native_timeout → parse → clamp(5_000, 3_600_000) → run_capture_command. The integration test measures the deadline the CLI actually ended up using, config path included.

The narrower measurement was not worth losing the configuration path plus cross-platform coverage.

Kept, not replaced

The coarse [10s, 60s) window stays exactly as it is. It answers "did the parent end this run, or did the child exit on its own after 120s" — which the delta cannot answer, since a parent that ignored its deadline entirely and a parent that honored it both produce a difference the subtraction would have to interpret. The two assertions answer different questions and both are needed. The diff is purely additive: no existing assertion, exit code (17 / 124), or byte-for-byte stdout check (captured ok / captured fail, no trailing newline) was modified.

Test output

running 4 tests
test headless_capture_fast_success_does_not_wait_for_timeout ... ok
test headless_capture_fast_nonzero_preserves_exit_code ... ok
test headless_capture_slow_command_times_out ... ok
test headless_capture_timeout_fires_near_its_deadline ... ok

test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 150 filtered out; finished in 14.30s

Suite runtime is unchanged — 14.30s against 14.84s before the new test — because the new test's 10s wait overlaps the existing slow test's under cargo's default parallelism.

Full crate, both targets:

test result: ok. 1023 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 8.85s
test result: ok. 154 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 21.99s

cargo fmt --all -- --check is clean.

[cubic-dev-ai]

All reported issues were addressed across 1 file (changes from recent commits).

<sub>Reply with feedback, questions, or to request a fix.

Re-trigger cubic</sub>

[junhoyeo]

Valid, and fixed in 093f25a.

The noise model is symmetric and I only defended one side of the subtraction. The reason the two sides were not treated the same was cost, not principle: a baseline sample costs ~45ms once warm, while a sample of the timed-out run costs a full HEADLESS_SLOW_TIMEOUT_MS, so an eager min-of-two there would have added 10s to every run of the suite on every CI leg to insure against a spike that has never been observed (worst measured residual: 0.12s on the loaded windows-latest runner, ~20ms locally).

So the timed-out side is now a minimum of samples as well, sampled lazily: the second sample is taken only when the first disagrees with the configured deadline. Steady state stays at one wait, and the protection you asked for is there when it is actually needed.

Worth spelling out that this cannot hide a regression, since a conditional resample looks like a retry:

• A second sample is only ever taken when the assertion is already failing, and a minimum can only move the estimate down — so the resample can rescue a spike that inflated the measurement, and nothing else.
• A deadline that really is too long measures too long twice. Re-running the 5x injection confirms it: the test now takes both samples and still fails with measured 49.99086375s ... accepted 5s..=15s.
• A deadline that fires early measures short twice, and min keeps it short, so the lower bound is if anything stricter.

The behavioural assertions — exit 124, exit 17, byte-for-byte stdout — are checked on every sample and are never retried. Only the timing measurement is resampled.

[cubic-dev-ai]

All reported issues were addressed across 1 file (changes from recent commits).

<sub>Tip: Review your code locally with the cubic CLI to iterate faster.

Re-trigger cubic</sub>

[junhoyeo]

Valid, and fixed in b527b71.

You are right, and it follows directly from a property I had already written into the comment two paragraphs above without carrying it through: the resample takes a minimum, so it only ever moves the measurement down. That makes the < low branch provably incapable of changing the outcome — it spent a second full HEADLESS_SLOW_TIMEOUT_MS to arrive at the failure it had already arrived at.

The resample is now conditioned on measured_deadline > high alone, and the comment states why the lower half is deliberately excluded rather than leaving it as something to rediscover.

Both directions re-verified by scaling the deadline in run_capture_command:

• timeout * 4 / 1 too long (5x, 50s effective) — resamples, then fails: measured 49.981630375s ... accepted 5s..=15s, 105s.
• timeout / 4 too short (2.5s effective) — fails on the first sample: measured 2.47093175s ... accepted 5s..=15s, 8.39s, no second timed-out run.

So the too-short case now fails roughly an order of magnitude faster, and the too-long case keeps the spike protection it was added for.