diff --git a/src/__tests__/baselines/source-function-lines.json b/src/__tests__/baselines/source-function-lines.json index 16c5b2580..63482ba8e 100644 --- a/src/__tests__/baselines/source-function-lines.json +++ b/src/__tests__/baselines/source-function-lines.json @@ -1,7 +1,7 @@ { "$comment": "Production functions over 200 lines, keyed \"file :: name\", and their length. Maintained by src/__tests__/source-size-ratchet.test.ts.", "count": 350, - "total": 113326, + "total": 113317, "entries": { "app/achievements/page.tsx :: AchievementsPage": 206, "app/api/admin/backups/upload/route.ts :: apiHandler(arg)": 314, @@ -297,7 +297,7 @@ "lib/insights/comprehensive-generate.ts :: generateComprehensiveInsight": 876, "lib/insights/features.ts :: extractFeatures": 796, "lib/insights/mood-aggregates.ts :: fetchMoodAggregates": 246, - "lib/insights/status-provider.ts :: runStatusCompletion": 224, + "lib/insights/status-provider.ts :: runStatusCompletion": 215, "lib/integrations/connection-health-load.ts :: loadConnectionFacts": 227, "lib/integrations/status.ts :: recordSyncFailure": 292, "lib/jobs/apple-health-import-worker.ts :: handleAppleHealthImport": 300, diff --git a/src/__tests__/baselines/version-stamp-comments.json b/src/__tests__/baselines/version-stamp-comments.json index c2c255493..2892e75da 100644 --- a/src/__tests__/baselines/version-stamp-comments.json +++ b/src/__tests__/baselines/version-stamp-comments.json @@ -1,7 +1,7 @@ { "$comment": "Comment lines that open with a release version, per file under src/. Maintained by src/__tests__/version-stamp-ratchet.test.ts.", "count": 2897, - "total": 9262, + "total": 9259, "entries": { "__tests__/account-payload-consumer-guard.test.ts": 2, "__tests__/acting-account-boundary-guard.test.ts": 7, @@ -1783,7 +1783,7 @@ "lib/ai/prompts/weight.ts": 2, "lib/ai/provider-chain.ts": 1, "lib/ai/provider-health-ledger.ts": 3, - "lib/ai/provider-runner.ts": 14, + "lib/ai/provider-runner.ts": 11, "lib/ai/provider.ts": 10, "lib/ai/reasoning/__tests__/controls.test.ts": 1, "lib/ai/reasoning/controls.ts": 2, diff --git a/src/lib/ai/__tests__/provider-runner-background-bench.test.ts b/src/lib/ai/__tests__/provider-runner-background-bench.test.ts index 976b546b4..e17e9c558 100644 --- a/src/lib/ai/__tests__/provider-runner-background-bench.test.ts +++ b/src/lib/ai/__tests__/provider-runner-background-bench.test.ts @@ -111,6 +111,19 @@ describe("#1279: background work and a benched provider", () => { ]); } expect(gateway.calls).toBe(HARD_FAILURE_SKIP_THRESHOLD); + // The bench sent nothing; a hop that reached the provider did. + const benched = await walk( + "job", + "u-bench", + "openai-compatible", + gateway, + ledger, + ).then( + () => null, + (e: unknown) => e, + ); + expect(benched).toBeInstanceOf(AllProvidersFailedError); + expect((benched as AllProvidersFailedError).sentNothing).toBe(true); // One line for the window, not one per job. expect(signals("ai.chain.background_paused")).toHaveLength(1); expect(signals("ai.chain.background_paused")[0].meta).toMatchObject({ @@ -139,6 +152,7 @@ describe("#1279: background work and a benched provider", () => { expect((err as AllProvidersFailedError).attempts[0].failureKind).toBe( "reasoning_only", ); + expect((err as AllProvidersFailedError).sentNothing).toBe(false); }); it("walks the benched provider for a job-rationed call a person waits on", async () => { diff --git a/src/lib/ai/provider-runner.ts b/src/lib/ai/provider-runner.ts index fe6174638..684853b5c 100644 --- a/src/lib/ai/provider-runner.ts +++ b/src/lib/ai/provider-runner.ts @@ -38,50 +38,36 @@ import { const NEVER_SKIP: ReadonlySet = new Set(["local"]); /** - * v1.4.16 — multi-provider redundancy runner. + * The multi-provider redundancy runner: a provider completion with a + * hard-failure walk across an ordered list of providers, so one provider's + * outage (a 401 from an expired Codex sign-in, a 503 brown-out, a network + * reset) cascades to the next configured provider instead of failing the + * request. * - * The chain runner wraps a provider completion with a hard-failure - * walkthrough across an ordered list of providers. The motivation is - * the maintainer's "ein Provider-Ausfall darf die Insights nicht zerschiessen" - * mandate: a 401 from Codex (OAuth expired), a 503 from OpenAI - * (upstream brown-out), or a network reset MUST cascade to the next - * configured provider rather than 422-ing the whole request. + * Hard failures (`isHardProviderFailure`) cascade. A malformed-JSON reply is + * NOT a hard failure — it is a prompt-following issue, so it bubbles to the + * caller's own validator rather than masking itself as provider + * unavailability and walking the chain. Every provider receives the same + * enriched system prompt; `outcome.workingProvider.providerType` attributes + * feedback per provider. * - * Hard failures (`isHardProviderFailure`) cascade. A malformed-JSON - * reply is NOT a hard failure — it is a prompt-following issue, so it - * bubbles to the caller's own validator rather than masking itself as - * provider unavailability and walking the chain. - * - * Cross-feature coupling: - * - B5a's `MEDICAL_REFERENCES` is shared via the system prompt; each - * provider in the chain receives the same enriched context. - * - B5e (planned v1.4.17) reads `outcome.workingProvider.providerType` - * to attribute feedback per provider; that's why we re-export it - * out of the runner instead of the wrapper. - * - * The cache: a provider that worked on the last call gets first crack - * on the next, so a user whose Codex OAuth lapsed doesn't re-burn the - * 401 round-trip on every request for the next hour. Cache is - * in-process (per worker), keyed by `userId`, TTL 1h. No coordination - * across workers — when scaling out we'd move this to Redis, but for - * v1.4.16 the per-worker cache is enough to absorb the typical - * "polling reload" pattern. - * - * v1.18.7 — DECISION: the volatile per-worker hint is left - * in-process and NOT folded into the durable Postgres health ledger. The - * ledger already shares the load-bearing signal across workers (the - * skip-hint reorder in `resolveChainOrder` pushes a dead-credential / - * backoff provider to the chain tail for every worker), so the only thing + * The cache: a provider that worked on the last call gets first crack on the + * next, so a user whose Codex sign-in lapsed doesn't re-burn the 401 + * round-trip on every request for the next hour. In-process (per worker), + * keyed by `userId`, TTL 1h. It stays out of the durable Postgres health + * ledger on purpose: the ledger already shares the load-bearing signal across + * workers (the skip-hint reorder in `resolveChainOrder`), so the only thing * uncoordinated is a soft "tried this one last, put it first" reorder whose - * worst case is a single redundant first-hop per worker per hour — exactly - * the bound the v1.18.7 AI audit deemed acceptable at single-maintainer - * scale. Promoting the hint to a per-request ledger write would add write - * amplification on the hot path for a negligible saving; revisit only if a - * multi-worker deploy shows measurable redundant-hop cost. + * worst case is one redundant first hop per worker per hour. Promoting it to + * a per-request ledger write would add write amplification on the hot path; + * revisit only if a multi-worker deploy shows measurable redundant-hop cost. */ const LAST_WORKING_TTL_MS = 60 * 60 * 1000; // 1h +/** The `failureReason` of a hop the operator cost cap refused unsent. */ +const OPERATOR_CAP_REFUSAL = "operator-cost-cap-exhausted"; + interface CacheEntry { providerType: ProviderChainType; expiresAt: number; @@ -223,6 +209,13 @@ export class AllProvidersFailedError extends Error { * a model that reasons without answering is paid for every time. */ readonly tokensSpent: number; + /** + * #1279 — true when no hop sent a request: every provider was benched for + * background work or refused by the operator cost cap. Such a failure says + * nothing about what was asked, so a caller that backs off the record it + * failed on does not count it. + */ + readonly sentNothing: boolean; constructor(attempts: FallbackHop[]) { super( @@ -236,6 +229,13 @@ export class AllProvidersFailedError extends Error { (sum, a) => sum + (a.tokensSpent ?? 0), 0, ); + this.sentNothing = + attempts.length > 0 && + attempts.every( + (a) => + a.failureKind === "paused" || + a.failureReason === OPERATOR_CAP_REFUSAL, + ); const first = attempts[0]; this.primaryCredentialExpired = first !== undefined && @@ -631,7 +631,7 @@ async function runRawChain( const hop: FallbackHop = { providerType: candidate.providerType, attempt: i + 1, - failureReason: "operator-cost-cap-exhausted", + failureReason: OPERATOR_CAP_REFUSAL, httpStatus: null, }; hops.push(hop); diff --git a/src/lib/insights/__tests__/status-negative-window.test.ts b/src/lib/insights/__tests__/status-negative-window.test.ts index 63cf60d1e..56b253fc6 100644 --- a/src/lib/insights/__tests__/status-negative-window.test.ts +++ b/src/lib/insights/__tests__/status-negative-window.test.ts @@ -22,6 +22,7 @@ vi.mock("@/lib/db", () => ({ import { STATUS_NEGATIVE_WINDOW_BASE_MS, clearStatusNegativeWindows, + holdStatusNoteWhileBenched, statusNegativeWindowMs, statusNoteCoolingDown, writeStatusNegativeWindow, @@ -116,6 +117,57 @@ describe("writeStatusNegativeWindow", () => { }); }); +describe("holdStatusNoteWhileBenched", () => { + // A run that sent nothing because every provider was benched says nothing + // about the note: counting it left the note waiting up to two hours after + // the provider recovered. + it("opens the first window and leaves the streak as it was", async () => { + findUnique.mockResolvedValue({ retryAt: new Date(Date.now() - MINUTE) }); + const before = Date.now(); + await holdStatusNoteWhileBenched({ + userId: "u1", + cacheAction: "insights.weight-status.en", + todayKey: TODAY, + }); + const args = written(); + expect(args.update).not.toHaveProperty("failureStreak"); + expect(args.create).toMatchObject({ failureStreak: 0, dateKey: TODAY }); + const window = args.update.retryAt.getTime() - before; + expect(window).toBeGreaterThanOrEqual(STATUS_NEGATIVE_WINDOW_BASE_MS); + expect(window).toBeLessThan(STATUS_NEGATIVE_WINDOW_BASE_MS + MINUTE); + }); + + it("leaves an open window alone, and the failure after it uncounted", async () => { + findUnique.mockResolvedValue({ + retryAt: new Date(Date.now() + MINUTE), + failureStreak: 3, + }); + await holdStatusNoteWhileBenched({ + userId: "u1", + cacheAction: "insights.weight-status.en", + todayKey: TODAY, + }); + await writeStatusNegativeWindow({ + userId: "u1", + cacheAction: "insights.weight-status.en", + todayKey: TODAY, + reason: "error", + }); + expect(upsert).not.toHaveBeenCalled(); + }); + + it("never throws: a missed hold only lets the next failure count", async () => { + findUnique.mockRejectedValue(new Error("pool exhausted")); + await expect( + holdStatusNoteWhileBenched({ + userId: "u1", + cacheAction: "insights.weight-status.en", + todayKey: TODAY, + }), + ).resolves.toBeUndefined(); + }); +}); + describe("statusNegativeWindowMs", () => { it("doubles from five minutes to a two-hour ceiling", () => { expect([1, 2, 3, 4, 5, 6, 7, 30].map(statusNegativeWindowMs)).toEqual( diff --git a/src/lib/insights/__tests__/status-provider-budget.test.ts b/src/lib/insights/__tests__/status-provider-budget.test.ts index e0e3f23ac..046eb60bd 100644 --- a/src/lib/insights/__tests__/status-provider-budget.test.ts +++ b/src/lib/insights/__tests__/status-provider-budget.test.ts @@ -60,6 +60,7 @@ vi.mock("@/lib/db", () => ({ // #1279 — the note's negative window, read before any provider work. insightStatusCache: { findUnique: vi.fn(async () => noteWindow), + upsert: vi.fn(async () => ({})), }, }, })); @@ -374,6 +375,36 @@ describe("runStatusCompletion — ledger accounting", () => { expect(again.kind).toBe("ok"); }); + it("holds the note without counting a run the bench sent nothing for (#1279)", async () => { + runRawCompletionWithFallback.mockRejectedValue( + Object.assign(new Error("All 1 configured providers failed"), { + sentNothing: true, + }), + ); + const { prisma } = await import("@/lib/db"); + const result = await runStatusCompletion( + completionArgs({ cacheAction: "insights.weight-status.en" }), + ); + expect(result.kind).toBe("error"); + expect(prisma.insightStatusCache.upsert).toHaveBeenCalledWith( + expect.objectContaining({ + create: expect.objectContaining({ failureStreak: 0 }), + update: expect.not.objectContaining({ + failureStreak: expect.anything(), + }), + }), + ); + }); + + it("leaves a run that reached a provider to the caller's counted window", async () => { + runRawCompletionWithFallback.mockRejectedValue(new Error("upstream down")); + const { prisma } = await import("@/lib/db"); + await runStatusCompletion( + completionArgs({ cacheAction: "insights.weight-status.en" }), + ); + expect(prisma.insightStatusCache.upsert).not.toHaveBeenCalled(); + }); + it("charges what a failed chain reported spending (#1279)", async () => { // A model that reasons and never answers is billed for every call; a // full refund let background work spend without the ceiling seeing it. diff --git a/src/lib/insights/status-negative-window.ts b/src/lib/insights/status-negative-window.ts index bafb032a2..d6d740337 100644 --- a/src/lib/insights/status-negative-window.ts +++ b/src/lib/insights/status-negative-window.ts @@ -72,6 +72,48 @@ export async function writeStatusNegativeWindow(args: { }); } +/** + * #1279 — hold a note while its chain sent nothing: every provider was + * benched for background work (or refused by the operator cost cap). Such a + * run says nothing about the note, and counting it left the note waiting up + * to two hours after the provider recovered. Opens the first window unless + * one is open and leaves the streak as it was, so the caller's own failure + * write lands inside it and neither moves nor counts. Best-effort: a missed + * hold only lets that write count. + */ +export async function holdStatusNoteWhileBenched(args: { + userId: string; + cacheAction: string; + todayKey: string; +}): Promise { + const key = statusCacheKey(args.cacheAction); + if (!key) return; + const where = { userId_metric_locale: { userId: args.userId, ...key } }; + try { + const row = await prisma.insightStatusCache.findUnique({ + where, + select: { retryAt: true }, + }); + const now = Date.now(); + if (row?.retryAt && row.retryAt.getTime() > now) return; + const retryAt = new Date(now + STATUS_NEGATIVE_WINDOW_BASE_MS); + await prisma.insightStatusCache.upsert({ + where, + create: { + userId: args.userId, + ...key, + dateKey: args.todayKey, + retryAt, + negativeReason: "error", + failureStreak: 0, + }, + update: { retryAt, negativeReason: "error" }, + }); + } catch { + // The caller's own write still opens a window. + } +} + /** * True while the note's negative-cache window is open. #1279 — checked right * before a status generation reaches a provider (`runStatusCompletion`), so diff --git a/src/lib/insights/status-provider.ts b/src/lib/insights/status-provider.ts index 4dec02709..37750e7c5 100644 --- a/src/lib/insights/status-provider.ts +++ b/src/lib/insights/status-provider.ts @@ -21,6 +21,7 @@ import { reserveBudget, resolveCostOwner, resolveDailyCapFor, + type BudgetCostOwner, } from "@/lib/ai/coach/budget"; import { AI_BUDGETS, @@ -36,7 +37,10 @@ import { type BackgroundReasoningJob, } from "@/lib/ai/reasoning/levels"; import { resolveJobReasoning } from "@/lib/ai/reasoning/controls"; -import { statusNoteCoolingDown } from "./status-negative-window"; +import { + holdStatusNoteWhileBenched, + statusNoteCoolingDown, +} from "./status-negative-window"; /** * v1.41 — the fallback ceiling for a status-path call that reasons. Thinking @@ -332,16 +336,7 @@ export async function runStatusCompletion( ); if (raced.timedOut || raced.errored || raced.value === null) { - // A timeout or failure: charge only what a reply reported spending, never - // an invented figure. #1279 — a failed chain's report counts: a model - // that reasons without answering bills every call, and a full refund let - // background work spend without the day's ceiling ever seeing it. - const spent = spentOnFailure(raced.error); - await reconcileSpend(userId, reservation.reserved, spent, dateKey, 0, { - servedBy: null, - reservedOwner: reservation.owner, - }); - return { kind: raced.timedOut ? "timeout" : "error" }; + return failedRun(raced, { userId, cacheAction, dateKey, reservation }); } const { result, workingProvider, tokensSpent } = raced.value; @@ -395,6 +390,44 @@ export async function runStatusCompletion( }; } +/** + * A run that timed out or failed. It charges only what a reply reported + * spending, never an invented figure; #1279 — a failed chain's report counts, + * since a model that reasons without answering bills every call, and a full + * refund let background work spend without the day's ceiling seeing it. A + * chain that sent nothing (the bench) holds the note without counting it. + */ +async function failedRun( + raced: { timedOut: boolean; error?: unknown }, + run: { + userId: string; + cacheAction: string; + dateKey: string; + reservation: { reserved: number; owner: BudgetCostOwner }; + }, +): Promise { + const spent = spentOnFailure(raced.error); + await reconcileSpend( + run.userId, + run.reservation.reserved, + spent, + run.dateKey, + 0, + { + servedBy: null, + reservedOwner: run.reservation.owner, + }, + ); + if ((raced.error as { sentNothing?: unknown } | null)?.sentNothing === true) { + await holdStatusNoteWhileBenched({ + userId: run.userId, + cacheAction: run.cacheAction, + todayKey: run.dateKey, + }); + } + return { kind: raced.timedOut ? "timeout" : "error" }; +} + /** * Over the day's ceiling. Reported as `error` — a TRANSIENT miss the caller * serves the fallback for without persisting it — deliberately NOT `none`,