From bf954e4b443abb4c702cdff3deb55bb7d53b770f Mon Sep 17 00:00:00 2001 From: Tom Boucher Date: Mon, 8 Jun 2026 23:42:24 -0400 Subject: [PATCH] fix(#916): deterministic phase-complete subprocess in regression tests (#917) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The bug #1998 subtest "checkbox updated when archived milestones exist in
" flaked under the high-concurrency docker run (~672 test files in parallel): the current-milestone checkbox was left unchecked. Root cause: `gsd-tools phase complete` writes ROADMAP.md as its LAST step, after a read-heavy parse/lock sequence. Under heavy parallel CPU/IO contention the test's tight `timeout: 10000` fired mid-parse and SIGTERM'd the subprocess before that write landed, leaving ROADMAP.md pristine (both phases `- [ ]`). The bare `catch {}` silently swallowed the kill, so a timeout masqueraded as a "checkbox not checked" assertion failure. All I/O is scoped to each test's tmpDir, so there is no cross-process race — the timeout was the sole cause. Consolidate all 7 duplicated `phase complete` call sites (suites #1998, #2005, #2526) into a shared runPhaseComplete() helper that: 1. raises the timeout to 60s so the test's own timer never kills the subprocess under load; 2. never silently swallows a signal/timeout kill (rethrows loudly with captured output) while still tolerating a clean non-zero exit for the ROADMAP-asserting tests via { tolerateExit: true }. No retry loop. Verified with 3x `gsd-test --reset` full docker runs (13207 tests / 2311 suites each, 0 failures, flaky subtest green every round). Closes #916 Co-authored-by: Claude Opus 4.8 --- tests/phase.test.cjs | 122 ++++++++++++++++++++----------------------- 1 file changed, 56 insertions(+), 66 deletions(-) diff --git a/tests/phase.test.cjs b/tests/phase.test.cjs index 08f0e0a7b..5820a9998 100644 --- a/tests/phase.test.cjs +++ b/tests/phase.test.cjs @@ -3364,6 +3364,55 @@ describe('bug #1962: normalizePhaseName preserves letter suffix case', () => { // (consolidated from tests/bug-1998-phase-complete-checkbox.test.cjs) // ───────────────────────────────────────────────────────────────────────────── +/** + * Run `gsd-tools phase complete ` for the phase-complete regression + * suites and return its stdout. + * + * `phase complete` writes ROADMAP.md as its LAST step, after a read-heavy + * parse/lock sequence (ROADMAP read, two extractCurrentMilestone STATE.md + * parses, REQUIREMENTS read, phase-dir scan, STATE read — all before the single + * writePlanningFileSet flush). Under the high-concurrency docker run (~672 test + * files in parallel), a tight 10s timeout could fire mid-parse and SIGTERM the + * subprocess BEFORE that write landed, leaving ROADMAP.md untouched. Call sites + * that used a bare `catch {}` then silently proceeded to assert on the pristine + * file — an intermittent "checkbox not checked" failure (bug #1998 flake). + * + * Two-part fix, no retry loop: + * 1. A generous timeout so the test's own timer never kills the subprocess + * under load (10s cold-node startup × 672-way CPU/IO contention was the + * real culprit — all I/O is scoped to tmpDir, so there is no cross-process + * race to blame). + * 2. Never silently swallow a signal/timeout kill: it means the process was + * terminated before completing its writes, so we surface it loudly with + * context instead of letting it masquerade as an assertion failure. A + * *clean* non-zero exit is still tolerated when `tolerateExit` is set, + * because the ROADMAP write has already landed before any post-write step + * that may exit non-zero in these minimal fixtures. + */ +function runPhaseComplete(tmpDir, { phase = '1', tolerateExit = false } = {}) { + try { + return execFileSync('node', [GSD_TOOLS_BIN, 'phase', 'complete', phase], { + cwd: tmpDir, + timeout: 60000, + encoding: 'utf-8', + }); + } catch (err) { + // A signal/timeout kill terminated the process before it finished writing — + // never tolerate it; surface it with whatever output was captured. + if (err.killed || err.signal != null || err.code === 'ETIMEDOUT') { + throw new Error( + `gsd-tools phase complete ${phase} was killed before completion ` + + `(signal=${err.signal}, code=${err.code}). ` + + `stdout=${err.stdout || ''} stderr=${err.stderr || ''}` + ); + } + if (tolerateExit) { + return `${err.stdout || ''}${err.stderr || ''}`; + } + throw err; + } +} + describe('bug #1998: phase complete updates overview checkbox', () => { let tmpDir; let planningDir; @@ -3419,11 +3468,7 @@ describe('bug #1998: phase complete updates overview checkbox', () => { '| 2. Features | 0/1 | Pending | - |', ].join('\n')); - try { - execFileSync('node', [GSD_TOOLS_BIN, 'phase', 'complete', '1'], { cwd: tmpDir, timeout: 10000 }); - } catch { - // Command may exit non-zero if STATE.md update fails, but ROADMAP.md update happens first - } + runPhaseComplete(tmpDir, { tolerateExit: true }); const result = fs.readFileSync(roadmapPath, 'utf-8'); assert.match(result, /- \[x\] \*\*Phase 1: Foundation\*\*/, 'overview checkbox should be checked'); @@ -3468,11 +3513,7 @@ describe('bug #1998: phase complete updates overview checkbox', () => { '
', ].join('\n')); - try { - execFileSync('node', [GSD_TOOLS_BIN, 'phase', 'complete', '1'], { cwd: tmpDir, timeout: 10000 }); - } catch { - // May exit non-zero - } + runPhaseComplete(tmpDir, { tolerateExit: true }); const result = fs.readFileSync(roadmapPath, 'utf-8'); assert.match(result, /- \[x\] \*\*Phase 1: Setup\*\*/, 'current milestone checkbox should be checked'); @@ -3559,11 +3600,7 @@ describe('bug #2005: phase complete updates plan count when milestone is inside '', ].join('\n')); - try { - execFileSync('node', [GSD_TOOLS_BIN, 'phase', 'complete', '1'], { cwd: tmpDir, timeout: 10000 }); - } catch { - // May exit non-zero if STATE.md update fails, but ROADMAP.md update is the target - } + runPhaseComplete(tmpDir, { tolerateExit: true }); const result = fs.readFileSync(roadmapPath, 'utf-8'); @@ -3619,9 +3656,7 @@ describe('bug #2005: phase complete updates plan count when milestone is inside '', ].join('\n')); - try { - execFileSync('node', [GSD_TOOLS_BIN, 'phase', 'complete', '1'], { cwd: tmpDir, timeout: 10000 }); - } catch {} + runPhaseComplete(tmpDir, { tolerateExit: true }); const result = fs.readFileSync(roadmapPath, 'utf-8'); @@ -3709,22 +3744,7 @@ describe('bug #2526: phase complete warns about unregistered REQ-IDs', () => { '| REQ-001 | 1 | Pending |', ].join('\n')); - let stdout = ''; - let stderr = ''; - try { - const result = execFileSync('node', [GSD_TOOLS_BIN, 'phase', 'complete', '1'], { - cwd: tmpDir, - timeout: 10000, - encoding: 'utf-8', - }); - stdout = result; - } catch (err) { - stdout = err.stdout || ''; - stderr = err.stderr || ''; - throw err; - } - - const combined = stdout + stderr; + const combined = runPhaseComplete(tmpDir); assert.match(combined, /REQ-002/, 'output should mention REQ-002 as missing from Traceability table'); assert.match(combined, /REQ-003/, 'output should mention REQ-003 as missing from Traceability table'); }); @@ -3776,22 +3796,7 @@ describe('bug #2526: phase complete warns about unregistered REQ-IDs', () => { '| REQ-002 | 1 | Pending |', ].join('\n')); - let stdout = ''; - let stderr = ''; - try { - const result = execFileSync('node', [GSD_TOOLS_BIN, 'phase', 'complete', '1'], { - cwd: tmpDir, - timeout: 10000, - encoding: 'utf-8', - }); - stdout = result; - } catch (err) { - stdout = err.stdout || ''; - stderr = err.stderr || ''; - throw err; - } - - const combined = stdout + stderr; + const combined = runPhaseComplete(tmpDir); assert.doesNotMatch( combined, /unregistered|missing.*traceability|not in.*traceability/i, @@ -3845,22 +3850,7 @@ describe('bug #2526: phase complete warns about unregistered REQ-IDs', () => { '| REQ-001 | 1 | Pending |', ].join('\n')); - let stdout = ''; - let stderr = ''; - try { - const result = execFileSync('node', [GSD_TOOLS_BIN, 'phase', 'complete', '1'], { - cwd: tmpDir, - timeout: 10000, - encoding: 'utf-8', - }); - stdout = result; - } catch (err) { - stdout = err.stdout || ''; - stderr = err.stderr || ''; - throw err; - } - - const combined = stdout + stderr; + const combined = runPhaseComplete(tmpDir); assert.match(combined, /REQ-002/, 'should warn about REQ-002'); assert.match(combined, /REQ-003/, 'should warn about REQ-003'); assert.match(combined, /REQ-004/, 'should warn about REQ-004');