Skip to content

Commit 445c9fc

Browse files
authored
fix(review): add a stalled-no-output fast-fail deadline for claude-code (#5013)
claude-code never got the same firstOutputTimeoutMs/stalledNoOutput fast-fail mechanism codex already has (added for the original GITTENSORY-K/M dead-air hang) -- deliberately, on the belief at the time that claude-code had no comparable prod-observed hang. That premise is now stale: subscription_cli_timeout for provider=claude-code accumulated 4,030+ events over 12 days, ongoing. Mirror codex's proven pattern: a separate, shorter deadline (default 30s, independently configurable via CLAUDE_AI_FIRST_OUTPUT_TIMEOUT_MS) that only fires when stdout has produced zero bytes, distinct from a genuine full-timeout. Closes #4994
1 parent 51208ce commit 445c9fc

4 files changed

Lines changed: 118 additions & 11 deletions

File tree

apps/gittensory-ui/src/lib/selfhost-env-reference.ts

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -85,6 +85,10 @@ export const SELFHOST_ENV_REFERENCE_ROWS: SelfHostEnvReferenceRow[] = [
8585
name: "CLAUDE_AI_EFFORT",
8686
firstReference: "src/selfhost/ai.ts",
8787
},
88+
{
89+
name: "CLAUDE_AI_FIRST_OUTPUT_TIMEOUT_MS",
90+
firstReference: "src/selfhost/ai.ts",
91+
},
8892
{
8993
name: "CLAUDE_AI_MODEL",
9094
firstReference: "src/selfhost/ai.ts",
@@ -482,6 +486,7 @@ export const SELFHOST_ENV_REFERENCE_MARKDOWN = [
482486
"| `BACKUP_ACKNOWLEDGED` | `src/server.ts` |",
483487
"| `BROWSER_WS_ENDPOINT` | `src/selfhost/stubs/puppeteer.ts` |",
484488
"| `CLAUDE_AI_EFFORT` | `src/selfhost/ai.ts` |",
489+
"| `CLAUDE_AI_FIRST_OUTPUT_TIMEOUT_MS` | `src/selfhost/ai.ts` |",
485490
"| `CLAUDE_AI_MODEL` | `src/selfhost/ai.ts` |",
486491
"| `CLAUDE_AI_TIMEOUT_MS` | `src/selfhost/ai.ts` |",
487492
"| `CLOUDFLARE_D1_MONITOR_ACCOUNT_ID` | `src/selfhost/d1-size-probe.ts` |",

src/env.d.ts

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -102,9 +102,13 @@ declare global {
102102
CLAUDE_AI_MODEL?: string;
103103
CLAUDE_AI_EFFORT?: string;
104104
CLAUDE_AI_TIMEOUT_MS?: string;
105+
/** Fast-fail deadline for a stalled-no-output claude-code subprocess (#4994) — see resolveClaudeFirstOutputTimeoutMs. */
106+
CLAUDE_AI_FIRST_OUTPUT_TIMEOUT_MS?: string;
105107
CODEX_AI_MODEL?: string;
106108
CODEX_AI_EFFORT?: string;
107109
CODEX_AI_TIMEOUT_MS?: string;
110+
/** Fast-fail deadline for a stalled-no-output codex subprocess (#codex-first-output-timeout) — see resolveCodexFirstOutputTimeoutMs. */
111+
CODEX_AI_FIRST_OUTPUT_TIMEOUT_MS?: string;
108112
OLLAMA_AI_BASE_URL?: string;
109113
OLLAMA_AI_API_KEY?: string;
110114
OLLAMA_AI_MODEL?: string;

src/selfhost/ai.ts

Lines changed: 33 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -227,6 +227,19 @@ export function resolveCodexFirstOutputTimeoutMs(env: Record<string, string | un
227227
return 30_000;
228228
}
229229

230+
// #4994: the SAME fast-fail deadline as resolveCodexFirstOutputTimeoutMs above, for the claude-code CLI. When this
231+
// pattern was first built (#codex-first-output-timeout), Claude Code had no prod-observed dead-air hang, so it was
232+
// deliberately left unwired for that provider (see the historical rationale that used to live on SpawnFn's
233+
// `firstOutputTimeoutMs` field). That premise is now stale: `selfhost_ai_provider_failed: subscription_cli_timeout`
234+
// for `provider: claude-code` accumulated 4,030+ events over 12 days in production (GITTENSORY-K/M/8/Z), the exact
235+
// shape this mechanism exists to catch and distinguish from a genuine full-timeout. Same bounds/defaults as Codex's
236+
// version for consistency; independent env var so either CLI's deadline can be tuned without affecting the other.
237+
export function resolveClaudeFirstOutputTimeoutMs(env: Record<string, string | undefined>): number {
238+
const raw = Number(firstConfigured(env.CLAUDE_AI_FIRST_OUTPUT_TIMEOUT_MS));
239+
if (Number.isFinite(raw) && raw > 0) return Math.min(120_000, Math.max(1_000, raw));
240+
return 30_000;
241+
}
242+
230243
/** Read the per-call repo override matching this provider variant (#3902) -- ollama/openai/openai-compatible
231244
* each have their OWN `.gittensory.yml` field, so a bare `options.model`-style single field would collide
232245
* across variants sharing this one function. `firstConfigured` gives the repo override priority over the
@@ -646,11 +659,12 @@ type SpawnFn = (
646659
input?: string;
647660
timeoutMs: number;
648661
cwd?: string;
649-
// Optional, generic on SpawnFn (not codex-specific) so any CLI whose real progress lands on STDOUT (not
650-
// stderr banners/logs) could opt in later — but ONLY codex wires it up today (see
651-
// resolveCodexFirstOutputTimeoutMs): Claude Code has no comparable prod-observed dead-air hang, so leaving
652-
// this undefined for that caller keeps its spawn path byte-identical to before this option existed. See the
653-
// stdout-only rationale on the timer construction below — this deadline is cleared by stdout data ONLY.
662+
// Optional, generic on SpawnFn so any CLI whose real progress lands on STDOUT (not stderr banners/logs) can
663+
// opt in. Originally codex-only (resolveCodexFirstOutputTimeoutMs) — claude-code was deliberately left
664+
// unwired on the belief it had no comparable dead-air hang, until GITTENSORY-K/M/8/Z (#4994) proved that
665+
// premise stale (4,030+ subscription_cli_timeout events). Both CLI providers wire this up now
666+
// (resolveCodexFirstOutputTimeoutMs / resolveClaudeFirstOutputTimeoutMs). See the stdout-only rationale on
667+
// the timer construction below — this deadline is cleared by stdout data ONLY.
654668
firstOutputTimeoutMs?: number;
655669
},
656670
) => Promise<{ stdout: string; code: number | null; stderr?: string; timedOut?: boolean; stalledNoOutput?: boolean }>;
@@ -794,6 +808,10 @@ export function createClaudeCodeAi(parentEnv: Record<string, string | undefined>
794808
const claudeModel = resolveModel(configuredClaudeModel(parentEnv, options.claudeModel), model, "claude-sonnet-5");
795809
const effort = resolveEffort(firstConfigured(options.claudeEffort, parentEnv.CLAUDE_AI_EFFORT));
796810
const timeoutMs = resolveClaudeCliTimeoutMs(parentEnv);
811+
// #4994: same clamp reasoning as createCodexAi's identical line — keeps the fast-fail deadline strictly
812+
// below the full timeout even if a low CLAUDE_AI_TIMEOUT_MS override (floor 30_000ms) would otherwise let
813+
// them collide, which would make the "outer" timeout unreachable and defeat having two distinct signals.
814+
const firstOutputTimeoutMs = Math.min(resolveClaudeFirstOutputTimeoutMs(parentEnv), Math.max(1, timeoutMs - 1));
797815
let attempted = false;
798816
let stdoutForMetrics = "";
799817
try {
@@ -820,12 +838,20 @@ export function createClaudeCodeAi(parentEnv: Record<string, string | undefined>
820838
const spawn = spawnImpl ?? (await defaultSpawn());
821839
const args = ["--print", "--output-format", "json", "--model", claudeModel, "--permission-mode", "plan", "--effort", effort, "--disallowedTools", "Bash,Edit,Write,WebFetch,WebSearch"];
822840
attempted = true;
823-
const { stdout, code, stderr, timedOut } = await spawn(
841+
const { stdout, code, stderr, timedOut, stalledNoOutput } = await spawn(
824842
"claude",
825843
args,
826-
{ env, input: prompt, timeoutMs, cwd: await isolatedCliCwd() },
844+
{ env, input: prompt, timeoutMs, firstOutputTimeoutMs, cwd: await isolatedCliCwd() },
827845
);
828846
stdoutForMetrics = stdout;
847+
if (timedOut && stalledNoOutput) {
848+
// Fast-fail path (#4994, GITTENSORY-K/M/8/Z), mirrors createCodexAi's identical stalled-no-output
849+
// branch: killed at firstOutputTimeoutMs, well before the full timeoutMs, because STDOUT produced no
850+
// bytes at all. A distinct error (never reusing `subscription_cli_timeout`) so this fast-fail is
851+
// separately countable in Sentry/logs from a genuine full-timeout where the process was at least
852+
// emitting output before it was killed.
853+
throw new Error("claude_stalled_no_output: no stdout within firstOutputTimeoutMs — claude likely hung");
854+
}
829855
if (timedOut) throw new Error("subscription_cli_timeout");
830856
// Surface the STRUCTURED error envelope FIRST. `claude --output-format json` reports API/auth/model errors in its
831857
// stdout JSON ({is_error,api_error_status}) on a NON-ZERO exit too — e.g. an unknown model exits 1 with the 404

test/unit/selfhost-ai.test.ts

Lines changed: 76 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,7 @@ import { chmodSync, mkdirSync, mkdtempSync, writeFileSync } from "node:fs";
22
import { tmpdir } from "node:os";
33
import { delimiter, join } from "node:path";
44
import { afterEach, describe, expect, it, vi } from "vitest";
5-
import { assertNoLegacySharedAiEnv, buildProvider, claudeErrorStatus, codexErrorFromStdout, createAnthropicAi, createChainAi, createClaudeCodeAi, createCodexAi, createOpenAiCompatibleAi, createSelfHostAi, extractCliText, extractCliUsage, isAiProviderHealthy, markAiProviderUnhealthyAtBoot, resetAiProviderCircuitBreakerForTest, resetAiProviderHealthForTest, resolveAiReviewerPlan, resolveClaudeCliTimeoutMs, resolveCodexAuthPath, resolveCodexCliTimeoutMs, resolveCodexEffort, resolveCodexFirstOutputTimeoutMs, resolveEffort, resolveModel, resolveProviderNames, resolveRequiredCliProviders, resolveSubscriptionCliPath, redactSecrets, routeProviders, shouldMarkAiProviderUnhealthyAtBoot, subscriptionCliEnv, withAdvisoryAiEnv } from "../../src/selfhost/ai";
5+
import { assertNoLegacySharedAiEnv, buildProvider, claudeErrorStatus, codexErrorFromStdout, createAnthropicAi, createChainAi, createClaudeCodeAi, createCodexAi, createOpenAiCompatibleAi, createSelfHostAi, extractCliText, extractCliUsage, isAiProviderHealthy, markAiProviderUnhealthyAtBoot, resetAiProviderCircuitBreakerForTest, resetAiProviderHealthForTest, resolveAiReviewerPlan, resolveClaudeCliTimeoutMs, resolveClaudeFirstOutputTimeoutMs, resolveCodexAuthPath, resolveCodexCliTimeoutMs, resolveCodexEffort, resolveCodexFirstOutputTimeoutMs, resolveEffort, resolveModel, resolveProviderNames, resolveRequiredCliProviders, resolveSubscriptionCliPath, redactSecrets, routeProviders, shouldMarkAiProviderUnhealthyAtBoot, subscriptionCliEnv, withAdvisoryAiEnv } from "../../src/selfhost/ai";
66
import { labelSelfHostReviewerModel, labelSelfHostReviewerModels } from "../../src/selfhost/ai-config";
77
import { renderMetrics, resetMetrics } from "../../src/selfhost/metrics";
88

@@ -78,6 +78,22 @@ describe("provider-specific CLI timeouts (#selfhost — no shared timeout ambigu
7878
// zero/negative also falls back (raw > 0 false branch)
7979
expect(resolveCodexFirstOutputTimeoutMs({ CODEX_AI_FIRST_OUTPUT_TIMEOUT_MS: "0" })).toBe(30_000);
8080
});
81+
it("resolveClaudeFirstOutputTimeoutMs defaults to 30s, is independent of effort, and honors + clamps CLAUDE_AI_FIRST_OUTPUT_TIMEOUT_MS (#4994)", () => {
82+
// absent → the 30s default (?? right side)
83+
expect(resolveClaudeFirstOutputTimeoutMs({})).toBe(30_000);
84+
// effort must NOT scale this deadline — a slow COMPLETION is not a slow first byte.
85+
expect(resolveClaudeFirstOutputTimeoutMs({ CLAUDE_AI_EFFORT: "max" })).toBe(30_000);
86+
// present + valid → honored verbatim (?? left side, within bounds)
87+
expect(resolveClaudeFirstOutputTimeoutMs({ CLAUDE_AI_FIRST_OUTPUT_TIMEOUT_MS: "15000" })).toBe(15_000);
88+
// clamped to the 1s floor
89+
expect(resolveClaudeFirstOutputTimeoutMs({ CLAUDE_AI_FIRST_OUTPUT_TIMEOUT_MS: "1" })).toBe(1_000);
90+
// clamped to the 120s ceiling (well under the shortest full timeout, 120_000ms)
91+
expect(resolveClaudeFirstOutputTimeoutMs({ CLAUDE_AI_FIRST_OUTPUT_TIMEOUT_MS: "999999" })).toBe(120_000);
92+
// non-finite/garbage falls back to the default (Number.isFinite false branch)
93+
expect(resolveClaudeFirstOutputTimeoutMs({ CLAUDE_AI_FIRST_OUTPUT_TIMEOUT_MS: "not-a-number" })).toBe(30_000);
94+
// zero/negative also falls back (raw > 0 false branch)
95+
expect(resolveClaudeFirstOutputTimeoutMs({ CLAUDE_AI_FIRST_OUTPUT_TIMEOUT_MS: "0" })).toBe(30_000);
96+
});
8197
});
8298

8399
afterEach(() => {
@@ -1348,6 +1364,35 @@ describe("subscription CLI helpers + fail-safe", () => {
13481364
}
13491365
});
13501366

1367+
// REGRESSION (GITTENSORY-K/M/8/Z, #4994): the real defaultSpawn fast-fail path against a genuinely-hung fake
1368+
// `claude` that writes nothing to either stream and never exits — mirrors the identical codex real-subprocess
1369+
// test below, proving createClaudeCodeAi's plumbing (not just a stubbed spawn) actually wires
1370+
// firstOutputTimeoutMs through to the shared defaultSpawn timer logic.
1371+
it("REAL subprocess: a fake claude that never writes to either stream is killed at the fast-fail deadline, not the full timeout", async () => {
1372+
const dir = mkdtempSync(join(tmpdir(), "fakecli-"));
1373+
const fake = join(dir, "claude");
1374+
writeFileSync(fake, "#!/usr/bin/env node\nprocess.stdin.on('data',()=>{});\nsetInterval(()=>{},1000);\n");
1375+
chmodSync(fake, 0o755);
1376+
const origPath = process.env.PATH;
1377+
try {
1378+
const start = Date.now();
1379+
await expect(
1380+
createClaudeCodeAi({
1381+
PATH: `${dir}:${origPath ?? ""}`,
1382+
CLAUDE_CODE_OAUTH_TOKEN: "t",
1383+
// Full timeout stays large (60s) so a false-pass (hitting the FULL timeout instead of the fast one)
1384+
// would make this test hang for a minute rather than silently succeed for the wrong reason.
1385+
CLAUDE_AI_TIMEOUT_MS: "60000",
1386+
CLAUDE_AI_FIRST_OUTPUT_TIMEOUT_MS: "200",
1387+
}).run("sonnet", { prompt: "hello" }),
1388+
).rejects.toThrow(/claude_stalled_no_output/);
1389+
// Killed at ~200ms (the fast-fail deadline), nowhere near the 60_000ms full timeout.
1390+
expect(Date.now() - start).toBeLessThan(5_000);
1391+
} finally {
1392+
process.env.PATH = origPath;
1393+
}
1394+
}, 10_000);
1395+
13511396
it("drives the REAL subprocess (defaultSpawn) against a fake `codex` on PATH", async () => {
13521397
const dir = mkdtempSync(join(tmpdir(), "fakecli-"));
13531398
const fake = join(dir, "codex");
@@ -1540,6 +1585,32 @@ describe("subscription CLI helpers + fail-safe", () => {
15401585
);
15411586
});
15421587

1588+
it("REGRESSION (GITTENSORY-K/M/8/Z, #4994): a stalled-no-output timeout is thrown as claude_stalled_no_output, distinct from subscription_cli_timeout, and passes firstOutputTimeoutMs through to spawn", async () => {
1589+
let capturedOpts: { timeoutMs: number; firstOutputTimeoutMs?: number } | undefined;
1590+
const stalled: StubSpawn = async (_cmd, _args, o) => {
1591+
capturedOpts = o;
1592+
return { stdout: "", code: null, stderr: "", timedOut: true, stalledNoOutput: true };
1593+
};
1594+
await expect(createClaudeCodeAi({ CLAUDE_CODE_OAUTH_TOKEN: "t" }, stalled).run("m", { prompt: "x" })).rejects.toThrow(
1595+
/claude_stalled_no_output/,
1596+
);
1597+
// Never the generic message — the whole point is that these two failure modes are separately observable.
1598+
await expect(createClaudeCodeAi({ CLAUDE_CODE_OAUTH_TOKEN: "t" }, stalled).run("m", { prompt: "x" })).rejects.not.toThrow(
1599+
/^subscription_cli_timeout/,
1600+
);
1601+
// The fast-fail deadline defaults to 30s and is strictly less than the (180s-default) full timeout.
1602+
expect(capturedOpts?.firstOutputTimeoutMs).toBe(30_000);
1603+
expect(capturedOpts?.timeoutMs).toBe(180_000);
1604+
expect(capturedOpts?.firstOutputTimeoutMs).toBeLessThan(capturedOpts!.timeoutMs);
1605+
});
1606+
1607+
it("a full timeout WITHOUT stalledNoOutput still throws the generic subscription_cli_timeout, not claude_stalled_no_output (some output was produced before the kill)", async () => {
1608+
const timedOutWithOutput: StubSpawn = async () => ({ stdout: "partial output before kill", code: null, timedOut: true, stalledNoOutput: false });
1609+
await expect(createClaudeCodeAi({ CLAUDE_CODE_OAUTH_TOKEN: "t" }, timedOutWithOutput).run("m", { prompt: "x" })).rejects.toThrow(
1610+
/^subscription_cli_timeout$/,
1611+
);
1612+
});
1613+
15431614
it("REGRESSION (GITTENSORY-K/GITTENSORY-M): a stalled-no-output timeout is thrown as codex_stalled_no_output, distinct from codex_timeout, and passes firstOutputTimeoutMs through to spawn", async () => {
15441615
let capturedOpts: { timeoutMs: number; firstOutputTimeoutMs?: number } | undefined;
15451616
const stalled: StubSpawn = async (_cmd, _args, o) => {
@@ -1768,7 +1839,7 @@ describe("subscription CLI helpers + fail-safe", () => {
17681839
}
17691840
});
17701841

1771-
it("defaultSpawn's spawn-error handler clears whichever timers were actually armed — firstOutputTimer present (codex) vs absent (claude-code)", async () => {
1842+
it("defaultSpawn's spawn-error handler clears the firstOutputTimer for both providers (#4994: both now arm one)", async () => {
17721843
// Explicit env (no ambient CODEX_HOME / GITTENSORY_ENABLE_UNSAFE_CODEX_REVIEWER inherited from the operator's
17731844
// shell) so this reaches the REAL ENOENT spawn error deterministically, rather than short-circuiting on the
17741845
// credential-isolation guard the way an ambient CODEX_HOME would.
@@ -1778,8 +1849,9 @@ describe("subscription CLI helpers + fail-safe", () => {
17781849
{ prompt: "x" },
17791850
),
17801851
).rejects.toThrow(/ENOENT/);
1781-
// Claude Code never sets firstOutputTimeoutMs (no comparable prod hang), so this exercises the SAME spawn()
1782-
// error path's firstOutputTimer-ABSENT branch — the option is simply never passed for this provider.
1852+
// Claude Code now also passes firstOutputTimeoutMs (#4994) — this exercises the SAME spawn() error path's
1853+
// firstOutputTimer-PRESENT branch for claude too, proving the error handler clears it cleanly (no leaked
1854+
// timer, no unhandled rejection) rather than only ever having been exercised via codex.
17831855
await expect(
17841856
createClaudeCodeAi({ PATH: "/nonexistent-gittensory-empty", CLAUDE_CODE_OAUTH_TOKEN: "t" }).run("sonnet", { prompt: "x" }),
17851857
).rejects.toThrow(/ENOENT/);

0 commit comments

Comments
 (0)