diff --git a/src/review/planner.ts b/src/review/planner.ts index d47140caa8..3959cfa4fd 100644 --- a/src/review/planner.ts +++ b/src/review/planner.ts @@ -113,10 +113,14 @@ async function runPlannerModel(env: Env, system: string, user: string): Promise< if (!ai || typeof ai.run !== "function") return { text: null }; const gatewayId = env.AI_GATEWAY_ID?.trim(); const extra = gatewayId ? { gateway: { id: gatewayId } } : undefined; - for (const model of [BEST_REVIEW_MODELS[0], RELIABLE_FALLBACK_MODELS[0]]) { + const models = [BEST_REVIEW_MODELS[0], RELIABLE_FALLBACK_MODELS[0]]; + for (const [modelIndex, model] of models.entries()) { for (let attempt = 0; attempt < 2; attempt += 1) { try { - const result = await ai.run(model, { max_tokens: PLANNER_MAX_TOKENS, temperature: 0.2, messages: [{ role: "system", content: system }, { role: "user", content: user }] }, extra); + // #5046: this loop has no logging of its own -- the provider's own error log is the ONLY visibility + // into a failure here, so the truly last attempt must stay Sentry-visible (finalAttempt unset/true); + // every earlier attempt is about to be retried and can log quietly. + 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); const text = coerceAiText(result).trim(); if (text) return { text, usage: coerceAiUsage(result) }; } catch { diff --git a/src/selfhost/ai.ts b/src/selfhost/ai.ts index 8e0106aff2..d0e39c5a50 100644 --- a/src/selfhost/ai.ts +++ b/src/selfhost/ai.ts @@ -40,6 +40,15 @@ interface AiRunOptions { repoFullName?: string; pullNumber?: number; attempt?: number; + // True (or omitted, the safe default) when this is the LAST attempt the caller's own retry loop will make — + // false marks an attempt the caller is about to retry. logSelfHostAiProviderFailed uses this to log at warn + // (a retried attempt is not yet a real problem) instead of error (Sentry-visible) for a non-final attempt, + // matching the "per-attempt=warn, exhausted=error" policy runWorkersOpinion's OWN logging already documents + // (#26) -- previously this file's error log fired on every single attempt regardless, amplifying one review's + // 3x-retry-per-model into up to 6 separate Sentry events for what the caller treats as one failure (#5046). + // Callers with no retry loop of their own (a single ai.run() call) leave this unset, so their one attempt IS + // final and stays loud, unchanged from before this field existed. + finalAttempt?: boolean; // `.gittensory.yml` `review.ai_model` (#selfhost-ai-model-override): per-repo override for the subscription // CLI providers, resolved by the caller from the repo's manifest and forwarded here so this file makes no // 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: { repoFullName?: string | undefined; pullNumber?: number | undefined; attempt?: number | undefined; + finalAttempt?: boolean | undefined; }): void { - console.error( + // #5046: only the FINAL attempt of a caller's own retry loop is Sentry-visible (error); a retried attempt logs + // at warn (still in Workers Logs, but not forwarded) -- explicit `false` is the only thing that quiets it, so + // a single-shot caller that never sets this field keeps today's always-loud behavior. + const level = input.finalAttempt === false ? "warn" : "error"; + const log = level === "warn" ? console.warn : console.error; + log( JSON.stringify({ - level: "error", + level, event: "selfhost_ai_provider_failed", provider: input.provider, model: input.model || "default", @@ -884,6 +899,7 @@ export function createClaudeCodeAi(parentEnv: Record repoFullName: options.repoFullName, pullNumber: options.pullNumber, attempt: options.attempt, + finalAttempt: options.finalAttempt, }); throw error; } finally { @@ -982,6 +998,7 @@ export function createCodexAi( repoFullName: options.repoFullName, pullNumber: options.pullNumber, attempt: options.attempt, + finalAttempt: options.finalAttempt, }); throw error; } finally { diff --git a/src/services/ai-review.ts b/src/services/ai-review.ts index 62c12d4884..6b164bb80d 100644 --- a/src/services/ai-review.ts +++ b/src/services/ai-review.ts @@ -1069,6 +1069,10 @@ async function runWorkersOpinion( ...(correlation?.openaiCompatibleModel !== undefined ? { openaiCompatibleModel: correlation.openaiCompatibleModel } : {}), ...(correlation?.anthropicModel !== undefined ? { anthropicModel: correlation.anthropicModel } : {}), attempt, + // #5046: only the truly last attempt (last model, last retry) should escalate to Sentry via the + // provider's own error log -- every earlier attempt in this loop is about to be retried, and this + // loop's own per-attempt warn below is already the correct signal for those. + finalAttempt: attempt === 2 && modelIndex === models.length - 1, }, extra, ); @@ -1790,6 +1794,9 @@ async function runDualAiTieBreakJudgeCall( : {}), ...(correlation?.pullNumber !== undefined ? { pullNumber: correlation.pullNumber } : {}), attempt, + // #5046: same reasoning as runWorkersOpinion above -- only the truly last attempt escalates the + // provider's own error log to Sentry. + finalAttempt: attempt === 2 && modelIndex === models.length - 1, }, extra, ); diff --git a/src/services/ai-slop.ts b/src/services/ai-slop.ts index 3062750802..7241eab007 100644 --- a/src/services/ai-slop.ts +++ b/src/services/ai-slop.ts @@ -147,12 +147,20 @@ async function runWorkersSlopOpinion(env: Env, system: string, user: string, max const gatewayId = env.AI_GATEWAY_ID?.trim(); const extra: AiGatewayOptions | undefined = gatewayId ? { gateway: { id: gatewayId } } : undefined; // Primary then a reliable per-slot fallback (distinct model families), 3× retry each before giving up. - for (const model of WORKERS_SLOP_MODELS) { + for (const [modelIndex, model] of WORKERS_SLOP_MODELS.entries()) { for (let attempt = 0; attempt < WORKERS_SLOP_ATTEMPTS_PER_MODEL; attempt += 1) { try { + // #5046: this loop has no logging of its own -- the provider's own error log is the ONLY visibility + // into a failure here, so the truly last attempt must stay Sentry-visible (finalAttempt unset/true); + // every earlier attempt is about to be retried and can log quietly. const result = await ai.run( model, - { max_tokens: maxTokens, temperature: 0, messages: [{ role: "system", content: system }, { role: "user", content: user }] }, + { + max_tokens: maxTokens, + temperature: 0, + messages: [{ role: "system", content: system }, { role: "user", content: user }], + finalAttempt: attempt === WORKERS_SLOP_ATTEMPTS_PER_MODEL - 1 && modelIndex === WORKERS_SLOP_MODELS.length - 1, + }, extra, ); const parsed = parseSlopOpinion(coerceAiText(result)); diff --git a/test/unit/selfhost-ai.test.ts b/test/unit/selfhost-ai.test.ts index 9919df867c..2b5f3102fa 100644 --- a/test/unit/selfhost-ai.test.ts +++ b/test/unit/selfhost-ai.test.ts @@ -472,6 +472,47 @@ describe("createChainAi (fallback)", () => { expect(logged.attempt).toBeUndefined(); errorSpy.mockRestore(); }); + + it("REGRESSION (#5046): finalAttempt:false logs the provider failure at warn, not error (a retried attempt is not yet Sentry-worthy)", async () => { + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {}); + const failing: StubSpawn = async () => ({ stdout: "", code: 1, stderr: "transient" }); + + await expect(createClaudeCodeAi({ CLAUDE_CODE_OAUTH_TOKEN: "t" }, failing).run("m", { prompt: "x", attempt: 0, finalAttempt: false })).rejects.toThrow(); + + expect(errorSpy).not.toHaveBeenCalled(); + const logged = JSON.parse(String(warnSpy.mock.calls[0]?.[0])); + expect(logged).toMatchObject({ level: "warn", event: "selfhost_ai_provider_failed", attempt: 0 }); + errorSpy.mockRestore(); + warnSpy.mockRestore(); + }); + + it("REGRESSION (#5046): finalAttempt:true (the exhausted attempt) still logs the provider failure at error", async () => { + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {}); + const failing: StubSpawn = async () => ({ stdout: "", code: 1, stderr: "final" }); + + await expect(createClaudeCodeAi({ CLAUDE_CODE_OAUTH_TOKEN: "t" }, failing).run("m", { prompt: "x", attempt: 2, finalAttempt: true })).rejects.toThrow(); + + expect(warnSpy).not.toHaveBeenCalled(); + const logged = JSON.parse(String(errorSpy.mock.calls[0]?.[0])); + expect(logged).toMatchObject({ level: "error", event: "selfhost_ai_provider_failed", attempt: 2 }); + errorSpy.mockRestore(); + warnSpy.mockRestore(); + }); + + it("REGRESSION (#5046): a single-shot caller that never sets finalAttempt keeps today's always-loud behavior", async () => { + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {}); + const failing: StubSpawn = async () => ({ stdout: "", code: 1, stderr: "single shot" }); + + await expect(createClaudeCodeAi({ CLAUDE_CODE_OAUTH_TOKEN: "t" }, failing).run("m", { prompt: "x" })).rejects.toThrow(); + + expect(warnSpy).not.toHaveBeenCalled(); + expect(errorSpy).toHaveBeenCalledTimes(1); + errorSpy.mockRestore(); + warnSpy.mockRestore(); + }); }); describe("AI provider request duration/error metrics (#4367)", () => {