fix(ai-checker): keep CLI stderr out of the verdict and surface it on failure

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'
This commit is contained in:
lior
2026-08-08 22:30:39 +03:00
parent fa18eeef35
commit da51193264
2 changed files with 85 additions and 43 deletions
+31 -3
View File
@@ -135,6 +135,7 @@ export abstract class AiCheckerBase<
// Active check state // Active check state
protected checkMuxName: string | null = null; protected checkMuxName: string | null = null;
protected checkTempFile: string | null = null; protected checkTempFile: string | null = null;
protected checkStderrFile: string | null = null;
protected checkPromptFile: string | null = null; protected checkPromptFile: string | null = null;
protected checkPollTimer: NodeJS.Timeout | null = null; protected checkPollTimer: NodeJS.Timeout | null = null;
protected checkTimeoutTimer: 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 shortId = this.sessionId.slice(0, 8);
const timestamp = Date.now(); const timestamp = Date.now();
this.checkTempFile = join(tmpdir(), `${this.tempFilePrefix}-${shortId}-${timestamp}.txt`); 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.checkPromptFile = join(tmpdir(), `${this.tempFilePrefix}-prompt-${shortId}-${timestamp}.txt`);
this.checkMuxName = `${this.muxNamePrefix}${shortId}`; this.checkMuxName = `${this.muxNamePrefix}${shortId}`;
@@ -386,6 +388,7 @@ export abstract class AiCheckerBase<
// Ensure output temp file exists (empty) so we can poll it // Ensure output temp file exists (empty) so we can poll it
writeFileSync(this.checkTempFile, ''); writeFileSync(this.checkTempFile, '');
writeFileSync(this.checkStderrFile, '');
// Write prompt to file to avoid E2BIG error (argument list too long) // Write prompt to file to avoid E2BIG error (argument list too long)
// The prompt can be 16KB+ which exceeds shell argument limits // 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 modelArg = `--model "${this.config.model.replace(/"/g, '\\"')}"`;
const augmentedPath = getAugmentedPath(); const augmentedPath = getAugmentedPath();
const claudeCmd = `cat "${this.checkPromptFile}" | claude -p ${modelArg} --output-format text`; 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 // Spawn tmux session
try { try {
@@ -461,18 +464,32 @@ export abstract class AiCheckerBase<
const output = content.replace(this.doneMarker, '').trim(); const output = content.replace(this.doneMarker, '').trim();
if (!output) { 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 // Delegate to subclass for verdict parsing
const parsed = this.parseVerdict(output); const parsed = this.parseVerdict(output);
if (!parsed) { 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); 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 { private cleanupCheck(): void {
// Clear poll timer // Clear poll timer
if (this.checkPollTimer) { if (this.checkPollTimer) {
@@ -509,6 +526,17 @@ export abstract class AiCheckerBase<
this.checkTempFile = null; this.checkTempFile = null;
} }
if (this.checkStderrFile) {
try {
if (existsSync(this.checkStderrFile)) {
unlinkSync(this.checkStderrFile);
}
} catch {
// Best effort cleanup
}
this.checkStderrFile = null;
}
if (this.checkPromptFile) { if (this.checkPromptFile) {
try { try {
if (existsSync(this.checkPromptFile)) { if (existsSync(this.checkPromptFile)) {
+54 -40
View File
@@ -71,7 +71,8 @@ describe('AiIdleChecker', () => {
describe('Output Parsing', () => { describe('Output Parsing', () => {
it('should parse IDLE verdict', async () => { it('should parse IDLE verdict', async () => {
// Set up mock to return IDLE result after polling // 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__'); .mockReturnValueOnce('IDLE\nSession shows completion message and prompt.\n__AICHECK_DONE__');
const checkPromise = checker.check('some terminal output'); const checkPromise = checker.check('some terminal output');
@@ -87,7 +88,8 @@ describe('AiIdleChecker', () => {
}); });
it('should parse WORKING verdict', async () => { it('should parse WORKING verdict', async () => {
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync
.mockReturnValueOnce('')
.mockReturnValueOnce('WORKING\nSpinner characters detected, still processing.\n__AICHECK_DONE__'); .mockReturnValueOnce('WORKING\nSpinner characters detected, still processing.\n__AICHECK_DONE__');
const checkPromise = checker.check('some terminal output'); const checkPromise = checker.check('some terminal output');
@@ -100,8 +102,7 @@ describe('AiIdleChecker', () => {
}); });
it('should handle lowercase verdict', async () => { it('should handle lowercase verdict', async () => {
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('idle\nDone.\n__AICHECK_DONE__');
.mockReturnValueOnce('idle\nDone.\n__AICHECK_DONE__');
const checkPromise = checker.check('output'); const checkPromise = checker.check('output');
await vi.advanceTimersByTimeAsync(500); await vi.advanceTimersByTimeAsync(500);
@@ -112,7 +113,8 @@ describe('AiIdleChecker', () => {
}); });
it('should return ERROR for unparseable output', async () => { it('should return ERROR for unparseable output', async () => {
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync
.mockReturnValueOnce('')
.mockReturnValueOnce('Something unexpected happened.\n__AICHECK_DONE__'); .mockReturnValueOnce('Something unexpected happened.\n__AICHECK_DONE__');
const checkPromise = checker.check('output'); const checkPromise = checker.check('output');
@@ -125,8 +127,7 @@ describe('AiIdleChecker', () => {
}); });
it('should return ERROR for empty output', async () => { it('should return ERROR for empty output', async () => {
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('__AICHECK_DONE__');
.mockReturnValueOnce('__AICHECK_DONE__');
const checkPromise = checker.check('output'); const checkPromise = checker.check('output');
await vi.advanceTimersByTimeAsync(500); await vi.advanceTimersByTimeAsync(500);
@@ -175,10 +176,34 @@ describe('AiIdleChecker', () => {
await vi.advanceTimersByTimeAsync(500); await vi.advanceTimersByTimeAsync(500);
await checkPromise; await checkPromise;
expect(mockedWriteFileSync).toHaveBeenCalledWith( expect(mockedWriteFileSync).toHaveBeenCalledWith(expect.stringContaining('codeman-aicheck-'), '');
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) // Should have tried to kill the tmux session (initial kill + cleanup kill)
const killCalls = mockedExecSync.mock.calls.filter( 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); expect(killCalls.length).toBeGreaterThan(0);
}); });
@@ -236,8 +261,7 @@ describe('AiIdleChecker', () => {
describe('Cooldown', () => { describe('Cooldown', () => {
it('should start cooldown after WORKING verdict', async () => { it('should start cooldown after WORKING verdict', async () => {
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('WORKING\nStill processing.\n__AICHECK_DONE__');
.mockReturnValueOnce('WORKING\nStill processing.\n__AICHECK_DONE__');
const checkPromise = checker.check('output'); const checkPromise = checker.check('output');
await vi.advanceTimersByTimeAsync(500); await vi.advanceTimersByTimeAsync(500);
@@ -250,8 +274,7 @@ describe('AiIdleChecker', () => {
}); });
it('should return to ready after cooldown expires', async () => { it('should return to ready after cooldown expires', async () => {
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__');
.mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__');
const checkPromise = checker.check('output'); const checkPromise = checker.check('output');
await vi.advanceTimersByTimeAsync(1000); await vi.advanceTimersByTimeAsync(1000);
@@ -267,8 +290,7 @@ describe('AiIdleChecker', () => {
}); });
it('should not start new check during cooldown', async () => { it('should not start new check during cooldown', async () => {
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__');
.mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__');
const firstCheck = checker.check('output'); const firstCheck = checker.check('output');
await vi.advanceTimersByTimeAsync(1000); await vi.advanceTimersByTimeAsync(1000);
@@ -283,8 +305,7 @@ describe('AiIdleChecker', () => {
describe('Error Handling', () => { describe('Error Handling', () => {
it('should start error cooldown after parse error', async () => { it('should start error cooldown after parse error', async () => {
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('garbage output\n__AICHECK_DONE__');
.mockReturnValueOnce('garbage output\n__AICHECK_DONE__');
const checkPromise = checker.check('output'); const checkPromise = checker.check('output');
await vi.advanceTimersByTimeAsync(1000); await vi.advanceTimersByTimeAsync(1000);
@@ -302,8 +323,7 @@ describe('AiIdleChecker', () => {
const cooldowns = [1100, 2100]; // Wait slightly longer than each cooldown const cooldowns = [1100, 2100]; // Wait slightly longer than each cooldown
for (let i = 0; i < 3; i++) { for (let i = 0; i < 3; i++) {
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('garbage\n__AICHECK_DONE__');
.mockReturnValueOnce('garbage\n__AICHECK_DONE__');
const checkPromise = checker.check('output'); const checkPromise = checker.check('output');
await vi.advanceTimersByTimeAsync(1000); await vi.advanceTimersByTimeAsync(1000);
@@ -321,8 +341,7 @@ describe('AiIdleChecker', () => {
it('should reset error counter on successful check', async () => { it('should reset error counter on successful check', async () => {
// First check: error // First check: error
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('garbage\n__AICHECK_DONE__');
.mockReturnValueOnce('garbage\n__AICHECK_DONE__');
const firstCheck = checker.check('output'); const firstCheck = checker.check('output');
await vi.advanceTimersByTimeAsync(1000); await vi.advanceTimersByTimeAsync(1000);
await firstCheck; await firstCheck;
@@ -332,8 +351,7 @@ describe('AiIdleChecker', () => {
await vi.advanceTimersByTimeAsync(1100); await vi.advanceTimersByTimeAsync(1100);
// Second check: success // Second check: success
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('IDLE\nDone.\n__AICHECK_DONE__');
.mockReturnValueOnce('IDLE\nDone.\n__AICHECK_DONE__');
const secondCheck = checker.check('output'); const secondCheck = checker.check('output');
await vi.advanceTimersByTimeAsync(1000); await vi.advanceTimersByTimeAsync(1000);
await secondCheck; await secondCheck;
@@ -352,8 +370,7 @@ describe('AiIdleChecker', () => {
describe('Buffer Handling', () => { describe('Buffer Handling', () => {
it('should strip ANSI codes from terminal buffer', async () => { it('should strip ANSI codes from terminal buffer', async () => {
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('IDLE\n__AICHECK_DONE__');
.mockReturnValueOnce('IDLE\n__AICHECK_DONE__');
const ansiBuffer = '\x1b[1mBold\x1b[0m \x1b[32mGreen\x1b[0m text'; const ansiBuffer = '\x1b[1mBold\x1b[0m \x1b[32mGreen\x1b[0m text';
const checkPromise = checker.check(ansiBuffer); const checkPromise = checker.check(ansiBuffer);
@@ -365,8 +382,7 @@ describe('AiIdleChecker', () => {
}); });
it('should trim buffer to maxContextChars', async () => { it('should trim buffer to maxContextChars', async () => {
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('IDLE\n__AICHECK_DONE__');
.mockReturnValueOnce('IDLE\n__AICHECK_DONE__');
// Create buffer longer than maxContextChars (1000) // Create buffer longer than maxContextChars (1000)
const longBuffer = 'x'.repeat(2000); const longBuffer = 'x'.repeat(2000);
@@ -402,8 +418,7 @@ describe('AiIdleChecker', () => {
describe('Reset', () => { describe('Reset', () => {
it('should clear all state on reset', async () => { it('should clear all state on reset', async () => {
// Trigger a WORKING verdict to set state // Trigger a WORKING verdict to set state
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__');
.mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__');
const checkPromise = checker.check('output'); const checkPromise = checker.check('output');
await vi.advanceTimersByTimeAsync(1000); await vi.advanceTimersByTimeAsync(1000);
@@ -440,24 +455,24 @@ describe('AiIdleChecker', () => {
const handler = vi.fn(); const handler = vi.fn();
checker.on('checkCompleted', handler); checker.on('checkCompleted', handler);
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('IDLE\nAll done.\n__AICHECK_DONE__');
.mockReturnValueOnce('IDLE\nAll done.\n__AICHECK_DONE__');
const checkPromise = checker.check('output'); const checkPromise = checker.check('output');
await vi.advanceTimersByTimeAsync(1000); await vi.advanceTimersByTimeAsync(1000);
await checkPromise; await checkPromise;
expect(handler).toHaveBeenCalledWith(expect.objectContaining({ expect(handler).toHaveBeenCalledWith(
verdict: 'IDLE', expect.objectContaining({
})); verdict: 'IDLE',
})
);
}); });
it('should emit cooldownStarted event after WORKING', async () => { it('should emit cooldownStarted event after WORKING', async () => {
const handler = vi.fn(); const handler = vi.fn();
checker.on('cooldownStarted', handler); checker.on('cooldownStarted', handler);
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__');
.mockReturnValueOnce('WORKING\nBusy.\n__AICHECK_DONE__');
const checkPromise = checker.check('output'); const checkPromise = checker.check('output');
await vi.advanceTimersByTimeAsync(1000); await vi.advanceTimersByTimeAsync(1000);
@@ -477,8 +492,7 @@ describe('AiIdleChecker', () => {
const cooldowns = [1100, 2100]; // Wait longer than exponential backoff const cooldowns = [1100, 2100]; // Wait longer than exponential backoff
for (let i = 0; i < 3; i++) { for (let i = 0; i < 3; i++) {
mockedReadFileSync.mockReturnValueOnce('') mockedReadFileSync.mockReturnValueOnce('').mockReturnValueOnce('garbage\n__AICHECK_DONE__');
.mockReturnValueOnce('garbage\n__AICHECK_DONE__');
const checkPromise = checker.check('output'); const checkPromise = checker.check('output');
await vi.advanceTimersByTimeAsync(1000); await vi.advanceTimersByTimeAsync(1000);
await checkPromise; await checkPromise;