diff --git a/docs/integrations/google-health.md b/docs/integrations/google-health.md index f1fbe715f..600a52fc7 100644 --- a/docs/integrations/google-health.md +++ b/docs/integrations/google-health.md @@ -143,16 +143,24 @@ Google answers that first resumed request with `400`, the slice reads the data type again without the bound, passes over the readings newer than its note without writing them, and carries on writing from there. The refusal is noted per data type, so later slices read without the bound straight away. The pages -passed over are not counted against the slice's five minutes or 500 pages: -otherwise a history deeper than one slice would spend every slice passing over -what earlier slices wrote and never write anything new. Only the job's own -time limit stops a slice while it is passing over, so on such an account each -slice takes longer the further back the backfill has got. A `400` that names -something else (the page token, the page size) is still a failure. +passed over are not counted against the slice's 500 pages, but they do run on +its five minutes, and passing over stops after three minutes at most, so a +slice never holds the account longer than a slice. Wherever the walk stops, on +a limit or on a rate limit, it keeps Google's page token for the page it read +last, and the next slice reads that one page again and goes on from there +instead of passing over everything earlier slices wrote: the pages read stay +in proportion to the history. If Google no longer takes the token, or the page +it returns no longer reaches the noted reading, the slice starts again from the +newest page and passes over as before. A `400` that names something else (the +page size, or the page token of a walk that did not start from a kept one) is +still a failure. The hourly sync waits for the slice that is running (up to eight minutes) instead of skipping the account, so recent data keeps arriving while an old -history is still coming in. +history is still coming in. The hourly job stays inside its own fifteen-minute +limit: the wait is cut short when the job's time runs low, the sync after it +gets only what is left and leaves the rest of its window to the next hour, and +an account the job reaches after its time is up waits for the next hour. Google limits how many requests one account may make per minute. When a sync reaches that limit Google answers `429`, and HealthLog waits and repeats the diff --git a/src/app/api/medications/intake/bulk/__tests__/dose-arrival-scope.test.ts b/src/app/api/medications/intake/bulk/__tests__/dose-arrival-scope.test.ts new file mode 100644 index 000000000..3c8e9c0aa --- /dev/null +++ b/src/app/api/medications/intake/bulk/__tests__/dose-arrival-scope.test.ts @@ -0,0 +1,137 @@ +/** + * The Apple Health dose arrival record (`MEDICATION_DOSE` in the per-type + * arrival table) describes the phone's Apple Health sync. A narrow, + * single-purpose credential is not that sync, so a batch it sends never + * writes the record, the same rule the measurement batch keeps. + */ +import { beforeEach, describe, expect, it, vi } from "vitest"; +import { NextRequest } from "next/server"; + +vi.mock("@/lib/db", () => ({ + prisma: { + medication: { + findMany: vi.fn(), + findFirst: vi.fn(), + updateMany: vi.fn(), + }, + medicationIntakeEvent: { + create: vi.fn(), + findUnique: vi.fn(), + findMany: vi.fn(), + update: vi.fn(), + findFirst: vi.fn(), + }, + user: { update: vi.fn() }, + auditLog: { create: vi.fn() }, + }, +})); +vi.mock("@/lib/api-handler", async (importOriginal) => { + const actual = await importOriginal(); + return { ...actual, requireAuth: vi.fn() }; +}); +vi.mock("@/lib/integrations/healthkit-type-sync", async (importOriginal) => { + const actual = + await importOriginal< + typeof import("@/lib/integrations/healthkit-type-sync") + >(); + return { ...actual, recordHealthKitTypeArrivals: vi.fn() }; +}); +vi.mock("@/lib/auth/audit", () => ({ auditLog: vi.fn() })); +vi.mock("@/lib/rate-limit", () => ({ + checkRateLimit: vi.fn(), + rateLimitHeaders: () => ({}), +})); +vi.mock("@/lib/idempotency", () => ({ + withIdempotency: + (fn: (...args: Args) => Promise) => + (...args: Args) => + fn(...args), +})); +vi.mock("@/lib/cache/invalidate", () => ({ + invalidateUserMedications: vi.fn(), +})); +vi.mock("@/lib/notifications/medication-intake-sync", () => ({ + queueMedicationIntakeSync: vi.fn(), +})); +vi.mock("@/lib/logging/transports", () => ({ emitIfSampled: vi.fn() })); +vi.mock("@/lib/db-compat", () => ({ + ensureDbCompatibility: vi.fn().mockResolvedValue(undefined), +})); +vi.mock("next/headers", () => ({ + headers: vi.fn(async () => ({ get: () => null })), + cookies: vi.fn(async () => ({ + get: () => undefined, + set: () => {}, + delete: () => {}, + })), +})); + +import { POST } from "../route"; +import { prisma } from "@/lib/db"; +import { requireAuth } from "@/lib/api-handler"; +import { recordHealthKitTypeArrivals } from "@/lib/integrations/healthkit-type-sync"; +import { checkRateLimit } from "@/lib/rate-limit"; + +const USER = { + id: "user-1", + username: "tester", + role: "USER" as const, + timezone: "Europe/Berlin", +}; + +/** A replayed Apple dose: the cheapest batch that still counts as an arrival. */ +async function postReplayedDose(): Promise { + vi.mocked(prisma.medicationIntakeEvent.findMany).mockResolvedValueOnce([ + { id: "row-existing", externalId: "hk-dose-1" }, + ] as never); + return POST( + new NextRequest("http://localhost/api/medications/intake/bulk", { + method: "POST", + headers: { "content-type": "application/json" }, + body: JSON.stringify({ + syncTrigger: "background", + entries: [ + { + medicationId: "med-apple", + takenAt: "2026-06-15T12:00:00.000Z", + source: "APPLE_HEALTH", + externalId: "hk-dose-1", + }, + ], + }), + }), + ); +} + +beforeEach(() => { + vi.resetAllMocks(); + vi.mocked(checkRateLimit).mockResolvedValue({ allowed: true } as never); + vi.mocked(prisma.user.update).mockResolvedValue({} as never); + vi.mocked(prisma.auditLog.create).mockResolvedValue({} as never); + vi.mocked(prisma.medication.findMany).mockResolvedValue([ + { id: "med-apple", externalSource: "APPLE_HEALTH" }, + ] as never); +}); + +describe("the dose arrival record and the credential that sent the batch", () => { + it("is written for the phone's own session", async () => { + vi.mocked(requireAuth).mockResolvedValue({ + session: { id: "s" }, + user: USER, + } as never); + const res = await postReplayedDose(); + expect(res.status).toBe(200); + expect(recordHealthKitTypeArrivals).toHaveBeenCalledTimes(1); + }); + + it("is not written for a narrow, single-purpose credential", async () => { + vi.mocked(requireAuth).mockResolvedValue({ + session: { id: "t" }, + user: USER, + bearerScope: "measurements:write", + } as never); + const res = await postReplayedDose(); + expect(res.status).toBe(200); + expect(recordHealthKitTypeArrivals).not.toHaveBeenCalled(); + }); +}); diff --git a/src/app/api/medications/intake/bulk/route.ts b/src/app/api/medications/intake/bulk/route.ts index d5dfdb2de..00bfc9d5d 100644 --- a/src/app/api/medications/intake/bulk/route.ts +++ b/src/app/api/medications/intake/bulk/route.ts @@ -43,7 +43,7 @@ import { NextRequest } from "next/server"; import { z } from "zod/v4"; import { prisma } from "@/lib/db"; -import { apiHandler, requireAuth } from "@/lib/api-handler"; +import { apiHandler, isScopedCredential, requireAuth } from "@/lib/api-handler"; import { annotate } from "@/lib/logging/context"; import { auditLog } from "@/lib/auth/audit"; import { @@ -195,7 +195,13 @@ interface EntryResult { export const POST = apiHandler(withIdempotency<[NextRequest]>(postBulk)); async function postBulk(request: NextRequest): Promise { - const { user } = await requireAuth(); + const auth = await requireAuth(); + const { user } = auth; + // A narrow, single-purpose credential (a bridge, an ingest token) is no + // Apple Health sync, so it never writes the dose arrival record below. The + // bare `requireAuth()` refuses such a credential today; the check keeps the + // record honest should this route ever declare a scope. + const scoped = isScopedCredential(auth); const rl = await checkRateLimit( `medications:intake:bulk:${user.id}`, @@ -520,6 +526,8 @@ async function postBulk(request: NextRequest): Promise { canonicalSlot, takenAt: entry.takenAt as Date, externalId: entry.externalId, + scheduledFor: entry.scheduledFor ?? null, + userTz: user.timezone, })) ) { canonicalSlot = null; @@ -1019,7 +1027,7 @@ async function postBulk(request: NextRequest): Promise { doseArrival.accepted += 1; if (result.status !== "duplicate") doseArrival.newSamples += 1; } - if (doseArrival.accepted > 0) { + if (doseArrival.accepted > 0 && !scoped) { await recordHealthKitTypeArrivals(prisma, { userId: user.id, counts: new Map([[MEDICATION_DOSE_ARRIVAL_TYPE, doseArrival]]), diff --git a/src/lib/google-health/__tests__/edge-filter-fallback.test.ts b/src/lib/google-health/__tests__/edge-filter-fallback.test.ts index caa2255f6..af018c13e 100644 --- a/src/lib/google-health/__tests__/edge-filter-fallback.test.ts +++ b/src/lib/google-health/__tests__/edge-filter-fallback.test.ts @@ -33,6 +33,7 @@ vi.mock("@/lib/logging/context", () => ({ import { GOOGLE_HEALTH_DATA_TYPES, + GOOGLE_HEALTH_SKIP_MS, type GoogleHealthDataPoint, forEachDataPointPage, googleHealthSliceBudget, @@ -47,7 +48,9 @@ import { readGoogleHealthBackfillCursors, readGoogleHealthBackfillEdgeFilterUnsupported, recordGoogleHealthBackfillPage, + recordGoogleHealthBackfillResumePoint, runWithGoogleHealthBackfillResume, + type GoogleHealthBackfillCursor, } from "../sync-core"; const MINUTE = 60_000; @@ -284,31 +287,181 @@ describe("passing over the samples beyond the edge inside a slice", () => { expect(outcome.truncated).toBe(true); }); - it("does not stop on the slice's clock while it is still passing over", async () => { + it("stops on the slice's clock while it is still passing over, and keeps its place", async () => { let clock = 0; safeFetchMock.mockImplementation(async (url: string) => { clock += 10_000; return respond(url); }); - // Each request takes ten seconds and the slice has fifteen, counted from - // when the collection started; passing over the first three pages takes - // forty. + // Each request takes ten seconds and the slice has fifteen; passing over + // the first three pages takes thirty. The slice does not run on past its + // clock for the skip any more: it stops and saves where it got to. const budget = googleHealthSliceBudget(15_000, 500, () => clock); - budget.deadline = 15_000; - const { pages } = await runWithGoogleHealthStop( + const onResumePoint = vi.fn(); + const { pages, outcome } = await runWithGoogleHealthStop( () => false, () => walk({ resumable: true, - edge: { at: at(15), order: "desc", filter: false }, + edge: { at: at(15), order: "desc", filter: false, onResumePoint }, }), budget, ); - // The crossing page and the two after it, inside the fifteen seconds the - // slice still had once the skip was given back. - expect(pages).toHaveLength(3); - expect(budget.deadline).toBe(55_000); + expect(pages).toHaveLength(0); + expect(budget.deadline).toBe(15_000); expect(budget.stopReason).toBe("time_budget"); + expect(outcome.truncated).toBe(true); + expect(onResumePoint).toHaveBeenCalledWith({ token: "1", page: 1 }); + }); + + it("stops passing over on its own limit inside a long slice, and keeps its place", async () => { + let clock = 0; + safeFetchMock.mockImplementation(async (url: string) => { + clock += 60_000; + return respond(url); + }); + // The edge is six pages deep; each request takes a minute, and the skip + // may run for three of the slice's sixty. + const budget = googleHealthSliceBudget(3_600_000, 500, () => clock); + const onResumePoint = vi.fn(); + const { pages, outcome } = await runWithGoogleHealthStop( + () => false, + () => + walk({ + resumable: true, + edge: { at: at(30), order: "desc", filter: false, onResumePoint }, + }), + budget, + ); + expect(GOOGLE_HEALTH_SKIP_MS).toBe(3 * 60_000); + expect(pages).toHaveLength(0); + expect(safeFetchMock).toHaveBeenCalledTimes(3); + expect(outcome.truncated).toBe(true); + // The slice itself is not over: other collections may still run. + expect(budget.stopReason).toBeNull(); + expect(onResumePoint).toHaveBeenCalledWith({ token: "2", page: 2 }); + }); + + it("goes on from the saved place, rereading only its page", async () => { + const filtered = await walk({ + resumable: true, + edge: { at: at(30), order: "desc" }, + }); + server.requests = []; + safeFetchMock.mockClear(); + const tokens: Array = []; + safeFetchMock.mockImplementation(async (url: string) => { + tokens.push(new URL(url).searchParams.get("pageToken")); + return respond(url); + }); + const { rows, outcome } = await walk({ + resumable: true, + edge: { + at: at(30), + order: "desc", + filter: false, + resumeFrom: { token: "2", page: 2 }, + }, + }); + expect(rows).toEqual(filtered.rows); + expect(tokens).toEqual(["2", "3", "4", "5", "6", "7"]); + expect(outcome.truncated).toBe(false); + }); + + it("saves its place on a rate limit it cannot wait out", async () => { + let n = 0; + safeFetchMock.mockImplementation(async (url: string) => + ++n === 3 + ? new Response( + JSON.stringify({ + error: { code: 429, status: "RESOURCE_EXHAUSTED" }, + }), + { + status: 429, + headers: { + "content-type": "application/json", + "retry-after": "3600", + }, + }, + ) + : respond(url), + ); + const budget = googleHealthSliceBudget(3_600_000, 500); + const onResumePoint = vi.fn(); + const { pages, outcome } = await runWithGoogleHealthStop( + () => false, + () => + walk({ + resumable: true, + edge: { at: at(30), order: "desc", filter: false, onResumePoint }, + }), + budget, + ); + expect(pages).toHaveLength(0); + expect(budget.stopReason).toBe("rate_limited"); + expect(outcome.truncated).toBe(true); + expect(onResumePoint).toHaveBeenCalledWith({ token: "1", page: 1 }); + }); + + it("reads from the newest page when Google refuses the saved token", async () => { + let n = 0; + safeFetchMock.mockImplementation(async (url: string) => + ++n === 1 + ? json( + { + error: { + code: 400, + status: "INVALID_ARGUMENT", + message: "Invalid page token.", + }, + }, + 400, + ) + : respond(url), + ); + const { rows, outcome } = await walk({ + resumable: true, + edge: { + at: at(30), + order: "desc", + filter: false, + resumeFrom: { token: "2", page: 2 }, + }, + }); + expect(rows).toHaveLength(TOTAL - 30); + expect(outcome.truncated).toBe(false); + }); + + it("reads from the newest page when the saved place no longer reaches the edge", async () => { + // Page 7 holds only samples older than the edge: the list moved under + // the token, and going on from it could step over samples nobody wrote. + const { rows } = await walk({ + resumable: true, + edge: { + at: at(30), + order: "desc", + filter: false, + resumeFrom: { token: "7", page: 7 }, + }, + }); + expect(rows.map((p) => p.heartRate)).toEqual( + Array.from({ length: TOTAL - 30 }, (_, i) => ({ + beatsPerMinute: String(60 + 30 + i), + sampleTime: { physicalTime: at(30 + i).toISOString() }, + })), + ); + }); + + it("does not charge the pages it passed over against the walk's own ceiling", async () => { + // Three pages passed over, then a ceiling of two written pages: both are + // written, not one. + const { pages, outcome } = await walk({ + resumable: true, + maxPages: 2, + edge: { at: at(15), order: "desc", filter: false }, + }); + expect(pages).toHaveLength(2); + expect(outcome.truncated).toBe(true); }); it("still stops on the job's own budget", async () => { @@ -410,6 +563,75 @@ describe("the note that a collection refuses the edge filter", () => { expect(lastProgress()).not.toHaveProperty("edgeFilterUnsupported"); }); + it("keeps a saved place in the list, counts it as progress only when it moves forward, and hands it to the next slice", async () => { + server.refuseUpperBound = true; + const cursor = { + at: at(30).toISOString(), + order: "desc" as const, + pages: 4, + }; + const run = ( + cursors: Map, + point: { token: string; page: number }, + ) => + runWithGoogleHealthBackfillResume( + "u1", + new Set(), + () => recordGoogleHealthBackfillResumePoint("fetchHeartRate", point), + cursors, + new Set(["fetchHeartRate"]), + ); + + const first = await run(new Map([["fetchHeartRate", cursor]]), { + token: "4", + page: 4, + }); + expect(first.advanced.has("fetchHeartRate")).toBe(true); + const saved = readGoogleHealthBackfillCursors(lastProgress()); + expect(saved.get("fetchHeartRate")).toEqual({ + ...cursor, + resume: { token: "4", page: 4, reached: 4 }, + }); + + // The same place again, or one short of it, is not progress. + const again = await run(new Map(saved), { token: "4", page: 4 }); + expect(again.advanced.size).toBe(0); + const back = await run(new Map(saved), { token: "2", page: 2 }); + expect(back.advanced.size).toBe(0); + expect( + readGoogleHealthBackfillCursors(lastProgress()).get("fetchHeartRate") + ?.resume, + ).toEqual({ token: "2", page: 2, reached: 4 }); + + // A page written keeps the place; the next slice is handed it. + await runWithGoogleHealthBackfillResume( + "u1", + new Set(), + () => + recordGoogleHealthBackfillPage("fetchHeartRate", { + first: at(30), + last: at(34), + }), + new Map(saved), + new Set(["fetchHeartRate"]), + ); + const next = readGoogleHealthBackfillCursors(lastProgress()); + expect(next.get("fetchHeartRate")?.resume).toEqual( + saved.get("fetchHeartRate")?.resume, + ); + await runWithGoogleHealthBackfillResume( + "u1", + new Set(), + async () => { + expect( + googleHealthBackfillCursor("fetchHeartRate")?.edge, + ).toMatchObject({ filter: false, resumeFrom: { token: "4", page: 4 } }); + }, + next, + new Set(["fetchHeartRate"]), + ); + }); + it("reads only well-formed keys", () => { expect([ ...readGoogleHealthBackfillEdgeFilterUnsupported({ diff --git a/src/lib/google-health/__tests__/sync-time-budget.test.ts b/src/lib/google-health/__tests__/sync-time-budget.test.ts new file mode 100644 index 000000000..8b2bd3b4b --- /dev/null +++ b/src/lib/google-health/__tests__/sync-time-budget.test.ts @@ -0,0 +1,85 @@ +/** + * A caller's time limit (`shouldStop`, the hourly job's budget) reaches every + * walk of the sync cycle, so a walk stops when it is spent; and a cycle that + * stopped on it is not stamped, so the next run reads the rest from the same + * watermark. + */ +import { beforeEach, describe, expect, it, vi } from "vitest"; + +const { prismaMock, recordSyncSuccess, resources } = vi.hoisted(() => { + return { + prismaMock: { + integrationStatus: { findUnique: vi.fn(async () => null) }, + googleHealthConnection: { + findUnique: vi.fn(async () => ({ lastSyncedAt: null })), + update: vi.fn(async () => ({})), + }, + }, + recordSyncSuccess: vi.fn(async () => {}), + resources: { + workout: vi.fn(async () => 0), + sleep: vi.fn(async () => 0), + activity: vi.fn(async () => 0), + metrics: vi.fn(async () => 0), + }, + }; +}); + +vi.mock("@/lib/db", () => ({ prisma: prismaMock })); + +// The account lock is a Postgres advisory lock on a connection of its own; +// these cases run without a database, so the lock is always free. +vi.mock("../sync-lock", () => ({ + withGoogleHealthSyncLock: async ( + _userId: string, + run: () => Promise, + ) => ({ + ran: true, + result: await run(), + }), +})); +vi.mock("@/lib/integrations/status", () => ({ + isReauthRequired: vi.fn(async () => false), + recordSyncSuccess, +})); +vi.mock("@/lib/rollups/measurement-rollups", () => ({ + collapseToTypeDayKeys: vi.fn(() => []), + recomputeUserRollups: vi.fn(async () => {}), +})); +vi.mock("@/lib/insights/comprehensive-generate", () => ({ + invalidateStatusInsightsForTypes: vi.fn(async () => {}), +})); +vi.mock("../sync-workout", () => ({ syncUserWorkout: resources.workout })); +vi.mock("../sync-sleep", () => ({ syncUserSleep: resources.sleep })); +vi.mock("../sync-activity", () => ({ syncUserActivity: resources.activity })); +vi.mock("../sync-metrics", () => ({ syncUserMetrics: resources.metrics })); + +import { googleHealthSliceExhausted } from "../client"; +import { syncUserGoogleHealth } from "../sync"; + +beforeEach(() => { + vi.clearAllMocks(); + prismaMock.googleHealthConnection.findUnique.mockResolvedValue({ + lastSyncedAt: null, + }); +}); + +describe("the caller's time limit inside the sync cycle", () => { + it("is what every resource's walks are asked, and an untouched one never stops", async () => { + let spent = false; + const asked: boolean[] = []; + resources.metrics.mockImplementation(async () => { + asked.push(googleHealthSliceExhausted()); + spent = true; + asked.push(googleHealthSliceExhausted()); + return 0; + }); + await syncUserGoogleHealth("budget-user", { shouldStop: () => spent }); + expect(asked).toEqual([false, true]); + + asked.length = 0; + spent = false; + await syncUserGoogleHealth("budget-user"); + expect(asked).toEqual([false, false]); + }); +}); diff --git a/src/lib/google-health/client.ts b/src/lib/google-health/client.ts index 10bb8c07d..2cbf02b73 100644 --- a/src/lib/google-health/client.ts +++ b/src/lib/google-health/client.ts @@ -169,7 +169,11 @@ export interface GoogleHealthSliceBudget { /** * Of `pages`, those a walk only passed over on its way to its edge, because * Google refused the edge filter (see `forEachDataPointPage`). They are not - * charged against `maxPages`, and the time they took moves `deadline` on. + * charged against `maxPages`. Their time is: a skip runs on the slice's + * clock like any other read, and on its own shorter limit + * (`GOOGLE_HEALTH_SKIP_MS`), and keeps its place for the next slice when it + * stops. Only a skip that had to start over from the newest page, because + * its saved place was refused, moves `deadline` on by the time it took. */ skippedPages: number; stopReason: GoogleHealthSliceStopReason | null; @@ -253,14 +257,21 @@ function noteSlicePage(): void { } /** - * Give back to the slice in scope the pages and time a walk spent passing - * over samples beyond its edge (no-op outside a slice). + * Note one page the walk only passed over on its way to its edge: read, but + * not charged against the slice's pages (no-op outside a slice). */ -function refundSliceSkip(pages: number, ms: number): void { +function noteSliceSkip(): void { const slice = stopStorage.getStore()?.slice; - if (!slice) return; - slice.skippedPages += pages; - if (slice.deadline !== null) slice.deadline += ms; + if (slice) slice.skippedPages += 1; +} + +/** + * Give back to the slice in scope the time a skip took that had to start over + * from the newest page (no-op outside a slice). + */ +function extendSliceDeadline(ms: number): void { + const slice = stopStorage.getStore()?.slice; + if (slice && slice.deadline !== null) slice.deadline += ms; } /** The slice clock in scope, or the wall clock outside a slice. */ @@ -747,8 +758,13 @@ interface DataPointQuery { * beyond the edge here instead (see `forEachDataPointPage`); the walk falls * back to that on its own when Google refuses the bound, and calls * `onFilterUnsupported` once when it does. `tz` reads an offset-less sample - * time the way the edge was recorded. `maxSkipPages` bounds how many pages - * the walk may pass over before it reaches the edge. + * time the way the edge was recorded. `maxSkipPages` bounds how far into + * the unbounded list the walk may get before it reaches the edge. + * + * A walk without the bound keeps its place in that list across slices: + * `resumeFrom` is where an earlier slice's walk stopped, and + * `onResumePoint` is told where this one stops (see + * `GoogleHealthResumePoint`). */ edge?: { at: Date; @@ -757,9 +773,38 @@ interface DataPointQuery { tz?: string; onFilterUnsupported?: () => void | Promise; maxSkipPages?: number; + resumeFrom?: GoogleHealthResumePoint; + onResumePoint?: (point: GoogleHealthResumePoint) => void | Promise; }; } +/** + * Where a walk without the edge bound stopped in the unbounded list: the page + * token that fetched the last page it read, and that page's position (pages + * from the newest one, which is position 0). The next slice starts by reading + * that page again rather than the newest one, so it passes over only what is + * left between it and the edge instead of everything earlier slices wrote. + * + * Re-reading the last page, not the one after it, is what lets the walk check + * the token still points where it did: the page must hold a sample at or + * beyond the edge. A list that lost samples in between could otherwise move + * the token past samples nobody wrote. A page that fails the check, or a + * token Google refuses, sends the walk back to the newest page, the way it + * read before it kept its place. + */ +export interface GoogleHealthResumePoint { + token: string; + page: number; +} + +/** + * The longest a walk passes over samples beyond its edge in one slice before + * it stops and keeps its place for the next. Shorter than the slice, so a + * slice that has to skip still writes, and never longer than it: a skip runs + * on the slice's clock and the account's lock is held no longer than a slice. + */ +export const GOOGLE_HEALTH_SKIP_MS = 3 * 60 * 1000; + const pad2 = (n: number): string => String(n).padStart(2, "0"); /** @@ -1202,158 +1247,202 @@ export async function forEachDataPointPage( const walk = async ( dateStyle: GoogleHealthDateFilterStyle, edgeBy: "filter" | "skip", + resumeFrom: GoogleHealthResumePoint | undefined, + restarted: boolean, ): Promise => { let fetched = 0; - let pageToken: string | null | undefined; + let pageToken: string | null | undefined = resumeFrom?.token; + // The token that fetched the page last read, and that page's position. + let lastToken: string | undefined; + let lastPosition = -1; let pageCount = 0; let stopped = false; // Reading without the edge bound: the pages before the edge are passed // over, not written, until the first sample at or beyond it. const skipTo = edge && edgeBy === "skip" ? edge : undefined; let crossed = skipTo === undefined; + // Pages passed over in this walk. Never reset: the walk's page ceiling + // counts the pages it wrote, `pageCount - skipped`, before the crossing + // and after it alike. let skipped = 0; + const startPosition = resumeFrom?.page ?? 0; const skipStartedAt = skipTo ? sliceNow() : 0; const maxSkip = skipTo?.maxSkipPages ?? GOOGLE_HEALTH_DENSE_MAX_PAGES; + const sampleAt = (point: GoogleHealthDataPoint): number | null => + googleHealthSampleInstant(point, dataType, skipTo?.tz)?.getTime() ?? null; const beyondEdge = (point: GoogleHealthDataPoint): boolean | null => { - const t = googleHealthSampleInstant(point, dataType, skipTo?.tz); + const t = sampleAt(point); if (t === null || !skipTo) return null; return skipTo.order === "desc" - ? t.getTime() > skipTo.at.getTime() - : t.getTime() < skipTo.at.getTime(); + ? t > skipTo.at.getTime() + : t < skipTo.at.getTime(); }; - const refundSkip = () => { - if (skipped > 0) refundSliceSkip(skipped, sliceNow() - skipStartedAt); - skipped = 0; + const reachesEdge = (point: GoogleHealthDataPoint): boolean => { + const t = sampleAt(point); + if (t === null || !skipTo) return false; + return skipTo.order === "desc" + ? t >= skipTo.at.getTime() + : t <= skipTo.at.getTime(); }; - try { - do { - // A walk still passing over the samples beyond its edge does not stop - // on the slice's budget, only on the job's: the skip writes nothing, - // so a slice that stopped inside it would have nothing to show, and - // the next slice would start the same skip over (see - // `GoogleHealthSliceBudget.skippedPages`). - if (crossed ? stopRequested(resumable) : stopRequested(false)) { - stopped = true; - break; - } - if (!crossed && skipped >= maxSkip) { - getEvent()?.addWarning( - `google-health ${verb}: passed over ${skipped} pages without reaching the resume edge`, - ); - stopped = true; - break; - } - const params = new URLSearchParams({ pageSize: String(pageSize) }); - const filters: string[] = []; - if (query.start) { - const { field, bound } = incrementalFilter( - dataType, - query.start, - query.tz, - dateStyle, - ); - filters.push(`${field} >= "${bound}"`); - } - const edgeFiltered = edge !== undefined && edgeBy === "filter"; - if (edgeFiltered) { - const { field, bound } = incrementalFilter( - dataType, - edge.at, - query.tz, - dateStyle, - ); - filters.push( - `${field} ${edge.order === "desc" ? "<=" : ">="} "${bound}"`, - ); - } - if (filters.length > 0) params.set("filter", filters.join(" AND ")); - if (pageToken) params.set("pageToken", pageToken); + do { + // A skip that had to start over from the newest page runs as the walk + // did before it kept its place: on the job's budget alone, its time + // given back to the slice once it crosses. Every other read stops on + // the slice's budget, and a skip also on its own shorter limit; it + // keeps its place below, so the next slice goes on from there. + const untimed = !crossed && restarted; + if (untimed ? stopRequested(false) : stopRequested(resumable)) { + stopped = true; + break; + } + if (!crossed && startPosition + pageCount >= maxSkip) { + getEvent()?.addWarning( + `google-health ${verb}: passed over ${startPosition + pageCount} pages without reaching the resume edge`, + ); + stopped = true; + break; + } + if ( + !crossed && + !untimed && + resumable && + inSlice() && + sliceNow() - skipStartedAt >= GOOGLE_HEALTH_SKIP_MS + ) { + stopped = true; + break; + } + const params = new URLSearchParams({ pageSize: String(pageSize) }); + const filters: string[] = []; + if (query.start) { + const { field, bound } = incrementalFilter( + dataType, + query.start, + query.tz, + dateStyle, + ); + filters.push(`${field} >= "${bound}"`); + } + const edgeFiltered = edge !== undefined && edgeBy === "filter"; + if (edgeFiltered) { + const { field, bound } = incrementalFilter( + dataType, + edge.at, + query.tz, + dateStyle, + ); + filters.push( + `${field} ${edge.order === "desc" ? "<=" : ">="} "${bound}"`, + ); + } + if (filters.length > 0) params.set("filter", filters.join(" AND ")); + if (pageToken) params.set("pageToken", pageToken); - requestCount += 1; - // v1.42 (#1023) — the first filtered daily-summary read answering 400 - // is the expected trigger for the snake_case retry below, not a - // failure: some accounts reject the documented camelCase prefix on - // some types, and the very next request answers 200. It was logged as - // an error next to the 200 that followed it. It is recorded as a note - // now; any other 400 still carries its error. The same holds for the - // first resumed request refusing the edge bound. - const firstRequest = requestCount === 1; - const firstOfWalk = pageCount === 0; - const edgeRefused = (status: number, detail: string | undefined) => - edgeFiltered && - firstOfWalk && - status === 400 && - refusesEdgeFilter(detail); - const { status, json, verdict, apiErrorDetail } = - await googleHealthDataRequest( - accessToken, - `${verb}(page=${pageCount})`, - (token) => - safeFetch( - `${GOOGLE_HEALTH_API_BASE}/users/me/dataTypes/${dataType.path}/dataPoints?${params}`, - { - method: "GET", - headers: { Authorization: `Bearer ${token}` }, - }, - ), - (status, detail) => - canFallBack && - dateStyle === "camel" && - firstRequest && - status === 400 - ? "date_filter_rejected_retrying_snake_case" - : edgeRefused(status, detail) - ? "edge_filter_rejected_reading_without_it" + requestCount += 1; + // v1.42 (#1023) — the first filtered daily-summary read answering 400 + // is the expected trigger for the snake_case retry below, not a + // failure: some accounts reject the documented camelCase prefix on + // some types, and the very next request answers 200. It was logged as + // an error next to the 200 that followed it. It is recorded as a note + // now; any other 400 still carries its error. The same holds for the + // first resumed request refusing the edge bound, and for a saved + // place in the unbounded list Google no longer takes. + const firstRequest = requestCount === 1; + const firstOfWalk = pageCount === 0; + const edgeRefused = (status: number, detail: string | undefined) => + edgeFiltered && + firstOfWalk && + status === 400 && + refusesEdgeFilter(detail); + const resumeRefused = (status: number) => + resumeFrom !== undefined && firstOfWalk && status === 400; + const requestToken = pageToken ?? undefined; + const { status, json, verdict, apiErrorDetail } = + await googleHealthDataRequest( + accessToken, + `${verb}(page=${pageCount})`, + (token) => + safeFetch( + `${GOOGLE_HEALTH_API_BASE}/users/me/dataTypes/${dataType.path}/dataPoints?${params}`, + { + method: "GET", + headers: { Authorization: `Bearer ${token}` }, + }, + ), + (status, detail) => + canFallBack && + dateStyle === "camel" && + firstRequest && + status === 400 + ? "date_filter_rejected_retrying_snake_case" + : edgeRefused(status, detail) + ? "edge_filter_rejected_reading_without_it" + : resumeRefused(status) + ? "resume_token_rejected_reading_from_newest" : undefined, - ); - if (edgeRefused(status, apiErrorDetail)) { - throw new EdgeFilterRefused(); - } - // A rate limit the request could not wait out ends a resumable walk - // inside a backfill slice where it is: the pages before it are written - // and their edge recorded, so this is a pause, not a failure. The slice - // ends with it, since every other walk would meet the same quota. - if (status === 429 && resumable && inSlice()) { - endSlice("rate_limited"); - stopped = true; - break; - } - if (verdict.classification !== "success") { - throw new GoogleHealthApiError({ - verb, - classification: verdict.classification, - httpStatus: verdict.httpStatus, - reason: verdict.reason, - upstreamError: apiErrorDetail, - }); - } + ); + if (edgeRefused(status, apiErrorDetail)) { + throw new EdgeFilterRefused(); + } + if (resumeRefused(status)) throw new ResumePointLost(); + // A rate limit the request could not wait out ends a resumable walk + // inside a backfill slice where it is: the pages before it are written + // and their edge recorded, so this is a pause, not a failure. The slice + // ends with it, since every other walk would meet the same quota. + if (status === 429 && resumable && inSlice()) { + endSlice("rate_limited"); + stopped = true; + break; + } + if (verdict.classification !== "success") { + throw new GoogleHealthApiError({ + verb, + classification: verdict.classification, + httpStatus: verdict.httpStatus, + reason: verdict.reason, + upstreamError: apiErrorDetail, + }); + } - let page = json?.dataPoints ?? []; - pageToken = json?.nextPageToken ?? null; - pageCount += 1; - fetched += page.length; - noteSlicePage(); - if (!crossed) { - // Placed samples beyond the edge were written by an earlier slice; - // one without a sample time cannot be placed and is passed over - // with them until the walk is past the edge. - const kept = page.filter((p) => beyondEdge(p) === false); - if (kept.length === 0) { - skipped += 1; - continue; - } - crossed = true; - refundSkip(); - page = page.filter((p) => beyondEdge(p) !== true); + let page = json?.dataPoints ?? []; + // A saved place has to still hold a sample at or beyond the edge; + // past it, samples nobody wrote could lie behind the token. + if (resumeFrom && firstOfWalk && !page.some(reachesEdge)) { + throw new ResumePointLost(); + } + if (requestToken !== undefined) { + lastToken = requestToken; + lastPosition = startPosition + pageCount; + } + pageToken = json?.nextPageToken ?? null; + pageCount += 1; + fetched += page.length; + noteSlicePage(); + if (!crossed) { + // Placed samples beyond the edge were written by an earlier slice; + // one without a sample time cannot be placed and is passed over + // with them until the walk is past the edge. + const kept = page.filter((p) => beyondEdge(p) === false); + if (kept.length === 0) { + skipped += 1; + noteSliceSkip(); + continue; } - await onPage(page); - } while (pageToken && pageCount - skipped < maxPages); - } finally { - refundSkip(); + crossed = true; + if (restarted) extendSliceDeadline(sliceNow() - skipStartedAt); + page = page.filter((p) => beyondEdge(p) !== true); + } + await onPage(page); + } while (pageToken && pageCount - skipped < maxPages); + + const truncated = stopped || Boolean(pageToken); + // Keep the place for the next slice. Only a walk without the bound has + // one, and only one that ended short needs it. + if (skipTo && truncated && lastToken !== undefined) { + await skipTo.onResumePoint?.({ token: lastToken, page: lastPosition }); } - - notePagination(pageCount, fetched, stopped || Boolean(pageToken)); + notePagination(pageCount, fetched, truncated); }; // The fallback only exists for filtered daily-summary reads — every other @@ -1363,15 +1452,28 @@ export async function forEachDataPointPage( let style: GoogleHealthDateFilterStyle = "camel"; let edgeBy: "filter" | "skip" = edge?.filter === false ? "skip" : "filter"; - const run = async (dateStyle: GoogleHealthDateFilterStyle) => { + // From the saved place in the unbounded list when there is one; once from + // the newest page when that place is lost. + const walkSkipping = async (dateStyle: GoogleHealthDateFilterStyle) => { + const resumeFrom = edge?.resumeFrom; + if (!resumeFrom) return walk(dateStyle, "skip", undefined, false); try { - await walk(dateStyle, edgeBy); + await walk(dateStyle, "skip", resumeFrom, false); + } catch (err) { + if (!(err instanceof ResumePointLost)) throw err; + await walk(dateStyle, "skip", undefined, true); + } + }; + const run = async (dateStyle: GoogleHealthDateFilterStyle) => { + if (edgeBy === "skip") return walkSkipping(dateStyle); + try { + await walk(dateStyle, edgeBy, undefined, false); } catch (err) { if (!(err instanceof EdgeFilterRefused)) throw err; // Once: the walk without the bound sends no edge filter to refuse. edgeBy = "skip"; await edge?.onFilterUnsupported?.(); - await walk(dateStyle, edgeBy); + await walk(dateStyle, edgeBy, undefined, false); } }; try { @@ -1403,6 +1505,18 @@ class EdgeFilterRefused extends Error { } } +/** + * Thrown inside a walk that started from a saved place in the unbounded list + * (`GoogleHealthResumePoint`) when Google refused the token or the page it + * returned no longer reaches the edge; the walk starts over from the newest + * page. + */ +class ResumePointLost extends Error { + constructor() { + super("google-health: saved place in the list lost"); + } +} + /** * Whether a 400 on the first resumed request is Google refusing the edge * bound, rather than something else about the request. The request differs diff --git a/src/lib/google-health/sync-core.ts b/src/lib/google-health/sync-core.ts index 048e3bd55..9bf3bf29c 100644 --- a/src/lib/google-health/sync-core.ts +++ b/src/lib/google-health/sync-core.ts @@ -44,6 +44,7 @@ import { noteGoogleHealthOutcomeFailure, noteGoogleHealthWritten, refreshAccessToken, + type GoogleHealthResumePoint, type GoogleHealthTokenSource, } from "./client"; import { getUserGoogleHealthCredentials } from "./credentials"; @@ -441,6 +442,14 @@ export interface GoogleHealthBackfillCursor { order: "desc" | "asc"; /** Pages this collection has read across every attempt so far. */ pages: number; + /** + * Only for a collection read without the edge bound: where its last walk + * stopped in the unbounded list (see `GoogleHealthResumePoint`), and the + * furthest position any walk of it has saved. A saved place counts as the + * slice's progress only when it is further than every one before it, so a + * chain of slices that keep passing over the same pages ends. + */ + resume?: { token: string; page: number; reached: number }; } /** What one collection came to in one backfill attempt. */ @@ -503,13 +512,25 @@ export function readGoogleHealthBackfillCursors( const c = progressRecord(raw); const at = typeof c.at === "string" ? c.at : null; if (!at || Number.isNaN(Date.parse(at))) continue; + const r = progressRecord(c.resume); + const count = (v: unknown): number => + typeof v === "number" && Number.isFinite(v) && v > 0 ? Math.trunc(v) : 0; + const resume = + typeof r.token === "string" && + r.token.length > 0 && + r.token.length <= 4096 && + count(r.page) > 0 + ? { + token: r.token, + page: count(r.page), + reached: Math.max(count(r.reached), count(r.page)), + } + : undefined; out.set(key, { at: new Date(at).toISOString(), order: c.order === "asc" ? "asc" : "desc", - pages: - typeof c.pages === "number" && Number.isFinite(c.pages) && c.pages > 0 - ? Math.trunc(c.pages) - : 0, + pages: count(c.pages), + ...(resume ? { resume } : {}), }); } return out; @@ -555,7 +576,12 @@ async function persistBackfillProgress( cursors: Object.fromEntries( [...next.cursors].map(([key, c]) => [ key, - { at: c.at, order: c.order, pages: c.pages }, + { + at: c.at, + order: c.order, + pages: c.pages, + ...(c.resume ? { resume: c.resume } : {}), + }, ]), ), // Only once there is something to say, so a backfill that never met @@ -626,24 +652,80 @@ export async function runWithGoogleHealthBackfillResume( * where every walk reads its whole window. */ export function googleHealthBackfillCursor(key: GoogleHealthCollectionKey): { - edge?: { at: Date; order: "desc" | "asc"; filter: boolean }; + edge?: { + at: Date; + order: "desc" | "asc"; + filter: boolean; + resumeFrom?: GoogleHealthResumePoint; + }; pagesSoFar: number; } | null { const resume = backfillResumeStorage.getStore(); if (!resume) return null; const cursor = resume.cursors.get(key); + const filter = !resume.edgeFilterUnsupported.has(key); return cursor ? { edge: { at: new Date(cursor.at), order: cursor.order, - filter: !resume.edgeFilterUnsupported.has(key), + filter, + ...(!filter && cursor.resume + ? { + resumeFrom: { + token: cursor.resume.token, + page: cursor.resume.page, + }, + } + : {}), }, pagesSoFar: cursor.pages, } : { pagesSoFar: 0 }; } +/** + * Record where a collection's walk without the edge bound stopped in the + * unbounded list, so the next slice goes on from there. A place further than + * every one saved before counts as this slice's progress (the backfill sends + * another slice on it), even when no page was written: a skip deeper than one + * slice is worked through over several. Outside a backfill, or for a + * collection without an edge, this does nothing. + */ +export async function recordGoogleHealthBackfillResumePoint( + key: GoogleHealthCollectionKey, + point: GoogleHealthResumePoint, +): Promise { + const resume = backfillResumeStorage.getStore(); + if (!resume) return; + const current = resume.cursors.get(key); + if (!current) return; + const reached = current.resume?.reached ?? 0; + const further = point.page > reached; + const cursors = new Map(resume.cursors); + cursors.set(key, { + ...current, + resume: { + token: point.token, + page: point.page, + reached: Math.max(reached, point.page), + }, + }); + try { + await persistBackfillProgress(resume, { done: resume.done, cursors }); + if (further && !resume.advanced.has(key)) { + resume.advanced.set(key, current.at); + } + } catch (err) { + getEvent()?.addWarning( + `google-health: backfill progress write failed for ${key}: ${err}`, + ); + annotate({ + meta: { "googleHealth.backfill.progressWriteFailed": key }, + }); + } +} + /** * Note that Google refused the edge filter on a resumed request of this * collection, so every later slice reads without it from the start instead @@ -718,6 +800,8 @@ export async function recordGoogleHealthBackfillPage( at: moved ? far.toISOString() : current!.at, order, pages: (current?.pages ?? 0) + 1, + // The saved place stays until the walk records where it stopped. + ...(current?.resume ? { resume: current.resume } : {}), }; const cursors = new Map(resume.cursors); cursors.set(key, nextCursor); diff --git a/src/lib/google-health/sync-metrics.ts b/src/lib/google-health/sync-metrics.ts index de2a0f945..743cccf6c 100644 --- a/src/lib/google-health/sync-metrics.ts +++ b/src/lib/google-health/sync-metrics.ts @@ -56,6 +56,7 @@ import { handleCollectionFetchError, noteGoogleHealthEdgeFilterUnsupported, recordGoogleHealthBackfillPage, + recordGoogleHealthBackfillResumePoint, runGoogleHealthCollection, upsertGoogleHealthMeasurements, type GoogleHealthMeasurementUpsert, @@ -312,6 +313,15 @@ async function syncMetricCollection( maxSkipPages: ceiling, onFilterUnsupported: () => noteGoogleHealthEdgeFilterUnsupported(resource.verb), + // A place past a page whose write failed would leave that + // page's rows behind it, like a moved edge would. + onResumePoint: (point) => + edgeHeld + ? undefined + : recordGoogleHealthBackfillResumePoint( + resource.verb, + point, + ), }, } : {}), diff --git a/src/lib/google-health/sync.ts b/src/lib/google-health/sync.ts index b0a72601f..85ba41422 100644 --- a/src/lib/google-health/sync.ts +++ b/src/lib/google-health/sync.ts @@ -11,6 +11,7 @@ import { invalidateUserMeasurements } from "@/lib/cache/invalidate"; import { resolveUserTimezone } from "@/lib/tz/resolver"; import { runWithGoogleHealthClientOutcome, + runWithGoogleHealthStop, type GoogleHealthClientOutcome, } from "./client"; import { syncUserActivity } from "./sync-activity"; @@ -100,6 +101,14 @@ export interface GoogleHealthSyncOptions { * account's sync lock. Zero (the default) answers `busy` at once. */ waitForLockMs?: number; + /** + * The caller's time limit, asked before every request once the run holds + * the account (the hourly job's expiry). A walk that is told to stop ends + * there and reports itself truncated: the cycle is not stamped, so the next + * run reads the rest from the same watermark. Not for the backfill, which + * sets its own limits around the whole run. + */ + shouldStop?: () => boolean; } const RESOURCE_STATUSES = new Set([ @@ -292,7 +301,7 @@ async function runGoogleHealthSyncCycle( { name: "dense-heart-rate", fn: syncUserMetrics }, ]; - const cycle = await runWithGoogleHealthSyncCycle(async () => { + const runResources = async () => { let total = 0; let anyFailed = false; const resourceOutcomes: GoogleHealthResourceOutcome[] = []; @@ -334,7 +343,13 @@ async function runGoogleHealthSyncCycle( await persistProgress("in_progress", total, anyFailed, resourceOutcomes); } return { total, anyFailed, resources: resourceOutcomes }; - }); + }; + const shouldStop = opts.shouldStop; + const cycle = await runWithGoogleHealthSyncCycle(() => + shouldStop + ? runWithGoogleHealthStop(shouldStop, runResources) + : runResources(), + ); const total = cycle.result.total; let anyFailed = cycle.result.anyFailed || cycle.hardFailures.length > 0; diff --git a/src/lib/integrations/__tests__/status.test.ts b/src/lib/integrations/__tests__/status.test.ts index a4d365a01..0c0ea8351 100644 --- a/src/lib/integrations/__tests__/status.test.ts +++ b/src/lib/integrations/__tests__/status.test.ts @@ -30,6 +30,9 @@ vi.mock("@/lib/db", () => ({ findUnique: vi.fn(), findMany: vi.fn(), }, + integrationWatch: { + findFirst: vi.fn(), + }, }, })); @@ -161,6 +164,50 @@ describe("recordSyncFailure — under threshold", () => { }); describe("recordSyncFailure — at threshold", () => { + it("does not page a streak the watchdog already announced for the same connection", async () => { + vi.mocked(prisma.integrationStatus.findUnique).mockResolvedValueOnce({ + consecutiveFailuresByKind: { + transient: 2, + reauth_required: 0, + persistent: 0, + }, + persistentFailureStartedAt: null, + alertedAt: null, + } as never); + vi.mocked(prisma.integrationStatus.upsert).mockResolvedValueOnce({ + alertedAt: null, + } as never); + vi.mocked(prisma.integrationWatch.findFirst).mockResolvedValueOnce({ + id: "watch-1", + } as never); + + await recordSyncFailure({ + userId: "u1", + integration: "withings", + kind: "transient", + message: "Withings refresh error: 503", + errorCode: "503", + }); + + expect(prisma.integrationWatch.findFirst).toHaveBeenCalledWith( + expect.objectContaining({ + where: expect.objectContaining({ + userId: "u1", + integration: "withings", + incidentReason: { not: null }, + alertedAt: { not: null }, + }), + }), + ); + expect(dispatchNotification).not.toHaveBeenCalled(); + // Stamped as announced, so later failures of the streak do not ask again. + expect(prisma.integrationStatus.update).toHaveBeenCalledWith( + expect.objectContaining({ + data: { alertedAt: expect.any(Date) }, + }), + ); + }); + it("dispatches an admin Telegram alert when failure count reaches default threshold (3)", async () => { // v1.4.47 W1 — the alert ladder reads Math.max(...buckets) so the // existing row must seed the bucket at N-1 before the in-memory diff --git a/src/lib/integrations/__tests__/watchdog-classify.test.ts b/src/lib/integrations/__tests__/watchdog-classify.test.ts index 9e9be7b9a..35dd48473 100644 --- a/src/lib/integrations/__tests__/watchdog-classify.test.ts +++ b/src/lib/integrations/__tests__/watchdog-classify.test.ts @@ -4,6 +4,7 @@ import { NORMAL_DELIVERY_MIN_DAYS, SOURCE_PROFILES, classifySilence, + FIRST_RUN_ALERTED_AT, currentIncident, decideWatchTransition, type WatchRow, @@ -244,6 +245,43 @@ describe("currentIncident", () => { ).toEqual({ reason: "unexpected_silence", since: ago(30) }); }); + it("never opens an incident for stale or stalled data on its own, however long it lasts", () => { + // An Apple Health account whose phone app stopped running reads as + // `no_new_data` for good; nothing an operator can do about it. + for (const reason of ["no_new_data", "sync_stalled"] as const) { + expect( + currentIncident({ + health: health("degraded", reason, ago(24 * 90)), + silentSince: null, + ledgerAlerted: false, + now: NOW, + }), + ).toBeNull(); + } + }); + + it("opens an incident for provider errors that have lasted more than a day", () => { + expect( + currentIncident({ + health: health("degraded", "provider_errors", ago(25)), + silentSince: null, + ledgerAlerted: false, + now: NOW, + }), + ).toEqual({ reason: "provider_errors", since: ago(25) }); + }); + + it("still opens a silence incident beside stale data", () => { + expect( + currentIncident({ + health: health("degraded", "no_new_data", ago(50)), + silentSince: ago(30), + ledgerAlerted: false, + now: NOW, + }), + ).toEqual({ reason: "unexpected_silence", since: ago(30) }); + }); + it("has no incident for a limited connection", () => { expect( currentIncident({ @@ -256,6 +294,27 @@ describe("currentIncident", () => { }); }); +describe("decideWatchTransition: an incident recorded on the first run", () => { + it("closes without a recovery note, since none was ever sent", () => { + expect( + decideWatchTransition({ + row: { + silentSince: ago(30), + incidentReason: "unexpected_silence", + incidentOpenedAt: ago(2), + alertedAt: FIRST_RUN_ALERTED_AT, + }, + incident: null, + ledgerAlerted: false, + }), + ).toEqual({ + kind: "close", + notify: false, + previousReason: "unexpected_silence", + }); + }); +}); + describe("decideWatchTransition", () => { const incident = { reason: "unexpected_silence" as const, since: ago(30) }; diff --git a/src/lib/integrations/status.ts b/src/lib/integrations/status.ts index 57bac23f8..d3f0675cb 100644 --- a/src/lib/integrations/status.ts +++ b/src/lib/integrations/status.ts @@ -798,7 +798,33 @@ export async function recordSyncFailure( const alertSignal = Math.max(...Object.values(buckets)); if (alertSignal >= threshold) { const previouslyAlerted = row.alertedAt != null; - if (!previouslyAlerted) { + // The watchdog may have announced this connection already (it pages a + // day-long provider error streak, a reauth or a silence on its own). Its + // open incident covers this streak too, and its recovery note ends it; + // a second page about the same trouble would only repeat it. + const watchdogAnnounced = + !previouslyAlerted && + !!(await prisma.integrationWatch.findFirst({ + where: { + userId, + integration, + incidentReason: { not: null }, + alertedAt: { not: null }, + }, + select: { id: true }, + })); + if (watchdogAnnounced) { + await prisma.integrationStatus.update({ + where: { userId_integration: { userId, integration } }, + data: { alertedAt: now }, + }); + annotate({ + action: { + name: "integrations.alert.covered_by_watchdog", + details: { integration }, + }, + }); + } else if (!previouslyAlerted) { const outcome = await maybeAlertAdmins({ userId, integration, diff --git a/src/lib/integrations/watchdog-classify.ts b/src/lib/integrations/watchdog-classify.ts index 0e0ab77f8..8b10705e3 100644 --- a/src/lib/integrations/watchdog-classify.ts +++ b/src/lib/integrations/watchdog-classify.ts @@ -13,10 +13,14 @@ * is watched for errors only. * * 2. Is there an incident the operator should hear about? - * Unexpected silence; or a health state of `action_required` / - * `degraded` that has lasted longer than `INCIDENT_AFTER_MS`; or a - * failure streak the sync ledger already paged about (adopted, so the - * operator still gets the one recovery note when it ends). + * Unexpected silence; or an `action_required` state, or a `degraded` + * one because the provider keeps erroring (`provider_errors`), that has + * lasted longer than `INCIDENT_AFTER_MS`; or a failure streak the sync + * ledger already paged about (adopted, so the operator still gets the + * one recovery note when it ends). `no_new_data` and `sync_stalled` on + * their own never page: they mostly mean the owner stopped using the + * source (an Apple Health account whose phone app has not run for a week + * reads as stale for good), which is nothing an operator can fix. * * One incident per connection at a time. It is announced once and closed once; * a change of reason while it is open (silence turning into a reauth) is the @@ -162,7 +166,13 @@ export function currentIncident(input: { if (health === null) return null; const troubled = health.state === "action_required" || health.state === "degraded"; - if (troubled) { + // What pages on its own: the owner has to act, or the provider errors. A + // streak the ledger already paged about is followed whatever it reads as + // now, so its end is still reported. + const pages = + health.state === "action_required" || + (health.state === "degraded" && health.reason === "provider_errors"); + if (troubled && (pages || input.ledgerAlerted)) { // A provider-side reauth flag (Google Health) can stand without a ledger // streak to date it; the last success is then when it last worked. const sinceIso = health.since ?? health.lastSuccessAt; @@ -179,6 +189,22 @@ export function currentIncident(input: { return null; } +/** + * The `alertedAt` an incident gets when the watchdog's first pass after a + * deploy found it already standing: counted as announced, so it is never + * paged, but never actually sent either, so its end sends no recovery note. + * The epoch, because no real announcement can carry it, and it keeps the + * marker inside the existing row. + */ +export const FIRST_RUN_ALERTED_AT = new Date(0); + +/** Whether an `alertedAt` records a message that was really sent. */ +export function wasAnnounced(alertedAt: Date | null | undefined): boolean { + return ( + alertedAt != null && alertedAt.getTime() !== FIRST_RUN_ALERTED_AT.getTime() + ); +} + export type WatchTransition = /** No incident before, none now. */ | { kind: "none" } @@ -210,7 +236,7 @@ export function decideWatchTransition(input: { if (input.incident === null) { return { kind: "close", - notify: input.row?.alertedAt != null, + notify: wasAnnounced(input.row?.alertedAt), previousReason: open, }; } diff --git a/src/lib/integrations/watchdog.ts b/src/lib/integrations/watchdog.ts index 5fbe4f211..797087652 100644 --- a/src/lib/integrations/watchdog.ts +++ b/src/lib/integrations/watchdog.ts @@ -31,6 +31,7 @@ import { } from "./connection-health-load"; import { INTEGRATION_MEASUREMENT_SOURCE } from "./metric-freshness"; import { + FIRST_RUN_ALERTED_AT, HISTORY_DAYS, SOURCE_PROFILES, classifySilence, @@ -50,6 +51,13 @@ export interface WatchdogSummary { incidentsOpened: number; incidentsClosed: number; notified: number; + /** + * The pass found no watch row at all: the first one after the watchdog was + * deployed. Incidents standing at that moment are recorded as already + * announced instead of paged, so a deploy does not page once for every + * connection that has been broken or quiet for months. + */ + firstRun: boolean; } const DAY_MS = 24 * 60 * 60 * 1000; @@ -219,12 +227,14 @@ export async function runIntegrationWatchdog(opts: { incidentsOpened: 0, incidentsClosed: 0, notified: 0, + firstRun: (await prisma.integrationWatch.count()) === 0, }; const userIds = await listWatchedUserIds(); + const outbox: WatchdogNote[] = []; for (const userId of userIds) { summary.usersScanned += 1; try { - await watchUser(userId, opts.mode, now, summary); + await watchUser(userId, opts.mode, now, summary, outbox); } catch (err) { // One account's failure must not stop the pass for everyone else. summary.usersFailed += 1; @@ -233,16 +243,182 @@ export async function runIntegrationWatchdog(opts: { ); } } + await flushWatchdogOutbox(outbox, now, summary); return summary; } -/** Watch every connection of one account. Exported for tests. */ +/** One operator message the pass has decided to send. */ +export interface WatchdogNote { + kind: "incident" | "recovery"; + userId: string; + key: ConnectionKey; + subjectLabel: string; + reason: string; + since: Date | null; + closedBecause?: "healthy" | "disconnected" | "not_expected"; +} + +/** + * More than this many accounts of one provider opening (or closing) an + * incident in the same pass is one provider-wide event, not that many + * separate ones: a provider outage, an expired app credential, a changed API. + * The operator gets one message for it instead of one per account. + */ +export const WATCHDOG_AGGREGATE_ABOVE = 3; + +const AGGREGATE_REASON_COPY: Partial> = { + unexpected_silence: "silent although they normally deliver every day", + reauth_required: "waiting to be reconnected by their owners", + paused_after_errors: "paused after a day of failing syncs", + provider_errors: "failing to sync for more than a day", +}; + +/** The most account emails one aggregated message names. */ +const AGGREGATE_NAMED = 10; + +/** + * Pure formatter for the provider-wide messages, exported for tests. Same + * rules as `formatWatchdogMessage`: plain text, a provider label, emails and + * server-built instants only. + */ +export function formatWatchdogAggregate( + kind: "incident" | "recovery", + key: ConnectionKey, + notes: WatchdogNote[], +): { title: string; message: string } { + const label = LABELS[key]; + const n = notes.length; + const named = notes.slice(0, AGGREGATE_NAMED).map((x) => x.subjectLabel); + const more = n > AGGREGATE_NAMED ? ` and ${n - AGGREGATE_NAMED} more` : ""; + const accounts = `Accounts: ${named.join(", ")}${more}.`; + if (kind === "recovery") { + return { + title: `${label} recovered for ${n} connections`, + message: `${label} is fine again for ${n} connections. ${accounts}`, + }; + } + const byReason = new Map(); + for (const note of notes) { + const list = byReason.get(note.reason) ?? []; + list.push(note); + byReason.set(note.reason, list); + } + const lines = [...byReason].map(([reason, list]) => { + const copy = + AGGREGATE_REASON_COPY[reason as IncidentReason] ?? "needing attention"; + const earliest = list + .map((x) => x.since) + .filter((d): d is Date => d !== null) + .sort((a, b) => a.getTime() - b.getTime())[0]; + const since = earliest ? ` since ${formatInstant(earliest)}` : ""; + return `${list.length} ${copy}${since}.`; + }); + return { + title: `${label}: ${n} connections need attention`, + message: `${lines.join(" ")} ${accounts}`, + }; +} + +/** + * Send what the pass decided, per provider: one message per account, or one + * for the provider when more than `WATCHDOG_AGGREGATE_ABOVE` accounts share + * it. An incident counts as announced (its `alertedAt` stamped) once a channel + * took the message, whichever form it went out in. A send that fails is a + * warning; the incident stays unannounced and the next pass tries again. + */ +export async function flushWatchdogOutbox( + outbox: WatchdogNote[], + now: Date, + summary: WatchdogSummary, +): Promise { + const groups = new Map(); + for (const note of outbox) { + const id = `${note.kind}:${note.key}`; + const list = groups.get(id) ?? []; + list.push(note); + groups.set(id, list); + } + outbox.length = 0; + + const markAnnounced = async (notes: WatchdogNote[]) => { + for (const note of notes) { + await prisma.integrationWatch.updateMany({ + where: { + userId: note.userId, + integration: note.key, + incidentReason: { not: null }, + }, + data: { alertedAt: now }, + }); + } + }; + + for (const notes of groups.values()) { + const { kind, key } = notes[0]!; + try { + if (notes.length > WATCHDOG_AGGREGATE_ABOVE) { + const text = formatWatchdogAggregate(kind, key, notes); + const outcome = await dispatchAdminSystemAlert({ + // About many accounts: no one owner, so every admin's tap opens the + // admin page. + subjectUserId: "", + title: text.title, + message: text.message, + metadata: { + integration: key, + watchdog: kind, + connections: notes.length, + }, + }); + if (outcome.channelsAttempted > 0) { + summary.notified += 1; + if (kind === "incident") await markAnnounced(notes); + } + continue; + } + for (const note of notes) { + const text = formatWatchdogMessage(note); + const outcome = await dispatchAdminSystemAlert({ + subjectUserId: note.userId, + title: text.title, + message: text.message, + metadata: { + integration: key, + reason: note.reason, + watchdog: kind, + }, + }); + if (outcome.channelsAttempted > 0) { + summary.notified += 1; + if (kind === "incident") await markAnnounced([note]); + } + } + } catch (err) { + getEvent()?.addWarning( + `integration watchdog could not send its ${kind} message for ${key}: ${err instanceof Error ? err.message : String(err)}`, + ); + } + } +} + +/** + * Watch every connection of one account. Exported for tests. Its operator + * messages go to `outbox` when one is passed (the pass sends them together at + * its end), and are sent before it returns otherwise. + */ export async function watchUser( userId: string, mode: WatchdogMode, now: Date, summary: WatchdogSummary, + outbox?: WatchdogNote[], ): Promise { + if (!outbox) { + const own: WatchdogNote[] = []; + await watchUser(userId, mode, now, summary, own); + await flushWatchdogOutbox(own, now, summary); + return; + } const [facts, rows, subject] = await Promise.all([ loadConnectionFacts(userId, CONNECTION_KEYS, now), prisma.integrationWatch.findMany({ where: { userId } }), @@ -266,6 +442,7 @@ export async function watchUser( now, subjectLabel, summary, + outbox, }); } } @@ -279,6 +456,7 @@ async function watchConnection(input: { now: Date; subjectLabel: string; summary: WatchdogSummary; + outbox: WatchdogNote[]; }): Promise { const { userId, key, fact, row, mode, now, summary } = input; const profile = SOURCE_PROFILES[key]; @@ -330,24 +508,17 @@ async function watchConnection(input: { let incidentOpenedAt = row?.incidentOpenedAt ?? null; let alertedAt = row?.alertedAt ?? null; - const announce = async (reason: string, since: Date | null) => { - const text = formatWatchdogMessage({ + // Sent once the pass is over (`flushWatchdogOutbox`), so many accounts of + // one provider failing at once come as one message. + const announce = (reason: string, since: Date | null) => { + input.outbox.push({ kind: "incident", + userId, key, subjectLabel: input.subjectLabel, reason, since, }); - const outcome = await dispatchAdminSystemAlert({ - subjectUserId: userId, - title: text.title, - message: text.message, - metadata: { integration: key, reason, watchdog: "incident" }, - }); - if (outcome.channelsAttempted > 0) { - alertedAt = now; - summary.notified += 1; - } }; switch (transition.kind) { @@ -357,7 +528,14 @@ async function watchConnection(input: { summary.incidentsOpened += 1; incidentReason = transition.reason; incidentOpenedAt = now; - await announce(transition.reason, transition.since); + if (summary.firstRun) { + // Standing since before the watchdog first looked: recorded as + // announced, not paged (see `WatchdogSummary.firstRun`), and marked + // so its end sends no recovery note either. + alertedAt = FIRST_RUN_ALERTED_AT; + } else { + announce(transition.reason, transition.since); + } break; case "adopt": // The ledger already paged about this streak; record it as announced so @@ -373,31 +551,21 @@ async function watchConnection(input: { alertedAt = now; } else if (transition.announce && incident) { // Opened earlier while no admin channel accepted the alert. - await announce(transition.reason, incident.since); + announce(transition.reason, incident.since); } break; case "close": summary.incidentsClosed += 1; if (transition.notify) { - const text = formatWatchdogMessage({ + input.outbox.push({ kind: "recovery", + userId, key, subjectLabel: input.subjectLabel, reason: transition.previousReason, since: null, closedBecause, }); - const outcome = await dispatchAdminSystemAlert({ - subjectUserId: userId, - title: text.title, - message: text.message, - metadata: { - integration: key, - reason: transition.previousReason, - watchdog: "recovery", - }, - }); - if (outcome.channelsAttempted > 0) summary.notified += 1; } incidentReason = null; incidentOpenedAt = null; @@ -405,8 +573,17 @@ async function watchConnection(input: { break; } - // Nothing to remember and nothing remembered: no row. - if (row === null && silentSince === null && incidentReason === null) return; + // Nothing to remember and nothing remembered: no row. Except on the first + // pass, which leaves a row for every connection it looked at, so the pass + // after it is not taken for a first one too. + if ( + row === null && + silentSince === null && + incidentReason === null && + !(summary.firstRun && fact.connected) + ) { + return; + } await prisma.integrationWatch.upsert({ where: { userId_integration: { userId, integration: key } }, diff --git a/src/lib/jobs/__tests__/google-health-backfill.test.ts b/src/lib/jobs/__tests__/google-health-backfill.test.ts index 86123d304..b9fb2c788 100644 --- a/src/lib/jobs/__tests__/google-health-backfill.test.ts +++ b/src/lib/jobs/__tests__/google-health-backfill.test.ts @@ -281,9 +281,10 @@ describe("runGoogleHealthBackfillForUser — slices", () => { it("derives the chain's ceiling from the work a backfill can do", () => { // Every collection once, plus every page the resumable collections may - // ever read (heart rate's 10 000 and four others' 1 000), plus slack. + // ever write (heart rate's 10 000 and four others' 1 000) and as many + // again for a saved place in the list moving forward, plus slack. expect(GOOGLE_HEALTH_BACKFILL_MAX_SLICE).toBe( - 17 + GOOGLE_HEALTH_RESUMABLE_PAGE_CEILING + 2, + 17 + 2 * GOOGLE_HEALTH_RESUMABLE_PAGE_CEILING + 2, ); expect(GOOGLE_HEALTH_RESUMABLE_PAGE_CEILING).toBe(10_000 + 4 * 1000); }); diff --git a/src/lib/jobs/google-health-backfill.ts b/src/lib/jobs/google-health-backfill.ts index b6bc711fe..4b07bda36 100644 --- a/src/lib/jobs/google-health-backfill.ts +++ b/src/lib/jobs/google-health-backfill.ts @@ -75,19 +75,23 @@ export const GOOGLE_HEALTH_BACKFILL_THROTTLED_DELAY_SECONDS = 5 * 60; * backfill can do rather than guessed. * * A slice is continued only when it made progress that is on disk: it - * finished a collection, or it moved a resumable collection's edge after - * writing at least one page. Collections finish once each, and a resumable - * collection's pages are capped across all attempts by its page ceiling - * (`GOOGLE_HEALTH_RESUMABLE_PAGE_CEILING`, the sum of them). So no chain of - * progressing slices is longer than the collections plus those pages; the two - * extra are slack for the first slice and the one that stamps the marker. In + * finished a collection, it moved a resumable collection's edge after + * writing at least one page, or a walk without the edge bound saved a place + * in the list further than any before it. Collections finish once each, a + * resumable collection's pages are capped across all attempts by its page + * ceiling (`GOOGLE_HEALTH_RESUMABLE_PAGE_CEILING`, the sum of them), and a + * saved place only ever moves forward, through no more pages than the ones + * written plus the ones passed over, which the same ceiling bounds. So no + * chain of progressing slices is longer than the collections plus twice + * those pages; the two extra are slack for the first slice and the one that + * stamps the marker. In * practice a chain is a handful of slices per year of dense history. A slice * past this is counting progress it does not make, and fails rather than * queueing another. */ export const GOOGLE_HEALTH_BACKFILL_MAX_SLICE = GOOGLE_HEALTH_COLLECTION_KEYS.length + - GOOGLE_HEALTH_RESUMABLE_PAGE_CEILING + + 2 * GOOGLE_HEALTH_RESUMABLE_PAGE_CEILING + 2; /** Test seam: a slice's budget, when not the production one. */ diff --git a/src/lib/jobs/integration-watchdog.ts b/src/lib/jobs/integration-watchdog.ts index ce6373037..f4ce883e8 100644 --- a/src/lib/jobs/integration-watchdog.ts +++ b/src/lib/jobs/integration-watchdog.ts @@ -57,6 +57,7 @@ function handlerFor(mode: WatchdogMode) { incidents_opened: s.incidentsOpened, incidents_closed: s.incidentsClosed, notified: s.notified, + first_run: s.firstRun ? 1 : 0, }); } catch (err) { evt.addWarning(`integration watchdog failed: ${err}`); diff --git a/src/lib/jobs/job-outcome.ts b/src/lib/jobs/job-outcome.ts index f62c00e65..b09cb08e8 100644 --- a/src/lib/jobs/job-outcome.ts +++ b/src/lib/jobs/job-outcome.ts @@ -113,6 +113,8 @@ export const JOB_FACT_ALLOWLIST: ReadonlySet = new Set([ "fetches", "finalised", "finalized", + // v1.42.4 — integration watchdog: the pass found no watch row (first run). + "first_run", "forced", "generated", "geo_backfill_carrier_resolved", diff --git a/src/lib/jobs/reminder/__tests__/google-health-sync-budget.test.ts b/src/lib/jobs/reminder/__tests__/google-health-sync-budget.test.ts new file mode 100644 index 000000000..24ffdcb44 --- /dev/null +++ b/src/lib/jobs/reminder/__tests__/google-health-sync-budget.test.ts @@ -0,0 +1,121 @@ +/** + * The hourly Google Health job runs under pg-boss's fifteen-minute expiry. + * An account whose backfill slice holds it can make the job wait eight of + * those minutes, and the sync after the wait used to run as long as it + * needed: past the expiry pg-boss marked the job failed and retried it beside + * the run still going. The pass now spends only the job's budget: the lock + * wait is capped at what is left, the sync is handed the budget and stops + * cleanly when it runs out, and an account reached after that is left for the + * next hour. + */ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; + +const { syncUserGoogleHealth, connections } = vi.hoisted(() => ({ + syncUserGoogleHealth: vi.fn(), + connections: [] as Array<{ userId: string }>, +})); + +vi.mock("@/lib/google-health/sync", () => ({ + GOOGLE_HEALTH_POLL_CONCURRENCY: 1, + isGoogleHealthParked: vi.fn(async () => false), + syncUserGoogleHealth, +})); +vi.mock("../shared", () => ({ + getWorkerPrisma: () => ({ + googleHealthConnection: { findMany: vi.fn(async () => connections) }, + }), +})); +vi.mock("@/lib/jobs/reminder-satisfy", () => ({ + enqueueReminderSatisfy: vi.fn(async () => {}), +})); +vi.mock("@/lib/logging/transports", () => ({ emitIfSampled: vi.fn() })); + +import type { Job } from "pg-boss"; +import { handleGoogleHealthSync } from "../google-health-sync"; +import { JOB_BUDGET_SHARE } from "@/lib/jobs/job-budget"; +import { GOOGLE_HEALTH_POLL_LOCK_WAIT_MS } from "@/lib/google-health/sync-lock"; + +const START = new Date("2026-10-15T10:00:00.000Z").getTime(); +const EXPIRY_S = 15 * 60; +const BUDGET_MS = EXPIRY_S * 1000 * JOB_BUDGET_SHARE; + +function cronJob(): Job<{ userId?: string }> { + return { + id: "tick", + name: "google-health-sync", + data: {}, + expireInSeconds: EXPIRY_S, + } as unknown as Job<{ userId?: string }>; +} + +beforeEach(() => { + vi.useFakeTimers({ toFake: ["Date"] }); + vi.setSystemTime(START); + syncUserGoogleHealth.mockReset(); + connections.length = 0; +}); +afterEach(() => { + vi.useRealTimers(); +}); + +describe("the hourly Google Health job and its expiry", () => { + it("hands the sync what is left of the budget after the lock wait, and stops it there", async () => { + connections.push({ userId: "waited" }, { userId: "late" }); + const seen: Array<{ beforeEnd: boolean; atEnd: boolean }> = []; + syncUserGoogleHealth.mockImplementation( + async (_userId: string, opts: { shouldStop: () => boolean }) => { + // Eight minutes waiting for the backfill slice to let go. + vi.setSystemTime(START + GOOGLE_HEALTH_POLL_LOCK_WAIT_MS); + const beforeEnd = opts.shouldStop(); + // The walk runs on until the budget is spent, and is told to stop. + vi.setSystemTime(START + BUDGET_MS); + seen.push({ beforeEnd, atEnd: opts.shouldStop() }); + return { + state: "truncated", + imported: 120, + failed: true, + resources: [], + }; + }, + ); + + const outcome = await handleGoogleHealthSync([cronJob()]); + + expect(syncUserGoogleHealth).toHaveBeenCalledTimes(1); + expect(syncUserGoogleHealth.mock.calls[0]![1]).toMatchObject({ + waitForLockMs: GOOGLE_HEALTH_POLL_LOCK_WAIT_MS, + }); + expect(seen).toEqual([{ beforeEnd: false, atEnd: true }]); + // A stop on the budget is the next hour's work, not a failure to retry; + // the account after it waits for the next hour. + expect(outcome.did).toMatchObject({ + users_partial: 1, + users_skipped: 1, + users_failed: 0, + users_retryable: 0, + }); + }); + + it("never waits for the lock past the budget", async () => { + connections.push({ userId: "a" }, { userId: "b" }); + syncUserGoogleHealth + .mockImplementationOnce(async () => { + // The first account takes most of the budget. + vi.setSystemTime(START + BUDGET_MS - 60_000); + return { state: "complete", imported: 1, failed: false, resources: [] }; + }) + .mockImplementationOnce(async () => ({ + state: "complete", + imported: 1, + failed: false, + resources: [], + })); + + await handleGoogleHealthSync([cronJob()]); + + expect(syncUserGoogleHealth).toHaveBeenCalledTimes(2); + expect(syncUserGoogleHealth.mock.calls[1]![1]).toMatchObject({ + waitForLockMs: 60_000, + }); + }); +}); diff --git a/src/lib/jobs/reminder/google-health-sync.ts b/src/lib/jobs/reminder/google-health-sync.ts index 7ac2e7d0f..0e49f4f64 100644 --- a/src/lib/jobs/reminder/google-health-sync.ts +++ b/src/lib/jobs/reminder/google-health-sync.ts @@ -16,6 +16,7 @@ import { syncUserGoogleHealth, } from "@/lib/google-health/sync"; import { GOOGLE_HEALTH_POLL_LOCK_WAIT_MS } from "@/lib/google-health/sync-lock"; +import { jobBudget, jobDeadline } from "@/lib/jobs/job-budget"; import { enqueueReminderSatisfy } from "@/lib/jobs/reminder-satisfy"; import { cleanupExpiredGoogleHealthOAuthStates } from "@/lib/jobs/google-health-oauth-state-cleanup"; import { @@ -58,6 +59,18 @@ export async function handleGoogleHealthSync( }); } + // The job's own expiry bounds the pass (`jobBudget`). An account that + // waited for its backfill slice gets what is left of it, not a fresh + // hour: the lock wait is capped at the time remaining, the sync stops + // its walks once the budget is spent and leaves the rest of its window + // to the next hour (the cycle is not stamped), and an account reached + // only after the budget is gone is left for the next hour untouched. + // Before, a tick could run on past its expiry, and pg-boss then marked + // it failed and retried it beside the run still going. + const shouldStop = jobBudget(jobs); + const deadline = Math.min( + ...jobs.map((job) => jobDeadline(job) ?? Number.POSITIVE_INFINITY), + ); // Fan the cohort out with bounded concurrency + per-user error isolation: // one slow Google response can't stall the whole cohort, and a single // user's failure is warned without aborting the pass. @@ -65,6 +78,7 @@ export async function handleGoogleHealthSync( const verdicts = await Promise.all( targets.map(({ userId }) => limit(async (): Promise => { + if (shouldStop()) return { status: "skipped", imported: 0 }; if (await isGoogleHealthParked(userId)) { return { status: "parked", imported: 0 }; } @@ -74,12 +88,33 @@ export async function handleGoogleHealthSync( // the tick waits for the slice to end rather than skipping the // account for as long as the whole import runs. const result = await syncUserGoogleHealth(userId, { - waitForLockMs: GOOGLE_HEALTH_POLL_LOCK_WAIT_MS, + waitForLockMs: Math.max( + 0, + Math.min( + GOOGLE_HEALTH_POLL_LOCK_WAIT_MS, + deadline - Date.now(), + ), + ), + shouldStop, }); // Another run of this account (its backfill, a manual sync) // still held the account after the wait; this tick leaves it // to that run. if (result.busy) return { status: "skipped", imported: 0 }; + // Stopped on the job's budget: the rest of the window is the + // next hour's, which is not a failure to retry. + if (result.failed && shouldStop()) { + if (result.imported > 0) { + fireAndForget(enqueueReminderSatisfy(userId), { + action: "reminder.satisfy.enqueue", + }); + } + return { + status: result.imported > 0 ? "partial" : "skipped", + imported: result.imported, + retryable: false, + }; + } const parked = result.failed && result.imported === 0 && diff --git a/src/lib/medications/scheduling/__tests__/extra-dose.test.ts b/src/lib/medications/scheduling/__tests__/extra-dose.test.ts index 67457ce71..715e568c7 100644 --- a/src/lib/medications/scheduling/__tests__/extra-dose.test.ts +++ b/src/lib/medications/scheduling/__tests__/extra-dose.test.ts @@ -10,18 +10,27 @@ import { describe, expect, it } from "vitest"; import { buildSlotBands, type SlotWindowInput } from "../attribution"; import { reconstructDoseHistory, type HistoryIntake } from "../dose-history"; -import { SAME_DOSE_TOLERANCE_MS, isAnotherDose } from "../slot-upsert"; +import { DOUBLE_ENTRY_TOLERANCE_MS, isAnotherDose } from "../slot-upsert"; const MIN = 60_000; const t0 = new Date("2026-06-09T20:00:00Z"); const plus = (minutes: number) => new Date(t0.getTime() + minutes * MIN); describe("isAnotherDose", () => { + // 22:00 in Berlin; the next local day starts two hours later. + const TZ = "Europe/Berlin"; + const external = (id: string, minutes: number, namesSlot = false) => ({ + takenAt: plus(minutes), + externalId: id, + namesSlot, + }); + it("a slot with nothing taken is never held by another dose", () => { expect( isAnotherDose( { takenAt: null, externalId: null }, - { takenAt: plus(600), externalId: "hk-2" }, + external("hk-2", 600), + TZ, ), ).toBe(false); }); @@ -30,40 +39,56 @@ describe("isAnotherDose", () => { expect( isAnotherDose( { takenAt: t0, externalId: "hk-1" }, - { takenAt: plus(600), externalId: "hk-1" }, + external("hk-1", 600), + TZ, ), ).toBe(false); }); - it("two external records a day apart are two doses", () => { - expect( - isAnotherDose( - { takenAt: t0, externalId: "hk-1" }, - { takenAt: plus(24 * 60 + 22), externalId: "hk-2" }, - ), - ).toBe(true); + it("a take on another local day is another dose, whoever recorded either", () => { + // 22:00 and 00:30 the next morning in Berlin: an hour and a half apart, + // two calendar days. + for (const held of [ + { takenAt: t0, externalId: "hk-1" }, + { takenAt: t0, externalId: null }, + ]) { + expect(isAnotherDose(held, external("hk-2", 150, true), TZ)).toBe(true); + expect(isAnotherDose(held, external("hk-2", 24 * 60 + 22), TZ)).toBe( + true, + ); + } }); - it("two external records within a minute are one dose entered twice", () => { - expect( - isAnotherDose( - { takenAt: t0, externalId: "hk-1" }, - { takenAt: new Date(t0.getTime() + 30_000), externalId: "hk-2" }, - ), - ).toBe(false); - }); - - it("a take with no external record merges within the tolerance only", () => { + it("a take logged in HealthLog converges with an external record of the same day", () => { const held = { takenAt: t0, externalId: null }; + expect(isAnotherDose(held, external("hk-2", 20), TZ)).toBe(false); + expect(isAnotherDose(held, external("hk-2", -90), TZ)).toBe(false); + }); + + it("a new record that names the slot is the slot's dose recorded again (an edit in Health)", () => { expect( - isAnotherDose(held, { - takenAt: new Date(t0.getTime() + SAME_DOSE_TOLERANCE_MS), - externalId: "hk-2", - }), + isAnotherDose( + { takenAt: t0, externalId: "hk-1" }, + external("hk-1-edited", 30, true), + TZ, + ), + ).toBe(false); + }); + + it("an unscheduled record of the same day is another dose beyond a double entry", () => { + const held = { takenAt: t0, externalId: "hk-1" }; + expect(isAnotherDose(held, external("hk-2", 30), TZ)).toBe(true); + expect( + isAnotherDose( + held, + { + takenAt: new Date(t0.getTime() + DOUBLE_ENTRY_TOLERANCE_MS), + externalId: "hk-2", + namesSlot: false, + }, + TZ, + ), ).toBe(false); - expect(isAnotherDose(held, { takenAt: plus(30), externalId: "hk-2" })).toBe( - true, - ); }); }); diff --git a/src/lib/medications/scheduling/slot-upsert.ts b/src/lib/medications/scheduling/slot-upsert.ts index fa1d63343..07b35a7ff 100644 --- a/src/lib/medications/scheduling/slot-upsert.ts +++ b/src/lib/medications/scheduling/slot-upsert.ts @@ -18,6 +18,7 @@ import type { PrismaClient } from "@/generated/prisma/client"; import { prisma as defaultPrisma } from "@/lib/db"; import { isP2002 } from "@/lib/prisma-errors"; +import { userDayKey } from "@/lib/tz/format"; import { resolveCanonicalSlotInstant } from "@/lib/medications/scheduling/resolve-slot-instant"; import { attributeTakenToSlot, @@ -747,43 +748,64 @@ export async function findPinConflict(input: { } /** - * How far apart two recorded takes of one slot may sit and still be the same - * dose logged twice (a tap in HealthLog and an entry in another app a few - * minutes later). Further apart, they are two doses. + * How far apart two different external dose records may sit and still be one + * dose entered twice rather than two doses. */ -export const SAME_DOSE_TOLERANCE_MS = 15 * 60_000; +export const DOUBLE_ENTRY_TOLERANCE_MS = 60_000; /** * Is `held` (the take a slot already carries) a different dose from the - * incoming external dose record? + * incoming external dose record, both attributed to the same slot by band? * * Band attribution maps a take to the slot whose band contains it, and a * weekly schedule's band reaches a day either side of the slot. Without this * check an extra dose logged the day after a Tuesday dose landed on the * Tuesday slot and overwrote it last-write-wins: the Tuesday time was - * replaced and the extra dose existed nowhere. + * replaced and the extra dose existed nowhere (#1221). The rule: * * - Nothing taken on the slot yet (pending, skipped): not another dose, the * incoming take is the slot's dose. * - The same external record: the same dose. - * - Two different external records: different doses, unless they sit within - * a minute of each other, which is a double entry rather than two doses. - * - Otherwise (the held take has no external record): the same dose within - * {@link SAME_DOSE_TOLERANCE_MS}, a different one beyond it. + * - A take on a different local calendar day (the user's zone): another + * dose. A slot is one dose a day; the band only reaches across midnight + * so a late take still counts for its slot. + * - The same local day, and the held take was logged in HealthLog (no + * external record): the same dose. A tap at 08:00 and the same dose + * recorded in Health at 08:20 converge onto the slot, one dose and one + * stock consumption. + * - The same local day, two different external records: the record says + * which it is. One that names this slot as its scheduled time is the + * slot's dose, recorded again: editing a dose in Health replaces it with + * a new record (a new UUID, possibly a new time), and that must move the + * slot's dose, not add a second one. One without a scheduled time of its + * own (Health logs an extra dose as unscheduled, and the phone then sends + * its own time) is another dose, unless it sits within + * {@link DOUBLE_ENTRY_TOLERANCE_MS} of the held one, which is one dose + * entered twice. */ export function isAnotherDose( held: { takenAt: Date | null; externalId: string | null }, - incoming: { takenAt: Date; externalId: string | null }, + incoming: { + takenAt: Date; + externalId: string | null; + /** The record's scheduled time is the slot itself. */ + namesSlot: boolean; + }, + userTz: string, ): boolean { if (held.takenAt === null) return false; if (held.externalId !== null && held.externalId === incoming.externalId) { return false; } - const gap = Math.abs(held.takenAt.getTime() - incoming.takenAt.getTime()); - if (held.externalId !== null && incoming.externalId !== null) { - return gap > 60_000; + if ( + userDayKey(held.takenAt, userTz) !== userDayKey(incoming.takenAt, userTz) + ) { + return true; } - return gap > SAME_DOSE_TOLERANCE_MS; + if (held.externalId === null || incoming.externalId === null) return false; + if (incoming.namesSlot) return false; + const gap = Math.abs(held.takenAt.getTime() - incoming.takenAt.getTime()); + return gap > DOUBLE_ENTRY_TOLERANCE_MS; } /** @@ -798,6 +820,9 @@ export async function slotHeldByAnotherDose(input: { canonicalSlot: Date; takenAt: Date; externalId: string | null; + /** The scheduled time the incoming record carries, if any. */ + scheduledFor: Date | null; + userTz: string; client?: Pick; }): Promise { const client = input.client ?? defaultPrisma; @@ -811,11 +836,20 @@ export async function slotHeldByAnotherDose(input: { }, select: { takenAt: true, externalId: true }, }); + const namesSlot = + input.scheduledFor !== null && + Math.abs(input.scheduledFor.getTime() - input.canonicalSlot.getTime()) <= + DOUBLE_ENTRY_TOLERANCE_MS; return rows.some((row) => - isAnotherDose(row, { - takenAt: input.takenAt, - externalId: input.externalId, - }), + isAnotherDose( + row, + { + takenAt: input.takenAt, + externalId: input.externalId, + namesSlot, + }, + input.userTz, + ), ); } diff --git a/tests/integration/google-health-backfill-multi-year.test.ts b/tests/integration/google-health-backfill-multi-year.test.ts index c501bc210..da6915dcc 100644 --- a/tests/integration/google-health-backfill-multi-year.test.ts +++ b/tests/integration/google-health-backfill-multi-year.test.ts @@ -24,10 +24,12 @@ * - every slice writes a log event naming its requests and where it got to; * - the heap does not grow with the history (run it under the production * ceiling: `NODE_OPTIONS=--max-old-space-size=524`); - * - and, in a second run over two years, a Google that refuses the resume + * - and, in a second run over four years, a Google that refuses the resume * edge's upper bound (`<=`): the backfill falls back to reading without - * it, notes the refusal so it is met only once, and still imports every - * reading exactly once. + * it, notes the refusal so it is met only once, keeps its place in the + * unbounded list from slice to slice so the pages it reads stay linear in + * the history (before, every slice passed over everything the slices + * before it wrote), and still imports every reading exactly once. * * Google is replaced at the `safeFetch` seam by a generator that builds each * page on request from the filter and page token it is asked with, so the @@ -433,9 +435,11 @@ describe("Google Health backfill over three years of heart rate (#1220)", () => }, 3_600_000); it("completes when Google refuses the resume edge's upper bound, meeting the refusal once", async () => { - // Two years: the first slice reads without an edge, the second resumes - // with the bound and is refused, the third reads without it from the start. - const points = 2 * 365 * 24 * 60; + // Four years: the first slice reads without an edge, the second resumes + // with the bound and is refused, every later one reads without it. Long + // enough that passing over everything already written on every slice + // would read the history several times over. + const points = 4 * 365 * 24 * 60; await seed(points); fake.refuseUpperBound = true; @@ -445,6 +449,8 @@ describe("Google Health backfill over three years of heart rate (#1220)", () => await import("@/lib/jobs/reminder/google-health-sync"); const { GOOGLE_HEALTH_TRANSIENT_RETRY } = await import("@/lib/google-health/client"); + const { GOOGLE_HEALTH_BACKFILL_SLICE_PAGES } = + await import("@/lib/jobs/google-health-backfill"); GOOGLE_HEALTH_TRANSIENT_RETRY.baseDelayMs = 0; const prisma = getPrismaClient(); @@ -452,6 +458,7 @@ describe("Google Health backfill over three years of heart rate (#1220)", () => kind: "google-health-backfill", data: { userId: USER, enqueuedAt: new Date().toISOString() }, }; + let hourlyRuns = 0; const slices: Array<{ imported: number; continued: number; @@ -495,6 +502,7 @@ describe("Google Health backfill over three years of heart rate (#1220)", () => ok: true, did: { users_skipped: 0, users_failed: 0, users_parked: 0 }, }); + hourlyRuns += 1; } } @@ -506,6 +514,22 @@ describe("Google Health backfill over three years of heart rate (#1220)", () => expect(connection.backfillProgress).toBeNull(); expect(payload).toBeNull(); expect(slices.slice(0, -1).every((s) => s.continued === 1)).toBe(true); + // The hourly sync ran between every two slices. + expect(slices.length).toBeGreaterThan(4); + expect(hourlyRuns).toBe(slices.length - 1); + + // The pages read stay linear in the history: every page once, the one + // pass over what the first slice wrote when the refusal was met, and a + // page or two per slice where it picks up again. Passing over everything + // already written on every slice read more than three times as many. + const historyPages = Math.ceil(points / 1000); + report( + `refusing run: backfill requests=${fake.backfillRequests} ` + + `history pages=${historyPages} slices=${slices.length}`, + ); + expect(fake.backfillRequests).toBeLessThanOrEqual( + historyPages + GOOGLE_HEALTH_BACKFILL_SLICE_PAGES + 2 * slices.length, + ); // The bound was asked for once, refused once, and never again: the // refusal was noted on the slice that met it and honoured after. @@ -514,10 +538,11 @@ describe("Google Health backfill over three years of heart rate (#1220)", () => expect(slices.filter((s) => s.refusalNoted !== undefined)).toEqual([ expect.objectContaining({ refusalNoted: ["fetchHeartRate"] }), ]); - // More than one slice had to pass over what the ones before it wrote, - // and each still wrote its share. + // Only the slice that met the refusal passed over what the slice before + // it wrote, and it still wrote its share; every later one went on from + // where the last stopped. const skipping = slices.filter((s) => s.skippedPages > 0); - expect(skipping.length).toBeGreaterThan(1); + expect(skipping).toHaveLength(1); expect(skipping.every((s) => s.imported > 0)).toBe(true); // Every reading exactly once, none of them rewritten. diff --git a/tests/integration/integration-watchdog.test.ts b/tests/integration/integration-watchdog.test.ts index 44de37b40..777e3ce80 100644 --- a/tests/integration/integration-watchdog.test.ts +++ b/tests/integration/integration-watchdog.test.ts @@ -92,6 +92,11 @@ beforeEach(async () => { }, }); vi.mocked(dispatchNotification).mockClear(); + // The watchdog has run on this instance before: its first pass after a + // deploy records what stands without paging (pinned on its own below). + await prisma().integrationWatch.create({ + data: { userId: ADMIN, integration: "withings" }, + }); }); describe("integration watchdog", () => { @@ -176,7 +181,9 @@ describe("integration watchdog", () => { const summary = await runIntegrationWatchdog({ mode: "hourly", now: NOW }); expect(summary.silencesFlagged).toBe(0); expect(dispatchNotification).not.toHaveBeenCalled(); - expect(await prisma().integrationWatch.count()).toBe(0); + expect( + await prisma().integrationWatch.count({ where: { userId: USER } }), + ).toBe(0); }); it("never alerts on silence for an on-demand source such as a scale", async () => { @@ -245,6 +252,272 @@ describe("integration watchdog", () => { }); }); +describe("what pages and what does not", () => { + it("never pages for an Apple Health account whose phone app stopped delivering weeks ago", async () => { + // Daily data until forty days ago, then nothing: the push cadence reads + // stale (`no_new_data`) for good. The owner stopped using the app; there + // is nothing for an operator to do. + await prisma().user.update({ + where: { id: USER }, + data: { + ouraAccessTokenEncrypted: null, + healthKitLastSyncedAt: new Date(NOW.getTime() - 40 * DAY), + }, + }); + await prisma().measurement.createMany({ + data: Array.from({ length: 30 }, (_, i) => ({ + userId: USER, + type: "ACTIVITY_STEPS" as const, + value: 5000, + unit: "count", + source: "APPLE_HEALTH" as const, + measuredAt: new Date(NOW.getTime() - (40 + i) * DAY), + })), + }); + vi.useFakeTimers({ toFake: ["Date"] }); + vi.setSystemTime(NOW); + try { + const health = await loadConnectionHealth(USER, ["apple-health"]); + expect(health["apple-health"]?.state).toBe("degraded"); + expect(health["apple-health"]?.reason).toBe("no_new_data"); + // A week of hourly and daily passes. + for (let day = 0; day < 7; day++) { + const at = new Date(NOW.getTime() + day * DAY); + const hourly = await runIntegrationWatchdog({ + mode: "hourly", + now: at, + }); + const daily = await runIntegrationWatchdog({ mode: "daily", now: at }); + expect(hourly.incidentsOpened + daily.incidentsOpened).toBe(0); + } + expect(dispatchNotification).not.toHaveBeenCalled(); + expect( + await prisma().integrationWatch.count({ + where: { userId: USER, incidentReason: { not: null } }, + }), + ).toBe(0); + } finally { + vi.useRealTimers(); + } + }); + + it("records what stands on its first pass after a deploy without paging, and pages normally after", async () => { + await prisma().integrationWatch.deleteMany(); + // A wearable that has been silent since before the watchdog existed. + await seedDailyReadings( + USER, + "OURA", + Array.from({ length: 13 }, (_, i) => i + 3), + 54, + ); + vi.useFakeTimers({ toFake: ["Date"] }); + vi.setSystemTime(NOW); + try { + await recordSyncSuccess(USER, "oura"); + const first = await runIntegrationWatchdog({ mode: "hourly", now: NOW }); + expect(first.firstRun).toBe(true); + expect(first.incidentsOpened).toBe(1); + expect(dispatchNotification).not.toHaveBeenCalled(); + const watch = await prisma().integrationWatch.findUniqueOrThrow({ + where: { userId_integration: { userId: USER, integration: "oura" } }, + }); + expect(watch.incidentReason).toBe("unexpected_silence"); + // Marked as announced, so no later pass pages it either. + expect(watch.alertedAt).not.toBeNull(); + + const later = new Date(NOW.getTime() + HOUR); + const second = await runIntegrationWatchdog({ + mode: "hourly", + now: later, + }); + expect(second.firstRun).toBe(false); + expect(dispatchNotification).not.toHaveBeenCalled(); + + // It ends without a recovery note: nothing was ever sent about it. + await prisma().measurement.create({ + data: { + userId: USER, + type: "RESTING_HEART_RATE", + value: 61, + unit: "bpm", + source: "OURA", + measuredAt: new Date(later.getTime() - 10 * 60 * 1000), + }, + }); + const recovered = await runIntegrationWatchdog({ + mode: "hourly", + now: new Date(later.getTime() + HOUR), + }); + expect(recovered.incidentsClosed).toBe(1); + expect(dispatchNotification).not.toHaveBeenCalled(); + + // A new incident after the first pass pages as usual. + for (let i = 0; i < 3; i++) { + await recordSyncFailure({ + userId: USER, + integration: "whoop", + kind: "transient", + message: "WHOOP error: 503", + errorCode: "503", + }); + } + expect(dispatchNotification).toHaveBeenCalledTimes(1); + } finally { + vi.useRealTimers(); + } + }); + + it("leaves a row behind on a first pass that found nothing wrong, so the next pass is not a first one", async () => { + await prisma().integrationWatch.deleteMany(); + await seedDailyReadings(USER, "OURA", [1, 2, 3], 2); + await recordSyncSuccess(USER, "oura"); + const first = await runIntegrationWatchdog({ mode: "hourly", now: NOW }); + expect(first.firstRun).toBe(true); + expect(await prisma().integrationWatch.count()).toBe(1); + const second = await runIntegrationWatchdog({ mode: "hourly", now: NOW }); + expect(second.firstRun).toBe(false); + }); +}); + +describe("the ledger and the watchdog page once between them", () => { + it("does not page a failure streak the watchdog already announced for the connection", async () => { + await prisma().integrationWatch.create({ + data: { + userId: USER, + integration: "oura", + silentSince: new Date(NOW.getTime() - 3 * DAY), + incidentReason: "unexpected_silence", + incidentOpenedAt: new Date(NOW.getTime() - DAY), + alertedAt: new Date(NOW.getTime() - DAY), + }, + }); + for (let i = 0; i < 3; i++) { + await recordSyncFailure({ + userId: USER, + integration: "oura", + kind: "transient", + message: "Oura error: 503", + errorCode: "503", + }); + } + expect(dispatchNotification).not.toHaveBeenCalled(); + const ledger = await prisma().integrationStatus.findUniqueOrThrow({ + where: { userId_integration: { userId: USER, integration: "oura" } }, + }); + expect(ledger.alertedAt).not.toBeNull(); + }); +}); + +describe("many accounts of one provider at once", () => { + async function silentOuraAccounts(n: number): Promise { + const ids: string[] = []; + for (let i = 0; i < n; i++) { + const id = `user-watchdog-many-${i}`; + await prisma().user.create({ + data: { + id, + username: `wd-many-${i}`, + email: `many-${i}@example.test`, + ouraAccessTokenEncrypted: "not-a-real-token", + }, + }); + await seedDailyReadings( + id, + "OURA", + Array.from({ length: 13 }, (_, d) => d + 3), + 54, + ); + await recordSyncSuccess(id, "oura"); + ids.push(id); + } + return ids; + } + + it("sends one provider-wide message and one recovery instead of one per account", async () => { + await prisma().user.update({ + where: { id: USER }, + data: { ouraAccessTokenEncrypted: null }, + }); + vi.useFakeTimers({ toFake: ["Date"] }); + vi.setSystemTime(NOW); + try { + const ids = await silentOuraAccounts(5); + const opened = await runIntegrationWatchdog({ mode: "hourly", now: NOW }); + expect(opened.incidentsOpened).toBe(5); + expect(dispatchedTitles()).toEqual([ + "Oura: 5 connections need attention", + ]); + const message = String( + ( + vi.mocked(dispatchNotification).mock.calls[0]![0] as { + message: string; + } + ).message, + ); + expect(message).toMatch( + /^5 silent although they normally deliver every day since \d{4}-\d{2}-\d{2} \d{2}:\d{2} UTC\./, + ); + // Every incident counts as announced: none is paged again. + expect( + await prisma().integrationWatch.count({ + where: { integration: "oura", alertedAt: { not: null } }, + }), + ).toBe(5); + await runIntegrationWatchdog({ + mode: "hourly", + now: new Date(NOW.getTime() + HOUR), + }); + expect(dispatchNotification).toHaveBeenCalledTimes(1); + + // All of them deliver again: one recovery note. + const later = new Date(NOW.getTime() + 2 * HOUR); + for (const id of ids) { + await prisma().measurement.create({ + data: { + userId: id, + type: "RESTING_HEART_RATE", + value: 61, + unit: "bpm", + source: "OURA", + measuredAt: new Date(later.getTime() - 10 * 60 * 1000), + }, + }); + } + const closed = await runIntegrationWatchdog({ + mode: "hourly", + now: later, + }); + expect(closed.incidentsClosed).toBe(5); + expect(dispatchedTitles()).toEqual([ + "Oura: 5 connections need attention", + "Oura recovered for 5 connections", + ]); + } finally { + vi.useRealTimers(); + } + }); + + it("still sends one message per account up to the threshold", async () => { + await prisma().user.update({ + where: { id: USER }, + data: { ouraAccessTokenEncrypted: null }, + }); + vi.useFakeTimers({ toFake: ["Date"] }); + vi.setSystemTime(NOW); + try { + await silentOuraAccounts(3); + await runIntegrationWatchdog({ mode: "hourly", now: NOW }); + expect(dispatchedTitles().sort()).toEqual([ + "Oura needs attention for many-0@example.test", + "Oura needs attention for many-1@example.test", + "Oura needs attention for many-2@example.test", + ]); + } finally { + vi.useRealTimers(); + } + }); +}); + describe("recent-call ring", () => { it("keeps the newest ten attempts, newest first, without any message text", async () => { for (let i = 0; i < 7; i++) { diff --git a/tests/integration/medication-extra-dose-apple-health.test.ts b/tests/integration/medication-extra-dose-apple-health.test.ts index df8465703..4e58ba78d 100644 --- a/tests/integration/medication-extra-dose-apple-health.test.ts +++ b/tests/integration/medication-extra-dose-apple-health.test.ts @@ -354,3 +354,144 @@ describe("an extra dose from Apple Health is stored as an unscheduled dose", () expect(adHoc.map(takenAtOf)).toEqual([wednesdayDose.getTime()]); }); }); + +/** Stock the medication with one open bottle of 100 units, one per dose. */ +async function stock(userId: string, medicationId: string): Promise { + const prisma = getPrismaClient(); + await prisma.medication.update({ + where: { id: medicationId }, + data: { unitsPerDose: 1 }, + }); + await prisma.medicationInventoryItem.create({ + data: { + userId, + medicationId, + state: "IN_USE", + containerType: "BOTTLE", + unitsTotal: 100, + unitsRemaining: 100, + firstUseAt: new Date(Date.now() - 60 * DAY_MS), + }, + }); +} + +async function unitsRemaining(medicationId: string): Promise { + const item = await getPrismaClient().medicationInventoryItem.findFirstOrThrow( + { where: { medicationId } }, + ); + return Number(item.unitsRemaining); +} + +/** A take tapped in HealthLog: no external record, no Apple provenance. */ +async function postAppTap(medicationId: string, slot: Date, takenAt: Date) { + const { POST } = await import("@/app/api/medications/intake/bulk/route"); + const response = await POST( + new NextRequest("http://localhost/api/medications/intake/bulk", { + method: "POST", + headers: { "content-type": "application/json" }, + body: JSON.stringify({ + entries: [ + { + medicationId, + scheduledFor: slot.toISOString(), + takenAt: takenAt.toISOString(), + }, + ], + }), + }), + ); + expect(response.status).toBe(200); +} + +describe("the same dose recorded twice is one dose", () => { + it("(d) a tap in HealthLog at 08:00 and the dose in Health at 08:20 the same day", async () => { + const userId = await signedInUser(); + const medicationId = await seedMedication(userId, { + timesOfDay: ["08:00"], + daysOfWeek: null, + }); + await stock(userId, medicationId); + const day = pastLocalDay(4); + const slot = localHmAsUtc(day, TZ, 8, 0); + const tapAt = slot; + const appleAt = new Date(slot.getTime() + 20 * MIN); + + await postAppTap(medicationId, slot, tapAt); + expect(await unitsRemaining(medicationId)).toBe(99); + // Health sends it as the slot's scheduled dose, and once more as an + // unscheduled one: either way it is the tapped dose. + for (const [externalId, scheduledFor] of [ + ["hk-d-1", slot], + ["hk-d-2", appleAt], + ] as const) { + const results = await postBulk([ + appleDose(medicationId, appleAt, externalId, scheduledFor), + ]); + expect(results.map((r) => r.status)).toEqual(["updated"]); + } + + const rows = await rowsOf(medicationId); + expect(rows).toHaveLength(1); + expect(rows[0]!.scheduledFor.getTime()).toBe(slot.getTime()); + // One dose, one unit off the bottle. + expect(await unitsRemaining(medicationId)).toBe(99); + const ledger = await readLedger( + medicationId, + new Date(slot.getTime() - 6 * 3_600_000), + new Date(slot.getTime() + 6 * 3_600_000), + ); + expect(ledger.filter((row) => row.kind === "ad_hoc")).toHaveLength(0); + }); + + it("(e) a dose edited in Health: a new record, moved by 30 minutes, inside the same slot", async () => { + const userId = await signedInUser(); + const medicationId = await seedMedication(userId, { + timesOfDay: ["22:00"], + daysOfWeek: null, + }); + await stock(userId, medicationId); + const slot = localHmAsUtc(pastLocalDay(2), TZ, 22, 0); + const firstAt = new Date(slot.getTime() + 2 * MIN); + const editedAt = new Date(slot.getTime() + 32 * MIN); + + await postBulk([appleDose(medicationId, firstAt, "hk-e-1", slot)]); + // Health replaces an edited dose with a new record; it still names the + // slot as its scheduled time. + const results = await postBulk([ + appleDose(medicationId, editedAt, "hk-e-2", slot), + ]); + expect(results.map((r) => r.status)).toEqual(["updated"]); + + const rows = await rowsOf(medicationId); + expect(rows).toHaveLength(1); + expect(rows[0]!.externalId).toBe("hk-e-2"); + expect(rows[0]!.takenAt?.getTime()).toBe(editedAt.getTime()); + expect(rows[0]!.scheduledFor.getTime()).toBe(slot.getTime()); + expect(await unitsRemaining(medicationId)).toBe(99); + }); + + it("(f) an extra dose the next day still stays its own dose, consuming its own unit", async () => { + const userId = await signedInUser(); + const medicationId = await seedMedication(userId, { + timesOfDay: ["22:00"], + daysOfWeek: "2,5", + }); + await stock(userId, medicationId); + const tuesday = pastLocalDay(2); + const tuesdaySlot = localHmAsUtc(tuesday, TZ, 22, 0); + const wednesdayDose = localHmAsUtc( + new Date(tuesday.getTime() + DAY_MS), + TZ, + 20, + 45, + ); + + await postAppTap(medicationId, tuesdaySlot, tuesdaySlot); + const results = await postBulk([ + appleDose(medicationId, wednesdayDose, "hk-f-wed"), + ]); + expect(results.map((r) => r.status)).toEqual(["inserted"]); + expect(await rowsOf(medicationId)).toHaveLength(2); + expect(await unitsRemaining(medicationId)).toBe(98); + }); +});