diff --git a/packages/codev/src/__tests__/issue-17-forge-swallow.test.ts b/packages/codev/src/__tests__/issue-17-forge-swallow.test.ts new file mode 100644 index 000000000..eb285173f --- /dev/null +++ b/packages/codev/src/__tests__/issue-17-forge-swallow.test.ts @@ -0,0 +1,263 @@ +/** + * Issue #17 — a broken forge concept rendered as an empty panel. + * + * `executeForgeCommand` returns `null` for a timeout, a non-zero exit and an + * unparseable body alike, and every caller reads `null` as "no results". + * Nothing reached stderr; `logDebug` sits behind `CODEV_DEBUG`, which nobody + * sets. + * + * Measured live on 2026-08-21: `recently-merged` on gitea against `~/dev/entriq` + * paged `pulls?state=closed` at 48.1s for page one against a 30s timeout, so it + * timed out every time. `getOverview` calls it on a 30s TTL and is hit by both + * the dashboard `/api/overview` poll and by every `afx status` while Tower runs. + * It had been failing on every one of those calls, invisibly, for as long as + * that repo had that many PRs. + * + * Nobody noticed because empty looks like a valid answer. An empty panel that + * means "broken" is worse than an error, because it is believable. + */ + +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; +import { + executeForgeCommand, + executeForgeCommandSync, + executeForgeCommandDetailed, + classifyForgeError, + _resetForgeFailureWarnings, +} from '../lib/forge.js'; + +let stderr: string[]; + +beforeEach(() => { + _resetForgeFailureWarnings(); + delete process.env.CODEV_FORGE_QUIET; + stderr = []; + vi.spyOn(process.stderr, 'write').mockImplementation((chunk: unknown) => { + stderr.push(String(chunk)); + return true; + }); +}); + +afterEach(() => { + vi.restoreAllMocks(); + _resetForgeFailureWarnings(); + delete process.env.CODEV_FORGE_QUIET; +}); + +const said = (): string => stderr.join(''); + +/** Wire the concept to an arbitrary shell command, bypassing provider presets. */ +const asCommand = (command: string | null) => ({ + forgeConfig: { 'recently-merged': command }, +}); + +describe('#17: a timeout says so instead of returning quietly', () => { + it('warns when the command exceeds its timeout', async () => { + const result = await executeForgeCommand('recently-merged', {}, { + ...asCommand('sleep 5'), + timeoutMs: 150, + }); + + expect(result).toBeNull(); + expect(said()).toContain("'recently-merged'"); + expect(said()).toContain('timed out'); + }, 20_000); + + it('says explicitly that the null is not an empty result', async () => { + // The whole defect in one sentence. A caller renders an empty panel from + // this null; the operator needs to know the panel is a lie. + await executeForgeCommand('recently-merged', {}, { ...asCommand('sleep 5'), timeoutMs: 150 }); + + expect(said()).toContain('NO RESULTS, which is not the same as none'); + }, 20_000); + + it('names the limit it exceeded, so the remedy is obvious', async () => { + await executeForgeCommand('recently-merged', {}, { ...asCommand('sleep 5'), timeoutMs: 150 }); + + expect(said()).toMatch(/limit \d+(ms|s)\b/); + }, 20_000); +}); + +describe('#17: a non-zero exit says so too', () => { + it('warns and names the exit code', async () => { + const result = await executeForgeCommand('recently-merged', {}, { + ...asCommand('exit 3'), + timeoutMs: 5_000, + }); + + expect(result).toBeNull(); + expect(said()).toContain('exited 3'); + }); + + it('carries the first line of stderr, which is usually the whole diagnosis', async () => { + await executeForgeCommand('recently-merged', {}, { + ...asCommand('echo "gh: not authenticated" >&2; exit 4'), + timeoutMs: 5_000, + }); + + expect(said()).toContain('gh: not authenticated'); + }); +}); + +describe('#17: a genuinely empty result stays silent', () => { + // The distinction that has to hold. If empty warns too, the warning means + // nothing and gets tuned out. + it('says nothing when the command succeeds with an empty list', async () => { + const result = await executeForgeCommand('recently-merged', {}, { + ...asCommand('echo "[]"'), + timeoutMs: 5_000, + }); + + expect(result).toEqual([]); + expect(said()).toBe(''); + }); + + it('says nothing when the command succeeds with results', async () => { + const result = await executeForgeCommand('recently-merged', {}, { + ...asCommand('echo \'[{"number":1}]\''), + timeoutMs: 5_000, + }); + + expect(result).toEqual([{ number: 1 }]); + expect(said()).toBe(''); + }); + + it('says nothing for a concept that is explicitly disabled', async () => { + // Not configured is not broken. Warning here would fire constantly on every + // install that deliberately turns a concept off. + const result = await executeForgeCommand('recently-merged', {}, asCommand(null)); + + expect(result).toBeNull(); + expect(said()).toBe(''); + }); +}); + +describe('#17: a poll loop reports a breakage once, not every tick', () => { + it('warns on the first failure and stays quiet after', async () => { + // getOverview runs on a 30s TTL against both the dashboard poll and every + // `afx status`. A warning per tick would be its own kind of unreadable. + for (let i = 0; i < 3; i++) { + await executeForgeCommand('recently-merged', {}, { ...asCommand('exit 3'), timeoutMs: 5_000 }); + } + + expect(said().match(/\[forge\]/g) ?? []).toHaveLength(1); + }); + + it('says that it will not repeat, so silence afterwards is not read as recovery', async () => { + await executeForgeCommand('recently-merged', {}, { ...asCommand('exit 3'), timeoutMs: 5_000 }); + + expect(said()).toContain('are silent'); + }); + + it('warns again when the SAME concept starts failing a different way', async () => { + // A concept that was erroring and starts timing out is new information. + await executeForgeCommand('recently-merged', {}, { ...asCommand('exit 3'), timeoutMs: 5_000 }); + await executeForgeCommand('recently-merged', {}, { ...asCommand('sleep 5'), timeoutMs: 150 }); + + expect(said().match(/\[forge\]/g) ?? []).toHaveLength(2); + }, 20_000); + + it('CODEV_FORGE_QUIET silences it entirely', async () => { + process.env.CODEV_FORGE_QUIET = '1'; + + await executeForgeCommand('recently-merged', {}, { ...asCommand('exit 3'), timeoutMs: 5_000 }); + + expect(said()).toBe(''); + }); +}); + +describe('#17: the sync variant swallows identically, so it warns identically', () => { + it('warns on a non-zero exit', () => { + const result = executeForgeCommandSync('recently-merged', {}, { + ...asCommand('exit 3'), + timeoutMs: 5_000, + }); + + expect(result).toBeNull(); + expect(said()).toContain('(sync)'); + expect(said()).toContain('exited 3'); + }); +}); + +describe('#17: the detailed variant hands the failure over instead of warning', () => { + it('stays silent — its caller is the one that reports', async () => { + const r = await executeForgeCommandDetailed('recently-merged', {}, { + ...asCommand('exit 3'), + timeoutMs: 5_000, + }); + + expect(r.ok).toBe(false); + expect(r.exitCode).toBe(3); + expect(said()).toBe(''); + }); + + it('classifies a timeout the same way the warning does', async () => { + const r = await executeForgeCommandDetailed('recently-merged', {}, { + ...asCommand('sleep 5'), + timeoutMs: 150, + }); + + expect(r.timedOut).toBe(true); + }, 20_000); +}); + +describe('#17: classifyForgeError', () => { + it('reads killed + signal as a timeout, which is how Node reports its own', () => { + expect(classifyForgeError({ killed: true, signal: 'SIGTERM', code: null }).timedOut).toBe(true); + }); + + it('does not read a bare non-zero exit as a timeout', () => { + // A killed process can still exit with a status, and a script that times + // out INTERNALLY exits non-zero with its own envelope on stdout. + const c = classifyForgeError({ code: 124, killed: false }); + + expect(c.timedOut).toBe(false); + expect(c.exitCode).toBe(124); + }); + + it('reports a non-numeric code as no exit code rather than as zero', () => { + expect(classifyForgeError({ code: 'ENOENT' }).exitCode).toBeNull(); + }); +}); + +describe('#17: exec and execSync report the same facts in different fields', () => { + // Measured directly against node 20. Reading only `code` lost every sync exit + // status and every sync timeout, which is how the sync variant stayed silent + // about both while looking like it was handled. + it('reads an async exit code from `code`', () => { + expect(classifyForgeError({ code: 3 }).exitCode).toBe(3); + }); + + it('reads a sync exit code from `status`', () => { + expect(classifyForgeError({ status: 3, signal: null }).exitCode).toBe(3); + }); + + it('reads an async timeout from killed + signal', () => { + expect(classifyForgeError({ killed: true, signal: 'SIGTERM' }).timedOut).toBe(true); + }); + + it('reads a sync timeout from ETIMEDOUT', () => { + expect(classifyForgeError({ code: 'ETIMEDOUT', status: null, signal: 'SIGTERM' }).timedOut).toBe(true); + }); + + it('does not read a sync non-zero exit as a timeout', () => { + expect(classifyForgeError({ status: 3, signal: null }).timedOut).toBe(false); + }); +}); + +describe('#17: the duration in the warning has to describe something', () => { + it('does not round a sub-second bound down to "0s"', async () => { + // "timed out after 0s (limit 0s)" is not a report, it is noise wearing the + // shape of one. + await executeForgeCommand('recently-merged', {}, { ...asCommand('sleep 5'), timeoutMs: 150 }); + + expect(said()).toContain('limit 150ms'); + expect(said()).not.toContain('limit 0s'); + }, 20_000); + + it('uses seconds once the bound is a second or more', async () => { + await executeForgeCommand('recently-merged', {}, { ...asCommand('sleep 30'), timeoutMs: 1_200 }); + + expect(said()).toContain('limit 1s'); + }, 20_000); +}); diff --git a/packages/codev/src/lib/forge.ts b/packages/codev/src/lib/forge.ts index 527bd0abb..0f009aed7 100644 --- a/packages/codev/src/lib/forge.ts +++ b/packages/codev/src/lib/forge.ts @@ -428,18 +428,23 @@ export async function executeForgeCommand( } const forgeEnv = buildForgeEnv(forgeConfig); + const timeout = options?.timeoutMs ?? DEFAULT_TIMEOUT_MS; + const started = Date.now(); try { const { stdout } = await execAsync(command, { cwd: options?.cwd, env: { ...process.env, ...forgeEnv, ...env }, - timeout: options?.timeoutMs ?? DEFAULT_TIMEOUT_MS, + timeout, maxBuffer: options?.maxBuffer ?? DEFAULT_MAX_BUFFER, }); return parseOutput(stdout, options?.raw); } catch (err: unknown) { logDebug(concept, err); + // #17: the null below is about to be read as "no results" by every caller. + // Say that it is not. + warnForgeFailure(concept, err, Date.now() - started, timeout, false); return null; } } @@ -514,20 +519,21 @@ export async function executeForgeCommandDetailed( }; } catch (err: unknown) { logDebug(concept, err); - const e = err as { code?: number | string; killed?: boolean; signal?: string; stdout?: string; stderr?: string }; - // `killed` plus a signal is how Node reports the timeout it enforced — - // verified during #12 against a command whose grandchild held the stdout - // pipe. An exit code alone cannot be read as a timeout: a killed process - // can still exit with a status, and a script that times out INTERNALLY (the - // shell watchdog in scripts/forge/_timeout.sh) exits non-zero with its own - // timeout envelope on stdout, which is why stdout is preserved below. - const timedOut = e.killed === true && typeof e.signal === 'string'; + const e = err as { stdout?: string; stderr?: string }; + // Classification is shared with the swallowing variants (#17) so the three + // entry points cannot drift on what counts as a timeout. `stdout` is + // preserved because a script that times out INTERNALLY (the shell watchdog + // in scripts/forge/_timeout.sh) exits non-zero with its own timeout + // envelope there; discarding it would throw the class of failure away at + // the last step. No warning is emitted here — this variant's whole purpose + // is to hand the failure to a caller that will report it. + const { timedOut, exitCode, message } = classifyForgeError(err); return { ok: false, data: e.stdout ? parseOutput(e.stdout, options?.raw) : null, stdout: e.stdout ?? '', - stderr: e.stderr ?? (err instanceof Error ? err.message : String(err)), - exitCode: typeof e.code === 'number' ? e.code : null, + stderr: e.stderr ?? message, + exitCode, timedOut, unavailable: false, durationMs: Date.now() - started, @@ -554,13 +560,15 @@ export function executeForgeCommandSync( } const forgeEnv = buildForgeEnv(forgeConfig); + const timeout = options?.timeoutMs ?? DEFAULT_TIMEOUT_MS; + const started = Date.now(); try { const stdout = execSync(command, { cwd: options?.cwd, env: { ...process.env, ...forgeEnv, ...env }, encoding: 'utf-8', - timeout: options?.timeoutMs ?? DEFAULT_TIMEOUT_MS, + timeout, maxBuffer: options?.maxBuffer ?? DEFAULT_MAX_BUFFER, stdio: ['pipe', 'pipe', 'pipe'], }); @@ -568,6 +576,8 @@ export function executeForgeCommandSync( return parseOutput(stdout, options?.raw); } catch (err: unknown) { logDebug(concept, err, true); + // #17: same swallow, same fix — this null is about to read as "no results". + warnForgeFailure(concept, err, Date.now() - started, timeout, true); return null; } } @@ -610,6 +620,111 @@ function parseOutput(stdout: string, raw?: boolean): unknown | null { } /** Log concept failure at debug level. */ +/** + * How a forge command failed (issue #17). + * + * `killed` plus a signal is how Node reports the timeout it enforced -- verified + * during #12 against a command whose grandchild held the stdout pipe. An exit + * code alone cannot be read as a timeout: a killed process can still exit with a + * status, and a script that times out INTERNALLY (the shell watchdog in + * scripts/forge/_timeout.sh) exits non-zero with its own timeout envelope on + * stdout. + */ +export function classifyForgeError(err: unknown): { + timedOut: boolean; + exitCode: number | null; + message: string; +} { + const e = err as { + code?: number | string; + status?: number | null; + killed?: boolean; + signal?: string; + stderr?: string; + }; + + // The two APIs report the same facts in different fields, measured directly: + // exec exit 3 -> { code: 3 } + // exec timeout -> { killed: true, signal: 'SIGTERM' } + // execSync exit 3 -> { status: 3, signal: null } + // execSync timeout -> { code: 'ETIMEDOUT', status: null, signal: 'SIGTERM' } + // Reading only `code` therefore lost every sync exit status and every sync + // timeout, which is how the sync variant stayed silent about both. + const exitCode = typeof e.code === 'number' + ? e.code + : typeof e.status === 'number' ? e.status : null; + + const timedOut = + (e.killed === true && typeof e.signal === 'string') + || e.code === 'ETIMEDOUT'; + + return { + timedOut, + exitCode, + message: (e.stderr || (err instanceof Error ? err.message : String(err))).trim(), + }; +} + +/** + * Concepts already warned about, so a poll loop reports a breakage once rather + * than every tick. Keyed by concept + failure kind: a concept that starts timing + * out after having merely errored is new information and says so. + */ +const warnedForgeFailures = new Set(); + +/** Test seam — the set is process-global and would leak between cases. */ +export function _resetForgeFailureWarnings(): void { + warnedForgeFailures.clear(); +} + +/** + * Say that a forge concept BROKE, rather than letting it read as empty (#17). + * + * `executeForgeCommand` returns `null` for a timeout, a non-zero exit and an + * unparseable body alike, and every caller reads `null` as "no results". A + * `recently-merged` that timed out on page one rendered as an empty merged + * panel with clean stderr, on every `afx status` and every dashboard poll, for + * as long as that repo had enough PRs -- and nobody noticed, because empty + * looks like a valid answer. + * + * Written to stderr, not behind CODEV_DEBUG: a failure nobody is told about is + * the defect. Once per concept+kind per process, because the callers here are + * poll loops on a 30s TTL and a warning every tick would be its own kind of + * unreadable. Silence it entirely with CODEV_FORGE_QUIET=1. + */ +function warnForgeFailure( + concept: string, + err: unknown, + durationMs: number, + timeoutMs: number, + sync: boolean, +): void { + if (process.env.CODEV_FORGE_QUIET) return; + + const { timedOut, exitCode, message } = classifyForgeError(err); + const kind = timedOut ? 'timeout' : exitCode !== null ? `exit-${exitCode}` : 'error'; + const key = `${concept}:${kind}`; + if (warnedForgeFailures.has(key)) return; + warnedForgeFailures.add(key); + + const where = sync ? ' (sync)' : ''; + // Sub-second values must not round to `0s`. A warning that reads + // "timed out after 0s (limit 0s)" describes nothing. + const secs = (ms: number): string => (ms < 1000 ? `${Math.round(ms)}ms` : `${Math.round(ms / 1000)}s`); + const detail = timedOut + ? `timed out after ${secs(durationMs)} (limit ${secs(timeoutMs)})` + : exitCode !== null + ? `exited ${exitCode}` + : 'failed'; + const firstLine = message.split('\n')[0].slice(0, 200); + + process.stderr.write( + `\x1b[33m[forge] '${concept}'${where} ${detail} — reporting NO RESULTS, which is not the same as none.` + + (firstLine ? `\n ${firstLine}` : '') + + `\n Further '${concept}' ${kind} failures this process are silent. CODEV_FORGE_QUIET=1 to silence entirely.\x1b[0m\n`, + ); +} + function logDebug(concept: string, err: unknown, sync = false): void { if (process.env.CODEV_DEBUG) { const msg = err instanceof Error ? err.message : String(err);