From 4698b3e349c9f418e779ef1548d7720b85ca5f27 Mon Sep 17 00:00:00 2001 From: Tom Boucher Date: Thu, 11 Jun 2026 14:11:50 -0400 Subject: [PATCH] fix(#1051): force-exit + per-chunk timeout for the windows full-test lane; close leaked test handles (#1054) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The `full test (windows-latest, 22)` job intermittently got CANCELLED at its 20m wall-clock cap with no failed test step — a false-negative gate (recurrence of #869). Root cause: a unit test leaves an open event-loop handle, so the chunk's `node --test` child hangs ~150s on Windows after its last test prints; two such stalls push the already-~13m job past 20m. Fix (defense in depth): - run-tests.cjs: pass --test-force-exit (Node >=22; engines requires >=22.0.0) so the runner exits once all tests finish regardless of lingering handles — the durable backstop. Account for the flag in the argv-length ceiling. - run-tests.cjs: add a per-chunk execFileSync timeout (default 600000ms, env RUN_TESTS_CHUNK_TIMEOUT_MS) that fails loudly with a diagnostic naming the chunk's files, so a hung chunk can never silently eat the job budget. - perf-316 test: terminate both Worker threads on all paths (afterEach + finally) so they cannot outlive the test. - locking-bugs test: kill spawned children in a finally that wraps the whole spawn -> waitFor -> barrier-release -> Promise.all sequence, so a barrier timeout no longer leaks live child processes. - Refresh the stale synckit comment (synckit/SDK bridge was removed). Regression tests in run-tests-harness: a hung chunk hits the per-chunk timeout and fails with a clear message; force-exit lets a chunk with a leaked handle exit cleanly. Closes #1051 Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: Claude Opus 4.8 --- scripts/run-tests.cjs | 67 +++++++++++++---- .../locking-bugs-1909-1916-1925-1927.test.cjs | 71 ++++++++++++------- .../perf-316-state-lock-buffer-alloc.test.cjs | 42 ++++++----- tests/run-tests-harness.test.cjs | 56 +++++++++++++++ 4 files changed, 181 insertions(+), 55 deletions(-) diff --git a/scripts/run-tests.cjs b/scripts/run-tests.cjs index 7e056e1c4..d83054da1 100644 --- a/scripts/run-tests.cjs +++ b/scripts/run-tests.cjs @@ -319,14 +319,13 @@ function main() { // Default concurrency: 4 on Linux/macOS, 2 on Windows. // // Windows has significantly higher per-subprocess overhead than Linux/macOS: - // - Windows Defender scans each spawned process - // - NTFS has higher file-system latency under concurrent access - // - synckit worker_threads (used by the SDK bridge in gsd-tools.cjs) spawn - // native threads that contend on SharedArrayBuffer + Atomics.wait; under - // Node 24 on Windows, 4-way concurrent gsd-tools invocations (each spawning - // a synckit worker) caused intermittent process crashes with empty stderr — - // a signature of OS-level resource exhaustion killing worker threads before - // they could flush. Reducing to 2 halves the peak concurrent worker count. + // - Windows Defender scans each spawned process on first execution, adding + // latency proportional to the number of concurrent spawns. + // - NTFS has higher file-system latency under concurrent access compared to + // ext4/APFS, which amplifies contention when multiple test chunks run in + // parallel and all read/write the same fixture directories. + // Reducing to 2 halves the peak concurrent subprocess count on Windows and + // keeps per-chunk wall-clock time well within the 20m CI job cap. // // Operator override via TEST_CONCURRENCY env var for local debugging. const defaultConcurrency = process.platform === 'win32' ? 2 : 4; @@ -343,7 +342,21 @@ function main() { const MAX_CMDLINE_CHARS = process.env.RUN_TESTS_MAX_CMDLINE_CHARS ? Number(process.env.RUN_TESTS_MAX_CMDLINE_CHARS) : 28000; // headroom below the 32,767 Windows ceiling - const FIXED_OVERHEAD = process.execPath.length + '--test'.length + concurrency.length + 8; + + // node:test does not exit until the event loop drains. A unit test that leaks + // an open handle (un-terminated Worker, un-killed child_process, ref'd timer) + // makes a chunk's `node --test` child hang ~150s on Windows AFTER its last test + // prints; two such stalls push the windows full lane past its 20m cap and the + // job is CANCELLED with no failed step — a false-negative gate (#1051, recurrence + // of #869). --test-force-exit (Node >=22; engines requires >=22.0.0) exits the + // runner once all tests finish regardless of lingering handles. The leaking + // tests are also fixed at the source; this is the defensive backstop. + // RUN_TESTS_NO_FORCE_EXIT=1 disables it (used by the harness regression test to + // observe the pre-fix hang). + const nodeMajor = Number(process.versions.node.split('.')[0]); + const forceExit = nodeMajor >= 22 && !process.env.RUN_TESTS_NO_FORCE_EXIT; + + const FIXED_OVERHEAD = process.execPath.length + '--test'.length + concurrency.length + (forceExit ? '--test-force-exit'.length + 1 : 0) + 8; const chunks = []; let current = []; let currentLen = FIXED_OVERHEAD; @@ -359,17 +372,45 @@ function main() { } if (current.length > 0) chunks.push(current); + // A chunk that still hangs (a leak the backstop somehow misses, or a wedged + // subprocess) must fail loudly rather than silently burn the job's wall-clock + // budget until the CI runner cancels the whole job. Default 10 min per chunk: + // well above a healthy chunk (~4-5 min on the windows lane) but below the 20m + // job cap. Operator/test override via RUN_TESTS_CHUNK_TIMEOUT_MS. + const chunkTimeoutMs = process.env.RUN_TESTS_CHUNK_TIMEOUT_MS + ? Number(process.env.RUN_TESTS_CHUNK_TIMEOUT_MS) + : 600000; + let firstFailureExit = 0; for (let i = 0; i < chunks.length; i++) { if (chunks.length > 1) { console.error(`run-tests: chunk ${i + 1}/${chunks.length} — ${chunks[i].length} files`); } try { - execFileSync(process.execPath, ['--test', concurrency, ...chunks[i]], { - stdio: 'inherit', - env: { ...process.env }, - }); + execFileSync( + process.execPath, + ['--test', ...(forceExit ? ['--test-force-exit'] : []), concurrency, ...chunks[i]], + { + stdio: 'inherit', + env: { ...process.env }, + timeout: chunkTimeoutMs, + }, + ); } catch (err) { + // When the per-chunk timeout fires, execFileSync kills the child and + // surfaces it as err.code === 'ETIMEDOUT' (POSIX) and/or err.killed === true + // (platform-dependent). Check both so detection holds on Windows and POSIX. + const timedOut = err.killed === true || err.code === 'ETIMEDOUT'; + if (timedOut) { + console.error( + `run-tests: chunk ${i + 1}/${chunks.length} exceeded the per-chunk timeout ` + + `of ${chunkTimeoutMs}ms and was killed — a test in this chunk is likely leaking ` + + `an open handle (un-terminated Worker, un-killed child process, or ref'd timer) ` + + `so node --test never exits. Files: ${chunks[i] + .map(f => f.split(/[\\/]/).pop()) + .join(' ')}`, + ); + } const code = err.status || 1; // Run every chunk so the operator sees all failures in one pass; report // the first non-zero exit at the end. diff --git a/tests/locking-bugs-1909-1916-1925-1927.test.cjs b/tests/locking-bugs-1909-1916-1925-1927.test.cjs index a5e571122..a3f981ea5 100644 --- a/tests/locking-bugs-1909-1916-1925-1927.test.cjs +++ b/tests/locking-bugs-1909-1916-1925-1927.test.cjs @@ -202,6 +202,7 @@ describe('#1925 TOCTOU: state commands use readModifyWriteStateMd', () => { // ── Spawn both subprocesses ─────────────────────────────────────────────── // Both start immediately; both block at the barrier until the orchestrator // confirms both are ready, then both proceed to contend on the STATE.md lock. + const children = []; function spawnWrapper(fieldName, fieldValue, readyFile) { return new Promise((resolve, reject) => { const child = spawn(nodeBin, [wrapperPath], { @@ -216,8 +217,10 @@ describe('#1925 TOCTOU: state commands use readModifyWriteStateMd', () => { }, stdio: 'pipe', }); + children.push(child); let stderr = ''; child.stderr.on('data', (d) => { stderr += d.toString(); }); + child.on('error', reject); child.on('close', (code) => { if (code !== 0) reject(new Error(`wrapper exited ${code}: ${stderr}`)); else resolve(); @@ -229,16 +232,20 @@ describe('#1925 TOCTOU: state commands use readModifyWriteStateMd', () => { const promiseB = spawnWrapper('Current Phase', '02', readyB); // ── Orchestrate: wait for both ready-signals, then drop the barrier ─────── - await waitFor(() => fs.existsSync(readyA) && fs.existsSync(readyB), { - timeoutMs: 10000, - stepMs: 10, - message: 'Timed out waiting for both subprocesses to reach barrier', - }); - // Both subprocesses are at the gate — drop the barrier simultaneously. - fs.unlinkSync(barrierPath); + try { + await waitFor(() => fs.existsSync(readyA) && fs.existsSync(readyB), { + timeoutMs: 10000, + stepMs: 10, + message: 'Timed out waiting for both subprocesses to reach barrier', + }); + // Both subprocesses are at the gate — drop the barrier simultaneously. + fs.unlinkSync(barrierPath); - // ── Collect results ─────────────────────────────────────────────────────── - await Promise.all([promiseA, promiseB]); + // ── Collect results ─────────────────────────────────────────────────────── + await Promise.all([promiseA, promiseB]); + } finally { + for (const c of children) { try { c.kill(); } catch { /* already exited */ } } + } const content = readStateMd(tmpDir); assert.ok( @@ -335,6 +342,7 @@ describe('#1925 TOCTOU: state commands use readModifyWriteStateMd', () => { // ── Spawn both subprocesses ─────────────────────────────────────────────── // Both start immediately; both block at the barrier until the orchestrator // confirms both are ready, then both proceed to contend on the STATE.md lock. + const children = []; function spawnWrapper(blockerId, readyFile) { return new Promise((resolve, reject) => { const child = spawn(nodeBin, [wrapperPath], { @@ -348,8 +356,10 @@ describe('#1925 TOCTOU: state commands use readModifyWriteStateMd', () => { }, stdio: 'pipe', }); + children.push(child); let stderr = ''; child.stderr.on('data', (d) => { stderr += d.toString(); }); + child.on('error', reject); child.on('close', (code) => { if (code !== 0) reject(new Error(`wrapper exited ${code}: ${stderr}`)); else resolve(); @@ -361,16 +371,20 @@ describe('#1925 TOCTOU: state commands use readModifyWriteStateMd', () => { const promiseB = spawnWrapper('Waiting for design review', readyB); // ── Orchestrate: wait for both ready-signals, then drop the barrier ─────── - await waitFor(() => fs.existsSync(readyA) && fs.existsSync(readyB), { - timeoutMs: 10000, - stepMs: 10, - message: 'Timed out waiting for both subprocesses to reach barrier', - }); - // Both subprocesses are at the gate — drop the barrier simultaneously. - fs.unlinkSync(barrierPath); + try { + await waitFor(() => fs.existsSync(readyA) && fs.existsSync(readyB), { + timeoutMs: 10000, + stepMs: 10, + message: 'Timed out waiting for both subprocesses to reach barrier', + }); + // Both subprocesses are at the gate — drop the barrier simultaneously. + fs.unlinkSync(barrierPath); - // ── Collect results ─────────────────────────────────────────────────────── - await Promise.all([promiseA, promiseB]); + // ── Collect results ─────────────────────────────────────────────────────── + await Promise.all([promiseA, promiseB]); + } finally { + for (const c of children) { try { c.kill(); } catch { /* already exited */ } } + } const content = readStateMd(tmpDir); assert.ok( @@ -455,6 +469,7 @@ describe('#1927 config.json: setConfigValue must hold planning lock', () => { const nodeBin = process.execPath; + const children = []; function spawnWrapper(configKey, configVal, readyFile) { return new Promise((resolve, reject) => { const child = spawn(nodeBin, [wrapperPath], { @@ -469,8 +484,10 @@ describe('#1927 config.json: setConfigValue must hold planning lock', () => { }, stdio: 'pipe', }); + children.push(child); let stderr = ''; child.stderr.on('data', (d) => { stderr += d.toString(); }); + child.on('error', reject); child.on('close', (code) => { if (code !== 0) reject(new Error(`wrapper exited ${code}: ${stderr}`)); else resolve(); @@ -482,14 +499,18 @@ describe('#1927 config.json: setConfigValue must hold planning lock', () => { const promiseB = spawnWrapper('workflow.research', 'false', readyB); // ── Wait for both to reach barrier, then release ────────────────────────── - await waitFor(() => fs.existsSync(readyA) && fs.existsSync(readyB), { - timeoutMs: 10000, - stepMs: 10, - message: 'Timed out waiting for both config-set subprocesses to reach barrier', - }); - fs.unlinkSync(barrierPath); + try { + await waitFor(() => fs.existsSync(readyA) && fs.existsSync(readyB), { + timeoutMs: 10000, + stepMs: 10, + message: 'Timed out waiting for both config-set subprocesses to reach barrier', + }); + fs.unlinkSync(barrierPath); - await Promise.all([promiseA, promiseB]); + await Promise.all([promiseA, promiseB]); + } finally { + for (const c of children) { try { c.kill(); } catch { /* already exited */ } } + } const config = readConfig(tmpDir); assert.strictEqual( diff --git a/tests/perf-316-state-lock-buffer-alloc.test.cjs b/tests/perf-316-state-lock-buffer-alloc.test.cjs index 8eaa96988..3924cc5ef 100644 --- a/tests/perf-316-state-lock-buffer-alloc.test.cjs +++ b/tests/perf-316-state-lock-buffer-alloc.test.cjs @@ -139,6 +139,7 @@ describe('perf #316: acquireStateLock hoists sleep buffer — exactly one SAB pe let tmpDir; let statePath; let lockPath; + let holderWorker; beforeEach(() => { tmpDir = makeTempDir(); @@ -147,7 +148,9 @@ describe('perf #316: acquireStateLock hoists sleep buffer — exactly one SAB pe fs.writeFileSync(statePath, MINIMAL_STATE_MD, 'utf-8'); }); - afterEach(() => { + afterEach(async () => { + await holderWorker?.terminate(); + holderWorker = null; try { fs.unlinkSync(lockPath); } catch { /* already gone */ } removeTempDir(tmpDir); }); @@ -162,7 +165,6 @@ describe('perf #316: acquireStateLock hoists sleep buffer — exactly one SAB pe // intervals ~1000ms ≈ hold duration). The lockAttempts assertion below // proves the retry path was exercised end-to-end. const holdMs = 1000; - let holderWorker; let resolveLockWritten; const lockWritten = new Promise((resolve) => { resolveLockWritten = resolve; }); const holderDone = new Promise((resolve, reject) => { @@ -210,22 +212,28 @@ describe('perf #316: acquireStateLock hoists sleep buffer — exactly one SAB pe assert.ok(fs.existsSync(lockPath), 'Worker A must have written the lock file'); // ── Worker B: call writeStateMd, measure SAB allocations ─────────────── - const writeResult = await new Promise((resolve, reject) => { - const writer = new Worker(WRITER_WORKER_CODE, { - eval: true, - workerData: { - stateCjsPath: STATE_CJS_PATH, - statePath, - content: MINIMAL_STATE_MD, - tmpDir, - }, + let writerWorker; + let writeResult; + try { + writeResult = await new Promise((resolve, reject) => { + writerWorker = new Worker(WRITER_WORKER_CODE, { + eval: true, + workerData: { + stateCjsPath: STATE_CJS_PATH, + statePath, + content: MINIMAL_STATE_MD, + tmpDir, + }, + }); + writerWorker.on('message', resolve); + writerWorker.on('error', reject); + writerWorker.on('exit', (code) => { + if (code !== 0) reject(new Error('Writer worker exit code: ' + code)); + }); }); - writer.on('message', resolve); - writer.on('error', reject); - writer.on('exit', (code) => { - if (code !== 0) reject(new Error('Writer worker exit code: ' + code)); - }); - }); + } finally { + await writerWorker?.terminate(); + } // Wait for Worker A to finish releasing await holderDone; diff --git a/tests/run-tests-harness.test.cjs b/tests/run-tests-harness.test.cjs index 343ca5fb8..0dbe2c48c 100644 --- a/tests/run-tests-harness.test.cjs +++ b/tests/run-tests-harness.test.cjs @@ -315,4 +315,60 @@ test('ambient GSD workstream vars are stripped by the runner', () => { ); }); }); + + describe('per-chunk timeout + force-exit (windows hang guard, #1051)', () => { + // A unit test that leaks an open handle (un-terminated Worker, un-killed + // child_process, ref'd timer) causes node --test to hang ~150s after its + // last test prints. Two such stalls push the windows full lane past its + // 20m CI cap and the job is CANCELLED — a false-negative gate. The harness + // now adds --test-force-exit (exits once all tests finish) and a per-chunk + // timeout (kills a hung child loudly instead of silently burning the budget). + + // Leaky fixture: the test passes immediately, then a ref'd setInterval keeps + // the event loop alive so `node --test` hangs unless --test-force-exit is on. + const LEAKY_BODY = `const { test } = require('node:test'); +test('passes but leaks a ref-d timer', () => {}); +setInterval(() => {}, 1 << 30); +`; + + test('a hung chunk hits the per-chunk timeout and fails with a clear message', () => { + // Regression proof: pre-fix (no timeout guard) this hung until the OS/CI + // killed it; now it fails fast with a diagnostic message. + fs.writeFileSync(path.join(tmpDir, 'leaky.test.cjs'), LEAKY_BODY, 'utf8'); + const r = runHarness(tmpDir, [], { + RUN_TESTS_NO_FORCE_EXIT: '1', + RUN_TESTS_CHUNK_TIMEOUT_MS: '2000', + }); + assert.notStrictEqual( + r.status, + 0, + `expected non-zero exit from timed-out chunk; got status=${r.status}\nSTDERR:\n${r.stderr}`, + ); + assert.match( + r.stderr, + /exceeded the per-chunk timeout/, + `expected timeout diagnostic in stderr; STDERR:\n${r.stderr}`, + ); + }); + + test('force-exit lets a chunk with a leaked handle exit cleanly', () => { + const nodeMajor = Number(process.versions.node.split('.')[0]); + // --test-force-exit was added in Node 22; skip on older engines. + if (nodeMajor < 22) { + return; // skip — harness test options object not available here; just return + } + fs.writeFileSync(path.join(tmpDir, 'leaky.test.cjs'), LEAKY_BODY, 'utf8'); + // force-exit is ON by default (RUN_TESTS_NO_FORCE_EXIT not set). + // 30s timeout: if force-exit works the child exits promptly after the test + // passes; if force-exit failed, the 30s timeout would fire and status ≠ 0. + const r = runHarness(tmpDir, [], { + RUN_TESTS_CHUNK_TIMEOUT_MS: '30000', + }); + assert.strictEqual( + r.status, + 0, + `expected zero exit with force-exit enabled; got status=${r.status} signal=${r.signal}\nSTDERR:\n${r.stderr}`, + ); + }); + }); });