|
| 1 | +#!/usr/bin/env node |
| 2 | +// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. |
| 3 | +// |
| 4 | +// run-with-stall-guard -- a stalled test run must SAY it stalled, not sit |
| 5 | +// in_progress until someone reads log timestamps. |
| 6 | +// |
| 7 | +// Test Core has hung mid-suite with frozen output -- three times in one day |
| 8 | +// (#4250). The signature is mechanical: a healthy run prints continuously and |
| 9 | +// finishes in ~9-12 minutes; a stalled one stops emitting bytes entirely (two |
| 10 | +// log fetches 9 minutes apart returned byte-identical content) while the job |
| 11 | +// stays in_progress until the job-level timeout or a human cancels. A job |
| 12 | +// timeout cannot tell "slow" from "stopped" -- only output progress can. So |
| 13 | +// this wrapper watches exactly that: if the wrapped command emits nothing for |
| 14 | +// --stall-minutes, it declares a stall, prints the last line seen and how long |
| 15 | +// ago it was seen, kills the command's process group, and exits 75 |
| 16 | +// (EX_TEMPFAIL: the sanctioned response is a rerun -- every #4250 occurrence |
| 17 | +// passed on rerun of the same commit). |
| 18 | +// |
| 19 | +// node scripts/run-with-stall-guard.mjs --log <file> [--stall-minutes N] -- <command...> |
| 20 | +// |
| 21 | +// It also owns the log tee: combined stdout+stderr is forwarded to this |
| 22 | +// process's stdout AND appended to --log (which check-test-completeness.mjs |
| 23 | +// reads afterwards). The old `cmd 2>&1 | tee $log` pattern needed |
| 24 | +// `set -o pipefail` or tee's exit status would mask a red suite; here the |
| 25 | +// child's real exit status is propagated by construction, so there is no pipe |
| 26 | +// to guard. Do not reintroduce `| tee`. |
| 27 | +// |
| 28 | +// Exit status: the child's own code when it finishes; 75 on a declared stall; |
| 29 | +// 1 when the child dies on a signal this guard did not send. |
| 30 | + |
| 31 | +import { spawn } from 'node:child_process'; |
| 32 | +import { createWriteStream } from 'node:fs'; |
| 33 | + |
| 34 | +const STALL_EXIT_CODE = 75; // EX_TEMPFAIL |
| 35 | +const CHECK_INTERVAL_MS = 5_000; |
| 36 | +const SIGKILL_GRACE_MS = 10_000; |
| 37 | + |
| 38 | +const argv = process.argv.slice(2); |
| 39 | +let logPath = ''; |
| 40 | +let stallMinutes = 10; |
| 41 | +let command = []; |
| 42 | + |
| 43 | +for (let i = 0; i < argv.length; i++) { |
| 44 | + if (argv[i] === '--log') logPath = argv[++i] ?? ''; |
| 45 | + else if (argv[i] === '--stall-minutes') stallMinutes = Number(argv[++i]); |
| 46 | + else if (argv[i] === '--') { |
| 47 | + command = argv.slice(i + 1); |
| 48 | + break; |
| 49 | + } else { |
| 50 | + console.error(`run-with-stall-guard: unknown option ${argv[i]}`); |
| 51 | + process.exit(1); |
| 52 | + } |
| 53 | +} |
| 54 | + |
| 55 | +if (!logPath || command.length === 0 || !Number.isFinite(stallMinutes) || stallMinutes <= 0) { |
| 56 | + console.error( |
| 57 | + 'run-with-stall-guard: usage: run-with-stall-guard.mjs --log <file> [--stall-minutes N] -- <command...>', |
| 58 | + ); |
| 59 | + process.exit(1); |
| 60 | +} |
| 61 | + |
| 62 | +const stallMs = stallMinutes * 60_000; |
| 63 | +const log = createWriteStream(logPath, { flags: 'w' }); |
| 64 | + |
| 65 | +// detached: own process group, so a stall verdict can kill pnpm -> turbo -> the |
| 66 | +// per-package vitest processes together, not just the top of the tree. |
| 67 | +const child = spawn(command[0], command.slice(1), { |
| 68 | + detached: true, |
| 69 | + stdio: ['ignore', 'pipe', 'pipe'], |
| 70 | +}); |
| 71 | + |
| 72 | +let lastOutputAt = Date.now(); |
| 73 | +let lastLine = '(no output yet)'; |
| 74 | +let carry = ''; |
| 75 | +let stalled = false; |
| 76 | + |
| 77 | +function onChunk(chunk) { |
| 78 | + lastOutputAt = Date.now(); |
| 79 | + process.stdout.write(chunk); |
| 80 | + log.write(chunk); |
| 81 | + |
| 82 | + // Remember the last complete non-blank line for the stall verdict. ANSI is |
| 83 | + // stripped so the verdict quotes text, not colour codes. |
| 84 | + carry = (carry + chunk.toString('utf8')).slice(-8192); |
| 85 | + const nl = carry.lastIndexOf('\n'); |
| 86 | + if (nl === -1) return; |
| 87 | + for (const line of carry.slice(0, nl).split('\n').reverse()) { |
| 88 | + const clean = line.replace(/\x1B\[[0-9;]*m/g, '').trim(); |
| 89 | + if (clean) { |
| 90 | + lastLine = clean; |
| 91 | + break; |
| 92 | + } |
| 93 | + } |
| 94 | + carry = carry.slice(nl + 1); |
| 95 | +} |
| 96 | + |
| 97 | +child.stdout.on('data', onChunk); |
| 98 | +child.stderr.on('data', onChunk); |
| 99 | + |
| 100 | +function killGroup(signal) { |
| 101 | + try { |
| 102 | + process.kill(-child.pid, signal); |
| 103 | + } catch { |
| 104 | + // Group already gone -- the 'exit' handler finishes up. |
| 105 | + } |
| 106 | +} |
| 107 | + |
| 108 | +const watchdog = setInterval(() => { |
| 109 | + const silentMs = Date.now() - lastOutputAt; |
| 110 | + if (silentMs < stallMs) return; |
| 111 | + |
| 112 | + stalled = true; |
| 113 | + clearInterval(watchdog); |
| 114 | + const banner = ` |
| 115 | +${'═'.repeat(72)} |
| 116 | +⛔ STALL: no test output for ${(silentMs / 60_000).toFixed(1)} minutes (limit: ${stallMinutes}m). |
| 117 | +
|
| 118 | + frozen since : ${new Date(lastOutputAt).toISOString()} |
| 119 | + last line : ${lastLine} |
| 120 | +
|
| 121 | + This is the #4250 failure mode -- the suite is STOPPED, not slow. A |
| 122 | + healthy run prints continuously; only a hang goes silent this long. |
| 123 | + Killing the test process group and failing the step now, instead of |
| 124 | + sitting in_progress until the job timeout. |
| 125 | +
|
| 126 | + Triage: every #4250 stall so far passed on a plain rerun of the same |
| 127 | + commit -- rerun this job before suspecting the diff. If it stalls twice |
| 128 | + at the same test file, add that occurrence to #4250. |
| 129 | +${'═'.repeat(72)} |
| 130 | +`; |
| 131 | + process.stdout.write(banner); |
| 132 | + log.write(banner); |
| 133 | + killGroup('SIGTERM'); |
| 134 | + setTimeout(() => killGroup('SIGKILL'), SIGKILL_GRACE_MS).unref(); |
| 135 | +}, CHECK_INTERVAL_MS); |
| 136 | + |
| 137 | +child.on('error', (err) => { |
| 138 | + clearInterval(watchdog); |
| 139 | + console.error(`run-with-stall-guard: failed to start ${command[0]} -- ${err.message}`); |
| 140 | + log.end(() => process.exit(1)); |
| 141 | +}); |
| 142 | + |
| 143 | +child.on('exit', (code, signal) => { |
| 144 | + clearInterval(watchdog); |
| 145 | + const finish = (status) => log.end(() => process.exit(status)); |
| 146 | + if (stalled) { |
| 147 | + finish(STALL_EXIT_CODE); |
| 148 | + } else if (signal) { |
| 149 | + console.error(`run-with-stall-guard: command killed by ${signal}`); |
| 150 | + finish(1); |
| 151 | + } else { |
| 152 | + finish(code ?? 1); |
| 153 | + } |
| 154 | +}); |
0 commit comments