diff --git a/src/lib/ai/provider-health-ledger.ts b/src/lib/ai/provider-health-ledger.ts index b6e25a4b6..8368aadab 100644 --- a/src/lib/ai/provider-health-ledger.ts +++ b/src/lib/ai/provider-health-ledger.ts @@ -149,6 +149,16 @@ export function classifyFailure(httpStatus: number | null): { * `provider_health` table. Writes use an atomic SQL upsert (the * rate-limiter pattern) so concurrent workers never clobber each other's * counters. + * + * One clock: the app's. Every instant a write stores is the `Date` the + * write took, bound as a parameter, never the database's `NOW()`, because + * every reader (`getSkipHints`, the background bench, the admin card, the + * server-health tri-state, the support report) compares those instants + * with the app's clock. Two clocks put a window wherever their skew put + * it: a process whose clock is pinned saw a five-minute backoff last until + * the database's clock plus five minutes, months away or already over. + * The columns are naive UTC timestamps, so the bound instant is cast with + * `::timestamp` (see `request-clock-sql.ts`). */ export const postgresProviderHealthLedger: ProviderHealthLedger = { async getSkipHints(userId) { @@ -196,6 +206,7 @@ export const postgresProviderHealthLedger: ProviderHealthLedger = { async recordSuccess(userId, providerType) { try { // Atomic upsert; a success always clears the negative cache. + const now = new Date(); await prisma.$executeRaw` INSERT INTO provider_health (id, user_id, provider_type, last_result, last_status, @@ -203,14 +214,14 @@ export const postgresProviderHealthLedger: ProviderHealthLedger = { next_retry_at, updated_at) VALUES (gen_random_uuid()::text, ${userId}, ${providerType}, 'ok', NULL, - 0, (NOW() AT TIME ZONE 'UTC'), NULL, NULL, (NOW() AT TIME ZONE 'UTC')) + 0, ${now}::timestamp, NULL, NULL, ${now}::timestamp) ON CONFLICT (user_id, provider_type) DO UPDATE SET last_result = 'ok', last_status = NULL, consecutive_failures = 0, - last_ok_at = (NOW() AT TIME ZONE 'UTC'), + last_ok_at = ${now}::timestamp, next_retry_at = NULL, - updated_at = (NOW() AT TIME ZONE 'UTC') + updated_at = ${now}::timestamp `; } catch { // Fire-and-forget — a failed write never blocks the hot path. @@ -228,10 +239,12 @@ export const postgresProviderHealthLedger: ProviderHealthLedger = { const pauseFrom = PROVIDER_PAUSE_THRESHOLD; const pauseBase = `${PROVIDER_PAUSE_BASE_MS} milliseconds`; const pauseMax = `${PROVIDER_PAUSE_MAX_MS} milliseconds`; + const now = new Date(); try { // Atomic upsert. `consecutive_failures` accumulates across workers; // an auth failure forces the cooldown regardless of count, a hard - // failure extends it. The cooldown anchors on NOW() so a fresh failure + // failure extends it. The cooldown anchors on the failure's own + // instant (the app's clock, like every reader) so a fresh failure // always re-arms the skip window. await prisma.$executeRaw` INSERT INTO provider_health @@ -240,13 +253,13 @@ export const postgresProviderHealthLedger: ProviderHealthLedger = { next_retry_at, updated_at) VALUES (gen_random_uuid()::text, ${userId}, ${providerType}, ${result}, - ${status}, 1, NULL, (NOW() AT TIME ZONE 'UTC'), (NOW() AT TIME ZONE 'UTC') + ${interval}::interval, (NOW() AT TIME ZONE 'UTC')) + ${status}, 1, NULL, ${now}::timestamp, ${now}::timestamp + ${interval}::interval, ${now}::timestamp) ON CONFLICT (user_id, provider_type) DO UPDATE SET last_result = ${result}, last_status = ${status}, consecutive_failures = provider_health.consecutive_failures + 1, - last_failure_at = (NOW() AT TIME ZONE 'UTC'), - next_retry_at = (NOW() AT TIME ZONE 'UTC') + CASE + last_failure_at = ${now}::timestamp, + next_retry_at = ${now}::timestamp + CASE WHEN ${result} = 'hard_failed' AND provider_health.consecutive_failures + 1 >= ${pauseFrom}::int THEN LEAST( @@ -258,7 +271,7 @@ export const postgresProviderHealthLedger: ProviderHealthLedger = { ) ELSE ${interval}::interval END, - updated_at = (NOW() AT TIME ZONE 'UTC') + updated_at = ${now}::timestamp `; } catch { // Fire-and-forget. diff --git a/tests/integration/provider-pause.test.ts b/tests/integration/provider-pause.test.ts index 3845e1ca1..7926d84ef 100644 --- a/tests/integration/provider-pause.test.ts +++ b/tests/integration/provider-pause.test.ts @@ -7,7 +7,7 @@ * Only Postgres can show the CASE arithmetic is right; the unit test can only * show the statement carries it. */ -import { beforeEach, describe, expect, it, vi } from "vitest"; +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; import { getPrismaClient, truncateAllTables } from "./setup"; @@ -21,6 +21,8 @@ import { PROVIDER_PAUSE_THRESHOLD, postgresProviderHealthLedger as ledger, } from "@/lib/ai/provider-health-ledger"; +import { partitionForBackgroundWork } from "@/lib/ai/background-bench"; +import { readServerProviderHealth } from "@/lib/ai/server-provider-health"; const prisma = getPrismaClient(); @@ -78,3 +80,89 @@ describe("provider pause in the Postgres ledger", () => { ).toBe("credential_expired"); }); }); + +/** + * Every instant the ledger stores is read back against the app's clock, so + * it has to be written with the app's clock too. With the app clock pinned + * far from the database's, a window written from the database's `NOW()` + * lands months away from where every reader looks for it. + */ +describe("provider health ledger on the app's clock", () => { + let userId: string; + + beforeEach(async () => { + await truncateAllTables(prisma); + const user = await prisma.user.create({ + data: { + email: "clock@example.test", + username: "clock", + passwordHash: "x", + }, + }); + userId = user.id; + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + async function row() { + return prisma.providerHealth.findFirstOrThrow({ + where: { userId, providerType: "admin-openai" }, + select: { lastFailureAt: true, lastOkAt: true, nextRetryAt: true }, + }); + } + + it("lifts a backoff five minutes after the failure, on a clock behind the database's", async () => { + const at = new Date("2020-01-01T12:00:00.000Z"); + vi.useFakeTimers({ toFake: ["Date"], now: at }); + for (let i = 0; i < 3; i += 1) { + await ledger.recordFailure(userId, "admin-openai", 500); + } + const stored = await row(); + expect(stored.lastFailureAt?.toISOString()).toBe(at.toISOString()); + expect(stored.nextRetryAt?.getTime()).toBe( + at.getTime() + HARD_FAILURE_COOLDOWN_MS, + ); + expect( + (await ledger.getSkipHints(userId)).get("admin-openai")?.reason, + ).toBe("backoff"); + + vi.setSystemTime(at.getTime() + HARD_FAILURE_COOLDOWN_MS + 1_000); + expect((await ledger.getSkipHints(userId)).size).toBe(0); + }); + + it("benches background work for the whole pause, on a clock ahead of the database's", async () => { + const at = new Date("2031-03-01T08:00:00.000Z"); + vi.useFakeTimers({ toFake: ["Date"], now: at }); + for (let i = 0; i < PROVIDER_PAUSE_THRESHOLD; i += 1) { + await ledger.recordFailure(userId, "admin-openai", 500); + } + const skips = await ledger.getSkipHints(userId); + const hint = skips.get("admin-openai"); + expect(hint?.reason).toBe("paused"); + expect(hint?.retryAt?.getTime()).toBe( + at.getTime() + PROVIDER_PAUSE_BASE_MS, + ); + const { walkable, benched } = partitionForBackgroundWork( + [{ providerType: "admin-openai" as const }], + skips, + () => false, + ); + expect(walkable).toEqual([]); + expect(benched.map((b) => b.candidate.providerType)).toEqual([ + "admin-openai", + ]); + + vi.setSystemTime(at.getTime() + PROVIDER_PAUSE_BASE_MS - 1_000); + expect((await ledger.getSkipHints(userId)).has("admin-openai")).toBe(true); + }); + + it("stamps a success with the app's instant, so the server health reads it as recent", async () => { + const at = new Date("2031-03-01T08:00:00.000Z"); + vi.useFakeTimers({ toFake: ["Date"], now: at }); + await ledger.recordSuccess(userId, "admin-openai"); + expect((await row()).lastOkAt?.toISOString()).toBe(at.toISOString()); + expect(await readServerProviderHealth()).toBe("healthy"); + }); +});