From da5119326480d27a325b7de65aebc19cc0fc2fec Mon Sep 17 00:00:00 2001 From: lior Date: Sat, 8 Aug 2026 22:30:39 +0300 Subject: [PATCH] fix(ai-checker): keep CLI stderr out of the verdict and surface it on failure MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit AiCheckerBase spawned the check with `> out 2>&1`, so anything the Claude CLI wrote to stderr landed inside the same file the verdict parser reads. A CLI that failed to start (corrupt settings, missing auth) produced either an empty verdict or an unparseable one, and the actual cause was destroyed on the way through — the user saw only "Empty output from AI idle check". stderr now goes to its own temp file. When output is empty or the verdict cannot be parsed, the first 200 characters of stderr are appended to the error message. The file is cleaned up alongside the existing temp files, including on the error paths. Two tests, both failing on master: expected 'export PATH="…' to contain ' 2> "' expected 'Empty output from AI idle check' to contain 'Claude CLI failed to load settings' --- src/ai-checker-base.ts | 34 +++++++++++-- test/ai-idle-checker.test.ts | 94 +++++++++++++++++++++--------------- 2 files changed, 85 insertions(+), 43 deletions(-) diff --git a/src/ai-checker-base.ts b/src/ai-checker-base.ts index ddb8bd14..d902a67f 100644 --- a/src/ai-checker-base.ts +++ b/src/ai-checker-base.ts @@ -135,6 +135,7 @@ export abstract class AiCheckerBase< // Active check state protected checkMuxName: string | null = null; protected checkTempFile: string | null = null; + protected checkStderrFile: string | null = null; protected checkPromptFile: string | null = null; protected checkPollTimer: NodeJS.Timeout | null = null; protected checkTimeoutTimer: NodeJS.Timeout | null = null; @@ -376,6 +377,7 @@ export abstract class AiCheckerBase< const shortId = this.sessionId.slice(0, 8); const timestamp = Date.now(); this.checkTempFile = join(tmpdir(), `${this.tempFilePrefix}-${shortId}-${timestamp}.txt`); + this.checkStderrFile = join(tmpdir(), `${this.tempFilePrefix}-stderr-${shortId}-${timestamp}.txt`); this.checkPromptFile = join(tmpdir(), `${this.tempFilePrefix}-prompt-${shortId}-${timestamp}.txt`); this.checkMuxName = `${this.muxNamePrefix}${shortId}`; @@ -386,6 +388,7 @@ export abstract class AiCheckerBase< // Ensure output temp file exists (empty) so we can poll it writeFileSync(this.checkTempFile, ''); + writeFileSync(this.checkStderrFile, ''); // Write prompt to file to avoid E2BIG error (argument list too long) // The prompt can be 16KB+ which exceeds shell argument limits @@ -396,7 +399,7 @@ export abstract class AiCheckerBase< const modelArg = `--model "${this.config.model.replace(/"/g, '\\"')}"`; const augmentedPath = getAugmentedPath(); const claudeCmd = `cat "${this.checkPromptFile}" | claude -p ${modelArg} --output-format text`; - const fullCmd = `export PATH="${augmentedPath}"; ${claudeCmd} > "${this.checkTempFile}" 2>&1; echo "${this.doneMarker}" >> "${this.checkTempFile}"; rm -f "${this.checkPromptFile}"`; + const fullCmd = `export PATH="${augmentedPath}"; ${claudeCmd} > "${this.checkTempFile}" 2> "${this.checkStderrFile}"; echo "${this.doneMarker}" >> "${this.checkTempFile}"; rm -f "${this.checkPromptFile}"`; // Spawn tmux session try { @@ -461,18 +464,32 @@ export abstract class AiCheckerBase< const output = content.replace(this.doneMarker, '').trim(); if (!output) { - return this.createErrorResult(`Empty output from ${this.checkDescription}`, durationMs); + const stderr = this.readStderrDiagnostic(); + const detail = stderr ? `: ${stderr}` : ''; + return this.createErrorResult(`Empty output from ${this.checkDescription}${detail}`, durationMs); } // Delegate to subclass for verdict parsing const parsed = this.parseVerdict(output); if (!parsed) { - return this.createErrorResult(`Could not parse verdict from: "${output.substring(0, 100)}"`, durationMs); + const stderr = this.readStderrDiagnostic(); + const detail = stderr ? `; stderr: "${stderr}"` : ''; + return this.createErrorResult(`Could not parse verdict from: "${output.substring(0, 100)}"${detail}`, durationMs); } return this.createResult(parsed.verdict, parsed.reasoning, durationMs); } + private readStderrDiagnostic(): string { + if (!this.checkStderrFile || !existsSync(this.checkStderrFile)) return ''; + + try { + return readFileSync(this.checkStderrFile, 'utf-8').trim().substring(0, 200); + } catch { + return ''; + } + } + private cleanupCheck(): void { // Clear poll timer if (this.checkPollTimer) { @@ -509,6 +526,17 @@ export abstract class AiCheckerBase< this.checkTempFile = null; } + if (this.checkStderrFile) { + try { + if (existsSync(this.checkStderrFile)) { + unlinkSync(this.checkStderrFile); + } + } catch { + // Best effort cleanup + } + this.checkStderrFile = null; + } + if (this.checkPromptFile) { try { if (existsSync(this.checkPromptFile)) { diff --git a/test/ai-idle-checker.test.ts b/test/ai-idle-checker.test.ts index 342b06d5..e0180a1c 100644 --- a/test/ai-idle-checker.test.ts +++ b/test/ai-idle-checker.test.ts @@ -71,7 +71,8 @@ describe('AiIdleChecker', () => { describe('Output Parsing', () => { it('should parse IDLE verdict', async () => { // Set up mock to return IDLE result after polling - mockedReadFileSync.mockReturnValueOnce('') // writeFileSync creates empty file + mockedReadFileSync + .mockReturnValueOnce('') // writeFileSync creates empty file .mockReturnValueOnce('IDLE\nSession shows completion message and prompt.\n__AICHECK_DONE__'); const checkPromise = checker.check('some terminal output'); @@ -87,7 +88,8 @@ describe('AiIdleChecker', () => { }); it('should parse WORKING verdict', async () => { - mockedReadFileSync.mockReturnValueOnce('') + mockedReadFileSync + .mockReturnValueOnce('') .mockReturnValueOnce('WORKING\nSpinner characters detected, still processing.\n__AICHECK_DONE__'); const checkPromise = checker.check('some terminal output'); @@ -100,8 +102,7 @@ describe('AiIdleChecker', () => { }); it('should handle lowercase verdict', async () => { - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('idle\nDone.\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('idle\nDone.\n__AICHECK_DONE__'); const checkPromise = checker.check('output'); await vi.advanceTimersByTimeAsync(500); @@ -112,7 +113,8 @@ describe('AiIdleChecker', () => { }); it('should return ERROR for unparseable output', async () => { - mockedReadFileSync.mockReturnValueOnce('') + mockedReadFileSync + .mockReturnValueOnce('') .mockReturnValueOnce('Something unexpected happened.\n__AICHECK_DONE__'); const checkPromise = checker.check('output'); @@ -125,8 +127,7 @@ describe('AiIdleChecker', () => { }); it('should return ERROR for empty output', async () => { - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('__AICHECK_DONE__'); const checkPromise = checker.check('output'); await vi.advanceTimersByTimeAsync(500); @@ -175,10 +176,34 @@ describe('AiIdleChecker', () => { await vi.advanceTimersByTimeAsync(500); await checkPromise; - expect(mockedWriteFileSync).toHaveBeenCalledWith( - expect.stringContaining('codeman-aicheck-'), - '' + expect(mockedWriteFileSync).toHaveBeenCalledWith(expect.stringContaining('codeman-aicheck-'), ''); + }); + + it('should keep Claude stderr separate from verdict output', async () => { + mockedReadFileSync.mockReturnValue('IDLE\n__AICHECK_DONE__'); + + const checkPromise = checker.check('output'); + await vi.advanceTimersByTimeAsync(500); + await checkPromise; + + const spawnArgs = mockedSpawn.mock.calls[0]?.[1]; + const command = spawnArgs?.[spawnArgs.length - 1]; + expect(command).toEqual(expect.any(String)); + expect(command).toContain(' 2> "'); + expect(command).not.toContain('2>&1'); + }); + + it('should include Claude stderr when no verdict is produced', async () => { + mockedReadFileSync.mockImplementation((path) => + String(path).includes('-stderr-') ? 'Claude CLI failed to load settings' : '__AICHECK_DONE__' ); + + const checkPromise = checker.check('output'); + await vi.advanceTimersByTimeAsync(500); + + const result = await checkPromise; + expect(result.verdict).toBe('ERROR'); + expect(result.reasoning).toContain('Claude CLI failed to load settings'); }); }); @@ -223,7 +248,7 @@ describe('AiIdleChecker', () => { // Should have tried to kill the tmux session (initial kill + cleanup kill) const killCalls = mockedExecSync.mock.calls.filter( - call => typeof call[0] === 'string' && call[0].includes('kill-session') + (call) => typeof call[0] === 'string' && call[0].includes('kill-session') ); expect(killCalls.length).toBeGreaterThan(0); }); @@ -236,8 +261,7 @@ describe('AiIdleChecker', () => { describe('Cooldown', () => { it('should start cooldown after WORKING verdict', async () => { - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('WORKING\nStill processing.\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('WORKING\nStill processing.\n__AICHECK_DONE__'); const checkPromise = checker.check('output'); await vi.advanceTimersByTimeAsync(500); @@ -250,8 +274,7 @@ describe('AiIdleChecker', () => { }); it('should return to ready after cooldown expires', async () => { - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__'); const checkPromise = checker.check('output'); await vi.advanceTimersByTimeAsync(1000); @@ -267,8 +290,7 @@ describe('AiIdleChecker', () => { }); it('should not start new check during cooldown', async () => { - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__'); const firstCheck = checker.check('output'); await vi.advanceTimersByTimeAsync(1000); @@ -283,8 +305,7 @@ describe('AiIdleChecker', () => { describe('Error Handling', () => { it('should start error cooldown after parse error', async () => { - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('garbage output\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('garbage output\n__AICHECK_DONE__'); const checkPromise = checker.check('output'); await vi.advanceTimersByTimeAsync(1000); @@ -302,8 +323,7 @@ describe('AiIdleChecker', () => { const cooldowns = [1100, 2100]; // Wait slightly longer than each cooldown for (let i = 0; i < 3; i++) { - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('garbage\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('garbage\n__AICHECK_DONE__'); const checkPromise = checker.check('output'); await vi.advanceTimersByTimeAsync(1000); @@ -321,8 +341,7 @@ describe('AiIdleChecker', () => { it('should reset error counter on successful check', async () => { // First check: error - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('garbage\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('garbage\n__AICHECK_DONE__'); const firstCheck = checker.check('output'); await vi.advanceTimersByTimeAsync(1000); await firstCheck; @@ -332,8 +351,7 @@ describe('AiIdleChecker', () => { await vi.advanceTimersByTimeAsync(1100); // Second check: success - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('IDLE\nDone.\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('IDLE\nDone.\n__AICHECK_DONE__'); const secondCheck = checker.check('output'); await vi.advanceTimersByTimeAsync(1000); await secondCheck; @@ -352,8 +370,7 @@ describe('AiIdleChecker', () => { describe('Buffer Handling', () => { it('should strip ANSI codes from terminal buffer', async () => { - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('IDLE\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('IDLE\n__AICHECK_DONE__'); const ansiBuffer = '\x1b[1mBold\x1b[0m \x1b[32mGreen\x1b[0m text'; const checkPromise = checker.check(ansiBuffer); @@ -365,8 +382,7 @@ describe('AiIdleChecker', () => { }); it('should trim buffer to maxContextChars', async () => { - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('IDLE\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('IDLE\n__AICHECK_DONE__'); // Create buffer longer than maxContextChars (1000) const longBuffer = 'x'.repeat(2000); @@ -402,8 +418,7 @@ describe('AiIdleChecker', () => { describe('Reset', () => { it('should clear all state on reset', async () => { // Trigger a WORKING verdict to set state - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__'); const checkPromise = checker.check('output'); await vi.advanceTimersByTimeAsync(1000); @@ -440,24 +455,24 @@ describe('AiIdleChecker', () => { const handler = vi.fn(); checker.on('checkCompleted', handler); - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('IDLE\nAll done.\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('IDLE\nAll done.\n__AICHECK_DONE__'); const checkPromise = checker.check('output'); await vi.advanceTimersByTimeAsync(1000); await checkPromise; - expect(handler).toHaveBeenCalledWith(expect.objectContaining({ - verdict: 'IDLE', - })); + expect(handler).toHaveBeenCalledWith( + expect.objectContaining({ + verdict: 'IDLE', + }) + ); }); it('should emit cooldownStarted event after WORKING', async () => { const handler = vi.fn(); checker.on('cooldownStarted', handler); - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__'); const checkPromise = checker.check('output'); await vi.advanceTimersByTimeAsync(1000); @@ -477,8 +492,7 @@ describe('AiIdleChecker', () => { const cooldowns = [1100, 2100]; // Wait longer than exponential backoff for (let i = 0; i < 3; i++) { - mockedReadFileSync.mockReturnValueOnce('') - .mockReturnValueOnce('garbage\n__AICHECK_DONE__'); + mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('garbage\n__AICHECK_DONE__'); const checkPromise = checker.check('output'); await vi.advanceTimersByTimeAsync(1000); await checkPromise;