From 595a8834400ef4473c2158c197520dd6cf89f50a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Sat, 24 Oct 2026 23:16:24 +0200 Subject: [PATCH] fix(ai): write the provider health ledger on the app's clock The ledger stamped last_failure_at, last_ok_at, next_retry_at and updated_at with the database's NOW(), while every reader compares them with the app's clock: the runner's skip hints and the background bench, the admin provider-health card, the server-health tri-state and the support report. A backoff or pause therefore sat wherever the skew between the two clocks put it. With the app clock pinned, a five-minute backoff lasted until the database's clock plus five minutes, months away, or was over before it began. Both writes now bind the instant they took as a parameter (`$N::timestamp`, the naive UTC columns), the same one-clock rule the summary reads follow. The escalating pause arithmetic is unchanged. The pause integration test pins the app clock years behind and ahead of the database's and checks the stored instants, a backoff that lifts after five minutes, a pause that benches background work for its full length, and a success the server health reads as recent. Refs #1279 --- src/lib/ai/provider-health-ledger.ts | 29 +++++--- tests/integration/provider-pause.test.ts | 90 +++++++++++++++++++++++- 2 files changed, 110 insertions(+), 9 deletions(-) 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"); + }); +});