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
This commit is contained in:
Marc-André Bombeck committed 2026-10-24 23:16:24 +02:00
1 parent dbe05c958c
commit 595a883440
2 files changed
+110 -9

No files matched your search

+21 -8
View File
@@ -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.
+89 -1
View File
@@ -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");
});
});