Skip to content

test(run-executor): make the timeout-honesty test deterministic - #68

Closed
tnunamak wants to merge 1 commit into
mainfrom
fix/run-executor-timeout-honesty-determinism
Closed

tnunamak wants to merge 1 commit into
mainfrom
fix/run-executor-timeout-honesty-determinism

Conversation

@tnunamak

@tnunamak tnunamak commented Sep 9, 2026 •

Copy link
Copy Markdown
Contributor

Why

A test that fails at random under load sends whoever investigates it hunting a bug in the run executor that is not there. reference-implementation/test/run-executor-timeout-honesty.test.ts was the last such test in the suite: across six controlled full-suite arms it failed once, and the failure landed on the least loaded arm — so it was load-sensitive, but not determined by the concurrency cap and not a leak of an unowned background task.

The test set maxRunWallClockMs to 150 ms and required a real connector subprocess to spawn, complete the START handshake (the first message the executor exchanges with the subprocess to confirm it is alive), durably ingest 5 records through a real in-memory ingest server, and emit a PROGRESS message of type phase_boundary — the connector's signal that it has finished one declared stage of work — all inside that window.

A watchdog is the timer that kills a run if no progress arrives before it fires. 150 ms was never enough, because maxRunWallClockMs is a resettable no-progress budget rather than a total-run budget: the watchdog re-arms on every PROGRESS message, via createAttemptWatchdog's markProgress (run-executor.ts, arm()). But that watchdog is constructed during run setup (run-executor.ts:1045) before the connector subprocess is spawned. Until the connector's first PROGRESS message arrives there is nothing to re-arm it, so the budget also covers node process startup — a cost the test does not control and cannot bound.

Measured with the run-executor's own elapsed_ms at the phase-boundary latch, on a 24-core host:

Condition elapsed_ms Budget Margin
Idle 84–124 ms 150 ms 26 ms
Under load up to 148 ms 150 ms 2 ms

The sibling test's own comment claimed 150 ms was "comfortably longer than the ingest round-trip". Idle, it already consumed 83% of the budget; under load, 98.7%.

What changed

This is deliberately not "raise 150 ms to 5 s".

The test generates two throwaway connectors on the fly, one per scenario shape. Both now emit a plain PROGRESS "connector ready" message immediately after START, which re-arms the watchdog once the process is up — so the ingest round-trip no longer shares a single allowance with process startup. The watchdog is armed at construction, before the spawn, so startup remains subject to the initial allowance: this does not make startup unbounded or remove timing sensitivity. Verified by counting markProgress calls across the file's 8 tests: 39 re-arms with the message versus 31 without, exactly 8 more, one per connector spawn.

Two claims from earlier revisions are retracted. One framed this as "removing the spawn race", which overclaims — startup is still bounded by the initial allowance. The other credited a drop in elapsed_ms; that was wrong, because startedAt is stamped at run-executor.ts:1122, before the watchdog exists, so elapsed_ms spans the spawn and is blind to the re-arm. The markProgress counts above come from instrumentation added for this change and were not independently reproduced.

The invariant is also named rather than implied: WALL_CLOCK_BUDGET_MS = 400 and POST_BOUNDARY_SLEEP_MS = WALL_CLOCK_BUDGET_MS * 3 — the latter being how long a connector keeps working locally after announcing a phase boundary, which must exceed the budget for the test to mean anything — replace scattered 150 / 500 / 2_000 literals, so "the post-boundary sleep must out-run the budget" is stated in one place instead of being an accident of two unrelated numbers.

The allowance rises from 150 ms to 400 ms and resets on readiness. No headroom multiplier or reduction in flake frequency is claimed: passing runs do not establish a causal rate change, and the earlier "~14×" figure was derived from the retracted elapsed_ms measurement.

What did not change

Production code is untouched — the diff is one test file.

Timeout honesty is not weakened. The property under test is that the executor reports a timeout as a timeout, and that a declared local-only phase boundary is not truncated. Every "must time out" test still uses a connector that hangs forever with no further progress, so only the watchdog can end those runs; a larger budget delays the kill, it cannot prevent it. The phase-boundary test's post-boundary sleep is still 3× the budget, so a re-armed rather than disarmed watchdog would still kill the run and fail the test. The test covering the secondary ceiling still relies on the real one: a run doing only local work is allowed four times the no-progress budget before it is killed, and that multiplier is unchanged. The control test asserting that a plain PROGRESS does not disarm the watchdog is now stronger, because its connector emits one, so the "phase_boundary, not merely PROGRESS" distinction is exercised rather than assumed.

The disarm logic itself remains separately covered, without any subprocess, by test/run-executor-watchdog.test.ts (2 of 2 pass, unchanged). That file uses real short timers rather than an injected or fake clock; no fake-clock proof exists here or is added by this change.

Verification

Node v22.23.1, branched on origin/main (bac55262f). 40 runs of the file in total:

Arm Result
Before, 10× idle 10/10 pass, 8/8 tests each
Before, 10× under load 10/10 pass, 8/8 tests each
After, 10× idle 10/10 pass, 8/8 tests each
After, 10× under bounded load UNVERIFIED — observed 10/10, logs not retained

The before arms passing is expected and is the point: this is a narrow-margin race, not a deterministic failure. The 2 ms measured margin, not a pass/fail count, is the evidence that the defect was real.

Retained logs cover 30 of the 40 runs; the fourth arm was run inline and its output was not kept, so that row is UNVERIFIED and establishes nothing. An independent review reproduced 10/10 on a different Node major version, but under idle conditions, which does not substantiate the loaded arm. Behavior under contention is unproved.

File runtime rises from about 4.8 s to about 7.7 s, because the five timeout tests now wait 400 ms instead of 150 ms before the watchdog fires. That is the honest cost of the larger budget.

ultracite, this repository's formatter and linter, reports one pre-existing formatting error on this file; it is present on unmodified origin/main and is not introduced here.

Assisted-by: AI

…timeout-honesty test

`run-executor-timeout-honesty.test.ts` was the last load-sensitive test in the
suite: it set `maxRunWallClockMs` to 150 ms and expected a real connector
subprocess to spawn, complete the START handshake, durably ingest 5 records and
emit a PROGRESS `phase_boundary` inside that one window.

`maxRunWallClockMs` is a resettable no-progress allowance, not a total-run
budget — `markProgress` re-arms the timer on every PROGRESS message — but the
watchdog is armed at construction, before the subprocess is spawned. With no
PROGRESS before the phase boundary, the first allowance had to cover `node`
startup, the handshake and the ingest round-trip together.

Measured via the run-executor's own `elapsed_ms` at the phase-boundary latch
(24-core host): 84-124 ms idle, up to 148 ms under load, against a 150 ms
allowance. A 2 ms margin. That metric spans the whole attempt from `startedAt`,
so it is the right diagnostic for what the old allowance had to cover in one
stretch — but it is NOT a measure of this change's effect.

This raises the no-progress allowance to 400 ms and resets it on connector
readiness; the completion case stays at three allowances and the secondary
ceiling at four. Startup remains subject to the initial allowance.

- Both generated connectors emit a plain `PROGRESS` "ready" message immediately
  after START, so the ingest round-trip no longer shares one allowance with
  process startup. This does not make startup unbounded and does not remove
  timing sensitivity. Verified by counting `markProgress` calls across the 8
  tests: 39 re-arms with the message versus 31 without — exactly 8 more, one per
  connector spawn. (`elapsed_ms` cannot show this: `startedAt` is stamped before
  the watchdog exists, so the re-arm does not move it.)
- The allowance and the post-boundary sleep become named constants
  (`WALL_CLOCK_BUDGET_MS`, `POST_BOUNDARY_SLEEP_MS = 3x`), so the invariant
  ("the sleep must out-run the allowance") is stated rather than encoded in two
  unrelated literals.

Timeout honesty is unweakened. Every "must time out" test still hangs forever
with no further progress, so only the watchdog can end those runs. The
phase-boundary test's sleep is still a multiple of the allowance, so a re-armed
(rather than disarmed) watchdog would still fail it. The control test that
asserts a plain PROGRESS does not disarm the watchdog now exercises that
distinction instead of assuming it, because its connector emits one.

No headroom multiplier or reduction in flake frequency is claimed; passing runs
do not establish a causal rate change, and reliability under contention is
unproved. Production code is untouched.

Assisted-by: AI
Signed-off-by: Tim Nunamaker <tnunamak@gmail.com>
@tnunamak

tnunamak commented Sep 10, 2026 •

Copy link
Copy Markdown
Contributor Author

Already on main; closing as landed.

Assisted-by: AI

@tnunamak tnunamak closed this Sep 10, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant