From 5d857657f430836ea348338cfbe59e5ac9d3bca2 Mon Sep 17 00:00:00 2001 From: pseudo Date: Sun, 23 Aug 2026 22:01:33 -0600 Subject: [PATCH] Say when a forge concept broke, instead of returning an empty result (#17) `executeForgeCommand` returns null for a timeout, a non-zero exit and an unparseable body alike, and all 20 call sites read 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 pages 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. The warning goes to stderr, not behind a debug flag -- a failure nobody is told about IS the defect. Once per concept+kind per process, because these callers are poll loops and a warning every tick is its own kind of unreadable; the message says it will not repeat, so later silence is not read as recovery. A concept that was erroring and starts timing out warns again, because that is new information. CODEV_FORGE_QUIET=1 silences it. A successful command with an empty body stays silent. That distinction is the whole point: if empty warns too, the warning means nothing. Classification is now shared with executeForgeCommandDetailed so the three entry points cannot drift, and fixing it exposed that the sync variant could never have reported either failure. Measured on node 20: 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` lost every sync exit status and every sync timeout. Detailed does not warn: its whole purpose is to hand the failure to a caller that will report it, and warning there would double-report. Not done: migrating the 20 callers to the detailed variant so the dashboard can render "could not load" instead of an empty panel. This is the issue's stated minimum, and it covers all 20 without touching any of them. Co-Authored-By: Claude Opus 5 (1M context) --- .../__tests__/issue-17-forge-swallow.test.ts | 263 ++++++++++++++++++ packages/codev/src/lib/forge.ts | 139 ++++++++- 2 files changed, 390 insertions(+), 12 deletions(-) create mode 100644 packages/codev/src/__tests__/issue-17-forge-swallow.test.ts 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);