feat(cli): enrich CLI timeout diagnostics + idle timeout + debug logging

The CLI provider previously surfaced only "CLI timed out (Xms)" on hang,
discarding accumulated stderr/stdout, pid, and timing — leaving users
unable to tell network hangs from auth failures from a slow model.

- runCli timeout/idle errors now include pid, elapsed, idle duration,
  utf-8 byte counts, plus stderr/stdout tails (with secret redaction
  for Bearer tokens, sk-* keys, and Authorization-style headers).
- Add optional cliIdleTimeoutMs (default 0/disabled): kill the CLI if
  no output for N ms, independent of the wall-clock cliTimeoutMs.
- Add optional debugLogging: console hooks at spawn/ok/fail with pid
  and byte counts for live diagnosis.
- Settled-guard on noteActivity/armIdleTimer prevents stale timers
  after first-wins settle (cancel / wall / idle / child-error / close).
- New unit coverage: rich diagnostic suffix, idle timeout firing, idle
  reset on heartbeat, secret redaction, idle normalization edge cases.

Change-Id: I9191f8d348ef43ff9605dc5169f0951f5af85d26
This commit is contained in:
fancivez 2026-05-05 17:33:25 +08:00 committed by wujunchen
parent 65cb81730a
commit 89464608aa
8 changed files with 269 additions and 10 deletions

View file

@ -52,6 +52,34 @@ export function resolveCliPath(name: string, override: string): string {
return name;
}
export interface RunCliOptions {
/** Idle timeout in ms — fail if no stdout/stderr data arrives for this long. 0 disables. */
idleTimeoutMs?: number;
/** When true, log spawn/settle lifecycle to console for diagnostics. */
debug?: boolean;
}
const DIAG_STDERR_TAIL_CHARS = 800;
const DIAG_STDOUT_TAIL_CHARS = 200;
function tail(text: string, max: number): string {
if (text.length <= max) return text;
return text.slice(-max);
}
const REDACT = '[REDACTED]';
function redactSecrets(text: string): string {
if (!text) return text;
return text
.replace(/\b(Bearer)\s+[\w.\-+/=]{6,}/gi, `$1 ${REDACT}`)
.replace(/\b(x-api-key|x-goog-api-key|api[_-]?key|authorization)\s*[:=]\s*[\w.\-+/=]{6,}/gi, `$1: ${REDACT}`)
.replace(/\b(sk-[A-Za-z0-9_\-]{12,})/g, REDACT);
}
function utf8ByteLength(text: string): number {
return Buffer.byteLength(text, 'utf8');
}
export function runCli(
cmd: string,
args: string[],
@ -59,21 +87,54 @@ export function runCli(
timeoutMs: number,
job?: GenerationJob,
spawnImpl: typeof spawn = spawn,
options: RunCliOptions = {},
): Promise<{ stdout: string; stderr: string }> {
const idleTimeoutMs = Math.max(0, Math.floor(options.idleTimeoutMs ?? 0));
const debug = !!options.debug;
return new Promise<{ stdout: string; stderr: string }>((resolve, reject) => {
let child: ReturnType<typeof spawn>;
let settled = false;
let timer: number | null = null;
let idleTimer: number | null = null;
const startedAt = Date.now();
let lastActivityAt = startedAt;
const clearTimers = () => {
if (timer) {
activeWindow.clearTimeout(timer);
timer = null;
}
if (idleTimer) {
activeWindow.clearTimeout(idleTimer);
idleTimer = null;
}
};
const fail = (err: Error) => {
if (settled) return;
settled = true;
if (timer) activeWindow.clearTimeout(timer);
clearTimers();
if (debug) {
console.warn('[parallel-reader] cli failed', {
cmd,
pid: child?.pid,
elapsedMs: Date.now() - startedAt,
error: err.message,
});
}
reject(err);
};
const succeed = (value: { stdout: string; stderr: string }) => {
if (settled) return;
settled = true;
if (timer) activeWindow.clearTimeout(timer);
clearTimers();
if (debug) {
console.info('[parallel-reader] cli ok', {
cmd,
pid: child?.pid,
elapsedMs: Date.now() - startedAt,
stdoutBytes: utf8ByteLength(value.stdout),
stderrBytes: utf8ByteLength(value.stderr),
});
}
resolve(value);
};
try {
@ -93,19 +154,63 @@ export function runCli(
},
});
} catch (e: unknown) {
return reject(new Error(`Failed to start ${cmd}: ${e instanceof Error ? e.message : String(e)}`));
const message = `Failed to start ${cmd}: ${e instanceof Error ? e.message : String(e)}`;
if (debug) console.warn('[parallel-reader] cli spawn failed', { cmd, error: message });
return reject(new Error(message));
}
if (debug) {
console.info('[parallel-reader] cli spawn', {
cmd,
argCount: args.length,
pid: child?.pid,
timeoutMs,
idleTimeoutMs,
});
}
let stdout = '';
let stderr = '';
const buildDiagSuffix = (idleMs: number): string => {
const elapsed = Date.now() - startedAt;
const stderrBytes = utf8ByteLength(stderr);
const stdoutBytes = utf8ByteLength(stdout);
const stderrTail = redactSecrets(tail(stderr, DIAG_STDERR_TAIL_CHARS));
const stdoutTail = redactSecrets(tail(stdout, DIAG_STDOUT_TAIL_CHARS));
let suffix =
` [pid=${child?.pid ?? 'unknown'} elapsed=${elapsed}ms idle=${idleMs}ms ` +
`stdout=${stdoutBytes}B stderr=${stderrBytes}B]`;
if (stderrTail) suffix += `\n--- stderr tail ---\n${stderrTail}`;
if (stdoutTail) suffix += `\n--- stdout tail ---\n${stdoutTail}`;
return suffix;
};
timer = activeWindow.setTimeout(() => {
try {
child.kill('SIGKILL');
} catch (e: unknown) {
console.warn('[parallel-reader] failed to kill timed-out CLI process', e);
}
fail(new Error(`CLI timed out (${timeoutMs}ms)`));
const idleMs = Date.now() - lastActivityAt;
fail(new Error(`CLI timed out (${timeoutMs}ms)${buildDiagSuffix(idleMs)}`));
}, timeoutMs);
const armIdleTimer = () => {
if (settled || !idleTimeoutMs) return;
if (idleTimer) activeWindow.clearTimeout(idleTimer);
idleTimer = activeWindow.setTimeout(() => {
const idleMs = Date.now() - lastActivityAt;
try {
child.kill('SIGKILL');
} catch (e: unknown) {
console.warn('[parallel-reader] failed to kill idle-timed-out CLI process', e);
}
fail(new Error(`CLI idle timeout (${idleTimeoutMs}ms)${buildDiagSuffix(idleMs)}`));
}, idleTimeoutMs);
};
armIdleTimer();
if (job) {
job.onCancel(() => {
try {
@ -126,11 +231,19 @@ export function runCli(
const childStderr = child.stderr;
const childStdin = child.stdin;
const noteActivity = () => {
if (settled) return;
lastActivityAt = Date.now();
armIdleTimer();
};
childStdout.on('data', (d) => {
stdout += d.toString('utf8');
noteActivity();
});
childStderr.on('data', (d) => {
stderr += d.toString('utf8');
noteActivity();
});
child.on('error', (e) => {
fail(new Error(`CLI startup error: ${e.message}. Try setting an absolute CLI path.`));
@ -179,7 +292,10 @@ export async function summarizeViaClaudeCode(
];
const claudeModel = (settings.model || '').trim();
if (claudeModel) args.push('--model', claudeModel);
const { stdout } = await runCli(cmd, args, user, settings.cliTimeoutMs, job, spawnImpl);
const { stdout } = await runCli(cmd, args, user, settings.cliTimeoutMs, job, spawnImpl, {
idleTimeoutMs: settings.cliIdleTimeoutMs,
debug: settings.debugLogging,
});
// --output-format json produces a JSON array of event objects.
// Find the "result" entry and extract its .result text field.
@ -231,6 +347,9 @@ export async function summarizeViaCodex(
// (claude-sonnet-4-6), which would break Codex if passed verbatim. Codex
// uses its own config.toml profile for model selection.
const args = ['exec', '--skip-git-repo-check', '--sandbox', 'read-only', '-'];
const { stdout } = await runCli(cmd, args, combined, settings.cliTimeoutMs, job, spawnImpl);
const { stdout } = await runCli(cmd, args, combined, settings.cliTimeoutMs, job, spawnImpl, {
idleTimeoutMs: settings.cliIdleTimeoutMs,
debug: settings.debugLogging,
});
return parseCardsJson(stdout, settings);
}

View file

@ -114,6 +114,10 @@ export const STRINGS: Record<string, Record<string, string>> = {
settingCliPathPlaceholder: '例:/Users/you/bin/codex',
settingCliTimeoutName: 'CLI 超时 (ms)',
settingCliTimeoutDesc: 'CLI 调用的最大等待时间(毫秒),最小 1000默认 120000',
settingCliIdleTimeoutName: 'CLI 静默超时 (ms)',
settingCliIdleTimeoutDesc: '若 CLI 持续 X 毫秒没有任何输出则视为卡死并终止0 表示关闭,建议 3000060000',
settingDebugLoggingName: '调试日志',
settingDebugLoggingDesc: '在浏览器控制台打印 CLI spawn / 完成 / 失败的诊断信息(含 PID、耗时、字节数',
sectionQuickSetup: '快速配置',
sectionReadingOutput: '阅读输出',
sectionAdvancedConnection: '高级连接设置',
@ -300,6 +304,12 @@ export const STRINGS: Record<string, Record<string, string>> = {
settingCliPathPlaceholder: 'Example: /Users/you/bin/codex',
settingCliTimeoutName: 'CLI timeout (ms)',
settingCliTimeoutDesc: 'Max wait time for CLI calls (ms). Minimum 1000, default 120000.',
settingCliIdleTimeoutName: 'CLI idle timeout (ms)',
settingCliIdleTimeoutDesc:
'Kill the CLI if it produces no output for this long. 0 disables. Recommended 3000060000.',
settingDebugLoggingName: 'Debug logging',
settingDebugLoggingDesc:
'Log CLI spawn / completion / failure to the browser console (PID, elapsed time, byte counts).',
sectionQuickSetup: 'Quick setup',
sectionReadingOutput: 'Reading output',
sectionAdvancedConnection: 'Advanced connection',

View file

@ -13,6 +13,7 @@ import {
getApiFormat,
getApiPreset,
normalizeCardCount,
normalizeCliIdleTimeoutMs,
normalizeCliTimeoutMs,
normalizeStreamingTimeoutMs,
PROMPT_LANGUAGES,
@ -424,7 +425,13 @@ export class ParallelReaderSettingTab extends PluginSettingTab {
private renderAdvancedConnectionCli(containerEl: HTMLElement) {
const settings = this.plugin.settings;
const userChangedTimeout = !!(settings.cliTimeoutMs && settings.cliTimeoutMs !== DEFAULT_SETTINGS.cliTimeoutMs);
const details = this.openCollapsibleSection(containerEl, 'sectionAdvancedConnection', userChangedTimeout);
const userChangedIdleTimeout = !!settings.cliIdleTimeoutMs;
const userEnabledDebug = !!settings.debugLogging;
const details = this.openCollapsibleSection(
containerEl,
'sectionAdvancedConnection',
userChangedTimeout || userChangedIdleTimeout || userEnabledDebug,
);
new Setting(details)
.setName(this.tr('settingCliTimeoutName'))
.setDesc(this.tr('settingCliTimeoutDesc'))
@ -437,6 +444,29 @@ export class ParallelReaderSettingTab extends PluginSettingTab {
this.plugin.saveSettingsDebounced();
}),
);
new Setting(details)
.setName(this.tr('settingCliIdleTimeoutName'))
.setDesc(this.tr('settingCliIdleTimeoutDesc'))
.addText((t) =>
t
.setPlaceholder('0')
.setValue(String(this.plugin.settings.cliIdleTimeoutMs ?? 0))
.onChange((v) => {
this.plugin.settings.cliIdleTimeoutMs = normalizeCliIdleTimeoutMs(v);
this.plugin.saveSettingsDebounced();
}),
);
new Setting(details)
.setName(this.tr('settingDebugLoggingName'))
.setDesc(this.tr('settingDebugLoggingDesc'))
.addToggle((toggle) =>
toggle.setValue(!!this.plugin.settings.debugLogging).onChange(async (v) => {
this.plugin.settings.debugLogging = v;
await this.plugin.saveSettings();
}),
);
}
/* ---------- 4. Advanced prompt (collapsed by default) ---------- */

View file

@ -13,6 +13,7 @@ export const CACHE_SCHEMA_VERSION = 2;
export const DEFAULT_MAX_CACHE_ENTRIES = 100;
export const MIN_STREAMING_TIMEOUT_MS = 1000;
export const MIN_CLI_TIMEOUT_MS = 1000;
export const MIN_CLI_IDLE_TIMEOUT_MS = 1000;
export const PROMPT_LANGUAGES = {
zh: '中文',
en: 'English',
@ -45,8 +46,10 @@ export const DEFAULT_SETTINGS: PluginSettings = {
model: 'claude-sonnet-4-6',
exportFolder: 'Reading/Articles',
cliTimeoutMs: 120000,
cliIdleTimeoutMs: 0,
streaming: true,
streamingTimeoutMs: 120000,
debugLogging: false,
};
export const API_FORMATS: Record<string, ApiFormat> = {
@ -215,7 +218,9 @@ export function normalizeSettings(settings: Readonly<PluginSettings>): PluginSet
if (out.maxCards < out.minCards) out.maxCards = out.minCards;
out.streamingTimeoutMs = normalizeStreamingTimeoutMs(out.streamingTimeoutMs);
out.cliTimeoutMs = normalizeCliTimeoutMs(out.cliTimeoutMs);
out.cliIdleTimeoutMs = normalizeCliIdleTimeoutMs(out.cliIdleTimeoutMs);
if (typeof out.customSystemPrompt !== 'string') out.customSystemPrompt = '';
out.debugLogging = !!out.debugLogging;
return out;
}
@ -243,6 +248,14 @@ export function normalizeCliTimeoutMs(value: unknown): number {
return n;
}
export function normalizeCliIdleTimeoutMs(value: unknown): number {
const n = Math.floor(Number(value));
if (!Number.isFinite(n) || n < 0) return 0;
if (n === 0) return 0;
if (n < MIN_CLI_IDLE_TIMEOUT_MS) return 0;
return n;
}
function cacheEntryTime(entry: CacheEntry): number {
const value = entry && (entry.lastAccessedAt || entry.generatedAt || entry.updatedAt);
const timestamp = Date.parse(value || '');

View file

@ -52,6 +52,7 @@ export {
getApiBaseUrl,
modelForApi,
normalizeCardCount,
normalizeCliIdleTimeoutMs,
normalizeCliTimeoutMs,
normalizeSettings,
normalizeStreamingTimeoutMs,

View file

@ -65,8 +65,10 @@ export interface PluginSettings {
model: string;
exportFolder: string;
cliTimeoutMs: number;
cliIdleTimeoutMs: number;
streaming: boolean;
streamingTimeoutMs: number;
debugLogging: boolean;
}
/* ---------- Provider types ---------- */

View file

@ -51,13 +51,62 @@ function createFakeChild() {
async function testRunCliEdgeCases() {
const timeoutChild = createFakeChild();
timeoutChild.pid = 4242;
await assert.rejects(
() => t.runCli('fake', [], '', 5, undefined, () => timeoutChild),
/CLI timed out \(5ms\)/,
'runCli rejects on timeout',
() => {
// emit some bytes before timeout so we can verify the diagnostic suffix carries them
setImmediate(() => {
timeoutChild.stderr.emit('data', Buffer.from('boom: connection reset'));
});
return t.runCli('fake', [], '', 20, undefined, () => timeoutChild);
},
(err) => {
assert.match(err.message, /CLI timed out \(20ms\)/, 'wall-clock timeout keeps original prefix');
assert.match(err.message, /pid=4242/, 'timeout error carries pid');
assert.match(err.message, /stderr=\d+B/, 'timeout error carries stderr byte count');
assert.match(err.message, /stderr tail/, 'timeout error includes stderr tail');
assert.match(err.message, /boom: connection reset/, 'timeout error preserves last stderr line');
return true;
},
'runCli rejects on timeout with rich diagnostics',
);
assert.strictEqual(timeoutChild.killedWith, 'SIGKILL', 'runCli kills timed out processes');
// Idle timeout fires when no data within idle window even if wall clock is generous.
const idleChild = createFakeChild();
idleChild.pid = 5252;
await assert.rejects(
() => t.runCli('fake', [], '', 60000, undefined, () => idleChild, { idleTimeoutMs: 15 }),
(err) => {
assert.match(err.message, /CLI idle timeout \(15ms\)/, 'idle timeout error message');
assert.match(err.message, /pid=5252/, 'idle timeout carries pid');
return true;
},
'runCli idle timeout fires when no output',
);
assert.strictEqual(idleChild.killedWith, 'SIGKILL', 'idle timeout kills the process');
// Idle timer must reset on data — child keeps emitting and only wall clock should fire.
const heartbeatChild = createFakeChild();
let cancelHeartbeat = false;
const heartbeatPromise = t.runCli('fake', [], '', 80, undefined, () => heartbeatChild, { idleTimeoutMs: 30 });
const beat = () => {
if (cancelHeartbeat) return;
heartbeatChild.stdout.emit('data', Buffer.from('.'));
setTimeout(beat, 10);
};
beat();
await assert.rejects(
() => heartbeatPromise,
(err) => {
cancelHeartbeat = true;
assert.match(err.message, /CLI timed out \(80ms\)/, 'wall-clock fires when idle resets keep happening');
assert.doesNotMatch(err.message, /CLI idle timeout/, 'idle timeout must not fire while data flows');
return true;
},
'runCli idle timer resets on incoming data',
);
const cancelChild = createFakeChild();
let cancelHandler = null;
const cancelPromise = t.runCli(
@ -86,6 +135,28 @@ async function testRunCliEdgeCases() {
/CLI process streams are unavailable/,
'runCli reports unavailable stdio streams',
);
// Diagnostic suffix must redact secrets that show up in stderr (Bearer tokens, sk- keys, etc.)
const secretChild = createFakeChild();
secretChild.pid = 6363;
await assert.rejects(
() => {
setImmediate(() => {
secretChild.stderr.emit(
'data',
Buffer.from('Authorization: Bearer sk-ant-supersecrettoken-xyz123 failed handshake'),
);
});
return t.runCli('fake', [], '', 20, undefined, () => secretChild);
},
(err) => {
assert.doesNotMatch(err.message, /sk-ant-supersecrettoken-xyz123/, 'token must not appear verbatim');
assert.match(err.message, /\[REDACTED\]/, 'redaction marker present');
assert.match(err.message, /failed handshake/, 'non-secret context preserved');
return true;
},
'runCli timeout suffix redacts secrets',
);
}
// ── summarizeViaClaudeCode args validation ──

View file

@ -111,6 +111,19 @@ assert.strictEqual(
'normalizeSettings protects invalid cli timeout values',
);
// normalizeCliIdleTimeoutMs: 0 means disabled, anything below MIN coerces to 0, valid passes through
assert.strictEqual(t.normalizeCliIdleTimeoutMs(0), 0, 'idle timeout 0 stays disabled');
assert.strictEqual(t.normalizeCliIdleTimeoutMs(45000), 45000, 'idle timeout valid value passes through');
assert.strictEqual(t.normalizeCliIdleTimeoutMs('30000'), 30000, 'idle timeout numeric string accepted');
assert.strictEqual(t.normalizeCliIdleTimeoutMs(500), 0, 'idle timeout below 1000ms disables (treats as off)');
assert.strictEqual(t.normalizeCliIdleTimeoutMs(-1), 0, 'idle timeout negative coerces to 0');
assert.strictEqual(t.normalizeCliIdleTimeoutMs('bad'), 0, 'idle timeout non-numeric coerces to 0');
assert.strictEqual(
t.normalizeSettings({ ...baseSettings, cliIdleTimeoutMs: 250 }).cliIdleTimeoutMs,
0,
'normalizeSettings disables sub-minimum idle timeout',
);
// applyApiProviderPreset clears credentials but keeps preset baseUrl (security: prevent cross-provider key leak)
{
const previous = {