Skip to content

fix(ci): nextest had no per-test timeout — the key name was wrong, so a hang killed the job anonymously and evicted the merge queue - #2517

Closed
noahgift wants to merge 2 commits into
mainfrom
fix/nextest-slow-timeout
Closed

fix(ci): nextest had no per-test timeout — the key name was wrong, so a hang killed the job anonymously and evicted the merge queue#2517
noahgift wants to merge 2 commits into
mainfrom
fix/nextest-slow-timeout

Conversation

@noahgift

Copy link
Copy Markdown
Contributor

main has not moved all day. This is why.

The defect

[profile.ci]
slow-warning = "60s"

There is no slow-warning key in nextest. The real one is slow-timeout. nextest does not reject an unknown key — it prints a warning and carries on:

warning: in config file .config/nextest.toml, ignoring unknown
         configuration key: profile.ci.slow-warning

So profile.ci had no per-test timeout at all. From merge_group job 95162862834 for #2502:

12:31:55  build starts
12:50:58  Starting 80806 tests across 69 binaries
13:36:07  ##[error]The operation was canceled.

45 minutes inside nextest, killed by the job's timeout-minutes: 85, naming no test. #2502 was evicted from the merge queue 31 seconds later.

That warning was line 353 of that job's log — and of every workspace-test log before it.

The compounding half

status-level = "fail" is below slow in nextest's ordering (none < fail < retry < slow < pass < all), so the SLOW lines that would have named the culprit were suppressed too. Measured on a probe crate:

status-level SLOW lines
fail (current) 0
slow 3

Fixing the timeout without this would have kept hiding the warning that precedes the kill.

terminate-after is measured, not guessed

Full workspace run on an idle 48-core box — 80,806 tests, 353s wall:

test duration
aprender-orchestrate bug_hunter::test_bh_mod_001_hunt_all_modes 202.7s
aprender-orchestrate bug_hunter::test_bh_mod_001_hunt_returns_result 157.3s
aprender-orchestrate bug_hunter::test_bh_mod_046_apply_spec_quality_gate_no_pmat 118.0s
aprender-train transformer_trainer::falsify_lora_tests::…rslora_stable_high_rank 67.5s

over 60s: 6 · over 120s: 2 · over 300s: 0

terminate-after = 20 periods = 1200s is ~6× the slowest real test, so it cannot kill a legitimately slow one — while a genuine hang dies at 20 minutes with a name instead of taking the whole job down anonymously.

(The bug_hunter tests are separately being made fast; this bound does not depend on that landing.)

Also fixed

  • timeout-minutes: 85 → 100. The step sets 75, but "Set up runner" measured 20 minutes, so 20 + 75 = 95 > 85 and the job timeout always fired first — producing a bare "The operation was canceled" naming no step. The step timeout must be the one that can fire, because it points at the step.
  • junit path was doubled. path is relative to the store dir, not the workspace root, so target/nextest/ci/junit.xml produced target/nextest/ci/target/nextest/ci/junit.xml. Now junit.xml, verified landing at target/nextest/ci/junit.xml.

Guarded

A warning nobody reads is not a diagnostic, so it is a hard failure now. check_nextest_config_keys.sh runs nextest's real parser against a three-line throwaway crate with this repo's config — no regex of my own guessing at nextest's schema — and fails on any ignored key. Its case table carries a control row so it cannot pass by reporting every key it sees.

Mutation: restoring slow-warning turns it RED; restoring slow-timeout turns it green. Verified both directions.

Wired into guard-runner-labels, which is in gate.needs. bashrs lint: 0 errors.

Refs #2502

…ng, so a hang killed the job anonymously and evicted the merge queue

.config/nextest.toml carried

    [profile.ci]
    slow-warning = "60s"

There is no `slow-warning` key in nextest. The real one is `slow-timeout`.
nextest does not reject an unknown key -- it prints a warning and continues:

    warning: in config file .config/nextest.toml, ignoring unknown
             configuration key: profile.ci.slow-warning

So profile.ci had NO per-test timeout at all. Consequence, merge_group job
95162862834 for #2502:

    12:31:55  build starts
    12:50:58  Starting 80806 tests across 69 binaries
    13:36:07  ##[error]The operation was canceled.

45 minutes inside nextest, killed by the JOB's `timeout-minutes: 85`, naming no
test. #2502 was evicted from the merge queue 31 seconds later. main did not move
all day.

That warning was line 353 of that job's log, and of every workspace-test log
before it.

Second, compounding defect: `status-level = "fail"` is BELOW `slow` in nextest's
ordering (none < fail < retry < slow < pass < all), so the SLOW lines that would
have named the culprit were suppressed too. Measured on a probe crate:
status-level="fail" emits 0 SLOW lines, "slow" emits 3. Fixing the timeout
without this would have kept hiding the warning that precedes the kill.

terminate-after is set from measurement, not a guess. Full workspace run on an
idle 48-core box, 80806 tests, 353s wall:

    202.7s  aprender-orchestrate bug_hunter::tests::test_bh_mod_001_hunt_all_modes
    157.3s  aprender-orchestrate bug_hunter::tests::test_bh_mod_001_hunt_returns_result
    118.0s  aprender-orchestrate bug_hunter::tests::test_bh_mod_046_apply_spec_quality_gate_no_pmat
     67.5s  aprender-train       transformer_trainer::falsify_lora_tests::...rslora_stable_high_rank

    over  60s: 6 tests      over 120s: 2      over 300s: 0

terminate-after = 20 periods = 1200s is ~6x the slowest real test, so it cannot
kill a legitimately slow one, while a genuine hang dies at 20 minutes WITH A NAME
instead of taking the whole job down anonymously.

Also fixed:

* `timeout-minutes: 85` -> 100 on workspace-test. The step sets 75, but "Set up
  runner" measured 20 minutes, so 20 + 75 = 95 > 85 and the JOB timeout always
  fired first -- producing a bare "The operation was canceled" that names no
  step. The step timeout must be the one that can fire, because it points at the
  step.

* junit `path` is relative to the store dir, not the workspace root, so
  "target/nextest/ci/junit.xml" produced
  target/nextest/ci/target/nextest/ci/junit.xml. Now "junit.xml", verified to
  land at target/nextest/ci/junit.xml.

Guarded, because a warning nobody reads is not a diagnostic:
scripts/check_nextest_config_keys.sh runs nextest's REAL parser against a
three-line throwaway crate with this repo's config and fails on any ignored key.
Its case table has a control row so it cannot just report every key it sees.

Mutation: restoring `slow-warning` turns the guard RED, and restoring
`slow-timeout` turns it green again. Verified both directions.

Wired into guard-runner-labels, which is in gate.needs. bashrs lint: 0 errors.

Refs #2502
…s not on the host runner

The first version failed with

    SKIP: cargo-nextest not installed; install with `cargo install cargo-nextest --locked`
    ##[error]Process completed with exit code 1

which is the guard failing CLOSED in the wrong place: every other step in
guard-runner-labels runs on the host, and cargo-nextest lives only in the
sovereign-ci image. Moved both steps into `docker run` against $IMAGE.

The probe crate has ZERO dependencies, so CARGO_NET_OFFLINE=1 is safe and no
registry mount is needed. Verified locally: both the check and its self-test
pass with CARGO_NET_OFFLINE=1.
@noahgift

Copy link
Copy Markdown
Contributor Author

Superseded by #2527, which consolidates this with the other guard PRs. All four inserted into the same guard-runner-labels block in ci.yml, so merging them separately meant one conflict per merge — and each rebase is another push competing with the merge queue. Resolved once in #2527; the commits are carried over unchanged.

@noahgift noahgift closed this Aug 16, 2026
auto-merge was automatically disabled August 16, 2026 21:08

Pull request was closed

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