golem15/msd-core
3
0
Fork 0
Code Issues Pull Requests Actions 1 Packages Projects Releases Wiki Activity

fix(#1051): force-exit + per-chunk timeout for the windows full-test lane; close leaked test handles (#1054)

Browse Source 
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 <noreply@anthropic.com>
This commit is contained in:
Tom Boucher
2026-06-11 14:11:50 -04:00
committed by GitHub
parent 58ed55683e
commit 4698b3e349
4 changed files with 181 additions and 55 deletions
Download Patch File Download Diff File Expand all files Collapse all files

67
scripts/run-tests.cjs
View File

@@ -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.

71
tests/locking-bugs-1909-1916-1925-1927.test.cjs
View File

@@ -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(

42
tests/perf-316-state-lock-buffer-alloc.test.cjs
View File

@@ -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;

56
tests/run-tests-harness.test.cjs
View File

@@ -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}`,
);
});
});
});