A hung Darling or Lite test shard names its test and still uploads its logs (#5587)

[erikdarlingdata]

Claude posting for Erik Darling.

Fixes #5587.

Why

Run 37824250187 attempt 1: Darling PG shard 3 ran to the job's 30-minute timeout and was cancelled. Its step list shows what the timeout does. "Run Darling PG tests" was in_progress and every later step (Warn, Stop PostgreSQL, both uploads) stayed pending. So a JOB timeout skips the always() steps. No log was kept and no timing was written, because the runner writes the per-test timing only when a chunk ends. A hang did not name its test.

What changes

• Step-level timeout (22 min) on "Run Darling PG tests" and "Run Lite tests (shard)". The step fails, the job goes on, and the always() steps run. Measured step times: Darling 6 to 11 min (run 37824250187), Lite up to 14 min (runs 37831712873, 37819589143, one full Lite shard). The job stays at 30. Trade-off: the comment above the Lite job (about Lite.Tests on hosted Windows runners grew from ~9½ to ~45 minutes in five days; the unsharded nightly run now exceeds its 90-minute cap #5208) says Lite shards are growing toward the 30-minute cap. 22 leaves 8 minutes over today's slowest. It is one number to raise if the growth continues.
• -longRunning 300 on each chunk's runner call (xUnit v3 4.0.1 has it: -longRunning <seconds>, "implies -diagnostics"). Threshold: the slowest normal Darling test in the timing artifacts is 120 s (the store-upgrade classes), so 300 s is above it and well under the step timeout. Proved it prints with a throwaway test (deleted before the push): [D::Darling.Tests] [Long Running Test] 'Darling.Tests.ThrowawayLongRunning.Sleeps', Elapsed: 00:00:03, repeated while it ran.
• Runner output kept. Each chunk's output is teed to TestResults/darling-runner-N.log (Lite: lite-runner-N.log) and uploaded as its own artifact (darling-runner-log-N, lite-runner-log-N) with always(). They are separate from the *-tests-timing-* artifacts because the shadow check and the Lite shard packer read those.
• "Upload PG log and test results on failure" now runs on failure() || cancelled().
• A real unbounded wait found and fixed in RollupBackfillLiveTests (shard 3), see below.

Lite has the same gap (job timeout 30, no step timeout, uploads behind the job), so it gets the same changes. nightly.yml runs the whole suite in one process under 150-minute job timeouts; it has the same no-name-on-hang shape. That is outside this brief, so it is noted, not changed.

Lock-wait ruling (shard 3, attempt 2's darling-tests-timing-3)

Attempt 2's artifact lists 374 test classes for shard 3 (one chunk). I scanned every one of them for LOCK TABLE, FOR UPDATE, pg_advisory, BeginTransaction, lock_timeout, statement_timeout, then read the classes that hold a lock while waiting on other code:

• QueryStoreIntervalPartitionsLiveTests (blockers hold ACCESS SHARE / SHARE UPDATE EXCLUSIVE on the interval tables, lines 536-580): every step it calls runs under SET LOCAL lock_timeout = 5s (QueryStoreIntervalPartitions.cs:83 LockTimeoutSeconds, :500 LockTimeoutSql, used at :715, :892, :942, :1001, :1098, :1256, :1354); Arm's retries are 3 times (30 s apart in the service, 100 ms in the test). The upsert test sets its own lock_timeout = '2s' (:260). Ends.
• QueryStoreIntervalPurgeRowCappedTests (row lock FOR UPDATE, line 488): the purge connection carries statement_timeout=500. Ends.
• ProvisioningSerializationTests (advisory locks, lines 192, 279, 521): every wait is WaitAsync(30 s) or has a 60 s argument. Ends.
• RetiredBaselineAggregateTests (lock_timeout = 1s, line 594). Ends.
• RollupBackfillLiveTests (line 627 holds ACCESS EXCLUSIVE on a raw chunk): does not provably end. After the test cancels the refresh it did _ = await refresh; while its own lock transaction was still open. The refresh's command timeout is SliceTimeoutSeconds = 60 * 60 (RollupBackfill.cs:666), longer than the job. If the cancel never reached the backend, nothing ended that wait. Fixed: the wait is refresh.WaitAsync(60 s); on the limit the lock is released in the existing finally, the refresh is let finish, and the test fails by name. Honest framing: attempt 1 kept no log, so this is a wait with no end in a shard-3 class that fits the signature, not proof that it was the hang.
• The other lock holders in shard 3 (StatementScrubQueryStatsLiveTests, PlanRegressionDailyTriggerCostRig) hold one connection's own transaction and no second connection waits on it.
• No shard-3 class holds a lock while a store starts (all the lock-holding tests run after their store is migrated), so the inferred V171/V172 scenario does not occur in test code.

Can the service wait the same way at start?

Yes, but every wait ends:

• V171/V172 (PgMigrations.cs:1202-1203, built at :910-918, SQL at :943): SET LOCAL lock_timeout = MigrationCommandTimeoutSeconds - 20 = 280 s (:7626 has the 300 s command timeout), so a reader holding an open transaction on the interval table makes the rung wait up to 280 s per table, then fail with 55P03 before the client timeout.
• The migration advisory lock is polled with pg_try_advisory_lock against MigrationLockWaitTimeoutSeconds = 5 * 300 = 1500 s (:7759, loop at :7888), then it either proceeds (store already current) or throws.
• The hourly partition step (QueryStoreIntervalPartitions.cs:500): 5 s lock_timeout on each step; Arm retries 3 times 30 s apart (:703-765).

So the service can sit for up to 280 s per rung at start behind a long reader, and a test that starts a store behind a long reader looks like a hang for 4 to 5 minutes. I changed no service code.

Nightly

nightly.yml runs the same two suites in one process each, so it had the same gap. Commit 2c31590 (merged with dev at 118f1a8) gives its two test steps the same report.

• Both steps (Run tests for Lite, Run Darling PG tests) now pass -longRunning 300 and tee the runner output to TestResults/lite-runner-nightly.log and TestResults/darling-runner-nightly.log. They still fail when the runner fails, through an explicit $LASTEXITCODE check right after the pipe.
• New always-upload steps publish lite-runner-log-nightly and darling-runner-log-nightly. The Darling failure upload now runs on failure() || cancelled().
• Step timeouts, from the last 5 completed nightly runs on dev (2026-10-06 to 2026-10-08):
  • Lite: the step took 32.4 to 44.2 minutes and the job ran at most 4.9 minutes longer than the step. Job timeout 150, so the step timeout is 150 - 4.9 - 5 = 140. The longest step is 32% of that, under the 70% bar, so the Lite step now has timeout-minutes: 140.
  • Darling: the step took 32.2 to 41.2 minutes and the job ran at most 5.1 minutes longer. Job timeout 60, the step timeout would be 60 - 5.1 - 5 = 49. The longest step is 84% of that, over the bar, so the Darling step has no timeout. A timeout there fails a slow but healthy run. The numbers are written in a comment above each step.
• CiShardHangReportTests has 4 new test cases (12 in all) pinning the nightly steps. Red-plant: with -longRunning 300 removed from the nightly Lite step the Lite case failed (Total 12, Failed 1). Restored, it passes.
• Run once at the end: CiShardHangReportTests, *Census*, *Ratchet*, *DocCommentHygiene* (590 tests, 0 failed, 1 skipped) and Stage=Guard (1432 tests, 0 failed). Build 0 warnings. nightly.yml and build.yml parse as YAML. Never dispatched the nightly workflow, so no real runner has run these steps yet.
• Not covered: the AltCover probe and test-map shard steps also run these suites, under the AltCover runner. They are not single-process test runs and I left them alone.

Test plan

• CiShardHangReportTests (new, 8 tests): step timeout present and under 25 min, -longRunning between 150 and 600 s, Tee to the runner log, uploads run on always(), failure upload on failure() || cancelled(), runner logs not inside the timing artifacts, and the Rollup wait pin. Red-planted once: with -longRunning, the step timeouts and cancelled() removed from the fixture copy, 5 of 7 failed; with the old RollupBackfillLiveTests.cs, the pin failed.
• CiShardCommandLineBudgetTests, RollupBackfillLiveTests (live, on a throwaway rig at port 55551, 0 skipped): pass. *Census*, *Ratchet*, *DocCommentHygiene* plus the two classes above: 594 total, 0 failed, 10 skipped (no rig). -trait Stage=Guard: 1420 total, 0 failed.
• Build: 0 warnings, 0 errors. build.yml parses as YAML.
• Not run: a real runner hitting the step timeout. The first slow shard on a pull request will show the [Long Running Test] line and the runner-log artifact; watch one run.
• Not run: the whole suite or any whole shard (laptop rule).

Head: see the PR.