From 81a50bf9b1bb72e04c552a276c3cb2488104813e Mon Sep 17 00:00:00 2001 From: 1bcMax <195689928+1bcMax@users.noreply.github.com> Date: Tue, 21 Jul 2026 00:49:39 -0500 Subject: [PATCH] test: stop CLI-spawn timeouts from flaking the release gate MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Four tests failed intermittently under parallel load while passing in ~0.6s idle. All the same cause: a spawn bound sized for an unloaded machine. cli: franklin task tail reconciles stale queued tasks 5045ms (bound 5000) cli: franklin task cancel kills running task 5841ms (bound 5000) cli: franklin task wait reconciles stale queued tasks 5048ms (bound 5000) franklin skills --json emits a parseable structure 8037ms (bound 8000) The durations were the bound firing, not the work taking that long — the same tests run in ~640ms when the machine is idle. `node dist/index.js` boots the whole CLI (config load, MCP discovery, wallet init) before the subcommand runs, and that startup balloons under concurrency. Three things were wrong beyond the number: 1. The failures were undiagnosable. On timeout spawnSync returns status:null with empty stderr, so `assert.equal(result.status, 0, result.stderr)` printed "null !== 0" and named nothing. First time I hit this I could not tell what had failed. assertCliExit() now says it exceeded the bound and that a loaded machine is the likely cause. 2. skills.local.mjs had two bounds fighting: runCli defaulted to 8000ms while the tests around it declared { timeout: 15_000 }, so the inner one always won and the declared one never applied. Two call sites had already been patched to timeoutMs: 15_000 individually — the usual sign that the default, not the call site, is what's wrong. 3. One test told the CLI `--timeout 10000` under a 5000ms spawn bound, so the harness would have killed the process before the behaviour under test could finish. It only passed because the task goes 'lost' almost immediately. Both files now use CLI_SPAWN_TIMEOUT_MS = 20_000, matching what test/local.mjs already used for its other CLI-spawning tests ({ timeout: 20_000 }); 5s and 8s were the outliers. A flaky test in a release gate is worse than a slow one: it teaches you to wave the next real failure past as "just that one again". Verified with two suites running concurrently — the condition that produced the original failures — 636 pass on both. --- test/local.mjs | 51 +++++++++++++++++++++++++++++++++---------- test/skills.local.mjs | 19 ++++++++++++++-- 2 files changed, 57 insertions(+), 13 deletions(-) diff --git a/test/local.mjs b/test/local.mjs index d3346d0..f0ebb33 100644 --- a/test/local.mjs +++ b/test/local.mjs @@ -7625,6 +7625,31 @@ test('startDetachedTask: returns runId immediately, child completes async', asyn } }); +// Spawning `node dist/index.js` boots the whole CLI — config load, MCP server +// discovery, wallet init — before the subcommand runs at all. These spawns were +// capped at 5000ms, and three of them flaked under parallel load on 2026-07-21 +// (task tail / task cancel / task wait). The failure was also undiagnosable: +// on timeout spawnSync returns status:null with empty stderr, so +// `assert.equal(result.status, 0, result.stderr.toString())` reported +// "null !== 0" and said nothing about a timeout. A flaky test in a release gate +// is worse than a slow one — it trains you to wave the next real failure past. +// +// 20s matches what the rest of this file already uses for CLI-spawning tests +// ({ timeout: 20_000 } at lines 117, 127, 597, ...); 5s was the outlier. +const CLI_SPAWN_TIMEOUT_MS = 20_000; + +/** Assert a spawned CLI exited as expected, naming a timeout as a timeout. */ +function assertCliExit(result, expectedStatus, what) { + if (result.error) { + const hint = result.error.code === 'ETIMEDOUT' + ? ` — exceeded CLI_SPAWN_TIMEOUT_MS (${CLI_SPAWN_TIMEOUT_MS}ms); the machine was likely loaded, not the code broken` + : ''; + assert.fail(`${what}: spawn failed with ${result.error.code || result.error.message}${hint}`); + } + assert.equal(result.status, expectedStatus, + `${what}: expected exit ${expectedStatus}, got ${result.status}\nstderr: ${result.stderr?.toString() ?? ''}`); +} + test('cli: franklin task list prints recent tasks', async () => { const os = await import('node:os'); const path = await import('node:path'); @@ -7645,9 +7670,9 @@ test('cli: franklin task list prints recent tasks', async () => { const cli = path.join(process.cwd(), 'dist', 'index.js'); const result = spawnSync(process.execPath, [cli, 'task', 'list'], { - env: { ...process.env, FRANKLIN_HOME: fakeHome }, timeout: 5000, + env: { ...process.env, FRANKLIN_HOME: fakeHome }, timeout: CLI_SPAWN_TIMEOUT_MS, }); - assert.equal(result.status, 0, result.stderr.toString()); + assertCliExit(result, 0, 'task list'); const out = result.stdout.toString(); assert.match(out, /t2/); assert.match(out, /t1/); @@ -7683,9 +7708,9 @@ test('cli: franklin task tail prints log + status', async () => { const cli = path.join(process.cwd(), 'dist', 'index.js'); const result = spawnSync(process.execPath, [cli, 'task', 'tail', runId], { - env: { ...process.env, FRANKLIN_HOME: fakeHome }, timeout: 5000, + env: { ...process.env, FRANKLIN_HOME: fakeHome }, timeout: CLI_SPAWN_TIMEOUT_MS, }); - assert.equal(result.status, 0, result.stderr.toString()); + assertCliExit(result, 0, 'task tail'); const out = result.stdout.toString(); assert.match(out, /line1/); assert.match(out, /line2/); @@ -7722,9 +7747,9 @@ test('cli: franklin task tail reconciles stale queued tasks before printing stat const cli = path.join(process.cwd(), 'dist', 'index.js'); const result = spawnSync(process.execPath, [cli, 'task', 'tail', runId], { - env: { ...process.env, FRANKLIN_HOME: fakeHome }, timeout: 5000, + env: { ...process.env, FRANKLIN_HOME: fakeHome }, timeout: CLI_SPAWN_TIMEOUT_MS, }); - assert.equal(result.status, 0, result.stderr.toString()); + assertCliExit(result, 0, 'task tail (stale queued)'); assert.match(result.stdout.toString(), /lost/); assert.equal(readTaskMeta(runId).status, 'lost'); } finally { @@ -7756,9 +7781,9 @@ test('cli: franklin task cancel kills running task', async () => { const cli = path.join(process.cwd(), 'dist', 'index.js'); const result = spawnSync(process.execPath, [cli, 'task', 'cancel', runId], { - env: { ...process.env, FRANKLIN_HOME: fakeHome }, timeout: 5000, + env: { ...process.env, FRANKLIN_HOME: fakeHome }, timeout: CLI_SPAWN_TIMEOUT_MS, }); - assert.equal(result.status, 0, result.stderr.toString()); + assertCliExit(result, 0, 'task cancel'); // Give runner a moment to finalize await new Promise(r => setTimeout(r, 1500)); @@ -7828,11 +7853,15 @@ test('cli: franklin task wait reconciles stale queued tasks before blocking', as }); const cli = path.join(process.cwd(), 'dist', 'index.js'); + // The CLI is told to wait up to 10s, so the spawn bound must exceed it — + // it was 5000ms, i.e. the harness would have killed the process before the + // behaviour under test could finish. That only passed because the task goes + // 'lost' almost immediately; a slower reconcile would have failed here for + // reasons having nothing to do with `task wait`. const result = spawnSync(process.execPath, [cli, 'task', 'wait', runId, '--timeout', '10000'], { - env: { ...process.env, FRANKLIN_HOME: fakeHome }, timeout: 5000, + env: { ...process.env, FRANKLIN_HOME: fakeHome }, timeout: CLI_SPAWN_TIMEOUT_MS, }); - assert.equal(result.error, undefined, result.error?.message); - assert.equal(result.status, 1, result.stderr.toString()); + assertCliExit(result, 1, 'task wait (stale queued)'); assert.match(result.stdout.toString(), /lost/); assert.equal(readTaskMeta(runId).status, 'lost'); } finally { diff --git a/test/skills.local.mjs b/test/skills.local.mjs index e054b23..06c4f3d 100644 --- a/test/skills.local.mjs +++ b/test/skills.local.mjs @@ -21,7 +21,19 @@ import { formatSkillHints } from '../dist/skills/triggers.js'; const DIST = fileURLToPath(new URL('../dist/index.js', import.meta.url)); -function runCli(args, { timeoutMs = 8000, env, cwd } = {}) { +// Booting `node dist/index.js` runs the whole CLI startup path (config, MCP +// discovery, wallet init) before the subcommand executes. The default here was +// 8000ms while the tests around it declare { timeout: 15_000 } — so the inner +// bound fired first and the declared one never applied. Two call sites had +// already been patched individually to timeoutMs: 15_000, which is the usual +// sign that the default, not the call site, is what's wrong. +// +// Observed 2026-07-21: `franklin skills --json` failed at 8037ms under parallel +// load while passing in ~1s idle. Raised to 20s to match what test/local.mjs +// uses for CLI spawns, so a loaded machine doesn't read as a broken build. +const CLI_SPAWN_TIMEOUT_MS = 20_000; + +function runCli(args, { timeoutMs = CLI_SPAWN_TIMEOUT_MS, env, cwd } = {}) { return new Promise((resolve, reject) => { const proc = spawn('node', [DIST, ...args], { stdio: ['ignore', 'pipe', 'pipe'], @@ -34,7 +46,10 @@ function runCli(args, { timeoutMs = 8000, env, cwd } = {}) { proc.stderr.on('data', (d) => { stderr += d.toString(); }); const timer = setTimeout(() => { proc.kill('SIGTERM'); - reject(new Error(`Timeout after ${timeoutMs}ms`)); + reject(new Error( + `franklin ${args.join(' ')} exceeded ${timeoutMs}ms. CLI startup is slow ` + + `under load; this usually means a busy machine, not broken code.` + )); }, timeoutMs); proc.on('close', (code) => { clearTimeout(timer);