Skip to content

Commit af46a90

Browse files
authored
fix(selfhost): only escalate the final AI-provider retry attempt to Sentry (#5046) (#5048)
logSelfHostAiProviderFailed fired console.error on every subscription- CLI attempt, not just the final one -- contradicting ai-review.ts's own documented "per-attempt=warn, exhausted=error" policy (#26). GITTENSORY-K (claude_stalled_no_output) hit 2077+ events: pulled raw events sharing the same jobId/trace_id at attempt 0, 1, 2, confirming one review's 3x-retry-per-model loop was independently escalating each attempt to Sentry instead of just the exhausted outcome. Thread finalAttempt through AiRunOptions (mirroring the existing attempt/jobId correlation fields) so the provider's own log can tell a retried attempt (quiet) from a genuinely exhausted one (loud). runWorkersOpinion, the dual-AI tie-break judge, the issue planner, and the AI slop advisory all compute it as "last attempt of the last model" and pass it through. Two of those callers (planner.ts, ai-slop.ts) have no logging of their own -- their retry loops rely entirely on this log for visibility, so a blanket downgrade would have silenced them; unset stays loud by default for exactly that reason.
1 parent aa9b145 commit af46a90

5 files changed

Lines changed: 83 additions & 6 deletions

File tree

src/review/planner.ts

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -113,10 +113,14 @@ async function runPlannerModel(env: Env, system: string, user: string): Promise<
113113
if (!ai || typeof ai.run !== "function") return { text: null };
114114
const gatewayId = env.AI_GATEWAY_ID?.trim();
115115
const extra = gatewayId ? { gateway: { id: gatewayId } } : undefined;
116-
for (const model of [BEST_REVIEW_MODELS[0], RELIABLE_FALLBACK_MODELS[0]]) {
116+
const models = [BEST_REVIEW_MODELS[0], RELIABLE_FALLBACK_MODELS[0]];
117+
for (const [modelIndex, model] of models.entries()) {
117118
for (let attempt = 0; attempt < 2; attempt += 1) {
118119
try {
119-
const result = await ai.run(model, { max_tokens: PLANNER_MAX_TOKENS, temperature: 0.2, messages: [{ role: "system", content: system }, { role: "user", content: user }] }, extra);
120+
// #5046: this loop has no logging of its own -- the provider's own error log is the ONLY visibility
121+
// into a failure here, so the truly last attempt must stay Sentry-visible (finalAttempt unset/true);
122+
// every earlier attempt is about to be retried and can log quietly.
123+
const result = await ai.run(model, { max_tokens: PLANNER_MAX_TOKENS, temperature: 0.2, messages: [{ role: "system", content: system }, { role: "user", content: user }], finalAttempt: attempt === 1 && modelIndex === models.length - 1 }, extra);
120124
const text = coerceAiText(result).trim();
121125
if (text) return { text, usage: coerceAiUsage(result) };
122126
} catch {

src/selfhost/ai.ts

Lines changed: 19 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,15 @@ interface AiRunOptions {
4040
repoFullName?: string;
4141
pullNumber?: number;
4242
attempt?: number;
43+
// True (or omitted, the safe default) when this is the LAST attempt the caller's own retry loop will make —
44+
// false marks an attempt the caller is about to retry. logSelfHostAiProviderFailed uses this to log at warn
45+
// (a retried attempt is not yet a real problem) instead of error (Sentry-visible) for a non-final attempt,
46+
// matching the "per-attempt=warn, exhausted=error" policy runWorkersOpinion's OWN logging already documents
47+
// (#26) -- previously this file's error log fired on every single attempt regardless, amplifying one review's
48+
// 3x-retry-per-model into up to 6 separate Sentry events for what the caller treats as one failure (#5046).
49+
// Callers with no retry loop of their own (a single ai.run() call) leave this unset, so their one attempt IS
50+
// final and stays loud, unchanged from before this field existed.
51+
finalAttempt?: boolean;
4352
// `.gittensory.yml` `review.ai_model` (#selfhost-ai-model-override): per-repo override for the subscription
4453
// CLI providers, resolved by the caller from the repo's manifest and forwarded here so this file makes no
4554
// manifest fetch of its own. Each field is read ONLY by its matching provider's `.run()` (claude-code reads
@@ -786,10 +795,16 @@ function logSelfHostAiProviderFailed(input: {
786795
repoFullName?: string | undefined;
787796
pullNumber?: number | undefined;
788797
attempt?: number | undefined;
798+
finalAttempt?: boolean | undefined;
789799
}): void {
790-
console.error(
800+
// #5046: only the FINAL attempt of a caller's own retry loop is Sentry-visible (error); a retried attempt logs
801+
// at warn (still in Workers Logs, but not forwarded) -- explicit `false` is the only thing that quiets it, so
802+
// a single-shot caller that never sets this field keeps today's always-loud behavior.
803+
const level = input.finalAttempt === false ? "warn" : "error";
804+
const log = level === "warn" ? console.warn : console.error;
805+
log(
791806
JSON.stringify({
792-
level: "error",
807+
level,
793808
event: "selfhost_ai_provider_failed",
794809
provider: input.provider,
795810
model: input.model || "default",
@@ -884,6 +899,7 @@ export function createClaudeCodeAi(parentEnv: Record<string, string | undefined>
884899
repoFullName: options.repoFullName,
885900
pullNumber: options.pullNumber,
886901
attempt: options.attempt,
902+
finalAttempt: options.finalAttempt,
887903
});
888904
throw error;
889905
} finally {
@@ -982,6 +998,7 @@ export function createCodexAi(
982998
repoFullName: options.repoFullName,
983999
pullNumber: options.pullNumber,
9841000
attempt: options.attempt,
1001+
finalAttempt: options.finalAttempt,
9851002
});
9861003
throw error;
9871004
} finally {

src/services/ai-review.ts

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1069,6 +1069,10 @@ async function runWorkersOpinion(
10691069
...(correlation?.openaiCompatibleModel !== undefined ? { openaiCompatibleModel: correlation.openaiCompatibleModel } : {}),
10701070
...(correlation?.anthropicModel !== undefined ? { anthropicModel: correlation.anthropicModel } : {}),
10711071
attempt,
1072+
// #5046: only the truly last attempt (last model, last retry) should escalate to Sentry via the
1073+
// provider's own error log -- every earlier attempt in this loop is about to be retried, and this
1074+
// loop's own per-attempt warn below is already the correct signal for those.
1075+
finalAttempt: attempt === 2 && modelIndex === models.length - 1,
10721076
},
10731077
extra,
10741078
);
@@ -1790,6 +1794,9 @@ async function runDualAiTieBreakJudgeCall(
17901794
: {}),
17911795
...(correlation?.pullNumber !== undefined ? { pullNumber: correlation.pullNumber } : {}),
17921796
attempt,
1797+
// #5046: same reasoning as runWorkersOpinion above -- only the truly last attempt escalates the
1798+
// provider's own error log to Sentry.
1799+
finalAttempt: attempt === 2 && modelIndex === models.length - 1,
17931800
},
17941801
extra,
17951802
);

src/services/ai-slop.ts

Lines changed: 10 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -147,12 +147,20 @@ async function runWorkersSlopOpinion(env: Env, system: string, user: string, max
147147
const gatewayId = env.AI_GATEWAY_ID?.trim();
148148
const extra: AiGatewayOptions | undefined = gatewayId ? { gateway: { id: gatewayId } } : undefined;
149149
// Primary then a reliable per-slot fallback (distinct model families), 3× retry each before giving up.
150-
for (const model of WORKERS_SLOP_MODELS) {
150+
for (const [modelIndex, model] of WORKERS_SLOP_MODELS.entries()) {
151151
for (let attempt = 0; attempt < WORKERS_SLOP_ATTEMPTS_PER_MODEL; attempt += 1) {
152152
try {
153+
// #5046: this loop has no logging of its own -- the provider's own error log is the ONLY visibility
154+
// into a failure here, so the truly last attempt must stay Sentry-visible (finalAttempt unset/true);
155+
// every earlier attempt is about to be retried and can log quietly.
153156
const result = await ai.run(
154157
model,
155-
{ max_tokens: maxTokens, temperature: 0, messages: [{ role: "system", content: system }, { role: "user", content: user }] },
158+
{
159+
max_tokens: maxTokens,
160+
temperature: 0,
161+
messages: [{ role: "system", content: system }, { role: "user", content: user }],
162+
finalAttempt: attempt === WORKERS_SLOP_ATTEMPTS_PER_MODEL - 1 && modelIndex === WORKERS_SLOP_MODELS.length - 1,
163+
},
156164
extra,
157165
);
158166
const parsed = parseSlopOpinion(coerceAiText(result));

test/unit/selfhost-ai.test.ts

Lines changed: 41 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -472,6 +472,47 @@ describe("createChainAi (fallback)", () => {
472472
expect(logged.attempt).toBeUndefined();
473473
errorSpy.mockRestore();
474474
});
475+
476+
it("REGRESSION (#5046): finalAttempt:false logs the provider failure at warn, not error (a retried attempt is not yet Sentry-worthy)", async () => {
477+
const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {});
478+
const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {});
479+
const failing: StubSpawn = async () => ({ stdout: "", code: 1, stderr: "transient" });
480+
481+
await expect(createClaudeCodeAi({ CLAUDE_CODE_OAUTH_TOKEN: "t" }, failing).run("m", { prompt: "x", attempt: 0, finalAttempt: false })).rejects.toThrow();
482+
483+
expect(errorSpy).not.toHaveBeenCalled();
484+
const logged = JSON.parse(String(warnSpy.mock.calls[0]?.[0]));
485+
expect(logged).toMatchObject({ level: "warn", event: "selfhost_ai_provider_failed", attempt: 0 });
486+
errorSpy.mockRestore();
487+
warnSpy.mockRestore();
488+
});
489+
490+
it("REGRESSION (#5046): finalAttempt:true (the exhausted attempt) still logs the provider failure at error", async () => {
491+
const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {});
492+
const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {});
493+
const failing: StubSpawn = async () => ({ stdout: "", code: 1, stderr: "final" });
494+
495+
await expect(createClaudeCodeAi({ CLAUDE_CODE_OAUTH_TOKEN: "t" }, failing).run("m", { prompt: "x", attempt: 2, finalAttempt: true })).rejects.toThrow();
496+
497+
expect(warnSpy).not.toHaveBeenCalled();
498+
const logged = JSON.parse(String(errorSpy.mock.calls[0]?.[0]));
499+
expect(logged).toMatchObject({ level: "error", event: "selfhost_ai_provider_failed", attempt: 2 });
500+
errorSpy.mockRestore();
501+
warnSpy.mockRestore();
502+
});
503+
504+
it("REGRESSION (#5046): a single-shot caller that never sets finalAttempt keeps today's always-loud behavior", async () => {
505+
const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {});
506+
const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {});
507+
const failing: StubSpawn = async () => ({ stdout: "", code: 1, stderr: "single shot" });
508+
509+
await expect(createClaudeCodeAi({ CLAUDE_CODE_OAUTH_TOKEN: "t" }, failing).run("m", { prompt: "x" })).rejects.toThrow();
510+
511+
expect(warnSpy).not.toHaveBeenCalled();
512+
expect(errorSpy).toHaveBeenCalledTimes(1);
513+
errorSpy.mockRestore();
514+
warnSpy.mockRestore();
515+
});
475516
});
476517

477518
describe("AI provider request duration/error metrics (#4367)", () => {

0 commit comments

Comments
 (0)