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/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/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/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/__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/__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__/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__/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__/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/__tests__/latest-per-type-read-guard.test.ts b/src/__tests__/latest-per-type-read-guard.test.ts index 4ebc51836..c7c5eca17 100644 --- a/src/__tests__/latest-per-type-read-guard.test.ts +++ b/src/__tests__/latest-per-type-read-guard.test.ts @@ -27,17 +27,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; @@ -100,9 +98,7 @@ 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([]); }); @@ -152,9 +148,7 @@ describe("latest-per-type reads", () => { 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); 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", () => { 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", () => { diff --git a/src/__tests__/sql-now-utc-guard.test.ts b/src/__tests__/sql-now-utc-guard.test.ts index 8846c7622..cf7b5baa3 100644 --- a/src/__tests__/sql-now-utc-guard.test.ts +++ b/src/__tests__/sql-now-utc-guard.test.ts @@ -20,14 +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/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 = @@ -46,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) => { @@ -80,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); } }); }); 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"); 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 c04feeb8f..0fb78dffd 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"; @@ -90,7 +91,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/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 }, 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(); 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/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. */ 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/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__/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/__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/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/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/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/__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/__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/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) { 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/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/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/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) { 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/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/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; -} 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/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 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 }; } /** 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); 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); +}); 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 () => { 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); +}); 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, }); });