diff --git a/.changeset/test-core-stall-guard.md b/.changeset/test-core-stall-guard.md new file mode 100644 index 0000000000..ef8ac652b1 --- /dev/null +++ b/.changeset/test-core-stall-guard.md @@ -0,0 +1,4 @@ +--- +--- + +ci: Test Core mid-suite stalls become labeled fast failures via an output stall guard (#4250). CI-only — releases nothing. diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index e32065a72f..a666cd7ebc 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -52,7 +52,12 @@ jobs: needs: filter if: needs.filter.outputs.core == 'true' runs-on: ubuntu-latest - timeout-minutes: 45 + # Backstop only — the stall guard on the test steps is the primary + # detector for a #4250-style hang and fires well before this. 30 min is + # 2.5-3× a normal run (main ~9.5 min, PR ~12 min), with margin for a cold + # Turbo cache; the old 45 left a hung job "running" for half an hour past + # any plausible healthy finish. + timeout-minutes: 30 permissions: contents: read @@ -117,18 +122,22 @@ jobs: # in parallel, and it dominated this job's critical path. The exclusion # subtracts from the affected set (verified: turbo unions inclusive # filters, then applies `!` negations to the result). - # `set -o pipefail` is load-bearing: GitHub runs these with `bash -e`, which - # does NOT set it, so `turbo … | tee` would report TEE's status and a - # failing suite would go green. That is the same class of bug the tee is - # here to catch, so it must not be introduced by the catching. + # run-with-stall-guard replaces the old `… 2>&1 | tee $log` + + # `set -o pipefail` idiom: the guard tees combined output to the log + # itself and propagates the suite's real exit status, so there is no + # pipe whose status tee could mask (do not reintroduce `| tee`). Its + # actual job is #4250: a run whose output freezes mid-suite while the + # job sits in_progress. Silence past --stall-minutes is declared a + # stall — a labeled red naming the last output line — instead of a + # 20-minute wait for a human (or the job timeout) to notice. 10 min is + # ~5× the longest healthy quiet gap and still under half a normal run. - name: Run affected tests (PR) if: github.event_name == 'pull_request' env: TURBO_SCM_BASE: ${{ github.event.pull_request.base.sha }} run: | - set -o pipefail - pnpm turbo run test --affected --filter=!@objectstack/dogfood --concurrency=4 \ - 2>&1 | tee "$RUNNER_TEMP/test-core.log" + node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/test-core.log" --stall-minutes 10 -- \ + pnpm turbo run test --affected --filter=!@objectstack/dogfood --concurrency=4 # Push to main: full run. Spec's suite runs here plain (uninstrumented); # the coverage-instrumented pass moved to the nightly Spec Coverage @@ -139,9 +148,8 @@ jobs: - name: Run all tests (push) if: github.event_name == 'push' run: | - set -o pipefail - pnpm turbo run test --filter=!@objectstack/dogfood --concurrency=4 \ - 2>&1 | tee "$RUNNER_TEMP/test-core.log" + node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/test-core.log" --stall-minutes 10 -- \ + pnpm turbo run test --filter=!@objectstack/dogfood --concurrency=4 # Runs even when the suite failed — that is when it earns its keep. A red # suite plus a GREEN completeness check means real test failures; a red diff --git a/scripts/run-with-stall-guard.mjs b/scripts/run-with-stall-guard.mjs new file mode 100644 index 0000000000..6f83cecf65 --- /dev/null +++ b/scripts/run-with-stall-guard.mjs @@ -0,0 +1,154 @@ +#!/usr/bin/env node +// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. +// +// run-with-stall-guard -- a stalled test run must SAY it stalled, not sit +// in_progress until someone reads log timestamps. +// +// Test Core has hung mid-suite with frozen output -- three times in one day +// (#4250). The signature is mechanical: a healthy run prints continuously and +// finishes in ~9-12 minutes; a stalled one stops emitting bytes entirely (two +// log fetches 9 minutes apart returned byte-identical content) while the job +// stays in_progress until the job-level timeout or a human cancels. A job +// timeout cannot tell "slow" from "stopped" -- only output progress can. So +// this wrapper watches exactly that: if the wrapped command emits nothing for +// --stall-minutes, it declares a stall, prints the last line seen and how long +// ago it was seen, kills the command's process group, and exits 75 +// (EX_TEMPFAIL: the sanctioned response is a rerun -- every #4250 occurrence +// passed on rerun of the same commit). +// +// node scripts/run-with-stall-guard.mjs --log [--stall-minutes N] -- +// +// It also owns the log tee: combined stdout+stderr is forwarded to this +// process's stdout AND appended to --log (which check-test-completeness.mjs +// reads afterwards). The old `cmd 2>&1 | tee $log` pattern needed +// `set -o pipefail` or tee's exit status would mask a red suite; here the +// child's real exit status is propagated by construction, so there is no pipe +// to guard. Do not reintroduce `| tee`. +// +// Exit status: the child's own code when it finishes; 75 on a declared stall; +// 1 when the child dies on a signal this guard did not send. + +import { spawn } from 'node:child_process'; +import { createWriteStream } from 'node:fs'; + +const STALL_EXIT_CODE = 75; // EX_TEMPFAIL +const CHECK_INTERVAL_MS = 5_000; +const SIGKILL_GRACE_MS = 10_000; + +const argv = process.argv.slice(2); +let logPath = ''; +let stallMinutes = 10; +let command = []; + +for (let i = 0; i < argv.length; i++) { + if (argv[i] === '--log') logPath = argv[++i] ?? ''; + else if (argv[i] === '--stall-minutes') stallMinutes = Number(argv[++i]); + else if (argv[i] === '--') { + command = argv.slice(i + 1); + break; + } else { + console.error(`run-with-stall-guard: unknown option ${argv[i]}`); + process.exit(1); + } +} + +if (!logPath || command.length === 0 || !Number.isFinite(stallMinutes) || stallMinutes <= 0) { + console.error( + 'run-with-stall-guard: usage: run-with-stall-guard.mjs --log [--stall-minutes N] -- ', + ); + process.exit(1); +} + +const stallMs = stallMinutes * 60_000; +const log = createWriteStream(logPath, { flags: 'w' }); + +// detached: own process group, so a stall verdict can kill pnpm -> turbo -> the +// per-package vitest processes together, not just the top of the tree. +const child = spawn(command[0], command.slice(1), { + detached: true, + stdio: ['ignore', 'pipe', 'pipe'], +}); + +let lastOutputAt = Date.now(); +let lastLine = '(no output yet)'; +let carry = ''; +let stalled = false; + +function onChunk(chunk) { + lastOutputAt = Date.now(); + process.stdout.write(chunk); + log.write(chunk); + + // Remember the last complete non-blank line for the stall verdict. ANSI is + // stripped so the verdict quotes text, not colour codes. + carry = (carry + chunk.toString('utf8')).slice(-8192); + const nl = carry.lastIndexOf('\n'); + if (nl === -1) return; + for (const line of carry.slice(0, nl).split('\n').reverse()) { + const clean = line.replace(/\x1B\[[0-9;]*m/g, '').trim(); + if (clean) { + lastLine = clean; + break; + } + } + carry = carry.slice(nl + 1); +} + +child.stdout.on('data', onChunk); +child.stderr.on('data', onChunk); + +function killGroup(signal) { + try { + process.kill(-child.pid, signal); + } catch { + // Group already gone -- the 'exit' handler finishes up. + } +} + +const watchdog = setInterval(() => { + const silentMs = Date.now() - lastOutputAt; + if (silentMs < stallMs) return; + + stalled = true; + clearInterval(watchdog); + const banner = ` +${'═'.repeat(72)} +⛔ STALL: no test output for ${(silentMs / 60_000).toFixed(1)} minutes (limit: ${stallMinutes}m). + + frozen since : ${new Date(lastOutputAt).toISOString()} + last line : ${lastLine} + + This is the #4250 failure mode -- the suite is STOPPED, not slow. A + healthy run prints continuously; only a hang goes silent this long. + Killing the test process group and failing the step now, instead of + sitting in_progress until the job timeout. + + Triage: every #4250 stall so far passed on a plain rerun of the same + commit -- rerun this job before suspecting the diff. If it stalls twice + at the same test file, add that occurrence to #4250. +${'═'.repeat(72)} +`; + process.stdout.write(banner); + log.write(banner); + killGroup('SIGTERM'); + setTimeout(() => killGroup('SIGKILL'), SIGKILL_GRACE_MS).unref(); +}, CHECK_INTERVAL_MS); + +child.on('error', (err) => { + clearInterval(watchdog); + console.error(`run-with-stall-guard: failed to start ${command[0]} -- ${err.message}`); + log.end(() => process.exit(1)); +}); + +child.on('exit', (code, signal) => { + clearInterval(watchdog); + const finish = (status) => log.end(() => process.exit(status)); + if (stalled) { + finish(STALL_EXIT_CODE); + } else if (signal) { + console.error(`run-with-stall-guard: command killed by ${signal}`); + finish(1); + } else { + finish(code ?? 1); + } +});