From bfeac46f06d85e1fbad9d294f544b705d99f3dc0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:25:52 +0200 Subject: [PATCH 01/19] fix(jobs): send a heavy job back to its queue instead of waiting in the handler pg-boss counts a job's expiry from the fetch and ends the handler at it, so a job that waited for the heavy lane spent its expiry in line: a long import let the weekly backup expire through every retry, and an upload that waited past its own expiry was failed, stopped counting as in use and lost its staged file to the sweep. A job that finds the lane taken now returns to created with start_after a minute ahead, at the same attempt, in one statement, and runs when the lane is free. The full-history integration drain joins the lane, and the guard checks that every heavy queue's policy lets a job go back to created. --- src/__tests__/job-queue-runtime-guard.test.ts | 67 +++++--- src/lib/jobs/__tests__/heavy-lane.test.ts | 142 +++++++++++------ src/lib/jobs/heavy-lane.ts | 127 +++++++-------- src/lib/jobs/job-outcome.ts | 4 +- .../reminder/register-integration-sync.ts | 10 +- tests/integration/heavy-lane-defer.test.ts | 147 ++++++++++++++++++ 6 files changed, 353 insertions(+), 144 deletions(-) create mode 100644 tests/integration/heavy-lane-defer.test.ts diff --git a/src/__tests__/job-queue-runtime-guard.test.ts b/src/__tests__/job-queue-runtime-guard.test.ts index 22a8b991a..71dd3a2fe 100644 --- a/src/__tests__/job-queue-runtime-guard.test.ts +++ b/src/__tests__/job-queue-runtime-guard.test.ts @@ -417,16 +417,6 @@ describe("a cron-fed queue polls slowly, a sent one does not", () => { }); }); -/** The text of the first `const NAME = …` in the tree, up to its end. */ -function constBody(texts: ReadonlyMap, name: string): string { - for (const [file, raw] of texts) { - if (new RegExp(`\\bconst\\s+${name}\\b`).test(raw)) { - return bodyOf(texts, { file, fn: name }).split(/\n\n/)[0]; - } - } - return ""; -} - describe("heavy jobs share the lane", () => { const all = scan(source); const laned = all.bindings.filter((b) => /\bheavyLane\s*\(/.test(b.text)); @@ -437,7 +427,10 @@ describe("heavy jobs share the lane", () => { ); }); - it("holds a lockedPass outside the lane, so an expiry retry does not queue twice", () => { + it("holds a lockedPass outside the lane, so an expiry retry finds the run going", () => { + // Outside, a retry pg-boss starts while the expired run still holds the + // lane finds the lock and settles; inside, the lane would defer it and + // run the job a second time once the first is done. const inverted = laned .filter((b) => /\blockedPass\s*\(/.test(b.text)) .filter((b) => b.text.indexOf("lockedPass") > b.text.indexOf("heavyLane")) @@ -445,17 +438,45 @@ describe("heavy jobs share the lane", () => { expect(inverted).toEqual([]); }); - it("keeps a waiter past its expiry only where nothing retries the job", () => { - const problems = Object.entries(HEAVY_QUEUES) - .filter(([, heavy]) => heavy.oneShot) - .flatMap(([queue]) => { - const entry = QUEUE_RUNTIME[queue]; - if (entry?.runtime !== "long") return [`${queue}: not a long queue`]; - const noRetry = entry.expiryVia.some((v) => - /\bretryLimit:\s*0\b/.test(constBody(source, v)), - ); - return noRetry ? [] : [`${queue}: its send options allow a retry`]; - }); - expect(problems).toEqual([]); + it("defers only on queues where a job can go back to created", () => { + // A deferred job returns from active to created. Under `short` (one + // queued job per key) and `stately` (one per state) a twin already + // queued would refuse it, and the job would fail instead of waiting. + const policies = policiesOf(source); + expect(policies.size).toBeGreaterThanOrEqual(40); + const refused = Object.keys(HEAVY_QUEUES) + .filter((queue) => /^(?:short|stately)$/.test(policies.get(queue) ?? "")) + .sort(); + expect(refused).toEqual([]); + // The planted case: the same check over a table that declares one. + const planted = new Map(source); + const file = REGISTRARS[2]; + planted.set( + file, + `const DATA_BACKUP_QUEUE = "data-backup";\nconst queuePolicies: QueuePolicyTable = {\n [DATA_BACKUP_QUEUE]: { policy: "short", reason: "x" },\n};\n`, + ); + expect(policiesOf(planted).get("data-backup")).toBe("short"); }); }); + +/** Every `[QUEUE]: { policy: "…" }` in a registrar's `queuePolicies`. */ +function policiesOf(texts: ReadonlyMap): Map { + const definitions = definitionsOf(texts); + const out = new Map(); + for (const file of REGISTRARS) { + const text = code(texts.get(file) ?? ""); + const m = /const\s+queuePolicies\s*:\s*QueuePolicyTable\s*=\s*\{/.exec( + text, + ); + if (!m) continue; + const open = m.index + m[0].length - 1; + const body = text.slice(open, closeOf(text, open)); + for (const entry of body.matchAll( + /\[\s*([A-Z][A-Z0-9_]*)\s*\]\s*:\s*\{\s*policy\s*:\s*"([a-z]+)"/g, + )) { + const queue = resolve(definitions, file, entry[1]); + if (queue) out.set(queue, entry[2]); + } + } + return out; +} diff --git a/src/lib/jobs/__tests__/heavy-lane.test.ts b/src/lib/jobs/__tests__/heavy-lane.test.ts index 9f9e7a2d7..0b97297ed 100644 --- a/src/lib/jobs/__tests__/heavy-lane.test.ts +++ b/src/lib/jobs/__tests__/heavy-lane.test.ts @@ -1,19 +1,21 @@ /** - * The heavy lane runs one heavy job at a time per process, first come first - * served; a waiter pg-boss expired leaves the line, a one-shot keeps its place. + * The heavy lane runs one heavy job at a time per process. A job that finds + * the lane taken goes back to its queue at once instead of waiting in the + * handler, where its expiry would run down while it stood in line. */ import { describe, expect, it, vi } from "vitest"; import type { Job } from "pg-boss"; vi.mock("@/lib/logging/context", () => ({ annotate: vi.fn() })); +vi.mock("@/lib/db", () => ({ prisma: {} })); import { heavyLane } from "../heavy-lane"; import { jobDone } from "../job-outcome"; type TestJob = Job<{ force?: boolean }>; -function job(data: { force?: boolean } = {}, signal?: AbortSignal): TestJob { - return { id: "j", data, signal } as unknown as TestJob; +function job(id = "j", data: { force?: boolean } = {}): TestJob { + return { id, data } as unknown as TestJob; } /** A handler that runs until `finish` is called, recording the overlap. */ @@ -29,87 +31,127 @@ function gate(log: string[], name: string) { return { handler, finish }; } +/** A stand-in for the way back to the queue, recording what went back. */ +function deferrals() { + const back: Array<{ queue: string; ids: string[] }> = []; + const defer = vi.fn(async (queue: string, jobs: readonly TestJob[]) => { + back.push({ queue, ids: jobs.map((j) => j.id) }); + return jobs.length; + }); + return { back, defer }; +} + const tick = () => new Promise((r) => setTimeout(r, 0)); describe("heavyLane", () => { - it("runs two heavy jobs of different queues one after the other", async () => { + it("sends a heavy job back to its queue while another holds the lane", async () => { const log: string[] = []; - const a = gate(log, "backup"); - const b = gate(log, "import"); - const first = heavyLane("data-backup", a.handler)([job()]); - const second = heavyLane("apple-health-import-v2", b.handler)([job()]); + const a = gate(log, "import"); + const b = gate(log, "backup"); + const { back, defer } = deferrals(); + const running = heavyLane( + "apple-health-import-v2", + a.handler, + undefined, + defer, + )([job("upload")]); await tick(); - expect(log).toEqual(["start:backup"]); + const outcome = await heavyLane( + "data-backup", + b.handler, + undefined, + defer, + )([job("weekly")]); + // It returned at once, without running and without waiting. + expect(outcome).toMatchObject({ ok: true, did: { lane_deferred: 1 } }); + expect(b.handler).not.toHaveBeenCalled(); + expect(back).toEqual([{ queue: "data-backup", ids: ["weekly"] }]); a.finish(); - await first; + await running; + // Once the lane is free the redelivered job runs. + const again = heavyLane( + "data-backup", + b.handler, + undefined, + defer, + )([job("weekly")]); await tick(); - expect(log).toEqual(["start:backup", "end:backup", "start:import"]); b.finish(); - await second; + await again; + expect(log).toEqual([ + "start:import", + "end:import", + "start:backup", + "end:backup", + ]); + expect(defer).toHaveBeenCalledTimes(1); }); - it("lets a light job of a heavy queue pass the line", async () => { + it("lets a light job of a heavy queue pass the lane", async () => { const log: string[] = []; const a = gate(log, "walk"); const b = gate(log, "warm"); + const { defer } = deferrals(); const notForced = (j: TestJob) => !j.data.force; const walk = heavyLane( "insight-pregenerate", a.handler, notForced, + defer, )([job()]); const warm = heavyLane( "insight-pregenerate", b.handler, notForced, - )([job({ force: true })]); + defer, + )([job("w", { force: true })]); await tick(); b.finish(); a.finish(); await Promise.all([walk, warm]); - // The warm started while the walk held the lane. expect(log.indexOf("start:warm")).toBeLessThan(log.indexOf("end:walk")); - }); - - it("drops a waiter pg-boss expired, and keeps a one-shot past its expiry", async () => { - const log: string[] = []; - const holder = gate(log, "holder"); - const pass = gate(log, "pass"); - const upload = gate(log, "upload"); - const held = heavyLane("data-backup-offhost", holder.handler)([job()]); - const expiry = new AbortController(); - const waitingPass = heavyLane( - "data-backup", - pass.handler, - )([job({}, expiry.signal)]); - const uploadExpiry = new AbortController(); - const waitingUpload = heavyLane( - "apple-health-import-v2", - upload.handler, - )([job({}, uploadExpiry.signal)]); - await tick(); - expiry.abort(); - uploadExpiry.abort(); - const outcome = await waitingPass; - expect(outcome).toMatchObject({ ok: true, did: { lane_expired: 1 } }); - expect(pass.handler).not.toHaveBeenCalled(); - holder.finish(); - await held; - await tick(); - expect(log).toEqual(["start:holder", "end:holder", "start:upload"]); - upload.finish(); - await waitingUpload; + expect(defer).not.toHaveBeenCalled(); }); it("frees the lane when a handler throws", async () => { - const failing = heavyLane("rollup-full-backfill", async () => { - throw new Error("boom"); - }); + const { defer } = deferrals(); + const failing = heavyLane( + "rollup-full-backfill", + async () => { + throw new Error("boom"); + }, + undefined, + defer, + ); await expect(failing([job()])).rejects.toThrow("boom"); const next = vi.fn(async () => jobDone({ jobs: 1 })); await expect( - heavyLane("data-backup", next)([job()]), + heavyLane("data-backup", next, undefined, defer)([job()]), ).resolves.toMatchObject({ ok: true }); + expect(next).toHaveBeenCalledTimes(1); + expect(defer).not.toHaveBeenCalled(); + }); + + it("fails the delivery when the way back to the queue fails", async () => { + const log: string[] = []; + const holder = gate(log, "holder"); + const { defer } = deferrals(); + const held = heavyLane( + "data-backup-offhost", + holder.handler, + undefined, + defer, + )([job()]); + await tick(); + const broken = vi.fn(async () => { + throw new Error("db down"); + }); + // pg-boss then retries it, rather than completing a job that never ran. + await expect( + heavyLane("data-backup", vi.fn(), undefined, broken)([job()]), + ).rejects.toThrow("db down"); + holder.finish(); + await held; }); it("refuses a queue that is not declared heavy", () => { diff --git a/src/lib/jobs/heavy-lane.ts b/src/lib/jobs/heavy-lane.ts index 032df827c..0f924880d 100644 --- a/src/lib/jobs/heavy-lane.ts +++ b/src/lib/jobs/heavy-lane.ts @@ -7,47 +7,44 @@ * process and one heap limit, and these jobs used to run side by side when * their schedules or a person's upload happened to meet, so the peak was the * sum of whatever overlapped rather than the largest one. Under the lane a - * heavy job waits for the one before it, first come first served. + * heavy job runs only while no other heavy job does. * * The lane lives in the process, not the database: the heap it protects is * the process's own, and another process has a heap of its own. * - * A job waits until its turn or until pg-boss gives up on it. At the job's - * expiry pg-boss aborts its signal and applies the queue's retry policy, so a - * waiter that sees the abort leaves the line without running and reports - * `lane_expired`; the retry takes its place. A queue bound with `lockedPass` - * holds that lock outside the lane, so the retry finds the lock taken while - * the original still waits instead of queueing a second time - * (`heavy-lane-guard.test.ts`). The exception is a one-shot: its input lives - * outside pg-boss (a staged upload, a restore row) and nothing retries it, so - * it keeps its place past the expiry and runs when its turn comes, as pg-boss - * lets a handler do. + * A job that arrives while the lane is taken does not wait in the handler. It + * goes back to the queue (`deferLaneJobs`): its row returns to `created` with + * `start_after` a little ahead, the claim cleared so the next fetch does not + * count an attempt, and pg-boss's completion of the handler then finds no + * active row and leaves it alone. Waiting in the handler instead ran the + * job's expiry down while it stood in line, because pg-boss counts the expiry + * from the fetch and ends the handler at it: a six-hour import let a + * two-hour backup expire through all its retries, and an upload that waited + * longer than its own expiry was failed, stopped counting as in use, and had + * its staged file swept from under it. A deferred job keeps its id, its + * retries and its staged upload, and its expiry starts when it runs. */ import type { Job } from "pg-boss"; +import { prisma } from "@/lib/db"; import { jobDone, type JobOutcome } from "@/lib/jobs/job-outcome"; import { annotate } from "@/lib/logging/context"; export interface HeavyQueue { /** What makes the job heavy. */ why: string; - /** A one-shot keeps its place past its expiry; see the module note. */ - oneShot?: true; } /** The queues that take the lane. */ export const HEAVY_QUEUES: Readonly> = { "apple-health-import-v2": { why: "Parses an export of up to several gigabytes.", - oneShot: true, }, "health-connect-import": { why: "Reads a Health Connect export database.", - oneShot: true, }, "backup-restore": { why: "Holds a batch of a whole account's readings per insert.", - oneShot: true, }, "data-backup": { why: "Serialises every account's whole record." }, "data-backup-offhost": { @@ -68,78 +65,74 @@ export const HEAVY_QUEUES: Readonly> = { "period-narrative-warm": { why: "The boundary-night walk: a narrative per account and period.", }, + "integration-backfill-admission": { + why: "A provider's full history for one account, page by page; the Google Health import is the largest heap in the tree.", + }, }; -type Waiter = () => void; +/** How far ahead a deferred job is put back in the queue. */ +export const LANE_DEFER_SECONDS = 60; -const NEVER = new AbortController().signal; +/** + * Put `jobs` of `queue` back in the queue to run `seconds` from now. The same + * reset pg-boss's own `restore()` makes, with `start_after` moved in the same + * statement: a restore followed by a separate update leaves a moment in which + * another fetch could claim the row, and the completion of this handler would + * then settle that newer claim, since a restored job's next claim keeps its + * attempt number. Answers how many rows went back. + */ +export async function deferLaneJobs( + queue: string, + jobs: readonly Job[], + seconds: number = LANE_DEFER_SECONDS, +): Promise { + const ids = jobs.map((job) => job.id); + return prisma.$executeRaw` + UPDATE pgboss.job + SET state = 'created', + started_on = NULL, + heartbeat_on = NULL, + upsert_by_key = NULL, + start_after = now() + make_interval(secs => ${seconds}::int) + WHERE name = ${queue} + AND id = ANY(${ids}::uuid[]) + AND state = 'active' + `; +} -const waiting: Waiter[] = []; let busy = false; -/** Resolves true once the lane is ours, false if `signal` aborts first. */ -function enter(signal: AbortSignal): Promise { - if (!busy) { - busy = true; - return Promise.resolve(true); - } - return new Promise((resolve) => { - const onAbort = () => { - const at = waiting.indexOf(grant); - if (at >= 0) waiting.splice(at, 1); - resolve(false); - }; - const grant: Waiter = () => { - signal.removeEventListener("abort", onAbort); - resolve(true); - }; - if (signal.aborted) return resolve(false); - signal.addEventListener("abort", onAbort, { once: true }); - waiting.push(grant); - }); -} - -function leave(): void { - const next = waiting.shift(); - if (next) next(); - else busy = false; -} - /** * Wrap `handler` so the jobs of `queue` run in the lane. `inLane` picks the * jobs that are heavy where a queue carries light ones too (a single * account's warm beside the nightly walk); a batch with none of them runs at - * once. + * once. `defer` is the way back to the queue; tests replace it. */ export function heavyLane>( queue: string, handler: (jobs: J[]) => Promise, inLane: (job: J) => boolean = () => true, + defer: (queue: string, jobs: readonly J[]) => Promise = deferLaneJobs, ): (jobs: J[]) => Promise { - const heavy = HEAVY_QUEUES[queue]; - if (!heavy) throw new Error(`heavyLane: ${queue} is not in HEAVY_QUEUES`); + if (!HEAVY_QUEUES[queue]) { + throw new Error(`heavyLane: ${queue} is not in HEAVY_QUEUES`); + } return async (jobs) => { if (!jobs.some(inLane)) return handler(jobs); - const queuedAt = Date.now(); - const entered = await enter( - heavy.oneShot ? NEVER : AbortSignal.any(signalsOf(jobs)), - ); - const waitedMs = Date.now() - queuedAt; - annotate({ - action: { - name: entered ? "job.heavy_lane.entered" : "job.heavy_lane.expired", - }, - meta: { queue, waited_ms: waitedMs }, - }); - if (!entered) return jobDone({ lane_expired: jobs.length }); + if (busy) { + const deferred = await defer(queue, jobs); + annotate({ + action: { name: "job.heavy_lane.deferred" }, + meta: { queue, jobs: jobs.length, deferred }, + }); + return jobDone({ lane_deferred: deferred }); + } + busy = true; + annotate({ action: { name: "job.heavy_lane.entered" }, meta: { queue } }); try { return await handler(jobs); } finally { - leave(); + busy = false; } }; } - -function signalsOf(jobs: readonly Job[]): AbortSignal[] { - return jobs.flatMap((job) => (job.signal ? [job.signal] : [])); -} diff --git a/src/lib/jobs/job-outcome.ts b/src/lib/jobs/job-outcome.ts index 04f85eb8e..672cc8ba3 100644 --- a/src/lib/jobs/job-outcome.ts +++ b/src/lib/jobs/job-outcome.ts @@ -143,8 +143,8 @@ export const JOB_FACT_ALLOWLIST: ReadonlySet = new Set([ "inventory_expired_count", "inventory_items_migrated", "jobs", - // A heavy job pg-boss expired while it waited for the heavy lane. - "lane_expired", + // Heavy jobs that found the lane taken and went back to their queue. + "lane_deferred", "legacy_rows_soft_deleted", "linked", "malformed", diff --git a/src/lib/jobs/reminder/register-integration-sync.ts b/src/lib/jobs/reminder/register-integration-sync.ts index 7fd137473..afb14ee91 100644 --- a/src/lib/jobs/reminder/register-integration-sync.ts +++ b/src/lib/jobs/reminder/register-integration-sync.ts @@ -70,6 +70,7 @@ import { type IntegrationBackfillAdmissionPayload, } from "@/lib/jobs/integration-backfill-admission"; import { drainIntegrationBackfillAdmission } from "@/lib/jobs/integration-backfill-drain"; +import { heavyLane } from "@/lib/jobs/heavy-lane"; import { INTEGRATION_WATCHDOG_DAILY_CRON, INTEGRATION_WATCHDOG_DAILY_QUEUE, @@ -491,7 +492,9 @@ export async function registerIntegrationSyncQueues( await createAndSchedule(boss, allQueues, schedules, queuePolicies); // pg-boss scopes groupConcurrency to one queue name, so every provider // reaches this shared durable queue before doing full-history work. The - // common group is enforced in PostgreSQL across worker processes/nodes. + // common group is enforced in PostgreSQL across worker processes/nodes; + // the heavy lane keeps an import off the heap while a backup, a restore + // or an upload is on it. await createAndWork( boss, @@ -500,7 +503,10 @@ export async function registerIntegrationSyncQueues( localConcurrency: INTEGRATION_BACKFILL_GLOBAL_CONCURRENCY, groupConcurrency: INTEGRATION_BACKFILL_GLOBAL_CONCURRENCY, }, - drainIntegrationBackfillAdmission, + heavyLane( + INTEGRATION_BACKFILL_ADMISSION_QUEUE, + drainIntegrationBackfillAdmission, + ), ); await createAndWork( diff --git a/tests/integration/heavy-lane-defer.test.ts b/tests/integration/heavy-lane-defer.test.ts new file mode 100644 index 000000000..bbd0f0485 --- /dev/null +++ b/tests/integration/heavy-lane-defer.test.ts @@ -0,0 +1,147 @@ +/** + * The heavy lane against a real pg-boss on a real Postgres: a heavy job that + * finds the lane taken goes back to its queue, keeps its id and its attempt, + * is not settled by pg-boss's completion of the handler that sent it back, + * and does not spend its expiry while it waits. + * + * The case it replaces: a job that waited in the handler ran its expiry down + * while it stood in line, because pg-boss counts the expiry from the fetch. + * Here the holder runs for six seconds against a two-second expiry on the + * waiting job; the waiting job still runs once, after the holder, without a + * single failed attempt. + */ +import { afterAll, beforeAll, describe, expect, it } from "vitest"; +import { PgBoss, type Job } from "pg-boss"; + +import { prisma } from "@/lib/db"; +import { deferLaneJobs, heavyLane } from "@/lib/jobs/heavy-lane"; +import { jobDone } from "@/lib/jobs/job-outcome"; + +let boss: PgBoss; + +const HOLDER_QUEUE = "data-backup-offhost"; +const WAITER_QUEUE = "data-backup"; +const WORK = { localConcurrency: 1, pollingIntervalSeconds: 0.5 } as const; + +const sleep = (ms: number) => new Promise((r) => setTimeout(r, ms)); + +beforeAll(async () => { + boss = new PgBoss({ connectionString: process.env.DATABASE_URL }); + await boss.start(); + await boss.createQueue(HOLDER_QUEUE); + await boss.createQueue(WAITER_QUEUE); +}, 120_000); + +afterAll(async () => { + await boss?.stop({ graceful: false }); +}); + +async function row(id: string) { + const rows = await prisma.$queryRaw< + Array<{ + state: string; + retry_count: number; + started_on: Date | null; + future: boolean; + }> + >` + SELECT state::text AS state, retry_count, started_on, + start_after > now() AS future + FROM pgboss.job WHERE id = ${id}::uuid + `; + return rows[0]; +} + +describe("deferLaneJobs", () => { + it("returns an active job to created, later, at the same attempt", async () => { + const id = await boss.send(WAITER_QUEUE, { probe: 1 }); + const [fetched] = await boss.fetch(WAITER_QUEUE); + expect(fetched?.id).toBe(id); + expect((await row(id!))?.state).toBe("active"); + + expect(await deferLaneJobs(WAITER_QUEUE, [fetched!], 30)).toBe(1); + expect(await row(id!)).toMatchObject({ + state: "created", + retry_count: 0, + started_on: null, + future: true, + }); + // Not claimable before its time. + expect(await boss.fetch(WAITER_QUEUE)).toEqual([]); + // pg-boss's completion of the handler finds no active row to settle. + await boss.complete(WAITER_QUEUE, id!); + expect((await row(id!))?.state).toBe("created"); + await boss.deleteJob(WAITER_QUEUE, id!); + }); + + it("leaves a job alone that is no longer active", async () => { + const id = await boss.send(WAITER_QUEUE, { probe: 2 }); + const job = { id, name: WAITER_QUEUE, data: {} } as unknown as Job; + expect(await deferLaneJobs(WAITER_QUEUE, [job], 30)).toBe(0); + expect((await row(id!))?.future).toBe(false); + await boss.deleteJob(WAITER_QUEUE, id!); + }); +}); + +describe("a heavy job behind a long one", () => { + it("waits in the queue, not in the handler, and runs once after it", async () => { + const log: string[] = []; + const deliveries: string[] = []; + const shortDefer = (queue: string, jobs: readonly Job[]) => + deferLaneJobs(queue, jobs, 1); + + await boss.work( + HOLDER_QUEUE, + WORK, + heavyLane( + HOLDER_QUEUE, + async () => { + log.push("start:holder"); + await sleep(6_000); + log.push("end:holder"); + return jobDone({ jobs: 1 }); + }, + undefined, + shortDefer, + ), + ); + await boss.work( + WAITER_QUEUE, + WORK, + heavyLane( + WAITER_QUEUE, + async () => { + log.push("run:waiter"); + return jobDone({ jobs: 1 }); + }, + undefined, + async (queue, jobs) => { + deliveries.push(jobs[0]!.id); + return shortDefer(queue, jobs); + }, + ), + ); + + await boss.send(HOLDER_QUEUE, {}, { expireInSeconds: 60 }); + await sleep(1_000); + const waiter = await boss.send( + WAITER_QUEUE, + {}, + { expireInSeconds: 2, retryLimit: 0 }, + ); + + await sleep(9_000); + await boss.offWork(WAITER_QUEUE); + await boss.offWork(HOLDER_QUEUE); + + // Three times its expiry in line, and not a single failed attempt. + expect(await row(waiter!)).toMatchObject({ + state: "completed", + retry_count: 0, + }); + // Sent back several times while the holder ran, then run once after it. + expect(deliveries.length).toBeGreaterThanOrEqual(2); + expect(new Set(deliveries)).toEqual(new Set([waiter])); + expect(log).toEqual(["start:holder", "end:holder", "run:waiter"]); + }, 60_000); +}); From 456976175bdab9b3f835c2fc822acb4bcecbf59d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:32:34 +0200 Subject: [PATCH 02/19] test(sql): allow the lane's clock read against pg-boss's timestamptz column --- src/__tests__/sql-now-utc-guard.test.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/src/__tests__/sql-now-utc-guard.test.ts b/src/__tests__/sql-now-utc-guard.test.ts index 8846c7622..b64c5e313 100644 --- a/src/__tests__/sql-now-utc-guard.test.ts +++ b/src/__tests__/sql-now-utc-guard.test.ts @@ -26,6 +26,7 @@ const ALLOWED: Record = { "src/lib/rollups/medication-compliance-rollups.ts": "computed_at is timestamptz", "src/lib/jobs/job-failures.ts": "pg-boss tables are timestamptz", + "src/lib/jobs/heavy-lane.ts": "pg-boss start_after is timestamptz", "src/lib/jobs/reminder/registrar-shared.ts": "pg-boss tables are timestamptz", "src/lib/db-compat.ts": "DDL default on a timestamptz column", }; From 34eea153a8aad5b5ab206fc078effa82adcbeaab Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:33:15 +0200 Subject: [PATCH 03/19] fix(strava): resume an unfinished backfill where the last run stopped One run reads at most forty pages of a hundred activities. A longer history ended as incomplete with no note of how far it got, so every boot read the same newest pages again, spent up to 190 of the instance's 200 requests per fifteen minutes on them, and never reached the older activities. The run now records the start of the oldest activity it read and sends the next run for after the rate window; that run asks Strava for the activities before it. A run that gets no further records nothing and sends nothing. The place is cleared when the backfill completes. --- .../0413_strava_backfill_resume/migration.sql | 12 ++ prisma/schema.prisma | 5 + src/lib/data-wipe/wipe-plan.ts | 1 + src/lib/export/backup-plan.ts | 1 + src/lib/jobs/integration-backfill-drain.ts | 8 +- src/lib/jobs/strava-backfill.ts | 101 +++++++++--- .../__tests__/sync-cursor-durability.test.ts | 1 + .../strava/__tests__/sync-page-walk.test.ts | 150 +++++++++++++++--- src/lib/strava/client.ts | 4 + src/lib/strava/sync.ts | 59 ++++++- 10 files changed, 289 insertions(+), 53 deletions(-) create mode 100644 prisma/migrations/0413_strava_backfill_resume/migration.sql diff --git a/prisma/migrations/0413_strava_backfill_resume/migration.sql b/prisma/migrations/0413_strava_backfill_resume/migration.sql new file mode 100644 index 000000000..821446acc --- /dev/null +++ b/prisma/migrations/0413_strava_backfill_resume/migration.sql @@ -0,0 +1,12 @@ +-- Where an unfinished Strava backfill picks up. +-- +-- One backfill run reads at most forty pages of a hundred activities. A +-- longer history ended the run as incomplete without a note of how far it +-- got, so every boot read the same newest forty pages again, up to 190 of +-- the 200 requests the whole instance may make in fifteen minutes, and the +-- older history was never reached. The column holds the start of the oldest +-- activity the last run read; the next run asks for activities before it. +-- Nullable and unset for every existing row: an unfinished backfill starts +-- once more from the newest page and records its place from then on. + +ALTER TABLE "users" ADD COLUMN "strava_backfill_resume_before" TIMESTAMP(3); diff --git a/prisma/schema.prisma b/prisma/schema.prisma index 11fa3b2f5..05b4527d1 100644 --- a/prisma/schema.prisma +++ b/prisma/schema.prisma @@ -316,6 +316,11 @@ model User { // First-connect full-history backfill marker (self-converging discovery // predicate `strava_backfill_completed_at IS NULL`), mirroring WHOOP/Fitbit. stravaBackfillCompletedAt DateTime? @map("strava_backfill_completed_at") + // Where an unfinished backfill picks up: the start of the oldest activity + // the last run read. A history longer than one run's page ceiling is read + // in runs that each walk further back from here, instead of every run + // starting again at the newest page. Cleared when the backfill completes. + stravaBackfillResumeBefore DateTime? @map("strava_backfill_resume_before") // Locale (null = use system/admin default) locale String? @map("locale") // "de" | "en" | null diff --git a/src/lib/data-wipe/wipe-plan.ts b/src/lib/data-wipe/wipe-plan.ts index f1867dbce..447f8f180 100644 --- a/src/lib/data-wipe/wipe-plan.ts +++ b/src/lib/data-wipe/wipe-plan.ts @@ -469,6 +469,7 @@ export const USER_RESET = { stravaAthleteId: null, stravaLastActivityAt: null, stravaBackfillCompletedAt: null, + stravaBackfillResumeBefore: null, healthKitConfigJson: Prisma.DbNull, healthKitLastSyncedAt: null, healthKitLastSyncTrigger: null, diff --git a/src/lib/export/backup-plan.ts b/src/lib/export/backup-plan.ts index 25a1246e1..91e5dc74c 100644 --- a/src/lib/export/backup-plan.ts +++ b/src/lib/export/backup-plan.ts @@ -960,6 +960,7 @@ export const USER_COLUMN_BACKUP_CLASS = { coachLastSeenAt: "OPERATIONAL", stravaLastActivityAt: "OPERATIONAL", stravaBackfillCompletedAt: "OPERATIONAL", + stravaBackfillResumeBefore: "OPERATIONAL", healthKitLastSyncedAt: "OPERATIONAL", healthKitLastSyncTrigger: "OPERATIONAL", healthKitLastBackgroundSyncAt: "OPERATIONAL", diff --git a/src/lib/jobs/integration-backfill-drain.ts b/src/lib/jobs/integration-backfill-drain.ts index df6ad556e..15ed48fdf 100644 --- a/src/lib/jobs/integration-backfill-drain.ts +++ b/src/lib/jobs/integration-backfill-drain.ts @@ -132,11 +132,15 @@ async function runAdmitted( return; } case "strava-backfill": { - const { imported } = await runStravaBackfillForUser(userId); + const { imported, continued } = await runStravaBackfillForUser( + userId, + data.slice ?? 0, + ); totals.imported += imported; + if (continued) totals.continued += 1; workerLog( "info", - `[strava-backfill] user=${userId} imported=${imported}`, + `[strava-backfill] user=${userId} imported=${imported}${continued ? " continued" : ""}`, ); return; } diff --git a/src/lib/jobs/strava-backfill.ts b/src/lib/jobs/strava-backfill.ts index 539396dad..5c36fc905 100644 --- a/src/lib/jobs/strava-backfill.ts +++ b/src/lib/jobs/strava-backfill.ts @@ -17,13 +17,16 @@ import { prisma } from "@/lib/db"; import { annotate } from "@/lib/logging/context"; import { getGlobalBoss } from "@/lib/jobs/boss-instance"; -import { integrationBackfillSourceOptions } from "@/lib/jobs/integration-backfill-admission"; +import { + enqueueIntegrationBackfillAdmission, + integrationBackfillSourceOptions, +} from "@/lib/jobs/integration-backfill-admission"; import { isReauthRequired } from "@/lib/integrations/status"; import { backfillVerdict, withPageWalkLedger, } from "@/lib/integrations/page-walk"; -import { syncUserStrava } from "@/lib/strava/sync"; +import { syncStravaHistory } from "@/lib/strava/sync"; export const STRAVA_BACKFILL_QUEUE = "strava-backfill"; @@ -40,23 +43,38 @@ export interface StravaBackfillPayload { } /** - * Per-user backfill handler. Runs a full-history sync for one account and - * stamps `stravaBackfillCompletedAt` only when the walk read the whole - * history, so the discovery query drops it. Idempotent: the - * `(userId, source, externalId)` workout upsert is key-stable, so a re-run + * The pause before the next run of an unfinished backfill: Strava's + * short-term rate window. One run spends up to forty page reads and 150 + * detail reads of the 200 the app may make in fifteen minutes, so the next + * run waits for a fresh window rather than opening on a 429 or starving the + * hourly syncs. + */ +export const STRAVA_BACKFILL_CONTINUATION_DELAY_SECONDS = 15 * 60; + +/** + * Per-user backfill handler. Runs one stretch of the full-history walk for + * one account and stamps `stravaBackfillCompletedAt` only when the walk read + * to the start of the history, so the discovery query drops it. Idempotent: + * the `(userId, source, externalId)` workout upsert is key-stable, so a re-run * (e.g. a reboot mid-walk) overwrites rather than duplicating. * * Verdict-gated (`backfillVerdict`, `integrations/page-walk.ts`), like the - * WHOOP and Fitbit backfills. A failed sync throws out of `syncUserStrava` - * (failure recorded first) and pg-boss retries. An activity walk that reached - * its page ceiling with history left is not complete: the marker stays unset - * without a retry, and boot discovery offers the account again. A connection - * parked for re-authorisation returns without stamping and without a retry, - * since every attempt would meet the same dead grant. + * WHOOP and Fitbit backfills. A failed sync throws out of the walk (failure + * recorded first) and pg-boss retries. A walk that reached its page ceiling + * with history left is not complete: it records where it got to + * (`stravaBackfillResumeBefore`, the start of the oldest activity it read) + * and sends the next run for after the rate window, which asks for the + * activities before that point. Without the note every run began again at + * the newest page, read the same forty pages and never reached the rest. A + * run that got no further than the last one records nothing and sends + * nothing, and the next boot offers the account again. A connection parked + * for re-authorisation returns without stamping and without a retry, since + * every attempt would meet the same dead grant. */ export async function runStravaBackfillForUser( userId: string, -): Promise<{ imported: number }> { + slice: number = 0, +): Promise<{ imported: number; continued: boolean }> { if (await isReauthRequired(userId, "strava")) { annotate({ action: { @@ -64,27 +82,56 @@ export async function runStravaBackfillForUser( details: { imported: 0 }, }, }); - return { imported: 0 }; + return { imported: 0, continued: false }; } - const { result: imported, truncated } = await withPageWalkLedger(() => - syncUserStrava(userId, { fullSync: true }), + const stored = await prisma.user.findUnique({ + where: { id: userId }, + select: { stravaBackfillResumeBefore: true }, + }); + const before = stored?.stravaBackfillResumeBefore ?? undefined; + const { result, truncated } = await withPageWalkLedger(() => + syncStravaHistory(userId, before), ); + const { imported, oldestStart } = result; // A failure has already thrown; what is left to decide is whether the walk // reached the beginning of the history. if (backfillVerdict({ failed: false, truncated }) === "incomplete") { + // One second past the oldest start, so an activity that shares it is + // read again rather than skipped; the upsert makes the overlap free. + const resumeBefore = oldestStart + ? new Date(oldestStart.getTime() + 1000) + : null; + const progressed = + resumeBefore !== null && + (before === undefined || resumeBefore.getTime() < before.getTime()); + if (progressed) { + await prisma.user.update({ + where: { id: userId }, + data: { stravaBackfillResumeBefore: resumeBefore }, + }); + } + const continued = progressed && (await sendNextRun(userId, slice)); annotate({ action: { name: "strava.backfill.truncated", - details: { imported, collections: truncated.join(",") }, + details: { + imported, + collections: truncated.join(","), + progressed, + continued, + }, }, }); - return { imported }; + return { imported, continued }; } await prisma.user.update({ where: { id: userId }, - data: { stravaBackfillCompletedAt: new Date() }, + data: { + stravaBackfillCompletedAt: new Date(), + stravaBackfillResumeBefore: null, + }, }); annotate({ @@ -93,7 +140,21 @@ export async function runStravaBackfillForUser( details: { imported }, }, }); - return { imported }; + return { imported, continued: false }; +} + +async function sendNextRun(userId: string, slice: number): Promise { + const boss = getGlobalBoss(); + if (!boss) return false; + const sent = await enqueueIntegrationBackfillAdmission( + boss, + { + kind: "strava-backfill", + data: { userId, enqueuedAt: new Date().toISOString(), slice: slice + 1 }, + }, + STRAVA_BACKFILL_CONTINUATION_DELAY_SECONDS, + ); + return Boolean(sent); } /** diff --git a/src/lib/strava/__tests__/sync-cursor-durability.test.ts b/src/lib/strava/__tests__/sync-cursor-durability.test.ts index 636e529ba..b4b9a9f84 100644 --- a/src/lib/strava/__tests__/sync-cursor-durability.test.ts +++ b/src/lib/strava/__tests__/sync-cursor-durability.test.ts @@ -182,6 +182,7 @@ describe("syncUserStrava cursor durability", () => { it("advances the backfill watermark after every workout is persisted", async () => { await expect(runStravaBackfillForUser("user-1")).resolves.toEqual({ imported: 3, + continued: false, }); expect(workouts.size).toBe(3); diff --git a/src/lib/strava/__tests__/sync-page-walk.test.ts b/src/lib/strava/__tests__/sync-page-walk.test.ts index 3f2f09f0e..395046631 100644 --- a/src/lib/strava/__tests__/sync-page-walk.test.ts +++ b/src/lib/strava/__tests__/sync-page-walk.test.ts @@ -11,13 +11,15 @@ const mocks = vi.hoisted(() => ({ fetchActivities: vi.fn(), annotate: vi.fn(), updateUser: vi.fn(), + findUser: vi.fn(), isReauthRequired: vi.fn(), + send: vi.fn(), })); vi.mock("@/lib/db", () => ({ prisma: { user: { - findUnique: vi.fn(async () => ({ stravaLastActivityAt: null })), + findUnique: mocks.findUser, updateMany: vi.fn(async () => ({ count: 1 })), update: mocks.updateUser, }, @@ -62,7 +64,7 @@ vi.mock("../client", async (importOriginal) => ({ fetchActivityById: vi.fn(async () => ({})), })); vi.mock("@/lib/jobs/boss-instance", () => ({ - getGlobalBoss: vi.fn(() => null), + getGlobalBoss: vi.fn(() => ({ send: mocks.send })), })); import { runStravaBackfillForUser } from "@/lib/jobs/strava-backfill"; @@ -71,27 +73,36 @@ import { syncUserStrava } from "../sync"; const PER_PAGE = 100; const BACKFILL_MAX_PAGES = 40; -/** A page of `n` activities; ids continue across pages. */ -function page(pageNo: number, n: number) { - return Array.from({ length: n }, (_, i) => { - const id = (pageNo - 1) * PER_PAGE + i + 1; - return { - id, - sport_type: "Run", - start_date: new Date(Date.UTC(2020, 0, 1) + id * 3_600_000).toISOString(), - moving_time: 1800, - elapsed_time: 1900, - average_heartrate: 140, - }; - }); +const HOUR = 3_600_000; +const T0 = Date.UTC(2020, 0, 1); + +/** Activity `id` of a history; a higher id started later. */ +function activity(id: number) { + return { + id, + sport_type: "Run", + start_date: new Date(T0 + id * HOUR).toISOString(), + moving_time: 1800, + elapsed_time: 1900, + average_heartrate: 140, + }; } -/** A history of `total` activities, served page by page. */ +/** + * A history of `total` activities served as Strava serves a walk without + * `after`: newest first, `before` (epoch seconds) cutting off the newer ones. + */ function history(total: number) { mocks.fetchActivities.mockImplementation( - async (_t: string, q: { page: number; perPage: number }) => { - const remaining = total - (q.page - 1) * q.perPage; - return page(q.page, Math.max(0, Math.min(q.perPage, remaining))); + async ( + _t: string, + q: { page: number; perPage: number; before?: number }, + ) => { + const ids = Array.from({ length: total }, (_, i) => total - i).filter( + (id) => q.before === undefined || T0 + id * HOUR < q.before * 1000, + ); + const from = (q.page - 1) * q.perPage; + return ids.slice(from, from + q.perPage).map(activity); }, ); } @@ -102,10 +113,30 @@ function truncatedAnnotations() { ); } +/** The resume point the user row holds, as the backfill writes it. */ +let resumeBefore: Date | null = null; + beforeEach(() => { vi.clearAllMocks(); + resumeBefore = null; mocks.isReauthRequired.mockResolvedValue(false); - mocks.updateUser.mockResolvedValue({ id: "user-1" }); + mocks.findUser.mockImplementation(async () => ({ + stravaLastActivityAt: null, + stravaBackfillResumeBefore: resumeBefore, + })); + mocks.updateUser.mockImplementation( + async ({ + data, + }: { + data: { stravaBackfillResumeBefore?: Date | null }; + }) => { + if ("stravaBackfillResumeBefore" in data) { + resumeBefore = data.stravaBackfillResumeBefore ?? null; + } + return { id: "user-1" }; + }, + ); + mocks.send.mockResolvedValue("job-next"); }); describe("Strava activity walk", () => { @@ -157,20 +188,42 @@ describe("Strava backfill verdict", () => { await expect(runStravaBackfillForUser("user-1")).resolves.toEqual({ imported: 3 * PER_PAGE - 1, + continued: false, }); expect(mocks.updateUser).toHaveBeenCalledWith({ where: { id: "user-1" }, - data: { stravaBackfillCompletedAt: expect.any(Date) }, + data: { + stravaBackfillCompletedAt: expect.any(Date), + stravaBackfillResumeBefore: null, + }, }); + expect(mocks.send).not.toHaveBeenCalled(); }); - it("leaves the marker unset, without a retry, when the walk was cut off", async () => { + it("records where a cut-off walk got to and sends the next run after the rate window", async () => { history((BACKFILL_MAX_PAGES + 1) * PER_PAGE); await expect(runStravaBackfillForUser("user-1")).resolves.toEqual({ imported: BACKFILL_MAX_PAGES * PER_PAGE, + continued: true, }); - expect(mocks.updateUser).not.toHaveBeenCalled(); + // The oldest activity read is id 101; the next run asks for those before. + expect(resumeBefore).toEqual(new Date(T0 + 101 * HOUR + 1000)); + expect(mocks.updateUser).not.toHaveBeenCalledWith( + expect.objectContaining({ + data: expect.objectContaining({ + stravaBackfillCompletedAt: expect.any(Date), + }), + }), + ); + expect(mocks.send).toHaveBeenCalledWith( + "integration-backfill-admission", + expect.objectContaining({ + kind: "strava-backfill", + data: expect.objectContaining({ userId: "user-1", slice: 1 }), + }), + expect.objectContaining({ startAfter: 15 * 60 }), + ); expect(mocks.annotate).toHaveBeenCalledWith( expect.objectContaining({ action: expect.objectContaining({ name: "strava.backfill.truncated" }), @@ -178,12 +231,63 @@ describe("Strava backfill verdict", () => { ); }); + it("goes on from the recorded place instead of the newest page, and finishes", async () => { + const total = (BACKFILL_MAX_PAGES + 10) * PER_PAGE; + history(total); + + await runStravaBackfillForUser("user-1"); + const firstRun = mocks.fetchActivities.mock.calls.length; + mocks.fetchActivities.mockClear(); + await expect(runStravaBackfillForUser("user-1", 1)).resolves.toEqual({ + imported: 10 * PER_PAGE + 1, + continued: false, + }); + + expect(firstRun).toBe(BACKFILL_MAX_PAGES); + // Every page of the second run asked for activities before the place + // the first one recorded (the oldest it read was id 1001), and the walk + // ended at the oldest activity. + const queries = mocks.fetchActivities.mock.calls.map(([, q]) => q); + expect(new Set(queries.map((q) => q.before))).toEqual( + new Set([(T0 + 1001 * HOUR) / 1000 + 1]), + ); + expect(queries.length).toBe(11); + expect(resumeBefore).toBeNull(); + expect(mocks.updateUser).toHaveBeenLastCalledWith({ + where: { id: "user-1" }, + data: { + stravaBackfillCompletedAt: expect.any(Date), + stravaBackfillResumeBefore: null, + }, + }); + }); + + it("records nothing and sends nothing when a run got no further than the last", async () => { + history((BACKFILL_MAX_PAGES + 1) * PER_PAGE); + // A place older than anything the walk can read past: the provider kept + // handing back the same newest pages. + mocks.fetchActivities.mockImplementation(async (_t, q) => + Array.from({ length: PER_PAGE }, (_, i) => + activity(5_000 - (q.page - 1) * PER_PAGE - i), + ), + ); + resumeBefore = new Date(T0); + + await expect(runStravaBackfillForUser("user-1")).resolves.toEqual({ + imported: BACKFILL_MAX_PAGES * PER_PAGE, + continued: false, + }); + expect(resumeBefore).toEqual(new Date(T0)); + expect(mocks.send).not.toHaveBeenCalled(); + }); + it("returns without walking or stamping while the connection waits for re-authorisation", async () => { mocks.isReauthRequired.mockResolvedValue(true); history(PER_PAGE); await expect(runStravaBackfillForUser("user-1")).resolves.toEqual({ imported: 0, + continued: false, }); expect(mocks.fetchActivities).not.toHaveBeenCalled(); expect(mocks.updateUser).not.toHaveBeenCalled(); diff --git a/src/lib/strava/client.ts b/src/lib/strava/client.ts index 4428f14e1..a5407f915 100644 --- a/src/lib/strava/client.ts +++ b/src/lib/strava/client.ts @@ -225,6 +225,8 @@ export interface StravaDetailedActivity extends StravaSummaryActivity { export interface FetchActivitiesQuery { /** Epoch SECONDS cursor — return activities started after this instant. */ after?: number; + /** Epoch SECONDS — return activities started before this instant. */ + before?: number; page?: number; perPage?: number; } @@ -269,6 +271,8 @@ export async function fetchActivities( const params = new URLSearchParams(); if (typeof query.after === "number") params.set("after", String(Math.floor(query.after))); + if (typeof query.before === "number") + params.set("before", String(Math.floor(query.before))); params.set("page", String(query.page ?? 1)); params.set("per_page", String(query.perPage ?? 100)); const json = await stravaGet( diff --git a/src/lib/strava/sync.ts b/src/lib/strava/sync.ts index 89070f8fd..7405530d0 100644 --- a/src/lib/strava/sync.ts +++ b/src/lib/strava/sync.ts @@ -102,10 +102,43 @@ export async function syncUserStrava( userId: string, opts: SyncUserStravaOptions = {}, ): Promise { + return (await runStravaSync(userId, opts)).imported; +} + +/** What one history run read, for the backfill to resume from. */ +export interface StravaHistoryRun { + imported: number; + /** + * The start of the oldest activity the run read, when the pages came + * newest first as Strava serves a walk without `after`; null otherwise, + * so a place is never recorded from pages in an order the resume does not + * expect. + */ + oldestStart: Date | null; +} + +/** + * One run of the full-history walk, from `before` (or the newest activity) + * back as far as one run's page ceiling reaches. + */ +export async function syncStravaHistory( + userId: string, + before?: Date, +): Promise { + return runStravaSync(userId, { fullSync: true }, before); +} + +async function runStravaSync( + userId: string, + opts: SyncUserStravaOptions, + before?: Date, +): Promise { const conn = await getStravaConnection(userId); - if (!conn) return 0; + if (!conn) return { imported: 0, oldestStart: null }; const fullSync = opts.fullSync ?? false; + const beforeEpoch = + before === undefined ? undefined : Math.floor(before.getTime() / 1000); // Resolve the incremental cursor. On a full backfill we walk all history // (`after` omitted). Otherwise start at the stored newest-activity instant @@ -167,6 +200,9 @@ export async function syncUserStrava( let rows: StravaWorkoutRow[]; let newestStart: Date | null = null; + let oldestStart: Date | null = null; + let previousStart: number | null = null; + let newestFirst = true; try { // Strava pages by number; a short page is the last one. A walk that @@ -178,7 +214,12 @@ export async function syncUserStrava( async (cursor) => { const page = cursor ?? 1; const activities = await authed((t) => - fetchActivities(t, { after: afterEpoch, page, perPage: PER_PAGE }), + fetchActivities(t, { + after: afterEpoch, + before: beforeEpoch, + page, + perPage: PER_PAGE, + }), ); const mapped: StravaWorkoutRow[] = []; for (const a of activities) { @@ -212,11 +253,13 @@ export async function syncUserStrava( mapped.push(row); if (a.start_date) { const d = new Date(a.start_date); - if ( - !Number.isNaN(d.getTime()) && - (!newestStart || d > newestStart) - ) { - newestStart = d; + if (!Number.isNaN(d.getTime())) { + if (!newestStart || d > newestStart) newestStart = d; + if (!oldestStart || d < oldestStart) oldestStart = d; + if (previousStart !== null && d.getTime() > previousStart) { + newestFirst = false; + } + previousStart = d.getTime(); } } } @@ -270,7 +313,7 @@ export async function syncUserStrava( annotate({ action: { name: "strava.sync.complete", details: { imported } }, }); - return imported; + return { imported, oldestStart: newestFirst ? oldestStart : null }; } /** From d770f81278223627dfb09f0e2cd7da82203bab18 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:34:21 +0200 Subject: [PATCH 04/19] fix(integrations): end a page walk on an empty cursor WHOOP and Oura answer the last page with an empty next_token as well as with null. The walk followed the empty string as a cursor, the client sent no token, read the first page a second time and the walk ended as a repeat, so the records came in twice and the backfill stayed incomplete for good. An empty cursor now ends the walk, for every provider that walks through it. --- .../integrations/__tests__/page-walk.test.ts | 10 ++++++++++ src/lib/integrations/page-walk.ts | 19 ++++++++++++++++--- src/lib/oura/__tests__/client.test.ts | 17 +++++++++++++++++ src/lib/whoop/__tests__/client.test.ts | 10 ++++++++++ 4 files changed, 53 insertions(+), 3 deletions(-) diff --git a/src/lib/integrations/__tests__/page-walk.test.ts b/src/lib/integrations/__tests__/page-walk.test.ts index 69980ff49..4db821965 100644 --- a/src/lib/integrations/__tests__/page-walk.test.ts +++ b/src/lib/integrations/__tests__/page-walk.test.ts @@ -32,6 +32,16 @@ describe("walkPages", () => { expect(walk.items).toEqual([0, 1, 2, 3]); }); + it("ends on an empty cursor instead of following it back to the first page", async () => { + const fetchPage = vi.fn(async (cursor: string | undefined) => ({ + items: [cursor ?? "first"], + next: "", + })); + const walk = await walkPages("test.empty", 10, fetchPage); + expect(walk).toEqual({ items: ["first"], pages: 1, truncated: false }); + expect(fetchPage).toHaveBeenCalledTimes(1); + }); + it("stops on a cursor it already followed, the first one included", async () => { const fetchPage = vi.fn(async () => ({ items: [1], next: 0 })); const walk = await walkPages( diff --git a/src/lib/integrations/page-walk.ts b/src/lib/integrations/page-walk.ts index 08af1771d..b8b92f451 100644 --- a/src/lib/integrations/page-walk.ts +++ b/src/lib/integrations/page-walk.ts @@ -15,7 +15,14 @@ * The backfill contract (`backfillVerdict`), the same for every provider: * - a failed collection is transient: the job throws and pg-boss retries; * - a truncated collection is not complete: the marker is not stamped, and - * boot discovery offers the account again, without a retry storm; + * boot discovery offers the account again, without a retry storm. Where + * a real history can outrun the ceiling (Strava's forty pages, about + * 4 000 activities), the backfill records how far it got and the next + * run goes on from there (`strava-backfill.ts`), or each run would read + * the same newest pages again. The other ceilings sit far above any + * history (a thousand pages for WHOOP and Withings), so a truncation + * there is a cursor that does not advance, which no resume can cure; + * the repeat check ends it on the first page it would read twice; * - a connection parked for re-authorisation is permanent until the person * reconnects: the runner returns without stamping and without a retry. * @@ -32,7 +39,13 @@ import { AsyncLocalStorage } from "node:async_hooks"; import { annotate } from "@/lib/logging/context"; -/** One page as the client read it. A null `next` ends the walk. */ +/** + * One page as the client read it. A null, absent or empty `next` ends the + * walk: WHOOP and Oura answer the last page with `next_token: ""` as well as + * with null, and an empty token followed as a cursor is no cursor at all, so + * the client asked for the first page again, read it twice and the walk + * ended as a repeat, leaving the backfill incomplete for good. + */ export interface WalkPage { items: readonly T[]; next: C | null | undefined; @@ -66,7 +79,7 @@ export async function walkPages( const result = await fetchPage(cursor, page); items.push(...result.items); const next = result.next; - if (next === null || next === undefined) { + if (next === null || next === undefined || next === "") { return { items, pages: page + 1, truncated: false }; } if (seen.has(next)) return truncated(label, items, page + 1, "repeat"); diff --git a/src/lib/oura/__tests__/client.test.ts b/src/lib/oura/__tests__/client.test.ts index b8e6b0893..e4c6148df 100644 --- a/src/lib/oura/__tests__/client.test.ts +++ b/src/lib/oura/__tests__/client.test.ts @@ -286,6 +286,23 @@ describe("fetchReadiness pagination", () => { }); expect(r).toHaveLength(2); }); + + it("ends on an empty next_token without reading the first page again", async () => { + const page = { + status: 200, + body: { + data: [{ id: "1", day: "2026-06-09", score: 70 }], + next_token: "", + }, + }; + const fetchMock = installFetchMock([page, page]); + const r = await fetchReadiness("tok", { + startDate: "2026-06-01", + endDate: "2026-06-10", + }); + expect(r).toHaveLength(1); + expect(fetchMock).toHaveBeenCalledTimes(1); + }); }); describe("mapReadiness", () => { diff --git a/src/lib/whoop/__tests__/client.test.ts b/src/lib/whoop/__tests__/client.test.ts index b5e4cab9c..fa0db0f1b 100644 --- a/src/lib/whoop/__tests__/client.test.ts +++ b/src/lib/whoop/__tests__/client.test.ts @@ -138,6 +138,16 @@ describe("fetchCollection pagination", () => { expect(fetchMock).toHaveBeenCalledTimes(1); }); + it("ends on an empty next_token without reading the first page again", async () => { + const fetchMock = installFetchMock([ + { status: 200, body: { records: [{ id: 1 }], next_token: "" } }, + { status: 200, body: { records: [{ id: 1 }], next_token: "" } }, + ]); + const recs = await fetchRecoveries("at"); + expect(recs).toHaveLength(1); + expect(fetchMock).toHaveBeenCalledTimes(1); + }); + it("throws WhoopApiError when a page returns 500", async () => { installFetchMock([{ status: 500, body: { error: "boom" } }]); await expect(fetchRecoveries("at")).rejects.toBeInstanceOf(WhoopApiError); From a7f1e72bad439163e7e03564482c5a3569f7233c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:38:29 +0200 Subject: [PATCH 05/19] fix(maintenance): leave vacuuming measurements to autovacuum Migration 0412 starts autovacuum on the table at 5 % dead rows, and the nightly check vacuumed at 10 %, a point autovacuum had always passed first. Two triggers for one task only hid which of them did it. The nightly check now measures and changes nothing: it warns when the dead rows reach four times autovacuum's threshold, which means autovacuum is not keeping up, and when the heap has outgrown its live rows. The operator's run keeps its steps. --- docs/ops/measurement-maintenance.md | 25 ++++---- .../measurement-maintenance-schedule.test.ts | 57 ++++++++++++------- src/lib/jobs/measurement-maintenance.ts | 53 ++++++++++------- 3 files changed, 86 insertions(+), 49 deletions(-) diff --git a/docs/ops/measurement-maintenance.md b/docs/ops/measurement-maintenance.md index 8429f15f8..d6a7865eb 100644 --- a/docs/ops/measurement-maintenance.md +++ b/docs/ops/measurement-maintenance.md @@ -137,8 +137,8 @@ it. ## Reading the result The run's wide event `job.measurement_maintenance` carries -`maintenance_outcome` (`completed`, `nothing_due`, `refused_purge_running`, -`failed`), the live and dead rows the run started from, the +`maintenance_outcome` (`completed`, `nothing_due` for the nightly check, +`refused_purge_running`, `failed`), the live and dead rows the run started from, the table and index sizes before and after, and `maintenance_steps`, one entry per step with its target, size before and after, and duration. The same sizes from `psql`: @@ -151,17 +151,22 @@ SELECT pg_size_pretty(pg_total_relation_size('measurements')) AS total, ## The nightly check Since v1.43.7 the same queue also runs by itself at 03:40 (Europe/Berlin). -That run names no steps: it reads the table's live and dead rows and runs a -plain `VACUUM (ANALYZE)` only when there are at least 10,000 dead rows and -more than one for every ten live ones. It never rebuilds an index, and a -plain vacuum stops neither reads nor writes. It shares the singleton key with -the run you start, so the two never overlap. The admin card keeps showing -only the runs you started. +That run names no steps and changes nothing: vacuuming the table is +autovacuum's job, which migration 0412 starts at 5 % dead rows instead of +Postgres's 20 %. The check reads the table's live and dead rows and warns +(`maintenance_autovacuum_behind` on the wide event) when there are at least +10,000 dead rows and more than one for every five live ones, four times the +point at which autovacuum should already have run. That means autovacuum is +not keeping up: look for a transaction left open for hours +(`pg_stat_activity`, `state = 'idle in transaction'`) or for autovacuum +workers busy elsewhere. The check never rebuilds an index. It shares the +singleton key with the run you start, so the two never overlap. The admin +card keeps showing only the runs you started. The check also measures how far the table file has grown past what its live rows need (`maintenance_bloat_factor` on the wide event, `bloat_factor` in the -job result). Past 3 it adds a warning to the event: a plain vacuum makes the -space reusable but does not shrink the file, and only `VACUUM FULL` does (see +job result). Past 3 it adds a warning to the event: a vacuum makes the space +reusable but does not shrink the file, and only `VACUUM FULL` does (see below). Why the table grew in the first place: until v1.43.7 an update that changed diff --git a/src/lib/jobs/__tests__/measurement-maintenance-schedule.test.ts b/src/lib/jobs/__tests__/measurement-maintenance-schedule.test.ts index 2a0eb28dc..da6ce0bbd 100644 --- a/src/lib/jobs/__tests__/measurement-maintenance-schedule.test.ts +++ b/src/lib/jobs/__tests__/measurement-maintenance-schedule.test.ts @@ -1,8 +1,11 @@ /** * The nightly measurements check: what it decides from the table's - * statistics. It vacuums only when dead rows pile up and never rebuilds; the + * statistics. It never vacuums and never rebuilds, since autovacuum owns the + * vacuuming (migration 0412); it warns when autovacuum falls behind. The * operator's run keeps the steps it names. */ +import { readFileSync } from "node:fs"; +import { join } from "node:path"; import { describe, expect, it, vi } from "vitest"; vi.mock("@/lib/db", () => ({ @@ -11,10 +14,11 @@ vi.mock("@/lib/db", () => ({ })); import { - DEAD_ROW_VACUUM_FLOOR, + AUTOVACUUM_SCALE_FACTOR, + DEAD_ROW_WARN_FLOOR, + autovacuumBehind, resolveSteps, tableHealth, - vacuumDue, type TableHealth, } from "@/lib/jobs/measurement-maintenance"; @@ -26,40 +30,53 @@ const health = (over: Partial = {}): TableHealth => ({ ...over, }); -describe("vacuumDue", () => { - it("vacuums once dead rows pass a tenth of the live ones", () => { - expect(vacuumDue(health({ deadRows: 100_001 }))).toBe(true); - expect(vacuumDue(health({ deadRows: 99_999 }))).toBe(false); +describe("autovacuumBehind", () => { + it("matches the threshold migration 0412 sets on the table", () => { + const migration = readFileSync( + join( + process.cwd(), + "prisma/migrations/0412_measurement_hot_updates/migration.sql", + ), + "utf8", + ); + expect(migration).toContain( + `autovacuum_vacuum_scale_factor = ${AUTOVACUUM_SCALE_FACTOR}`, + ); + }); + + it("warns once dead rows pass four times autovacuum's threshold", () => { + expect(autovacuumBehind(health({ deadRows: 200_001 }))).toBe(true); + expect(autovacuumBehind(health({ deadRows: 199_999 }))).toBe(false); }); it("leaves a small table alone below the floor", () => { expect( - vacuumDue(health({ liveRows: 100, deadRows: DEAD_ROW_VACUUM_FLOOR - 1 })), + autovacuumBehind( + health({ liveRows: 100, deadRows: DEAD_ROW_WARN_FLOOR - 1 }), + ), ).toBe(false); }); }); describe("resolveSteps", () => { - it("gives the nightly tick a vacuum when one is due and never a rebuild", () => { - expect(resolveSteps({}, health({ deadRows: 500_000 }))).toEqual({ - vacuum: true, - reindex: false, - }); - expect(resolveSteps(undefined, health())).toEqual({ - vacuum: false, - reindex: false, - }); + it("gives the nightly tick no step at all, whatever the dead rows", () => { + expect(resolveSteps({})).toEqual({ vacuum: false, reindex: false }); + expect(resolveSteps(undefined)).toEqual({ vacuum: false, reindex: false }); }); - it("keeps the operator's steps whatever the statistics say", () => { - expect(resolveSteps({ vacuum: false, reindex: true }, health())).toEqual({ + it("keeps the operator's steps", () => { + expect(resolveSteps({ vacuum: false, reindex: true })).toEqual({ vacuum: false, reindex: true, }); - expect(resolveSteps({ vacuum: true, reindex: false }, health())).toEqual({ + expect(resolveSteps({ vacuum: true, reindex: false })).toEqual({ vacuum: true, reindex: false, }); + expect(resolveSteps({ vacuum: true })).toEqual({ + vacuum: true, + reindex: true, + }); }); }); diff --git a/src/lib/jobs/measurement-maintenance.ts b/src/lib/jobs/measurement-maintenance.ts index b48ad7b96..a5e4efa0f 100644 --- a/src/lib/jobs/measurement-maintenance.ts +++ b/src/lib/jobs/measurement-maintenance.ts @@ -11,12 +11,16 @@ * (cookie-only admin), with the steps named; the rebuild only ever runs * this way, in a window the operator picks. * - The nightly check (`MEASUREMENT_MAINTENANCE_CRON`, a tick without - * steps). It reads the table's dead and live rows and vacuums only when - * the dead ones pass `vacuumDue`. A plain VACUUM takes no lock that stops - * reads or writes. It also measures how far the heap has grown past its - * live rows (`TableHealth.bloatFactor`); only a rewrite (`VACUUM FULL`, - * which locks the table) gives that space back, so past - * `TABLE_BLOAT_WARN_FACTOR` the run warns instead of acting. + * steps). It measures and never acts. Vacuuming the table is + * autovacuum's job, at the 5 % dead-row threshold migration 0412 gives + * the table; a second trigger here at 10 % never fired before autovacuum + * had already run, and two mechanisms for one task only hide which of + * them is doing it. The check warns when the dead rows pass + * `AUTOVACUUM_BEHIND_SHARE`, which means autovacuum is not keeping up + * (a long transaction holding it back, too few workers), and when the + * heap has grown past its live rows (`TableHealth.bloatFactor`) further + * than `TABLE_BLOAT_WARN_FACTOR`, which only a rewrite (`VACUUM FULL`, + * which locks the table) gives back. * * Why the indexes: after the purge the heap is small, but a B-tree does not * give back the pages its deleted entries held. VACUUM marks the heap space @@ -84,11 +88,17 @@ export interface MaintenanceSteps { /** 03:40 Europe/Berlin, inside the nightly maintenance band. */ export const MEASUREMENT_MAINTENANCE_CRON = "40 3 * * *"; -/** Dead rows, as a share of live ones, past which the nightly check vacuums. */ -export const DEAD_ROW_VACUUM_SHARE = 0.1; +/** The dead-row share at which autovacuum starts on the table (0412). */ +export const AUTOVACUUM_SCALE_FACTOR = 0.05; -/** Fewer dead rows than this are never worth a vacuum of their own. */ -export const DEAD_ROW_VACUUM_FLOOR = 10_000; +/** + * Dead rows, as a share of live ones, past which the nightly check warns + * that autovacuum is behind: four times its own threshold. + */ +export const AUTOVACUUM_BEHIND_SHARE = 4 * AUTOVACUUM_SCALE_FACTOR; + +/** Fewer dead rows than this are never worth a warning. */ +export const DEAD_ROW_WARN_FLOOR = 10_000; /** * Heap size against what the live rows need, past which the run warns that @@ -230,26 +240,25 @@ export async function tableHealth( }; } -/** Whether the dead rows are worth a vacuum of their own tonight. */ -export function vacuumDue(health: TableHealth): boolean { +/** Whether the dead rows say autovacuum is not keeping up with the table. */ +export function autovacuumBehind(health: TableHealth): boolean { return ( - health.deadRows >= DEAD_ROW_VACUUM_FLOOR && - health.deadRows > health.liveRows * DEAD_ROW_VACUUM_SHARE + health.deadRows >= DEAD_ROW_WARN_FLOOR && + health.deadRows > health.liveRows * AUTOVACUUM_BEHIND_SHARE ); } /** - * The steps a delivery takes: the operator's as asked, the nightly tick's a - * vacuum when one is due and never a rebuild. + * The steps a delivery takes: the operator's as asked, none for the nightly + * tick, which only measures. */ export function resolveSteps( payload: MeasurementMaintenancePayload | undefined, - health: TableHealth, ): MaintenanceSteps { const named = typeof payload?.vacuum === "boolean" || typeof payload?.reindex === "boolean"; - if (!named) return { vacuum: vacuumDue(health), reindex: false }; + if (!named) return { vacuum: false, reindex: false }; return { vacuum: payload?.vacuum ?? true, reindex: payload?.reindex ?? true }; } @@ -459,7 +468,7 @@ export async function handleMeasurementMaintenance( } } const health = await tableHealth(client); - const steps = resolveSteps(job?.data, health); + const steps = resolveSteps(job?.data); const summary = await runMeasurementMaintenance(client, steps); return { summary, health, steps }; } finally { @@ -486,6 +495,12 @@ export async function handleMeasurementMaintenance( evt.addMeta("maintenance_live_rows", health.liveRows); evt.addMeta("maintenance_dead_rows", health.deadRows); evt.addMeta("maintenance_heap_bytes", health.heapBytes); + if (autovacuumBehind(health)) { + evt.addMeta("maintenance_autovacuum_behind", true); + evt.addWarning( + `measurements holds ${health.deadRows} dead rows against ${health.liveRows} live; autovacuum starts at ${AUTOVACUUM_SCALE_FACTOR * 100} % and is not keeping up (look for a long-open transaction or too few autovacuum workers)`, + ); + } if (health.bloatFactor !== null) { evt.addMeta("maintenance_bloat_factor", health.bloatFactor); if (health.bloatFactor > TABLE_BLOAT_WARN_FACTOR) { From c782fa060a377e2815a31113db818f35fa59d538 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:38:29 +0200 Subject: [PATCH 06/19] fix(migrations): bound 0412's lock wait on measurements CREATE TRIGGER waits for an autovacuum that is preventing wraparound, and every write to the table queues behind the waiting request, the running release's included. SET LOCAL lock_timeout fails the migration after ten seconds instead, and the file rolls back whole. --- .../migration.sql | 12 +++++ .../measurement-hot-update.test.ts | 54 +++++++++++++++++-- 2 files changed, 62 insertions(+), 4 deletions(-) diff --git a/prisma/migrations/0412_measurement_hot_updates/migration.sql b/prisma/migrations/0412_measurement_hot_updates/migration.sql index b1123119c..6846cee4f 100644 --- a/prisma/migrations/0412_measurement_hot_updates/migration.sql +++ b/prisma/migrations/0412_measurement_hot_updates/migration.sql @@ -23,6 +23,18 @@ -- -- `to_jsonb(row)` compares every column, so a column added later is covered -- without touching this function. +-- +-- Lock wait. `CREATE TRIGGER` takes SHARE ROW EXCLUSIVE on the table and the +-- `ALTER TABLE ... SET` SHARE UPDATE EXCLUSIVE; both wait for an autovacuum +-- that is preventing wraparound, which does not step aside, and while they +-- wait every write to `measurements` queues behind them, including the ones +-- the running release still serves during a deploy. `migrate deploy` runs the +-- whole file as one transaction, so `SET LOCAL` bounds the wait for this file +-- alone: past ten seconds the migration fails and rolls back whole, the +-- writes go on, and the next deploy tries again once `prisma migrate resolve +-- --rolled-back 0412_measurement_hot_updates` has cleared the failed attempt. + +SET LOCAL lock_timeout = '10s'; CREATE OR REPLACE FUNCTION "measurements_keep_stamps_on_noop"() RETURNS trigger LANGUAGE plpgsql AS $$ diff --git a/tests/integration/measurement-hot-update.test.ts b/tests/integration/measurement-hot-update.test.ts index 7c9963da3..731809db6 100644 --- a/tests/integration/measurement-hot-update.test.ts +++ b/tests/integration/measurement-hot-update.test.ts @@ -7,9 +7,12 @@ * grew the table by a full row version and an entry in every index. Proven * here against Postgres: the no-op update keeps `updated_at` and * `sync_version` and is counted as HOT in the transaction's own statistics, - * a real change still moves both, and the nightly check reads the table's - * statistics and vacuums only when dead rows pass its threshold. + * a real change still moves both, the nightly check reads the table's + * statistics and leaves the vacuuming to autovacuum, and the migration gives + * up on a lock it cannot get instead of queueing every writer behind it. */ +import { readFileSync } from "node:fs"; +import { join } from "node:path"; import { Client } from "pg"; import { beforeEach, describe, expect, it } from "vitest"; @@ -100,7 +103,7 @@ describe("an update that changes nothing", () => { }); describe("the nightly check", () => { - it("reads the statistics and does nothing while no vacuum is due", async () => { + it("reads the statistics and leaves the vacuuming to autovacuum", async () => { await seedReading(); const db = new Client({ connectionString: process.env.DATABASE_URL }); await db.connect(); @@ -108,7 +111,7 @@ describe("the nightly check", () => { await db.query("ANALYZE measurements"); const health = await tableHealth(db); expect(health.heapBytes).toBeGreaterThan(0); - const steps = resolveSteps({}, health); + const steps = resolveSteps({}); expect(steps).toEqual({ vacuum: false, reindex: false }); const summary = await runMeasurementMaintenance(db, steps); expect(summary.outcome).toBe("nothing_due"); @@ -118,3 +121,46 @@ describe("the nightly check", () => { } }); }); + +describe("the migration's lock wait", () => { + it("fails within its lock timeout while another session holds the table", async () => { + // The migration's own text under fresh names, run the way `migrate + // deploy` runs a file: one multi-statement query, one transaction. + const sql = readFileSync( + join( + process.cwd(), + "prisma/migrations/0412_measurement_hot_updates/migration.sql", + ), + "utf8", + ) + .replaceAll("measurements_keep_stamps_on_noop", "lock_probe_fn") + .replaceAll("measurements_noop_update_keeps_stamps", "lock_probe_trg"); + const holder = new Client({ connectionString: process.env.DATABASE_URL }); + const migrator = new Client({ connectionString: process.env.DATABASE_URL }); + await holder.connect(); + await migrator.connect(); + try { + // What an anti-wraparound autovacuum holds, and does not give up. + await holder.query("BEGIN"); + await holder.query( + "LOCK TABLE measurements IN SHARE UPDATE EXCLUSIVE MODE", + ); + const startedAt = Date.now(); + const error = await migrator.query(sql).then( + () => null, + (err: { code?: string }) => err, + ); + expect(error?.code).toBe("55P03"); + expect(Date.now() - startedAt).toBeLessThan(30_000); + // Rolled back whole: nothing of the probe is left behind. + const { rows } = await migrator.query( + "SELECT to_regproc('lock_probe_fn') AS fn", + ); + expect(rows[0].fn).toBeNull(); + } finally { + await holder.query("ROLLBACK").catch(() => {}); + await holder.end(); + await migrator.end(); + } + }, 60_000); +}); From 6eb7e508df26944eb17108fc41e99017c6f3547c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:45:19 +0200 Subject: [PATCH 07/19] test(measurements): a re-import that changes nothing keeps its syncVersion The second import of the same export writes every column of the step row as it already was (compared column by column), so the update is a no-op and migration 0412 keeps updated_at and sync_version. The test expected the version to move on every write; it now pins that it never goes backwards and stays where the first import left it. --- tests/integration/measurements-batch.test.ts | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/tests/integration/measurements-batch.test.ts b/tests/integration/measurements-batch.test.ts index 488abe332..91c1b0295 100644 --- a/tests/integration/measurements-batch.test.ts +++ b/tests/integration/measurements-batch.test.ts @@ -1266,7 +1266,7 @@ describe("POST /api/measurements/batch (real Postgres)", () => { }); }); - it("re-imports an XML estimate onto one row with monotonic syncVersion", async () => { + it("re-imports an XML estimate onto one row without moving its syncVersion", async () => { const prisma = getPrismaClient(); const xmlPath = writeCumulativeXml(); await streamParseExportXml({ @@ -1288,11 +1288,15 @@ describe("POST /api/measurements/batch (real Postgres)", () => { externalId: "stats:HKQuantityTypeIdentifierStepCount:2026-07-20", }, }); + // The second import writes the same value, provenance and every other + // column, so the update changes nothing and migration 0412 keeps the + // row's stamps: the phone is not sent a row that did not change. The + // version never goes backwards; it stays where the first import left it. expect(rows).toHaveLength(1); expect(rows[0]).toMatchObject({ value: 8_526, aggregationProvenance: "EXPORT_XML_SOURCE_MAX", - syncVersion: 2, + syncVersion: 1, }); }); From 5d1d6aa176a895ea296bc38c1f7e0b6384cb8397 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:47:03 +0200 Subject: [PATCH 08/19] perf(day): cache the notable history in fixed blocks Each cell ran from a 90-day block boundary to today, so paging back through days left a nearly full copy of the two years per boundary in an unweighted bucket, and a cold day long ago read everything from its window to today. The history is now cached in 90-day blocks that end before today (the block holding today ends at today and carries it in its key), a window is put together from the blocks it touches, and the blocks it misses are read in one query. A cell holds at most one block of days per type. --- .../__tests__/notable-history-cache.test.ts | 64 +++++++++- src/lib/day/notable.ts | 113 ++++++++++++------ 2 files changed, 139 insertions(+), 38 deletions(-) diff --git a/src/lib/day/__tests__/notable-history-cache.test.ts b/src/lib/day/__tests__/notable-history-cache.test.ts index dd050aea9..256ded2e3 100644 --- a/src/lib/day/__tests__/notable-history-cache.test.ts +++ b/src/lib/day/__tests__/notable-history-cache.test.ts @@ -6,7 +6,7 @@ * The slice has to give exactly what a live read of the window would: the * extremes depend on where the series starts. */ -import { beforeEach, describe, expect, it, vi } from "vitest"; +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; const readLocalDailyStats = vi.fn(); vi.mock("@/lib/day/daily-stats", () => ({ @@ -17,8 +17,8 @@ vi.mock("@/lib/db", () => ({ })); import type { MeasurementType } from "@/generated/prisma/enums"; -import { __resetAllCachesForTests } from "@/lib/cache/server-cache"; -import { shiftDateKey, userDayKey } from "@/lib/tz/format"; +import { __resetAllCachesForTests, caches } from "@/lib/cache/server-cache"; +import { daysBetweenDateKeys, shiftDateKey, userDayKey } from "@/lib/tz/format"; import { NOTABLE_LOOKBACK_DAYS, @@ -74,6 +74,11 @@ function load(day: string, extra: { floor?: Date } = {}) { }); } +/** The block a day falls in, as the cache counts them. */ +function blockOf(day: string): number { + return Math.floor(daysBetweenDateKeys("1970-01-01", day) / 90); +} + /** What a live read of the window gives. */ function expected(day: string) { const series: Array<[string, number]> = []; @@ -93,7 +98,14 @@ describe("notable history cache", () => { const before = await load(shiftDateKey(SPIKE, -1)); const after = await load(shiftDateKey(SPIKE, 1)); - expect(readLocalDailyStats).toHaveBeenCalledTimes(1); + // One read, plus one for an earlier block when the oldest of the three + // windows starts across a block boundary. + const starts = new Set( + [-1, 0, 1].map((d) => + blockOf(shiftDateKey(SPIKE, d - NOTABLE_LOOKBACK_DAYS)), + ), + ); + expect(readLocalDailyStats).toHaveBeenCalledTimes(starts.size); expect(spike).toEqual(expected(SPIKE)); expect(spike.map((n) => n.kind)).toEqual(["extremeHigh"]); expect(before).toEqual(expected(shiftDateKey(SPIKE, -1))); @@ -119,3 +131,47 @@ describe("notable history cache", () => { expect(args.from).toEqual(floor); }); }); + +describe("notable history cache size", () => { + const cached: number[] = []; + beforeEach(() => { + cached.length = 0; + const set = caches.analytics.set.bind(caches.analytics); + vi.spyOn(caches.analytics, "set").mockImplementation((key, value, ttl) => { + if (key.includes("|notable-history|")) { + let days = 0; + for (const series of ( + value as Map> + ).values()) { + days = Math.max(days, series.size); + } + cached.push(days); + } + set(key, value, ttl); + }); + }); + afterEach(() => vi.restoreAllMocks()); + + it("holds a block of days per cell, and paging back a year adds a block per quarter", async () => { + for (let back = 0; back < 365; back += 1) { + const day = shiftDateKey(TODAY, -back); + expect(await load(day)).toEqual(expected(day)); + } + // Two years of history plus the year paged through, in 90-day blocks, + // each cached once: about thirteen cells, never one per day. + const blocks = + blockOf(TODAY) - + blockOf(shiftDateKey(TODAY, -364 - NOTABLE_LOOKBACK_DAYS)) + + 1; + expect(cached.length).toBe(blocks); + expect(Math.max(...cached)).toBeLessThanOrEqual(90); + expect(readLocalDailyStats.mock.calls.length).toBeLessThanOrEqual(blocks); + }); + + it("reads a cold day long ago up to that day's block, not up to today", async () => { + const day = shiftDateKey(TODAY, -700); + expect(await load(day)).toEqual(expected(day)); + const [args] = readLocalDailyStats.mock.calls[0] as [{ to: Date }]; + expect(userDayKey(args.to, TZ) <= shiftDateKey(day, 91)).toBe(true); + }); +}); diff --git a/src/lib/day/notable.ts b/src/lib/day/notable.ts index 4f275680a..32ab02261 100644 --- a/src/lib/day/notable.ts +++ b/src/lib/day/notable.ts @@ -187,23 +187,41 @@ export async function readFirstReadings( return out; } -/** Cached history starts on a block boundary, so neighbouring days share it. */ +/** + * The history is cached in fixed blocks of local days counted from the + * epoch, so neighbouring days share them and a block's size never grows. + */ const HISTORY_BLOCK_DAYS = 90; const HISTORY_EPOCH = "1970-01-01"; -/** Measurement writes sweep the cell; the TTL only bounds an idle one. */ +/** Measurement writes sweep the cells; the TTL only bounds an idle one. */ const HISTORY_TTL_MS = 15 * 60_000; +/** The first day of the block holding `day`. */ +function blockStartOf(day: string): string { + const offset = daysBetweenDateKeys(HISTORY_EPOCH, day); + return shiftDateKey( + HISTORY_EPOCH, + Math.floor(offset / HISTORY_BLOCK_DAYS) * HISTORY_BLOCK_DAYS, + ); +} + /** * The daily series behind the extremes, for the local days `[from, to]`. * * Every day view compares its day with the two years before it, so paging * from one day to the next read the same two years again. The history is - * cached per record, zone, source ladder and readable type set, from a block - * boundary at or before `from` up to today, and each caller takes its own - * slice: a day's value does not depend on the window around it, and a slice - * cut at local day keys is exactly the window the live read would see. A - * type the record's modules switch off is never read. A lookback floor - * inside the window, or a window that reaches past today, reads live. + * cached per record, zone, source ladder and readable type set in blocks of + * {@link HISTORY_BLOCK_DAYS} days, and a window is put together from the + * blocks it touches: a day's value does not depend on the window around it, + * so a slice cut at local day keys is exactly what the live read would see. + * A block that ends before today is the same whatever day it is read on; the + * block holding today ends at today and carries today in its key. Each cell + * therefore holds at most one block of days per type, paging back reuses the + * blocks it already has instead of caching a near-full copy of the two years + * per block boundary, and a cold day long ago reads its own two years, not + * everything from there to today. The blocks a window misses are read in one + * query. A type the record's modules switch off is never read. A lookback + * floor inside the window, or a window that reaches past today, reads live. */ async function readExtremeHistory(args: { userId: string; @@ -216,51 +234,78 @@ async function readExtremeHistory(args: { }): Promise { const fromInstant = startOfLocalDayKey(args.from, args.tz); const today = userDayKey(new Date(), args.tz); - const live = (from: Date) => + const read = (from: Date, lastDay: string) => readLocalDailyStats({ userId: args.userId, types: args.readable, from, - to: startOfLocalDayKey(shiftDateKey(args.to, 1), args.tz), + to: startOfLocalDayKey(shiftDateKey(lastDay, 1), args.tz), tz: args.tz, priorityJson: args.priorityJson, }); - if (args.floor && args.floor > fromInstant) return live(args.floor); - if (args.to > today) return live(fromInstant); + if (args.floor && args.floor > fromInstant) return read(args.floor, args.to); + if (args.to > today) return read(fromInstant, args.to); - const offset = daysBetweenDateKeys(HISTORY_EPOCH, args.from); - const blockStart = shiftDateKey( - HISTORY_EPOCH, - Math.floor(offset / HISTORY_BLOCK_DAYS) * HISTORY_BLOCK_DAYS, - ); const ladder = createHash("sha256") .update(JSON.stringify(args.priorityJson ?? null)) .digest("base64url") .slice(0, 16); - const key = [ + const prefix = [ args.userId, "notable-history", args.tz, ladder, [...args.readable].sort().join(","), - blockStart, - today, ].join("|"); const cache = caches.analytics as ServerCache; - const { value } = await cache.wrap( - key, - () => - readLocalDailyStats({ - userId: args.userId, - types: args.readable, - from: startOfLocalDayKey(blockStart, args.tz), - to: startOfLocalDayKey(shiftDateKey(today, 1), args.tz), - tz: args.tz, - priorityJson: args.priorityJson, - }), - HISTORY_TTL_MS, - ); - return sliceDays(value, args.from, args.to); + + const blocks: Array<{ start: string; end: string; key: string }> = []; + for ( + let start = blockStartOf(args.from); + start <= args.to; + start = shiftDateKey(start, HISTORY_BLOCK_DAYS) + ) { + const last = shiftDateKey(start, HISTORY_BLOCK_DAYS - 1); + const open = last >= today; + blocks.push({ + start, + end: open ? today : last, + key: `${prefix}|${start}|${open ? today : "closed"}`, + }); + } + + const found = new Map(); + const missing = blocks.filter((block) => { + const hit = cache.get(block.key); + if (hit) found.set(block.key, hit); + return !hit; + }); + if (missing.length > 0) { + const first = missing[0]!; + const last = missing[missing.length - 1]!; + const stats = await read( + startOfLocalDayKey(first.start, args.tz), + last.end, + ); + for (const block of blocks) { + if (block.start < first.start || block.end > last.end) continue; + const cell = sliceDays(stats, block.start, block.end); + cache.set(block.key, cell, HISTORY_TTL_MS); + found.set(block.key, cell); + } + } + + const out: DailyStats = new Map(); + for (const block of blocks) { + for (const [type, days] of found.get(block.key) ?? new Map()) { + const into = out.get(type) ?? new Map(); + for (const [day, value] of days) { + if (day >= args.from && day <= args.to) into.set(day, value); + } + out.set(type, into); + } + } + return out; } /** The days of `stats` inside `[from, to]`, a copy. */ From 5fdddaec0aac69ea901b02337d9007cbaf0a0888 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:51:12 +0200 Subject: [PATCH 09/19] test(guards): strip comments through the shared scanner --- ...lation-single-implementation-guard.test.ts | 6 +---- .../dose-ledger-single-source-guard.test.ts | 6 +---- .../insights-cached-text-access-guard.test.ts | 15 +++---------- .../latest-per-type-read-guard.test.ts | 22 +++++++------------ .../naive-timestamp-zone-shift-guard.test.ts | 16 ++++++-------- 5 files changed, 20 insertions(+), 45 deletions(-) diff --git a/src/__tests__/correlation-single-implementation-guard.test.ts b/src/__tests__/correlation-single-implementation-guard.test.ts index f9697ab84..708118b23 100644 --- a/src/__tests__/correlation-single-implementation-guard.test.ts +++ b/src/__tests__/correlation-single-implementation-guard.test.ts @@ -21,7 +21,7 @@ import { readFileSync } from "node:fs"; import { join } from "node:path"; import { describe, expect, it } from "vitest"; -import { walkSourceFiles } from "./helpers/source-files"; +import { stripComments, walkSourceFiles } from "./helpers/source-files"; const SRC = join(process.cwd(), "src"); @@ -34,10 +34,6 @@ const PEARSON_DEFINITION = /(?:function\s+|const\s+)\w*(?:pearson|correlationCoefficient)\w*\s*(?:=|\()/i; const DELETED = /(? diff --git a/src/__tests__/dose-ledger-single-source-guard.test.ts b/src/__tests__/dose-ledger-single-source-guard.test.ts index aff5974b4..071e24536 100644 --- a/src/__tests__/dose-ledger-single-source-guard.test.ts +++ b/src/__tests__/dose-ledger-single-source-guard.test.ts @@ -16,7 +16,7 @@ import { readFileSync } from "node:fs"; import { join } from "node:path"; import { describe, expect, it } from "vitest"; -import { walkSourceFiles } from "./helpers/source-files"; +import { stripComments, walkSourceFiles } from "./helpers/source-files"; const SRC = join(process.cwd(), "src"); @@ -31,10 +31,6 @@ const CALLERS: Record = { const CALL = /\breconstructDoseHistory\s*\(/; -function stripComments(text: string): string { - return text.replace(/\/\*[\s\S]*?\*\//g, "").replace(/^\s*\/\/.*$/gm, ""); -} - describe("one compliance ledger", () => { it("the dose rows are built only where this file says", () => { const callers = walkSourceFiles(SRC, { floor: 3000 }) diff --git a/src/__tests__/insights-cached-text-access-guard.test.ts b/src/__tests__/insights-cached-text-access-guard.test.ts index e9121158b..f5cff3900 100644 --- a/src/__tests__/insights-cached-text-access-guard.test.ts +++ b/src/__tests__/insights-cached-text-access-guard.test.ts @@ -19,7 +19,7 @@ import { join } from "node:path"; import { describe, expect, it } from "vitest"; -import { walkSourceFiles } from "./helpers/source-files"; +import { stripComments, walkSourceFiles } from "./helpers/source-files"; const SRC = join(process.cwd(), "src"); @@ -37,24 +37,15 @@ const ALLOWED: Readonly> = { "fills that input field from openInsightsCachedText", }; -/** The legacy name, not its sealed sibling, outside comment lines. */ +/** The legacy name, not its sealed sibling, outside comments. */ const LEGACY_NAME = /\binsightsCachedText\b(?!Encrypted)/; -function codeLines(source: string): string[] { - return source.split("\n").filter((line) => { - const t = line.trim(); - return !(t.startsWith("*") || t.startsWith("//") || t.startsWith("/*")); - }); -} - function filesSpellingTheLegacyName(): string[] { return walkSourceFiles(SRC, { floor: 2000 }) .filter((f) => !f.startsWith("generated/")) .filter((f) => !f.includes("__tests__/") && !/\.test\.tsx?$/.test(f)) .filter((f) => - codeLines(readFileSync(join(SRC, f), "utf8")).some((l) => - LEGACY_NAME.test(l), - ), + LEGACY_NAME.test(stripComments(readFileSync(join(SRC, f), "utf8"))), ); } diff --git a/src/__tests__/latest-per-type-read-guard.test.ts b/src/__tests__/latest-per-type-read-guard.test.ts index a0e7eb796..21f38c950 100644 --- a/src/__tests__/latest-per-type-read-guard.test.ts +++ b/src/__tests__/latest-per-type-read-guard.test.ts @@ -21,17 +21,15 @@ import { readFileSync } from "node:fs"; import { join } from "node:path"; import { describe, expect, it } from "vitest"; -import { walkSourceFiles } from "./helpers/source-files"; +import { stripComments, walkSourceFiles } from "./helpers/source-files"; + +/** The shared comment strip, plus SQL line comments inside template strings. */ +function stripCode(text: string): string { + return stripComments(text).replace(/^\s*--.*$/gm, ""); +} const SRC = join(process.cwd(), "src"); -function stripComments(text: string): string { - return text - .replace(/\/\*[\s\S]*?\*\//g, "") - .replace(/^\s*\/\/.*$/gm, "") - .replace(/^\s*--.*$/gm, ""); -} - /** `DISTINCT ON (type)` or `DISTINCT ON (m."type")`, the type alone. */ const LATEST_PER_TYPE = /DISTINCT\s+ON\s*\(\s*(?:\w+\s*\.\s*)?"?type"?\s*\)/i; @@ -64,18 +62,14 @@ describe("latest-per-type reads", () => { it("no production read keeps one row per type with DISTINCT ON", () => { const offenders = productionFiles().filter((file) => - LATEST_PER_TYPE.test( - stripComments(readFileSync(join(SRC, file), "utf8")), - ), + LATEST_PER_TYPE.test(stripCode(readFileSync(join(SRC, file), "utf8"))), ); expect(offenders).toEqual([]); }); it("the summaries slice is built only behind its cache cell", () => { const callers = productionFiles().filter((file) => - SLICE_BUILDER_CALL.test( - stripComments(readFileSync(join(SRC, file), "utf8")), - ), + SLICE_BUILDER_CALL.test(stripCode(readFileSync(join(SRC, file), "utf8"))), ); expect(callers).toEqual(["lib/analytics/summaries-slice.ts"]); }); diff --git a/src/__tests__/naive-timestamp-zone-shift-guard.test.ts b/src/__tests__/naive-timestamp-zone-shift-guard.test.ts index cfb111b5a..1ae978874 100644 --- a/src/__tests__/naive-timestamp-zone-shift-guard.test.ts +++ b/src/__tests__/naive-timestamp-zone-shift-guard.test.ts @@ -21,7 +21,12 @@ import { readFileSync } from "node:fs"; import { join } from "node:path"; import { describe, expect, it } from "vitest"; -import { walkSourceFiles } from "./helpers/source-files"; +import { stripComments, walkSourceFiles } from "./helpers/source-files"; + +/** The shared comment strip, plus SQL line comments inside template strings. */ +function stripCode(text: string): string { + return stripComments(text).replace(/^\s*--.*$/gm, ""); +} const SRC = join(process.cwd(), "src"); @@ -31,13 +36,6 @@ const SINGLE_SHIFT = const DOUBLE_SHIFT = /AT\s+TIME\s+ZONE\s+'UTC'\s*\)?\s*AT\s+TIME\s+ZONE\s+(?:\$\{|\$\d)/i; -function stripComments(text: string): string { - return text - .replace(/\/\*[\s\S]*?\*\//g, "") - .replace(/^\s*\/\/.*$/gm, "") - .replace(/^\s*--.*$/gm, ""); -} - describe("naive timestamp zone shifts", () => { it("the matcher fires on the single shift and spares the double one", () => { expect( @@ -62,7 +60,7 @@ describe("naive timestamp zone shifts", () => { !/\.test\.tsx?$/.test(file), ); const code = (file: string) => - stripComments(readFileSync(join(SRC, file), "utf8")); + stripCode(readFileSync(join(SRC, file), "utf8")); // The reads that shift correctly, so a sweep that reads nothing fails. const doubleShifts = files.filter((file) => DOUBLE_SHIFT.test(code(file))); expect(doubleShifts.length).toBeGreaterThanOrEqual(5); From 9b05d8c2159342cdf185e0cb701f09bef62a4fb3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:51:12 +0200 Subject: [PATCH 10/19] test(guards): derive the provider directories from the connection keys --- src/__tests__/helpers/provider-dirs.ts | 20 ++++++++++++++++ src/__tests__/page-walk-guard.test.ts | 32 +++++++++++--------------- 2 files changed, 33 insertions(+), 19 deletions(-) create mode 100644 src/__tests__/helpers/provider-dirs.ts diff --git a/src/__tests__/helpers/provider-dirs.ts b/src/__tests__/helpers/provider-dirs.ts new file mode 100644 index 000000000..9e2a187b4 --- /dev/null +++ b/src/__tests__/helpers/provider-dirs.ts @@ -0,0 +1,20 @@ +/** + * The directories under `src/lib` that hold a provider's client and sync, + * derived from the connection keys the product knows (`CONNECTION_KEYS`), + * so a guard over provider code cannot keep a list of its own that a new + * integration slips past. Each key is checked to be a directory: a key that + * names none fails here rather than narrowing a guard in silence. + */ +import { statSync } from "node:fs"; +import { join } from "node:path"; + +import { CONNECTION_KEYS } from "@/lib/integrations/connection-health"; + +const LIB = join(process.cwd(), "src", "lib"); + +export const PROVIDER_DIRS: readonly string[] = CONNECTION_KEYS.map((key) => { + if (!statSync(join(LIB, key), { throwIfNoEntry: false })?.isDirectory()) { + throw new Error(`provider-dirs: src/lib/${key} is not a directory`); + } + return key; +}); diff --git a/src/__tests__/page-walk-guard.test.ts b/src/__tests__/page-walk-guard.test.ts index bd843d704..a08129755 100644 --- a/src/__tests__/page-walk-guard.test.ts +++ b/src/__tests__/page-walk-guard.test.ts @@ -11,20 +11,10 @@ import { readFileSync } from "node:fs"; import { join } from "node:path"; import { describe, expect, it } from "vitest"; -import { walkSourceFiles } from "./helpers/source-files"; +import { PROVIDER_DIRS } from "./helpers/provider-dirs"; +import { stripComments, walkSourceFiles } from "./helpers/source-files"; const LIB = join(process.cwd(), "src", "lib"); -const PROVIDER_DIRS = [ - "dawarich", - "fitbit", - "google-health", - "nightscout", - "oura", - "polar", - "strava", - "whoop", - "withings", -]; /** * Page loops that stay outside `walkPages` on purpose, with how many matches * each file may hold and why. A file with more matches than its allowance has @@ -58,12 +48,6 @@ const EXCEPTIONS: Readonly> = { const PAGE_LOOP = /\b(?:pages?|pageCount|pagesRead|page)(?:\s*-\s*[A-Za-z_]\w*)?\s*(?:<|<=|>|>=)\s*(?:[A-Z_][A-Z0-9_]*|maxPages|[2-9]|[1-9]\d+)\b/g; -function strip(text: string): string { - return text - .replace(/\/\*[\s\S]*?\*\//g, "") - .replace(/(^|[^:])\/\/.*$/gm, "$1"); -} - describe("provider clients walk pages through walkPages", () => { const files = walkSourceFiles(LIB, { floor: 1000 }).filter( (f) => @@ -72,10 +56,20 @@ describe("provider clients walk pages through walkPages", () => { !f.endsWith(".test.ts"), ); const matches = (f: string) => - strip(readFileSync(join(LIB, f), "utf8")).match(PAGE_LOOP)?.length ?? 0; + stripComments(readFileSync(join(LIB, f), "utf8")).match(PAGE_LOOP) + ?.length ?? 0; it("walks the provider directories", () => { expect(files.length).toBeGreaterThanOrEqual(60); + expect(PROVIDER_DIRS).toEqual( + expect.arrayContaining(["strava", "whoop", "withings", "google-health"]), + ); + for (const dir of PROVIDER_DIRS) { + expect( + files.some((f) => f.startsWith(`${dir}/`)), + dir, + ).toBe(true); + } }); it("finds no page loop of their own beyond the exceptions", () => { From 5cbe52cada6604f193dc2b0bfa6a4188fcfa95a4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:51:12 +0200 Subject: [PATCH 11/19] test(guards): count the allowed sites per file instead of exempting the file An exempted file covered every bare formatter or clock read written into it later. Each entry now states how many sites it holds, and a file with one more fails like any other. --- src/__tests__/sql-now-utc-guard.test.ts | 67 +++++++++++++------ .../timezone-explicit-formatter-guard.test.ts | 27 +++++--- 2 files changed, 64 insertions(+), 30 deletions(-) diff --git a/src/__tests__/sql-now-utc-guard.test.ts b/src/__tests__/sql-now-utc-guard.test.ts index b64c5e313..cf7b5baa3 100644 --- a/src/__tests__/sql-now-utc-guard.test.ts +++ b/src/__tests__/sql-now-utc-guard.test.ts @@ -20,15 +20,36 @@ import { describe, expect, it } from "vitest"; const ROOT = join(__dirname, "..", ".."); const SRC = join(ROOT, "src"); -/** `file: reason` for every bare clock read that is deliberately left. */ -const ALLOWED: Record = { - "src/lib/rollups/mood-rollups.ts": "computed_at is timestamptz", - "src/lib/rollups/medication-compliance-rollups.ts": - "computed_at is timestamptz", - "src/lib/jobs/job-failures.ts": "pg-boss tables are timestamptz", - "src/lib/jobs/heavy-lane.ts": "pg-boss start_after is timestamptz", - "src/lib/jobs/reminder/registrar-shared.ts": "pg-boss tables are timestamptz", - "src/lib/db-compat.ts": "DDL default on a timestamptz column", +/** + * Every bare clock read that is deliberately left: the file, how many such + * reads it holds, and why. The count makes the exception cover those reads + * and not the next one written into the same file. + */ +const ALLOWED: Record = { + "src/lib/rollups/mood-rollups.ts": { + hits: 1, + why: "computed_at is timestamptz", + }, + "src/lib/rollups/medication-compliance-rollups.ts": { + hits: 1, + why: "computed_at is timestamptz", + }, + "src/lib/jobs/job-failures.ts": { + hits: 2, + why: "pg-boss tables are timestamptz", + }, + "src/lib/jobs/heavy-lane.ts": { + hits: 1, + why: "pg-boss start_after is timestamptz", + }, + "src/lib/jobs/reminder/registrar-shared.ts": { + hits: 1, + why: "pg-boss tables are timestamptz", + }, + "src/lib/db-compat.ts": { + hits: 1, + why: "DDL default on a timestamptz column", + }, }; const SQL_CLOCK = @@ -47,11 +68,11 @@ function walk(dir: string, out: string[] = []): string[] { return out; } -function offenders(): string[] { +/** Every bare clock read in the tree, allowed or not. */ +function bareReads(): string[] { const found: string[] = []; for (const file of walk(SRC)) { const rel = relative(ROOT, file); - if (ALLOWED[rel]) continue; readFileSync(file, "utf8") .split("\n") .forEach((line, index) => { @@ -81,18 +102,22 @@ describe("raw SQL clock reads are anchored to UTC", () => { }); it("leaves no bare NOW() / CURRENT_TIMESTAMP outside the allowlist", () => { - expect(offenders()).toEqual([]); + const reads = bareReads(); + const inFile = (rel: string) => + reads.filter((r) => r.startsWith(`${rel}:`)).length; + const over = reads.filter((r) => { + const rel = r.slice(0, r.indexOf(":")); + return !ALLOWED[rel] || inFile(rel) > ALLOWED[rel].hits; + }); + expect(over).toEqual([]); }); - it("keeps the allowlist honest: every entry still has a bare read", () => { - for (const rel of Object.keys(ALLOWED)) { - const lines = readFileSync(join(ROOT, rel), "utf8") - .replace(ANCHORED, "") - .split("\n"); - expect( - lines.some((line) => SQL_CLOCK.test(line)), - rel, - ).toBe(true); + it("keeps the allowlist honest: every entry holds exactly its count", () => { + const reads = bareReads(); + for (const [rel, { hits }] of Object.entries(ALLOWED)) { + expect(reads.filter((r) => r.startsWith(`${rel}:`)).length, rel).toBe( + hits, + ); } }); }); diff --git a/src/__tests__/timezone-explicit-formatter-guard.test.ts b/src/__tests__/timezone-explicit-formatter-guard.test.ts index be1b66a56..7b4977f68 100644 --- a/src/__tests__/timezone-explicit-formatter-guard.test.ts +++ b/src/__tests__/timezone-explicit-formatter-guard.test.ts @@ -31,19 +31,24 @@ const REPO_ROOT = resolve(__dirname, "../.."); /** * Bare formatter sites that are correct as they stand. Keep this short: it is - * an inventory of exceptions, not a parking space. Every entry says why. + * an inventory of exceptions, not a parking space. Every entry says why, and + * how many bare sites the file holds: an exception covers those sites, not + * whatever lands in the same file next. */ -const ALLOWLIST: ReadonlyArray<{ file: string; why: string }> = [ +const ALLOWLIST: ReadonlyArray<{ file: string; hits: number; why: string }> = [ { file: "src/components/ui/calendar.tsx", + hits: 1, why: "A `data-day` attribute on a calendar cell, derived from the grid's own arithmetic. It identifies a cell, it does not render a recorded moment.", }, { file: "src/components/cycle/cycle-calendar.tsx", + hits: 2, why: "Weekday headers walked from a fixed local date, and a month label built from a month anchor. Both are calendar arithmetic with no instant behind them.", }, { file: "src/lib/intl/formatter-cache.ts", + hits: 2, why: "The shared cache itself. Its options come from the caller, so the timezone is the caller's to supply and the guard should be asking them, not this.", }, ]; @@ -171,9 +176,13 @@ describe("date formatters name the calendar they render in", () => { }); it("has no unexplained formatter without an explicit timeZone", () => { - const unexplained = hits.filter( - (h) => !ALLOWLIST.some((a) => a.file === h.file), - ); + const unexplained = hits.filter((h) => { + const entry = ALLOWLIST.find((a) => a.file === h.file); + return ( + !entry || + hits.filter((other) => other.file === h.file).length > entry.hits + ); + }); if (unexplained.length > 0) { throw new Error( `${unexplained.length} formatter call(s) render a date without naming a timezone:\n\n` + @@ -182,7 +191,7 @@ describe("date formatters name the calendar they render in", () => { "profile timezone (`readStoredTimezone() || DEFAULT_TIMEZONE` on the client, " + "`resolveUserTimezone(userId)` on the server), or use the shared helpers in " + "@/lib/format. If the value is calendar arithmetic rather than a recorded " + - "instant, add the file to ALLOWLIST in this test with the reason.", + "instant, add the file to ALLOWLIST in this test with the reason and its count.", ); } }); @@ -209,9 +218,9 @@ describe("date formatters name the calendar they render in", () => { // that has moved on, and it quietly covers whatever lands in that file next. for (const entry of ALLOWLIST) { expect( - hits.some((h) => h.file === entry.file), - `stale allowlist entry — ${entry.file} no longer has a bare formatter`, - ).toBe(true); + hits.filter((h) => h.file === entry.file).length, + `stale allowlist entry — ${entry.file} holds a different number of bare formatters`, + ).toBe(entry.hits); } }); }); From f4262e2cc659409b938e6fcd933f8f213d5375a8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:51:13 +0200 Subject: [PATCH 12/19] test(guards): see a squared two-argument distance as a hand-rolled spread --- ...spread-single-implementation-guard.test.ts | 20 +++++++++++++------ 1 file changed, 14 insertions(+), 6 deletions(-) diff --git a/src/__tests__/spread-single-implementation-guard.test.ts b/src/__tests__/spread-single-implementation-guard.test.ts index 46b5dfa5a..cf7191b6e 100644 --- a/src/__tests__/spread-single-implementation-guard.test.ts +++ b/src/__tests__/spread-single-implementation-guard.test.ts @@ -20,7 +20,7 @@ import { readFileSync } from "node:fs"; import { join } from "node:path"; import { describe, expect, it } from "vitest"; -import { walkSourceFiles } from "./helpers/source-files"; +import { stripComments, walkSourceFiles } from "./helpers/source-files"; const SRC = join(process.cwd(), "src"); @@ -32,14 +32,17 @@ const ALLOWED: Record = { "lib/insights/mood-pattern-cards.ts": "A pooled variance for a t statistic.", "lib/insights/derived/trajectory.ts": "The residual standard error of a regression fit (÷ n − 2).", + "lib/insights/derived/sleep-score.ts": + "A circular SD of the sleep midpoint around its circular mean, the input of the consistency score; `spread` has no circular distance, and the score is never shown as a spread.", }; +/** + * A squared deviation: `(x - m) ** 2`, `(x - m) * (x - m)`, or a two-argument + * distance squared, `dist(x, m) ** 2` (a circular or otherwise custom + * deviation is still a hand-rolled spread). + */ const SQUARED_DEVIATION = - /\(\s*[\w.[\]]+\s*-\s*[\w.[\]]+\s*\)\s*\*\*\s*2|\(\s*([\w.[\]]+)\s*-\s*([\w.[\]]+)\s*\)\s*\*\s*\(\s*\1\s*-\s*\2\s*\)/; - -function stripComments(text: string): string { - return text.replace(/\/\*[\s\S]*?\*\//g, "").replace(/^\s*\/\/.*$/gm, ""); -} + /\(\s*[\w.[\]]+\s*-\s*[\w.[\]]+\s*\)\s*\*\*\s*2|\(\s*([\w.[\]]+)\s*-\s*([\w.[\]]+)\s*\)\s*\*\s*\(\s*\1\s*-\s*\2\s*\)|\b[A-Za-z_]\w*\s*\(\s*[\w.[\]]+\s*,\s*[\w.[\]]+\s*\)\s*\*\*\s*2/; function computesSpread(code: string): boolean { return SQUARED_DEVIATION.test(code) && code.includes("Math.sqrt("); @@ -59,6 +62,11 @@ describe("one standard deviation", () => { expect( computesSpread("acc += (v - mean) * (v - mean); Math.sqrt(acc / n);"), ).toBe(true); + expect( + computesSpread( + "xs.reduce((s, v) => s + circularMinuteDistance(v, mean) ** 2, 0); Math.sqrt(x);", + ), + ).toBe(true); }); it("no file outside the list computes its own", () => { From 2372fee37693335b8a646b0bd67611d1a0685862 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:58:02 +0200 Subject: [PATCH 13/19] fix(coach): count the daily question limit from the person's midnight The limit on clarifying questions reset at UTC midnight, which is the middle of the night in Europe and the afternoon on the American west coast. It now counts from the start of the person's own day. --- .../ai/coach/__tests__/clarify-tool.test.ts | 26 +++++++++++++++++++ src/lib/ai/coach/clarify.ts | 13 +++++++--- 2 files changed, 36 insertions(+), 3 deletions(-) diff --git a/src/lib/ai/coach/__tests__/clarify-tool.test.ts b/src/lib/ai/coach/__tests__/clarify-tool.test.ts index af7c6f27e..136350387 100644 --- a/src/lib/ai/coach/__tests__/clarify-tool.test.ts +++ b/src/lib/ai/coach/__tests__/clarify-tool.test.ts @@ -229,6 +229,32 @@ describe("clarificationAllowed", () => { ).resolves.toBe(false); }); + it("counts the day in the person's zone, not from UTC midnight", async () => { + // 23:30 UTC on 1 March is already 2 March in Auckland and still 1 March + // in Los Angeles; each day starts at its own local midnight. + const now = new Date("2026-03-01T23:30:00.000Z"); + await clarificationAllowed({ + userId: "u1", + conversationId: "c1", + now, + tz: "Pacific/Auckland", + }); + await clarificationAllowed({ + userId: "u1", + conversationId: "c1", + now, + tz: "America/Los_Angeles", + }); + const since = db.messageCount.mock.calls.map( + ([q]) => + (q as { where: { createdAt: { gte: Date } } }).where.createdAt.gte, + ); + expect(since).toEqual([ + new Date("2026-03-01T11:00:00.000Z"), + new Date("2026-03-01T08:00:00.000Z"), + ]); + }); + it("refuses when the count cannot be read", async () => { db.messageFindMany.mockRejectedValue(new Error("down")); await expect( diff --git a/src/lib/ai/coach/clarify.ts b/src/lib/ai/coach/clarify.ts index 3b12191c9..25ea236f0 100644 --- a/src/lib/ai/coach/clarify.ts +++ b/src/lib/ai/coach/clarify.ts @@ -30,6 +30,9 @@ import { type LatestMessagesLoader, } from "@/lib/ai/coach/latest-messages"; import { prisma } from "@/lib/db"; +import { startOfLocalDayKey } from "@/lib/tz/local-day"; +import { userDayKey } from "@/lib/tz/format"; +import { resolveUserTimezone } from "@/lib/tz/resolver"; import { annotate } from "@/lib/logging/context"; import type { Locale } from "@/lib/i18n/config"; import { resolveIntlLocale } from "@/lib/format-locale"; @@ -704,6 +707,8 @@ export async function clarificationAllowed(args: { userId: string; conversationId: string; now?: Date; + /** The person's zone; resolved from the account when absent. */ + tz?: string; }): Promise { const now = args.now ?? new Date(); try { @@ -726,9 +731,11 @@ export async function clarificationAllowed(args: { ) { return false; } - const dayStart = new Date( - Date.UTC(now.getUTCFullYear(), now.getUTCMonth(), now.getUTCDate()), - ); + // The person's day, not the server's: a limit that reset at UTC + // midnight reset at one or two in the morning in Berlin and in the + // afternoon in the Pacific. + const tz = args.tz ?? (await resolveUserTimezone(args.userId)); + const dayStart = startOfLocalDayKey(userDayKey(now, tz), tz); const today = await prisma.coachMessage.count({ where: { conversation: { userId: args.userId }, From 2f32a4458cd421a96d2cd8a98710cf2740995e48 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:58:02 +0200 Subject: [PATCH 14/19] fix(environment): end the nightly window on the person's today The default lookback ended on the UTC date, so east of UTC the local today stayed out of the window until the next night's run. --- .../__tests__/environment-fetch-range.test.ts | 35 ++++++++++++++++++ src/lib/jobs/environment-fetch.ts | 37 +++++++++++-------- 2 files changed, 57 insertions(+), 15 deletions(-) create mode 100644 src/lib/jobs/__tests__/environment-fetch-range.test.ts diff --git a/src/lib/jobs/__tests__/environment-fetch-range.test.ts b/src/lib/jobs/__tests__/environment-fetch-range.test.ts new file mode 100644 index 000000000..96c6df4e2 --- /dev/null +++ b/src/lib/jobs/__tests__/environment-fetch-range.test.ts @@ -0,0 +1,35 @@ +/** + * The nightly environment window ends on the person's today, not the UTC + * date: east of UTC the local day begins hours before the UTC one. + */ +import { describe, expect, it, vi } from "vitest"; + +vi.mock("@/lib/db", () => ({ prisma: {} })); + +import { resolveRange } from "../environment-fetch"; + +describe("resolveRange", () => { + // 20:00 UTC on 1 March is already 2 March in Auckland. + const now = new Date("2026-03-01T20:00:00.000Z"); + + it("ends the lookback on the local today", () => { + expect(resolveRange({}, "Pacific/Auckland", now)).toEqual({ + startDate: "2026-02-23", + endDate: "2026-03-02", + }); + expect(resolveRange({}, "America/Los_Angeles", now)).toEqual({ + startDate: "2026-02-22", + endDate: "2026-03-01", + }); + }); + + it("keeps an explicit range as given", () => { + expect( + resolveRange( + { startDate: "2025-01-01", endDate: "2025-01-31" }, + "Pacific/Auckland", + now, + ), + ).toEqual({ startDate: "2025-01-01", endDate: "2025-01-31" }); + }); +}); diff --git a/src/lib/jobs/environment-fetch.ts b/src/lib/jobs/environment-fetch.ts index 866a12971..eef50e48d 100644 --- a/src/lib/jobs/environment-fetch.ts +++ b/src/lib/jobs/environment-fetch.ts @@ -39,8 +39,9 @@ import { ENVIRONMENT_MAX_BACKFILL_DAYS, fetchAndStoreEnvironment, fillAirQualityGaps, - utcDayKey, } from "@/lib/environment/service"; +import { shiftDateKey, userDayKey } from "@/lib/tz/format"; +import { resolveUserTimezone } from "@/lib/tz/resolver"; import { enumerateDayCount } from "@/lib/environment/day-span"; import { recordError } from "@/lib/jobs/worker-status"; import { jobDone, jobFailed, type JobOutcome } from "@/lib/jobs/job-outcome"; @@ -54,8 +55,6 @@ export const ENVIRONMENT_FETCH_CRON = "10 2 * * *"; export const ENVIRONMENT_FETCH_CONCURRENCY = 1; -const MS_PER_DAY = 24 * 60 * 60 * 1000; - /** * Per-user fetch payload. An empty payload (no `userId`) is the daily discovery * tick. `startDate`/`endDate` (YYYY-MM-DD) drive the on-demand backfill; omitted @@ -67,18 +66,23 @@ export interface EnvironmentFetchPayload { endDate?: string; } -/** Resolve the date range for a per-user run (explicit range, else lookback). */ -function resolveRange(payload: EnvironmentFetchPayload): { - startDate: string; - endDate: string; -} { - const today = new Date(); - const endDate = payload.endDate ?? utcDayKey(today); +/** + * Resolve the date range for a per-user run (explicit range, else lookback). + * + * The lookback ends on the person's today, in the zone the service keys the + * stored days in, not on the UTC date: east of UTC the local day starts up to + * fourteen hours before the UTC one, and a window ending on the UTC date left + * the local today out until the next night's run. + */ +export function resolveRange( + payload: EnvironmentFetchPayload, + tz: string, + now: Date = new Date(), +): { startDate: string; endDate: string } { + const today = userDayKey(now, tz); + const endDate = payload.endDate ?? today; const startDate = - payload.startDate ?? - utcDayKey( - new Date(today.getTime() - ENVIRONMENT_LOOKBACK_DAYS * MS_PER_DAY), - ); + payload.startDate ?? shiftDateKey(today, -ENVIRONMENT_LOOKBACK_DAYS); return { startDate, endDate }; } @@ -208,7 +212,10 @@ export async function handleEnvironmentFetch( return jobDone({ skipped: "environment_module_disabled" }); } - const { startDate, endDate } = resolveRange(payload); + const { startDate, endDate } = resolveRange( + payload, + await resolveUserTimezone(userId), + ); // Clamp the span so a crafted backfill can never fan out an unbounded range. const span = enumerateDayCount(startDate, endDate); if (span > ENVIRONMENT_MAX_BACKFILL_DAYS) { From d91eb905fe1696517870278b2bd920046b8edf27 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:58:03 +0200 Subject: [PATCH 15/19] refactor(compliance): require the zone a dose window is read in The UTC reading of a window's HH:mm was right only for a UTC user, and the one production caller always passes the zone. --- .../compliance/__tests__/compliance.test.ts | 106 ++++++++++++------ src/lib/analytics/compliance/parsing.ts | 32 ++---- 2 files changed, 80 insertions(+), 58 deletions(-) diff --git a/src/lib/analytics/compliance/__tests__/compliance.test.ts b/src/lib/analytics/compliance/__tests__/compliance.test.ts index a2b355166..8ca4f82c6 100644 --- a/src/lib/analytics/compliance/__tests__/compliance.test.ts +++ b/src/lib/analytics/compliance/__tests__/compliance.test.ts @@ -1229,9 +1229,11 @@ describe("classifyIntakeTiming", () => { const scheduledDate = new Date("2025-01-15T00:00:00Z"); it('returns "missed" when takenAt is null', () => { - expect(classifyIntakeTiming(null, "08:00", "09:00", scheduledDate)).toBe( - "missed", - ); + expect( + classifyIntakeTiming(null, "08:00", "09:00", scheduledDate, { + tz: "UTC", + }), + ).toBe("missed"); }); // A degenerate POINT window (`windowStart === windowEnd`) is a real shape on @@ -1243,14 +1245,18 @@ describe("classifyIntakeTiming", () => { it('keeps a dose at the point itself "on_time"', () => { const takenAt = new Date("2025-01-15T07:00:00Z"); expect( - classifyIntakeTiming(takenAt, "07:00", "07:00", scheduledDate), + classifyIntakeTiming(takenAt, "07:00", "07:00", scheduledDate, { + tz: "UTC", + }), ).toBe("on_time"); }); it('does not classify a dose ~16h late as "on_time"', () => { const takenAt = new Date("2025-01-15T23:00:00Z"); expect( - classifyIntakeTiming(takenAt, "07:00", "07:00", scheduledDate), + classifyIntakeTiming(takenAt, "07:00", "07:00", scheduledDate, { + tz: "UTC", + }), ).toBe("very_late"); }); @@ -1258,7 +1264,9 @@ describe("classifyIntakeTiming", () => { // 13:00 is 6h past the point — outside the widened band + graces. const takenAt = new Date("2025-01-15T13:00:00Z"); expect( - classifyIntakeTiming(takenAt, "07:00", "07:00", scheduledDate), + classifyIntakeTiming(takenAt, "07:00", "07:00", scheduledDate, { + tz: "UTC", + }), ).not.toBe("on_time"); }); @@ -1266,30 +1274,38 @@ describe("classifyIntakeTiming", () => { // 00:30 the next day sits inside a 23:00 -> 01:00 window. const takenAt = new Date("2025-01-16T00:30:00Z"); expect( - classifyIntakeTiming(takenAt, "23:00", "01:00", scheduledDate), + classifyIntakeTiming(takenAt, "23:00", "01:00", scheduledDate, { + tz: "UTC", + }), ).toBe("on_time"); }); }); it('returns "on_time" when taken within the window', () => { const takenAt = new Date("2025-01-15T08:30:00Z"); - expect(classifyIntakeTiming(takenAt, "08:00", "09:00", scheduledDate)).toBe( - "on_time", - ); + expect( + classifyIntakeTiming(takenAt, "08:00", "09:00", scheduledDate, { + tz: "UTC", + }), + ).toBe("on_time"); }); it('returns "on_time" when taken exactly at windowStart', () => { const takenAt = new Date("2025-01-15T08:00:00Z"); - expect(classifyIntakeTiming(takenAt, "08:00", "09:00", scheduledDate)).toBe( - "on_time", - ); + expect( + classifyIntakeTiming(takenAt, "08:00", "09:00", scheduledDate, { + tz: "UTC", + }), + ).toBe("on_time"); }); it('returns "on_time" when taken exactly at windowEnd', () => { const takenAt = new Date("2025-01-15T09:00:00Z"); - expect(classifyIntakeTiming(takenAt, "08:00", "09:00", scheduledDate)).toBe( - "on_time", - ); + expect( + classifyIntakeTiming(takenAt, "08:00", "09:00", scheduledDate, { + tz: "UTC", + }), + ).toBe("on_time"); }); // Parameterised offset matrix relative to a `08:00 → 09:00` window. @@ -1319,16 +1335,20 @@ describe("classifyIntakeTiming", () => { // base instant is 08:00Z; positive offsets walk forward from there. const baseMs = new Date("2025-01-15T08:00:00Z").getTime(); const takenAt = new Date(baseMs + offsetMin * 60 * 1000); - expect(classifyIntakeTiming(takenAt, "08:00", "09:00", scheduledDate)).toBe( - expected, - ); + expect( + classifyIntakeTiming(takenAt, "08:00", "09:00", scheduledDate, { + tz: "UTC", + }), + ).toBe(expected); }); it('returns "very_late" when taken way before the grace period', () => { const takenAt = new Date("2025-01-15T03:00:00Z"); // 5h before 08:00 - expect(classifyIntakeTiming(takenAt, "08:00", "09:00", scheduledDate)).toBe( - "very_late", - ); + expect( + classifyIntakeTiming(takenAt, "08:00", "09:00", scheduledDate, { + tz: "UTC", + }), + ).toBe("very_late"); }); it("respects the configurable `lateMinutes` tail", () => { @@ -1339,6 +1359,7 @@ describe("classifyIntakeTiming", () => { const takenLate = new Date("2025-01-15T12:15:00Z"); expect( classifyIntakeTiming(takenLate, "08:00", "09:00", scheduledDate, { + tz: "UTC", lateMinutes: 30, }), ).toBe("late"); @@ -1346,6 +1367,7 @@ describe("classifyIntakeTiming", () => { const takenVeryLate = new Date("2025-01-15T12:45:00Z"); expect( classifyIntakeTiming(takenVeryLate, "08:00", "09:00", scheduledDate, { + tz: "UTC", lateMinutes: 30, }), ).toBe("very_late"); @@ -1354,33 +1376,41 @@ describe("classifyIntakeTiming", () => { it("handles overnight windows (windowEnd < windowStart)", () => { // Schedule: 23:00 - 01:00 (overnight) const takenAt = new Date("2025-01-15T23:30:00Z"); - expect(classifyIntakeTiming(takenAt, "23:00", "01:00", scheduledDate)).toBe( - "on_time", - ); + expect( + classifyIntakeTiming(takenAt, "23:00", "01:00", scheduledDate, { + tz: "UTC", + }), + ).toBe("on_time"); }); it("handles overnight window early intake", () => { // Schedule: 23:00 - 01:00, taken at 22:30 (30 min before windowStart) const takenAt = new Date("2025-01-15T22:30:00Z"); - expect(classifyIntakeTiming(takenAt, "23:00", "01:00", scheduledDate)).toBe( - "early", - ); + expect( + classifyIntakeTiming(takenAt, "23:00", "01:00", scheduledDate, { + tz: "UTC", + }), + ).toBe("early"); }); it("handles overnight window late intake", () => { // Schedule: 23:00 - 01:00, taken at 04:30 (3.5h past 01:00) const takenAt = new Date("2025-01-16T04:30:00Z"); - expect(classifyIntakeTiming(takenAt, "23:00", "01:00", scheduledDate)).toBe( - "late", - ); + expect( + classifyIntakeTiming(takenAt, "23:00", "01:00", scheduledDate, { + tz: "UTC", + }), + ).toBe("late"); }); it("handles overnight window very late intake", () => { // Schedule: 23:00 - 01:00, taken at 07:00 (6h past 01:00) const takenAt = new Date("2025-01-16T07:00:00Z"); - expect(classifyIntakeTiming(takenAt, "23:00", "01:00", scheduledDate)).toBe( - "very_late", - ); + expect( + classifyIntakeTiming(takenAt, "23:00", "01:00", scheduledDate, { + tz: "UTC", + }), + ).toBe("very_late"); }); it("interprets the window HH:mm in the supplied tz (non-UTC user)", () => { @@ -1400,9 +1430,11 @@ describe("classifyIntakeTiming", () => { // Without a tz the window HH:mm is read as UTC (08:00 UTC), so the very // same on-time dose reads as 7h15m off — very_late. This is the defect // the achievements perfect-day check hit for users far from UTC. - expect(classifyIntakeTiming(takenAt, "08:00", "09:00", slotInstant)).toBe( - "very_late", - ); + expect( + classifyIntakeTiming(takenAt, "08:00", "09:00", slotInstant, { + tz: "UTC", + }), + ).toBe("very_late"); }); }); diff --git a/src/lib/analytics/compliance/parsing.ts b/src/lib/analytics/compliance/parsing.ts index f863f6973..0c7b7d580 100644 --- a/src/lib/analytics/compliance/parsing.ts +++ b/src/lib/analytics/compliance/parsing.ts @@ -16,22 +16,12 @@ function parseHHmm(time: string): { hours: number; minutes: number } { } /** - * Build the UTC instant of local "HH:mm" on the calendar day `day` falls on. - * - * When `tz` is supplied the window `HH:mm` is interpreted in the user's zone - * (via {@link localHmAsUtc}) on the local day of `day` — so an "08:00" slot is - * 08:00 LOCAL, not 08:00 UTC. Without `tz` it keeps the legacy UTC anchoring - * (`setUTCHours`), which is only correct for a UTC user; a caller far from UTC - * must pass its zone or the punctuality band is offset by the zone's offset. + * Build the UTC instant of local "HH:mm" in `tz` on the local day of `day` + * (via {@link localHmAsUtc}), so an "08:00" slot is 08:00 LOCAL. */ -function toDateOnDay(time: string, day: Date, tz?: string): Date { +function toDateOnDay(time: string, day: Date, tz: string): Date { const { hours, minutes } = parseHHmm(time); - if (tz) { - return localHmAsUtc(day, tz, hours, minutes); - } - const d = new Date(day); - d.setUTCHours(hours, minutes, 0, 0); - return d; + return localHmAsUtc(day, tz, hours, minutes); } /** @@ -56,21 +46,21 @@ function toDateOnDay(time: string, day: Date, tz?: string): Date { * @param options.lateMinutes Width of the `late` band beyond the 3-hour * on-time tolerance, in minutes. Defaults to 120. Doses past this * tail land in `very_late`. - * @param options.tz IANA zone the window `HH:mm` is interpreted in. Supply - * the user's zone so an "08:00" slot means 08:00 LOCAL; omitting it keeps - * the legacy UTC interpretation (correct only for a UTC user). + * @param options.tz IANA zone the window `HH:mm` is interpreted in, so an + * "08:00" slot means 08:00 LOCAL. Required: a UTC fallback was right only + * for a UTC user and no caller relied on it. */ export function classifyIntakeTiming( takenAt: Date | null, windowStart: string, // "HH:mm" windowEnd: string, // "HH:mm" scheduledDate: Date, // the date this was scheduled - options?: { lateMinutes?: number; tz?: string }, + options: { lateMinutes?: number; tz: string }, ): IntakeTimingClass { if (takenAt === null) return "missed"; - let start = toDateOnDay(windowStart, scheduledDate, options?.tz); - let end = toDateOnDay(windowEnd, scheduledDate, options?.tz); + let start = toDateOnDay(windowStart, scheduledDate, options.tz); + let end = toDateOnDay(windowEnd, scheduledDate, options.tz); // A degenerate POINT window (`windowStart === windowEnd` — a single dose time // echoed into both fields, a real shape on legacy rows) used to fall into the @@ -94,7 +84,7 @@ export function classifyIntakeTiming( // 3h post-window grace: doses up to here are still `on_time`. const onTimeEnd = new Date(end.getTime() + 3 * HOUR_MS); // Configurable `late` tail past the on-time grace (default 120 min). - const lateTolerance = (options?.lateMinutes ?? 120) * 60 * 1000; + const lateTolerance = (options.lateMinutes ?? 120) * 60 * 1000; const lateEnd = new Date(onTimeEnd.getTime() + lateTolerance); const t = takenAt.getTime(); From 537a73d3b211fd1c90820d2e8c3bbbfec324176c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 09:58:03 +0200 Subject: [PATCH 16/19] refactor(measurements): drop the in-memory range aggregation nothing calls It bucketed by UTC day and was described as the route's fallback; no route has called it since the aggregation moved into SQL. --- .../__tests__/range-aggregation.test.ts | 69 ------------------ src/lib/measurements/range-aggregation.ts | 73 ------------------- 2 files changed, 142 deletions(-) diff --git a/src/lib/measurements/__tests__/range-aggregation.test.ts b/src/lib/measurements/__tests__/range-aggregation.test.ts index dfa7d99d7..06e493f3d 100644 --- a/src/lib/measurements/__tests__/range-aggregation.test.ts +++ b/src/lib/measurements/__tests__/range-aggregation.test.ts @@ -1,6 +1,5 @@ import { describe, it, expect } from "vitest"; import { - aggregateRows, pickAggregateGrain, rangeLengthDays, DAILY_AGGREGATE_THRESHOLD_DAYS, @@ -70,72 +69,4 @@ describe("range-aggregation", () => { expect(rangeLengthDays(t, t)).toBe(1); }); }); - - describe("aggregateRows", () => { - it("collapses to one row per day per type with mean values", () => { - const t0 = new Date("2026-05-01T08:00:00.000Z"); - const t1 = new Date("2026-05-01T18:00:00.000Z"); - const t2 = new Date("2026-05-02T08:00:00.000Z"); - const rows = [ - { type: "PULSE", value: 60, measuredAt: t0 }, - { type: "PULSE", value: 80, measuredAt: t1 }, - { type: "PULSE", value: 70, measuredAt: t2 }, - ]; - - const out = aggregateRows(rows, "daily"); - expect(out).toHaveLength(2); - expect(out[0].avg).toBe(70); - expect(out[0].count).toBe(2); - expect(out[1].avg).toBe(70); - expect(out[1].count).toBe(1); - }); - - it("collapses to one row per ISO week (Monday-anchored) with weekly", () => { - // 2026-05-04 is a Monday; surrounding days share the same bucket. - const monday = new Date("2026-05-04T10:00:00.000Z"); - const tuesday = new Date("2026-05-05T10:00:00.000Z"); - const nextMonday = new Date("2026-05-11T10:00:00.000Z"); - const rows = [ - { type: "WEIGHT", value: 75.0, measuredAt: monday }, - { type: "WEIGHT", value: 75.5, measuredAt: tuesday }, - { type: "WEIGHT", value: 76.0, measuredAt: nextMonday }, - ]; - const out = aggregateRows(rows, "weekly"); - expect(out).toHaveLength(2); - expect(out[0].count).toBe(2); - expect(out[0].avg).toBeCloseTo(75.25, 5); - expect(out[1].count).toBe(1); - }); - - it("keeps per-type buckets separate on the same day", () => { - const t = new Date("2026-05-01T12:00:00.000Z"); - const rows = [ - { type: "PULSE", value: 70, measuredAt: t }, - { type: "WEIGHT", value: 75, measuredAt: t }, - ]; - const out = aggregateRows(rows, "daily"); - expect(out).toHaveLength(2); - const types = new Set(out.map((r) => r.type)); - expect(types).toEqual(new Set(["PULSE", "WEIGHT"])); - }); - - it("collapses to one row per UTC calendar month with monthly", () => { - const a = new Date("2025-01-05T10:00:00.000Z"); - const b = new Date("2025-01-20T10:00:00.000Z"); - const c = new Date("2025-02-10T10:00:00.000Z"); - const rows = [ - { type: "WEIGHT", value: 75, measuredAt: a }, - { type: "WEIGHT", value: 76, measuredAt: b }, - { type: "WEIGHT", value: 77, measuredAt: c }, - ]; - const out = aggregateRows(rows, "monthly"); - expect(out).toHaveLength(2); - expect(out[0].count).toBe(2); - expect(out[0].avg).toBeCloseTo(75.5, 5); - expect(out[1].count).toBe(1); - expect(out[1].avg).toBe(77); - expect(out[0].bucketStart.toISOString()).toBe("2025-01-01T00:00:00.000Z"); - expect(out[1].bucketStart.toISOString()).toBe("2025-02-01T00:00:00.000Z"); - }); - }); }); diff --git a/src/lib/measurements/range-aggregation.ts b/src/lib/measurements/range-aggregation.ts index 71bc0f5fe..fc758a8c4 100644 --- a/src/lib/measurements/range-aggregation.ts +++ b/src/lib/measurements/range-aggregation.ts @@ -69,76 +69,3 @@ export function rangeLengthDays(from: Date, to: Date): number { const ms = to.getTime() - from.getTime(); return Math.max(1, Math.ceil(ms / 86_400_000)); } - -export interface AggregatedRow { - bucketStart: Date; - type: string; - avg: number; - count: number; -} - -interface RawRow { - type: string; - value: number; - measuredAt: Date; -} - -/** - * In-memory daily / weekly / monthly aggregation. Used by the route's - * fallback path and by the test harness — the production path runs the - * `aggregateRowsSql` query so the take cap never applies before - * bucketising (v1.4.28 R4-CODE-C1). - */ -export function aggregateRows( - rows: RawRow[], - grain: "daily" | "weekly" | "monthly", -): AggregatedRow[] { - const buckets = new Map< - string, - { bucketStart: Date; type: string; sum: number; count: number } - >(); - - for (const row of rows) { - const bucketStart = bucketStartFor(row.measuredAt, grain); - const key = `${row.type}@${bucketStart.getTime()}`; - const slot = buckets.get(key); - if (slot) { - slot.sum += row.value; - slot.count += 1; - } else { - buckets.set(key, { - bucketStart, - type: row.type, - sum: row.value, - count: 1, - }); - } - } - - return Array.from(buckets.values()) - .map((s) => ({ - bucketStart: s.bucketStart, - type: s.type, - avg: s.sum / s.count, - count: s.count, - })) - .sort((a, b) => a.bucketStart.getTime() - b.bucketStart.getTime()); -} - -function bucketStartFor(d: Date, grain: "daily" | "weekly" | "monthly"): Date { - if (grain === "daily") { - return new Date( - Date.UTC(d.getUTCFullYear(), d.getUTCMonth(), d.getUTCDate()), - ); - } - if (grain === "monthly") { - return new Date(Date.UTC(d.getUTCFullYear(), d.getUTCMonth(), 1)); - } - // Weekly — anchor to the start of the ISO week (Monday) in UTC. - const day = d.getUTCDay() || 7; // Sunday → 7 - const monday = new Date( - Date.UTC(d.getUTCFullYear(), d.getUTCMonth(), d.getUTCDate()), - ); - monday.setUTCDate(monday.getUTCDate() - (day - 1)); - return monday; -} From 689796db336c8c5cd66e542571ec94c11330d773 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 10:03:30 +0200 Subject: [PATCH 17/19] fix(integrations): log a failed sync as a signal, not an audit row The audit log is the trail of what a person or an admin did to an account. Every failed provider sync wrote a row there, burying that trail, and kept the provider's error message in plain text while the status row seals it. A failed sync now emits an integrations.sync.failed warning with the same counts and no message. --- docs/ops/attempt-number-semantics.md | 30 ++++++---- .../__tests__/admin-alert.test.ts | 11 +++- src/lib/integrations/__tests__/status.test.ts | 55 +++++++++++------- src/lib/integrations/status.ts | 58 +++++++++---------- tests/integration/integration-status.test.ts | 40 +++++++------ .../integration-sync-escalation.test.ts | 21 ++++--- 6 files changed, 125 insertions(+), 90 deletions(-) diff --git a/docs/ops/attempt-number-semantics.md b/docs/ops/attempt-number-semantics.md index b7b9ff5f8..9d6955b7a 100644 --- a/docs/ops/attempt-number-semantics.md +++ b/docs/ops/attempt-number-semantics.md @@ -1,18 +1,24 @@ -# `attemptNumber` audit-row vs alert-signal semantics +# `attempt_number` signal vs alert semantics Two numbers describe a failing integration sync, and they can diverge. -On-call operators reading an audit-log row alongside an admin alert -should expect the alert number to be smaller than (or equal to) the -audit number, never the other way around. +Operators reading an `integrations.sync.failed` log line alongside an admin +alert should expect the alert number to be smaller than (or equal to) the +logged number, never the other way around. + +Since v1.43.7 a failed sync is a `warn` signal in the log store, not an +audit-log row: the audit log records what a person or an admin did to an +account, and a provider answering 503 is neither. The provider's message is +not on the signal; it stays encrypted on the integration's status row and +shows in the integration's settings. ## The two numbers -`integrations.sync.failed` audit rows write -`attemptNumber = transient + reauth_required + persistent` — the **sum** +`integrations.sync.failed` signals carry +`attempt_number = transient + reauth_required + persistent` — the **sum** of all three failure buckets. This is the historical "consecutive failures" running total carried by the legacy `IntegrationStatus.consecutiveFailures` column (dropped in migration -`0077`, v1.4.47). Auditors looking at a single row see one integer +`0077`, v1.4.47). An operator looking at a single line sees one integer that captures how many failures the bucket ledger has accumulated since the last success. @@ -27,14 +33,14 @@ single-bucket threshold even if its sum looks alarming. ## When the two diverge A typed-failure-streak edge case: integration fails 2× transient, then -2× reauth_required, then 1× persistent. Audit row shows -`attemptNumber: 5`. Alert signal is `max(2, 2, 1) = 2`, which is below -the default threshold of 3, so no page fires. From the audit log this +2× reauth_required, then 1× persistent. The last signal shows +`attempt_number: 5`. The alert number is `max(2, 2, 1) = 2`, which is below +the default threshold of 3, so no page fires. From the log this looks like a sustained 5-failure outage; from the alert dispatcher it looks like three small bumps that never crossed a single-bucket ceiling. -Both readings are correct for their purpose. The audit log records what +Both readings are correct for their purpose. The signal records what happened end-to-end; the alert dispatcher only fires when a single failure mode persists, because mixed-bucket streaks usually indicate a transient network blip layered on top of an unrelated reauth prompt — @@ -43,7 +49,7 @@ we want to wake someone up for. ## Runbook implication -If you see an audit row with `attemptNumber >= threshold` but no alert +If you see a signal with `attempt_number >= threshold` but no alert was dispatched, check the per-bucket counts on `IntegrationStatus.consecutiveFailuresByKind` (DB column `consecutive_failures_by_kind`) for that user/integration pair. The diff --git a/src/lib/integrations/__tests__/admin-alert.test.ts b/src/lib/integrations/__tests__/admin-alert.test.ts index 77369ede9..fd38f1806 100644 --- a/src/lib/integrations/__tests__/admin-alert.test.ts +++ b/src/lib/integrations/__tests__/admin-alert.test.ts @@ -31,6 +31,11 @@ vi.mock("@/lib/db", () => ({ }, })); +vi.mock("@/lib/logging/signal", () => ({ + emitSignal: vi.fn(), + logCaught: vi.fn(), +})); + vi.mock("@/lib/auth/audit", () => ({ auditLog: vi.fn().mockResolvedValue(undefined), })); @@ -52,6 +57,7 @@ vi.mock("@/lib/crypto", () => ({ import { formatAdminAlertPayload, parkIntegrationAtReauth } from "../status"; import { prisma } from "@/lib/db"; import { auditLog } from "@/lib/auth/audit"; +import { emitSignal } from "@/lib/logging/signal"; import { dispatchNotification } from "@/lib/notifications/dispatcher"; beforeEach(() => { @@ -246,9 +252,8 @@ describe("parkIntegrationAtReauth — silent scope-skip park (v1.4.27 F20)", () }), }), ); - expect(auditLog).not.toHaveBeenCalledWith( - "integrations.sync.failed", - expect.anything(), + expect(emitSignal).not.toHaveBeenCalledWith( + expect.objectContaining({ action: "integrations.sync.failed" }), ); }); diff --git a/src/lib/integrations/__tests__/status.test.ts b/src/lib/integrations/__tests__/status.test.ts index ed75617b0..c970ef923 100644 --- a/src/lib/integrations/__tests__/status.test.ts +++ b/src/lib/integrations/__tests__/status.test.ts @@ -36,6 +36,11 @@ vi.mock("@/lib/db", () => ({ }, })); +vi.mock("@/lib/logging/signal", () => ({ + emitSignal: vi.fn(), + logCaught: vi.fn(), +})); + vi.mock("@/lib/auth/audit", () => ({ auditLog: vi.fn().mockResolvedValue(undefined), })); @@ -66,6 +71,7 @@ import { } from "../status"; import { prisma } from "@/lib/db"; import { auditLog } from "@/lib/auth/audit"; +import { emitSignal } from "@/lib/logging/signal"; import { dispatchNotification } from "@/lib/notifications/dispatcher"; beforeEach(() => { @@ -148,17 +154,24 @@ describe("recordSyncFailure — under threshold", () => { }); expect(prisma.integrationStatus.upsert).toHaveBeenCalledOnce(); - expect(auditLog).toHaveBeenCalledWith( - "integrations.sync.failed", + expect(emitSignal).toHaveBeenCalledWith( expect.objectContaining({ - userId: "u1", - details: expect.objectContaining({ + action: "integrations.sync.failed", + meta: expect.objectContaining({ integration: "withings", - attemptNumber: 1, + attempt_number: 1, state: "error_transient", }), }), ); + // A provider failure is not something a person did to the account: no + // audit row, and the provider's message stays sealed on the status row. + expect(auditLog).not.toHaveBeenCalledWith( + "integrations.sync.failed", + expect.anything(), + ); + const [signal] = vi.mocked(emitSignal).mock.calls[0]!; + expect(JSON.stringify(signal)).not.toContain("upstream"); expect(dispatchNotification).not.toHaveBeenCalled(); }); }); @@ -456,12 +469,12 @@ describe("recordSyncFailure — reauth_required", () => { const upsertArgs = vi.mocked(prisma.integrationStatus.upsert).mock .calls[0][0]; expect(upsertArgs.update).toMatchObject({ state: "error_reauth" }); - expect(auditLog).toHaveBeenCalledWith( - "integrations.sync.failed", + expect(emitSignal).toHaveBeenCalledWith( expect.objectContaining({ - details: expect.objectContaining({ + action: "integrations.sync.failed", + meta: expect.objectContaining({ kind: "reauth_required", - errorCode: "100", + error_code: "100", }), }), ); @@ -489,12 +502,12 @@ describe("recordSyncFailure — persistent (v1.4.42 W6)", () => { const upsertArgs = vi.mocked(prisma.integrationStatus.upsert).mock .calls[0][0]; expect(upsertArgs.update).toMatchObject({ state: "error_transient" }); - expect(auditLog).toHaveBeenCalledWith( - "integrations.sync.failed", + expect(emitSignal).toHaveBeenCalledWith( expect.objectContaining({ - details: expect.objectContaining({ + action: "integrations.sync.failed", + meta: expect.objectContaining({ kind: "persistent", - errorCode: "293", + error_code: "293", }), }), ); @@ -1089,12 +1102,12 @@ describe("transient-streak escalation", () => { persistent: 1, }); expect(upsertUpdate().persistentFailureStartedAt).toBeInstanceOf(Date); - expect(auditLog).toHaveBeenCalledWith( - "integrations.sync.failed", + expect(emitSignal).toHaveBeenCalledWith( expect.objectContaining({ - details: expect.objectContaining({ + action: "integrations.sync.failed", + meta: expect.objectContaining({ kind: "persistent", - escalatedFrom: "transient", + escalated_from: "transient", }), }), ); @@ -1116,12 +1129,12 @@ describe("transient-streak escalation", () => { persistent: 0, }); expect(upsertUpdate().persistentFailureStartedAt).toBeNull(); - expect(auditLog).toHaveBeenCalledWith( - "integrations.sync.failed", + expect(emitSignal).toHaveBeenCalledWith( expect.objectContaining({ - details: expect.objectContaining({ + action: "integrations.sync.failed", + meta: expect.objectContaining({ kind: "transient", - escalatedFrom: null, + escalated_from: null, }), }), ); diff --git a/src/lib/integrations/status.ts b/src/lib/integrations/status.ts index ec6b0f7cc..5e507d7e5 100644 --- a/src/lib/integrations/status.ts +++ b/src/lib/integrations/status.ts @@ -35,6 +35,7 @@ import { prisma } from "@/lib/db"; import { encrypt, decrypt } from "@/lib/crypto"; import { auditLog } from "@/lib/auth/audit"; import { annotate, getEvent } from "@/lib/logging/context"; +import { emitSignal } from "@/lib/logging/signal"; import { dispatchNotification, type DispatchOutcome, @@ -558,7 +559,7 @@ export interface RecordSyncFailureInput { * Record a sync failure. Always: * - increments the per-kind bucket in `consecutiveFailuresByKind` * - persists the encrypted error message - * - writes one `AuditLog` row with `integrations.sync.failed` + * - emits one `integrations.sync.failed` signal (not an audit row) * * If `kind === "reauth_required"` the row is parked at `error_reauth` * so the next scheduled sync skips. If `kind === "persistent"` and @@ -746,39 +747,36 @@ export async function recordSyncFailure( errorCode: errorCode ?? null, }); - // Audit log entry — fire-and-await so an integration test can assert - // it. The auth/audit helper is its own DB write so it's safe to call - // serially without bloating latency in the success path (which never - // calls this). + // One signal per failed sync, not an audit row. The audit log is the + // trail of what a person or an admin did to an account; a provider that + // answered 503 is neither, and one row per failed sync drowned that trail + // (and kept the provider's message there in plain text, while the status + // row seals it). The signal carries the same counts to the log store, and + // the status row keeps the current streak and the sealed message. // - // v1.4.47 — `attemptNumber` is now sourced from the bucket sum - // (the legacy `consecutiveFailures` column was dropped). The sum - // matches the legacy column's value for any row written after - // v1.4.43: a transient burst followed by a single persistent failure - // shows `attemptNumber = transient + persistent`, which is the same - // running total the legacy integer carried. + // `attempt_number` is the sum of the buckets, the running total the + // dropped `consecutiveFailures` column carried; the alert below uses the + // largest single bucket (docs/ops/attempt-number-semantics.md). const bucketTotal = buckets.transient + buckets.reauth_required + buckets.persistent; - await auditLog("integrations.sync.failed", { - userId, - details: { + emitSignal({ + action: "integrations.sync.failed", + level: "warn", + meta: { integration, kind: effectiveKind, - // Non-null only when the clock overrode the classifier, so an operator - // reading the trail can tell "the upstream said this was permanent" from - // "we concluded it was after a day of retrying". - escalatedFrom: escalatedFromTransient ? kind : null, - failingLeg: leg, - // Every leg the row currently holds an error for, not just this one — - // the audit trail is where an operator reconstructs an overlapping - // outage, and one leg per row was never enough to do it. - failingLegs, - failingSinceAt: failingSinceAt.toISOString(), - streakAgeMs, - errorCode: errorCode ?? null, - message, - attemptNumber: bucketTotal, - bucketCount: buckets[effectiveKind], + // Non-null only when the clock overrode the classifier: "the upstream + // said this was permanent" against "a day of retrying concluded it". + escalated_from: escalatedFromTransient ? kind : null, + failing_leg: leg, + // Every leg the row holds an error for, to reconstruct an overlapping + // outage. + failing_legs: failingLegs, + failing_since_at: failingSinceAt.toISOString(), + streak_age_ms: streakAgeMs, + error_code: errorCode ?? null, + attempt_number: bucketTotal, + bucket_count: buckets[effectiveKind], state: newState, }, }); @@ -941,7 +939,7 @@ export async function resumeIntegrationFromPark( * short-circuit. Unlike `recordSyncFailure`, this helper: * * 1. does NOT increment the per-kind failure buckets. - * 2. does NOT write an `integrations.sync.failed` audit row through + * 2. does NOT emit the `integrations.sync.failed` signal of * `recordSyncFailure`. A standalone `integrations.reauth_required` * row is written instead so the operations trail still shows the * park event. diff --git a/tests/integration/integration-status.test.ts b/tests/integration/integration-status.test.ts index 6a862fa1b..39198b593 100644 --- a/tests/integration/integration-status.test.ts +++ b/tests/integration/integration-status.test.ts @@ -3,13 +3,9 @@ * * The unit suite (`src/lib/integrations/__tests__/status.test.ts`) * mocks Prisma. This file lights up the real driver so we lock in the - * upsert + concurrent-write story AND prove that every sync failure - * writes one `AuditLog` row with the documented schema: - * - * action : "integrations.sync.failed" - * userId : - * details : { integration, kind, errorCode, message, - * attemptNumber, state } + * upsert + concurrent-write story, and that a sync failure leaves the audit + * log alone: it emits an `integrations.sync.failed` signal instead, and the + * provider's message stays sealed on the status row. * * The dispatcher is mocked at module level so we don't actually hit * Telegram while testing — the assertion is on the alerting side @@ -34,6 +30,11 @@ vi.mock("@/lib/db-compat", () => ({ // configs and call sendViaTelegram. We're not testing that path — // B3 owns it. Stub returns void so the helper's await chain // resolves cleanly. +vi.mock("@/lib/logging/signal", async (importOriginal) => { + const actual = await importOriginal(); + return { ...actual, emitSignal: vi.fn(actual.emitSignal) }; +}); + vi.mock("@/lib/notifications/dispatcher", () => ({ dispatchNotification: vi.fn().mockResolvedValue({ dispatched: true, @@ -53,6 +54,7 @@ import { resumeIntegrationFromPark, } from "@/lib/integrations/status"; import { dispatchNotification } from "@/lib/notifications/dispatcher"; +import { emitSignal } from "@/lib/logging/signal"; const TEST_USER_ID = "user-integration-status-e2e"; @@ -66,6 +68,7 @@ beforeEach(async () => { }, }); vi.mocked(dispatchNotification).mockClear(); + vi.mocked(emitSignal).mockClear(); }); describe("IntegrationStatus end-to-end", () => { @@ -103,16 +106,19 @@ describe("IntegrationStatus end-to-end", () => { const audits = await getPrismaClient().auditLog.findMany({ where: { action: "integrations.sync.failed", userId: TEST_USER_ID }, }); - expect(audits).toHaveLength(1); - const detailsParsed = JSON.parse(audits[0].details ?? "{}"); - expect(detailsParsed).toMatchObject({ - integration: "withings", - kind: "transient", - errorCode: "503", - message: "Withings refresh error: 503 - upstream", - attemptNumber: 1, - state: "error_transient", - }); + expect(audits).toHaveLength(0); + expect(emitSignal).toHaveBeenCalledWith( + expect.objectContaining({ + action: "integrations.sync.failed", + meta: expect.objectContaining({ + integration: "withings", + kind: "transient", + error_code: "503", + attempt_number: 1, + state: "error_transient", + }), + }), + ); }); it("getIntegrationStatus returns plaintext error after roundtrip (decryption succeeds)", async () => { diff --git a/tests/integration/integration-sync-escalation.test.ts b/tests/integration/integration-sync-escalation.test.ts index 2fc3f37f8..f39a66614 100644 --- a/tests/integration/integration-sync-escalation.test.ts +++ b/tests/integration/integration-sync-escalation.test.ts @@ -30,6 +30,11 @@ vi.mock("@/lib/db-compat", () => ({ ensureDbCompatibility: vi.fn().mockResolvedValue(undefined), })); +vi.mock("@/lib/logging/signal", async (importOriginal) => { + const actual = await importOriginal(); + return { ...actual, emitSignal: vi.fn(actual.emitSignal) }; +}); + vi.mock("@/lib/notifications/dispatcher", () => ({ dispatchNotification: vi.fn().mockResolvedValue(undefined), })); @@ -40,6 +45,7 @@ import { recordSyncFailure, recordSyncSuccess, } from "@/lib/integrations/status"; +import { emitSignal } from "@/lib/logging/signal"; const TEST_USER_ID = "user-sync-escalation"; const HOUR_MS = 60 * 60 * 1000; @@ -85,6 +91,7 @@ async function failTransient(integration: string, leg?: string) { } beforeEach(async () => { + vi.mocked(emitSignal).mockClear(); await truncateAllTables(getPrismaClient()); await getPrismaClient().user.create({ data: { @@ -124,15 +131,15 @@ describe("failure escalation", () => { }); expect(current!.persistentFailureStartedAt).toBeInstanceOf(Date); - const audits = await getPrismaClient().auditLog.findMany({ - where: { action: "integrations.sync.failed", userId: TEST_USER_ID }, - orderBy: { createdAt: "asc" }, - }); - const last = JSON.parse(audits[audits.length - 1]!.details ?? "{}"); + const signals = vi + .mocked(emitSignal) + .mock.calls.map(([signal]) => signal) + .filter((signal) => signal.action === "integrations.sync.failed"); + const last = signals[signals.length - 1]!.meta!; expect(last.kind).toBe("persistent"); - // The trail keeps the classifier's own verdict, so an operator can tell + // The signal keeps the classifier's own verdict, so an operator can tell // "the upstream said this was permanent" from "we concluded it was". - expect(last.escalatedFrom).toBe("transient"); + expect(last.escalated_from).toBe("transient"); }); it("parks the escalated streak a further window later and stops attempting", async () => { From b12bece49170b71fe587aaf7395b037e0467aae6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 10:03:30 +0200 Subject: [PATCH 18/19] fix(import): log a refused upload as a signal, not an audit row An upload refused for its size, a broken stream or a stopped worker is an operational outcome, not something done to the account. The admin import keeps its audit rows, since an admin acting on another account is. --- .../__tests__/route.test.ts | 18 +++++++++++++ .../api/import/apple-health-export/route.ts | 27 ++++++++++--------- .../api/import/health-connect-export/route.ts | 27 ++++++++++--------- 3 files changed, 46 insertions(+), 26 deletions(-) diff --git a/src/app/api/import/apple-health-export/__tests__/route.test.ts b/src/app/api/import/apple-health-export/__tests__/route.test.ts index 8acfc3b04..fb762f7fa 100644 --- a/src/app/api/import/apple-health-export/__tests__/route.test.ts +++ b/src/app/api/import/apple-health-export/__tests__/route.test.ts @@ -14,6 +14,10 @@ vi.mock("@/lib/auth/audit", () => ({ auditLog: vi.fn().mockResolvedValue(undefined), })); vi.mock("@/lib/logging/transports", () => ({ emitIfSampled: vi.fn() })); +vi.mock("@/lib/logging/signal", async (importOriginal) => ({ + ...(await importOriginal()), + emitSignal: vi.fn(), +})); vi.mock("@/lib/db-compat", () => ({ ensureDbCompatibility: vi.fn().mockResolvedValue(undefined), })); @@ -78,6 +82,8 @@ vi.mock("@/lib/db", () => ({ import { POST } from "../route"; import { getSession } from "@/lib/auth/session"; +import { auditLog } from "@/lib/auth/audit"; +import { emitSignal } from "@/lib/logging/signal"; const SESSION_OK = { session: { id: "sess-1", expiresAt: new Date(Date.now() + 3_600_000) }, @@ -144,6 +150,18 @@ describe("POST /api/import/apple-health-export", () => { ); const res = await POST(req); expect(res.status).toBe(413); + // A refused upload is an operational outcome, not an account action: a + // signal, never an audit row. + expect(auditLog).not.toHaveBeenCalledWith( + "import.apple-health.kickoff.denied", + expect.anything(), + ); + expect(emitSignal).toHaveBeenCalledWith( + expect.objectContaining({ + action: "import.apple-health.kickoff.denied", + meta: expect.objectContaining({ reason: "content_length_exceeded" }), + }), + ); }); it("returns 429 when the rate-limit window is exhausted", async () => { diff --git a/src/app/api/import/apple-health-export/route.ts b/src/app/api/import/apple-health-export/route.ts index eb3c81f50..20eb69061 100644 --- a/src/app/api/import/apple-health-export/route.ts +++ b/src/app/api/import/apple-health-export/route.ts @@ -26,6 +26,7 @@ import { apiHandler, requireAuth, HttpError } from "@/lib/api-handler"; import { apiError, apiSuccess, getClientIp } from "@/lib/api-response"; import { annotate } from "@/lib/logging/context"; import { auditLog } from "@/lib/auth/audit"; +import { emitSignal } from "@/lib/logging/signal"; import { checkRateLimit } from "@/lib/rate-limit"; import { getGlobalBoss } from "@/lib/jobs/boss-instance"; import { @@ -77,12 +78,12 @@ export const POST = apiHandler(async (request: NextRequest) => { // content-length cannot bypass it. const declaredBytes = Number(request.headers.get("content-length") ?? 0); if (declaredBytes > MAX_UPLOAD_BYTES) { - await auditLog("import.apple-health.kickoff.denied", { - userId: user.id, - ipAddress: getClientIp(request), - details: { + emitSignal({ + action: "import.apple-health.kickoff.denied", + level: "warn", + meta: { reason: "content_length_exceeded", - contentLength: declaredBytes, + content_length: declaredBytes, }, }); return apiError("Upload exceeds 1.5 GB limit", 413); @@ -107,10 +108,10 @@ export const POST = apiHandler(async (request: NextRequest) => { ); } catch (err) { const message = err instanceof Error ? err.message : "upload_failed"; - await auditLog("import.apple-health.kickoff.denied", { - userId: user.id, - ipAddress: getClientIp(request), - details: { reason: "stream_to_disk_failed", message }, + emitSignal({ + action: "import.apple-health.kickoff.denied", + level: "warn", + meta: { reason: "stream_to_disk_failed", message }, }); return apiError(`Multipart upload failed: ${message}`, 422); } @@ -150,10 +151,10 @@ export const POST = apiHandler(async (request: NextRequest) => { const boss = getGlobalBoss(); if (!boss) { - await auditLog("import.apple-health.kickoff.denied", { - userId: user.id, - ipAddress: getClientIp(request), - details: { reason: "worker_not_running" }, + emitSignal({ + action: "import.apple-health.kickoff.denied", + level: "warn", + meta: { reason: "worker_not_running" }, }); // Nothing will ever read the staged export; it must not stay in /tmp. await discardStagedUpload(uploaded.filePath); diff --git a/src/app/api/import/health-connect-export/route.ts b/src/app/api/import/health-connect-export/route.ts index 04177f556..d8eb2b6b8 100644 --- a/src/app/api/import/health-connect-export/route.ts +++ b/src/app/api/import/health-connect-export/route.ts @@ -22,6 +22,7 @@ import { apiHandler, requireAuth, HttpError } from "@/lib/api-handler"; import { apiError, apiSuccess, getClientIp } from "@/lib/api-response"; import { annotate } from "@/lib/logging/context"; import { auditLog } from "@/lib/auth/audit"; +import { emitSignal } from "@/lib/logging/signal"; import { checkRateLimit } from "@/lib/rate-limit"; import { getGlobalBoss } from "@/lib/jobs/boss-instance"; import { @@ -67,12 +68,12 @@ export const POST = apiHandler(async (request: NextRequest) => { const declaredBytes = Number(request.headers.get("content-length") ?? 0); if (declaredBytes > HEALTH_CONNECT_MAX_UPLOAD_BYTES) { - await auditLog("import.health-connect.kickoff.denied", { - userId: user.id, - ipAddress: getClientIp(request), - details: { + emitSignal({ + action: "import.health-connect.kickoff.denied", + level: "warn", + meta: { reason: "content_length_exceeded", - contentLength: declaredBytes, + content_length: declaredBytes, }, }); return apiError("Upload exceeds the 1 GB limit", 413); @@ -94,10 +95,10 @@ export const POST = apiHandler(async (request: NextRequest) => { ); } catch (err) { const message = err instanceof Error ? err.message : "upload_failed"; - await auditLog("import.health-connect.kickoff.denied", { - userId: user.id, - ipAddress: getClientIp(request), - details: { reason: "stream_to_disk_failed" }, + emitSignal({ + action: "import.health-connect.kickoff.denied", + level: "warn", + meta: { reason: "stream_to_disk_failed" }, }); return apiError(`Multipart upload failed: ${message}`, 422); } @@ -123,10 +124,10 @@ export const POST = apiHandler(async (request: NextRequest) => { const boss = getGlobalBoss(); if (!boss) { - await auditLog("import.health-connect.kickoff.denied", { - userId: user.id, - ipAddress: getClientIp(request), - details: { reason: "worker_not_running" }, + emitSignal({ + action: "import.health-connect.kickoff.denied", + level: "warn", + meta: { reason: "worker_not_running" }, }); await discardStagedUpload(uploaded.filePath); throw new HttpError(503, "Background worker is not running"); From 985372f711d8b678e26e693c373fd552bf316be1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 10:06:11 +0200 Subject: [PATCH 19/19] fix(insights): count failed fetches toward a bounded poll's ceiling The status and advisor polls counted attempts on dataUpdateCount, which a failed fetch does not move, while the last good payload stayed in place and still said preparing. A request that kept failing polled an open page for as long as it stayed open. Attempts now include the failed fetches. The poll inventory moves from a comment into a guard held to every refetchInterval in the tree; four polls were missing from the comment. --- .../client-poll-inventory-guard.test.ts | 197 ++++++++++++++++++ src/app/insights/medications/page.tsx | 3 +- .../insights/insights-layout-shell.tsx | 3 +- .../insights/use-insights-advisor.ts | 17 +- src/hooks/use-insight-status.ts | 12 +- .../__tests__/poll-attempt-count.test.ts | 44 ++++ src/lib/queries/refetch-interval.ts | 54 ++--- 7 files changed, 282 insertions(+), 48 deletions(-) create mode 100644 src/__tests__/client-poll-inventory-guard.test.ts create mode 100644 src/lib/queries/__tests__/poll-attempt-count.test.ts diff --git a/src/__tests__/client-poll-inventory-guard.test.ts b/src/__tests__/client-poll-inventory-guard.test.ts new file mode 100644 index 000000000..c3e14afa2 --- /dev/null +++ b/src/__tests__/client-poll-inventory-guard.test.ts @@ -0,0 +1,197 @@ +/** + * Structural guard: every client poll is in the inventory, in one of the + * three shapes `src/lib/queries/refetch-interval.ts` describes. + * + * The inventory used to be a comment, and a comment cannot fail: three polls + * (the Insights shell's briefing, the medication compliance card and two of + * the status hooks' cards) were missing from it. Here it is data, held to + * every `refetchInterval:` in the tree, with the number each file carries, so + * a new poll in a listed file fails as surely as one in a new file. + * + * A bounded poll counts its attempts with `pollAttemptCount`, failed fetches + * included: on `dataUpdateCount` alone a request that kept failing kept the + * last good payload (still `preparing`) and polled for as long as the page + * stayed open. + */ +import { readFileSync } from "node:fs"; +import { join } from "node:path"; +import { describe, expect, it } from "vitest"; + +import { + requireFloor, + stripComments, + walkSourceFiles, +} from "./helpers/source-files"; + +const SRC = join(process.cwd(), "src"); + +type Shape = "standing" | "until-done" | "bounded"; + +interface Poll { + /** How many `refetchInterval:` the file holds. */ + sites: number; + shape: Shape; + /** The interval, and why that figure; or what ends the poll. */ + cadence: string; +} + +const INVENTORY: Readonly> = { + // ── Standing: a fixed interval while mounted, paused on a hidden tab ── + "lib/queries/use-dashboard-snapshot.ts": { + sites: 1, + shape: "standing", + cadence: + "120 s, DASHBOARD_REFETCH_INTERVAL_MS; matches the snapshot cache TTL", + }, + "lib/queries/use-analytics-query.ts": { + sites: 1, + shape: "standing", + cadence: "120 s, DASHBOARD_REFETCH_INTERVAL_MS", + }, + "lib/queries/use-daily-digest.ts": { + sites: 1, + shape: "standing", + cadence: "120 s, DASHBOARD_REFETCH_INTERVAL_MS", + }, + "components/settings/notification-status-card.tsx": { + sites: 1, + shape: "standing", + cadence: "30 s; last-delivery results move while the panel is open", + }, + "components/admin/app-log-preview-section.tsx": { + sites: 1, + shape: "standing", + cadence: "30 s; an operator watching a live log", + }, + "components/gamification/achievement-unlock-notifier.tsx": { + sites: 1, + shape: "standing", + cadence: "5 min; out-of-band unlocks, an app-global poll", + }, + "components/admin/host-metrics-chart.tsx": { + sites: 1, + shape: "standing", + cadence: "5 min; the sampler's own cadence", + }, + // ── Until done: stops on a terminal state the server always reaches ── + "components/settings/import-panel/apple-health-import-card.tsx": { + sites: 1, + shape: "until-done", + cadence: "2 s until the job reports a terminal status", + }, + "components/settings/import-panel/health-connect-import-card.tsx": { + sites: 1, + shape: "until-done", + cadence: "2 s until the job reports a terminal status", + }, + "components/admin/backups-section.tsx": { + sites: 1, + shape: "until-done", + cadence: "2 s until no restore is active", + }, + "components/documents/documents-view.tsx": { + sites: 1, + shape: "until-done", + cadence: + "4 s until no document is inside its 3-minute upload window without an index", + }, + "components/insights/coach-panel/coach-conversation.tsx": { + sites: 1, + shape: "until-done", + cadence: + "2.5 s until the attachment is indexed or its upload window passed", + }, + "components/admin/pulse-day-mean-card.tsx": { + sites: 1, + shape: "until-done", + cadence: "10 s until the recompute reports done", + }, + "components/admin/measurement-maintenance-card.tsx": { + sites: 1, + shape: "until-done", + cadence: "10 s until the run reports done", + }, + "components/insights/period-narrative-card.tsx": { + sites: 1, + shape: "until-done", + cadence: + "5 s until the narrative arrives or `revalidating` clears; only mounted while looked at", + }, + // ── Bounded: model text on its way, with an attempt ceiling ── + "hooks/use-insight-status.ts": { + sites: 3, + shape: "bounded", + cadence: + "4 s, nextStatusPollInterval, 12 attempts (metric, biomarker, general cards)", + }, + "app/insights/medications/page.tsx": { + sites: 1, + shape: "bounded", + cadence: "4 s, nextStatusPollInterval, 12 attempts (compliance card)", + }, + "components/insights/use-insights-advisor.ts": { + sites: 1, + shape: "bounded", + cadence: "25 s, nextAdvisorPollInterval, 10 attempts (advisor)", + }, + "components/insights/insights-layout-shell.tsx": { + sites: 1, + shape: "bounded", + cadence: "25 s, nextAdvisorPollInterval, 10 attempts (briefing body)", + }, +}; + +const SITE = /\brefetchInterval\s*:/g; + +const files = walkSourceFiles(SRC, { floor: 3000 }).filter( + (f) => + !f.startsWith("generated/") && + !f.includes("__tests__/") && + !/\.test\.tsx?$/.test(f), +); +const code = new Map( + files.map((f) => [f, stripComments(readFileSync(join(SRC, f), "utf8"))]), +); +const sitesIn = (text: string) => text.match(SITE)?.length ?? 0; + +describe("client polls", () => { + it("lists every poll in the tree, with the number each file holds", () => { + const found = requireFloor( + "refetchInterval files", + files.filter((f) => sitesIn(code.get(f)!) > 0), + 15, + ); + const drift = found + .filter((f) => INVENTORY[f]?.sites !== sitesIn(code.get(f)!)) + .map((f) => `${f}: ${sitesIn(code.get(f)!)}`); + expect(drift).toEqual([]); + const gone = Object.keys(INVENTORY).filter((f) => !found.includes(f)); + expect(gone).toEqual([]); + }); + + it("counts a bounded poll's attempts with the failed fetches", () => { + const bounded = Object.entries(INVENTORY).filter( + ([, p]) => p.shape === "bounded", + ); + const problems = bounded.flatMap(([f, p]) => { + const text = code.get(f) ?? ""; + const counted = + text.match(/pollAttemptCount\(query\.state\)/g)?.length ?? 0; + return [ + ...(counted < p.sites + ? [`${f}: ${counted} of ${p.sites} counted`] + : []), + ...(/\.state\.dataUpdateCount\b/.test(text) + ? [`${f}: reads dataUpdateCount alone`] + : []), + ]; + }); + expect(problems).toEqual([]); + }); + + it("catches an unlisted poll", () => { + expect(sitesIn("useQuery({ refetchInterval: 5_000 })")).toBe(1); + expect(sitesIn("// refetchInterval: 5_000")).toBe(1); + expect(sitesIn(stripComments("// refetchInterval: 5_000"))).toBe(0); + }); +}); diff --git a/src/app/insights/medications/page.tsx b/src/app/insights/medications/page.tsx index 1545dc5e5..08fccaf84 100644 --- a/src/app/insights/medications/page.tsx +++ b/src/app/insights/medications/page.tsx @@ -7,6 +7,7 @@ import { Loader2, Pill } from "lucide-react"; import { useAiCapability } from "@/hooks/use-ai-capability"; import { useAuth } from "@/hooks/use-auth"; import { nextStatusPollInterval } from "@/hooks/use-insight-status"; +import { pollAttemptCount } from "@/lib/queries/refetch-interval"; import { queryKeys } from "@/lib/query-keys"; import { useTranslations } from "@/lib/i18n/context"; import { Badge } from "@/components/ui/badge"; @@ -142,7 +143,7 @@ export default function InsightsMedikamentePage() { refetchInterval: (query) => nextStatusPollInterval( query.state.data?.preparing, - query.state.dataUpdateCount, + pollAttemptCount(query.state), query.state.data?.revalidating, ), }); diff --git a/src/components/insights/insights-layout-shell.tsx b/src/components/insights/insights-layout-shell.tsx index 4414792c7..6659c5a45 100644 --- a/src/components/insights/insights-layout-shell.tsx +++ b/src/components/insights/insights-layout-shell.tsx @@ -13,6 +13,7 @@ import { nextAdvisorPollInterval, useInsightsAdvisorQuery, } from "@/components/insights/use-insights-advisor"; +import { pollAttemptCount } from "@/lib/queries/refetch-interval"; import { useAnalyticsQuery } from "@/lib/queries/use-analytics-query"; import { useInsightsLayoutQuery } from "@/hooks/use-insights-layout"; import { queryKeys } from "@/lib/query-keys"; @@ -89,7 +90,7 @@ export function InsightsLayoutShell({ children }: { children: ReactNode }) { refetchInterval: (query) => nextAdvisorPollInterval( query.state.data?.revalidating, - query.state.dataUpdateCount, + pollAttemptCount(query.state), ), }); diff --git a/src/components/insights/use-insights-advisor.ts b/src/components/insights/use-insights-advisor.ts index 34bf5fd10..e19700589 100644 --- a/src/components/insights/use-insights-advisor.ts +++ b/src/components/insights/use-insights-advisor.ts @@ -2,6 +2,7 @@ import { useCallback, useState } from "react"; import { useMutation, useQuery, useQueryClient } from "@tanstack/react-query"; +import { pollAttemptCount } from "@/lib/queries/refetch-interval"; import type { InsightResult } from "@/lib/ai/types"; // Type-only — the runtime schemas load lazily inside `fetchAdvisor` so // the zod module graph (`@/lib/ai/schema` is ~550 lines of zod builders) @@ -462,7 +463,7 @@ export function useInsightsAdvisorQuery( refetchInterval: (query) => nextAdvisorPollInterval( query.state.data?.payload?.revalidating, - query.state.dataUpdateCount, + pollAttemptCount(query.state), settling, ), }); @@ -470,14 +471,12 @@ export function useInsightsAdvisorQuery( // `dataUpdateCount` lives on the query STATE (the refetchInterval callback // reads it there); the observer result only exposes `dataUpdatedAt`. Read // it imperatively from the cache where the settle machinery needs it. - const readDataUpdateCount = useCallback( - () => - queryClient - .getQueryCache() - .find({ queryKey: queryKeys.insightsAdvisor() })?.state - .dataUpdateCount ?? 0, - [queryClient], - ); + const readDataUpdateCount = useCallback(() => { + const state = queryClient + .getQueryCache() + .find({ queryKey: queryKeys.insightsAdvisor() })?.state; + return state ? pollAttemptCount(state) : 0; + }, [queryClient]); // Apply the settle resolution the pure seam proves. Each poll result lands // in `query.data` (the poll's own cache write IS the fresh payload — no diff --git a/src/hooks/use-insight-status.ts b/src/hooks/use-insight-status.ts index cfb5be945..40c5b2096 100644 --- a/src/hooks/use-insight-status.ts +++ b/src/hooks/use-insight-status.ts @@ -4,6 +4,7 @@ import { useQuery, useQueryClient } from "@tanstack/react-query"; import { useAiCapability } from "@/hooks/use-ai-capability"; import { useAuth } from "@/hooks/use-auth"; +import { pollAttemptCount } from "@/lib/queries/refetch-interval"; import { useTranslations } from "@/lib/i18n/context"; import type { MetricStatusMetricId } from "@/lib/insights/metric-status-registry"; import type { AssessmentStatus } from "@/lib/insights/status-shared"; @@ -221,9 +222,8 @@ async function fetchStatusData( function useStatusPollAttemptCount(queryKey: readonly unknown[]): number { const queryClient = useQueryClient(); - return ( - queryClient.getQueryState(queryKey)?.dataUpdateCount ?? 0 - ); + const state = queryClient.getQueryState(queryKey); + return state ? pollAttemptCount(state) : 0; } /** @@ -324,7 +324,7 @@ export function useInsightStatus(metric: InsightStatusMetric) { refetchInterval: (query) => nextStatusPollInterval( query.state.data?.preparing, - query.state.dataUpdateCount, + pollAttemptCount(query.state), query.state.data?.revalidating, ), }); @@ -383,7 +383,7 @@ export function useInsightMetricStatus( refetchInterval: (query) => nextStatusPollInterval( query.state.data?.preparing, - query.state.dataUpdateCount, + pollAttemptCount(query.state), query.state.data?.revalidating, ), }); @@ -438,7 +438,7 @@ export function useInsightBiomarkerAssessment( refetchInterval: (query) => nextStatusPollInterval( query.state.data?.preparing, - query.state.dataUpdateCount, + pollAttemptCount(query.state), query.state.data?.revalidating, ), }); diff --git a/src/lib/queries/__tests__/poll-attempt-count.test.ts b/src/lib/queries/__tests__/poll-attempt-count.test.ts new file mode 100644 index 000000000..8a20cf42d --- /dev/null +++ b/src/lib/queries/__tests__/poll-attempt-count.test.ts @@ -0,0 +1,44 @@ +/** + * A bounded poll counts failed fetches as attempts. On `dataUpdateCount` + * alone a request that kept failing left the last `preparing` payload in + * place and polled an open page for as long as it stayed open. + */ +import { describe, expect, it } from "vitest"; + +import { + STATUS_POLL_MAX_ATTEMPTS, + nextStatusPollInterval, +} from "@/hooks/use-insight-status"; +import { nextAdvisorPollInterval } from "@/components/insights/use-insights-advisor"; +import { pollAttemptCount } from "../refetch-interval"; + +describe("pollAttemptCount", () => { + it("adds the failed fetches to the settled ones", () => { + expect(pollAttemptCount({ dataUpdateCount: 2, errorUpdateCount: 3 })).toBe( + 5, + ); + }); + + it("ends a status poll whose fetches keep failing", () => { + // One good `preparing` answer, then nothing but errors. + const failing = { dataUpdateCount: 1, errorUpdateCount: 0 }; + let polls = 0; + while (nextStatusPollInterval(true, pollAttemptCount(failing)) !== false) { + failing.errorUpdateCount += 1; + polls += 1; + expect(polls).toBeLessThanOrEqual(STATUS_POLL_MAX_ATTEMPTS); + } + expect(polls).toBe(STATUS_POLL_MAX_ATTEMPTS - 1); + }); + + it("ends an advisor poll whose fetches keep failing", () => { + const failing = { dataUpdateCount: 1, errorUpdateCount: 0 }; + let polls = 0; + while (nextAdvisorPollInterval(true, pollAttemptCount(failing)) !== false) { + failing.errorUpdateCount += 1; + polls += 1; + expect(polls).toBeLessThan(50); + } + expect(polls).toBeGreaterThan(0); + }); +}); diff --git a/src/lib/queries/refetch-interval.ts b/src/lib/queries/refetch-interval.ts index b2fc5b0de..2965cdfb0 100644 --- a/src/lib/queries/refetch-interval.ts +++ b/src/lib/queries/refetch-interval.ts @@ -14,53 +14,45 @@ */ export const DASHBOARD_REFETCH_INTERVAL_MS = 120_000; +/** + * How many fetches a bounded poll has made: the ones that settled with data + * and the ones that failed. TanStack Query's `dataUpdateCount` alone does not + * move on a failed fetch, and the last good payload stays in place, so a + * poll counted on it kept going for as long as the request kept failing. + */ +export function pollAttemptCount(state: { + dataUpdateCount: number; + errorUpdateCount: number; +}): number { + return state.dataUpdateCount + state.errorUpdateCount; +} + /* * ── Every client poll, in one place ───────────────────────────────────── * * The web client polls in three shapes, and each poll belongs to exactly - * one of them. A new poll picks its shape here, and is added to this list. + * one of them. The inventory of every poll, with its interval and why, is + * `src/__tests__/client-poll-inventory-guard.test.ts`: it is held to every + * `refetchInterval:` in the tree, so a new poll is added there or the suite + * fails. * * 1. STANDING — a fixed interval while the surface is mounted. TanStack * Query pauses it while the tab is hidden (`refetchIntervalInBackground` - * defaults to false), so it costs nothing on a background tab. - * - * | Surface | Interval | Why this figure | - * | ------------------------------------ | -------- | ------------------------------------------------- | - * | dashboard snapshot, analytics, digest | 120 s | this constant; matches the snapshot cache TTL | - * | version poller (`version-poller.tsx`) | 60 s | a deploy notice within a minute; plain timer | - * | notification channel status | 30 s | last-delivery results move while the panel is open | - * | admin app-log preview | 30 s | an operator watching a live log | - * | achievement unlock notifier | 5 min | out-of-band unlocks; an app-global poll | - * | admin host metrics chart | 5 min | the sampler's own cadence | + * defaults to false), so it costs nothing on a background tab. The + * version poller (`version-poller.tsx`, 60 s) is a plain timer of the + * same shape. * * 2. UNTIL-DONE — polls while a server job is visibly running and stops on * the terminal state the response reports. The interval is short because * a person is watching a progress indicator; the stop condition is what * bounds it, so it must be a state the server always reaches. * - * | Surface | Interval | Stops when | - * | ------------------------------------- | -------- | -------------------------------------------- | - * | Apple Health / Health Connect import | 2 s | the job reports a terminal status | - * | admin backup restore list | 2 s | no restore is active | - * | documents list | 4 s | no document is inside its 3-minute upload | - * | | | processing window without an index | - * | Coach staged attachment | 2.5 s | the same: index exists or window passed | - * | admin pulse day-mean / maintenance | 10 s | the recompute reports done | - * * 3. BOUNDED — polls while the server says fresh model text is on its way * (`preparing` / `revalidating`), with an attempt ceiling, because a * generation that keeps failing would otherwise poll an open page - * forever. The ceilings live beside the deciders and are unit-tested. - * - * | Surface | Interval | Ceiling | - * | ----------------------------- | -------- | ------------------------------------------ | - * | status cards (`use-insight-status.ts`, `nextStatusPollInterval`) | 4 s | 12 attempts | - * | advisor / briefing (`nextAdvisorPollInterval`) | 25 s | 10 attempts | - * | period narrative | 5 s | stops once the narrative arrives | - * - * The period narrative has no attempt ceiling: it stops on a state the - * server reaches (the warm writes text or clears `revalidating`), and it - * is only mounted while a person is looking at it. + * forever. The ceilings live beside the deciders + * (`nextStatusPollInterval`, `nextAdvisorPollInterval`) and count + * attempts with {@link pollAttemptCount}, failed fetches included. * * A document that is never indexed is the reason the two document polls are * bounded by the upload window (`RECENT_UPLOAD_WINDOW_MS` in