From 3abbad048efe330a65b47b637c478d9fd3f27024 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Fri, 25 Sep 2026 08:49:45 +0200 Subject: [PATCH 1/4] fix(backup): never run a restore again after its data committed A restore commits its transaction and then rebuilds the chart tiers. A worker that stopped during that rebuild left the job running with a stale heartbeat, and the boot sweep and the admission check treated it like any interrupted job: the sweep queued it again, so the second run deleted and re-wrote the account and lost whatever was written in between, and a second interruption closed it with "rolled back, nothing was changed", which was false. The job now records `committedAt` (added to migration 0347, which has not shipped) and awaits that write before the rebuild starts. The sweep and the admission check close a committed job as `failed_after_commit`, never queue it again, and evict the account's caches. The rebuild itself is left to the nightly and boot passes that already rebuild missing tiers. The module comment now says what an interrupted restore does (restarted once, then failed) and what happens to other writes while a restore runs: new rows are written at once, updates to rows the restore already deleted wait on their lock until it commits or rolls back. --- docs/api/openapi.yaml | 3 +- .../0347_backup_restore_jobs/migration.sql | 1 + prisma/schema.prisma | 7 ++ src/lib/export/restore-backup.ts | 9 +- src/lib/jobs/backup-restore.ts | 95 +++++++++++++++---- src/lib/openapi/routes/admin-backups.ts | 2 +- tests/integration/backup-restore-job.test.ts | 75 +++++++++++++++ 7 files changed, 171 insertions(+), 21 deletions(-) diff --git a/docs/api/openapi.yaml b/docs/api/openapi.yaml index 770175fd7..64eb574d1 100644 --- a/docs/api/openapi.yaml +++ b/docs/api/openapi.yaml @@ -71590,7 +71590,8 @@ components: additionalProperties: false description: "One restore job. `phase` and `progress` describe a running job; `result` is set once it `succeeded` (the same report the synchronous restore used to answer with, less `restored`); `failure` once it `failed`. - `attempts` counts the starts: a job whose worker stopped is started again, at most twice." + `attempts` counts the starts: a job whose worker stopped before the data was committed is started once more; one + that stopped after the commit is closed as `failed_after_commit` and never run again." AdminBackupRestorePhase: type: string enum: diff --git a/prisma/migrations/0347_backup_restore_jobs/migration.sql b/prisma/migrations/0347_backup_restore_jobs/migration.sql index 2cd30c357..fffe3ae30 100644 --- a/prisma/migrations/0347_backup_restore_jobs/migration.sql +++ b/prisma/migrations/0347_backup_restore_jobs/migration.sql @@ -21,6 +21,7 @@ CREATE TABLE "backup_restore_jobs" ( "result" JSONB, "failure" JSONB, "attempts" INTEGER NOT NULL DEFAULT 0, + "committed_at" TIMESTAMP(3), "heartbeat_at" TIMESTAMP(3), "created_at" TIMESTAMP(3) NOT NULL DEFAULT CURRENT_TIMESTAMP, "started_at" TIMESTAMP(3), diff --git a/prisma/schema.prisma b/prisma/schema.prisma index 01300662a..cf13f9c5e 100644 --- a/prisma/schema.prisma +++ b/prisma/schema.prisma @@ -5023,6 +5023,13 @@ model BackupRestoreJob { /// On failure: a stable `code`, a sentence an operator can act on, and the /// missing sections when that was the reason. Consumer: the status routes. failure Json? + /// When the restore transaction committed: from here on the account holds + /// the restored data, whatever happens to the steps after it. Written and + /// awaited before the rollup rebuild starts. Consumer: the boot sweep and + /// the admission check, which never queue a committed job again (a second + /// run would delete what the account gained since) and close it as + /// `failed_after_commit` instead; and the worker's own failure message. + committedAt DateTime? @map("committed_at") /// How many times a worker has started this job. Consumer: the boot sweep, /// which stops re-queueing after the second attempt. attempts Int @default(0) diff --git a/src/lib/export/restore-backup.ts b/src/lib/export/restore-backup.ts index d3d21529e..e9dad974f 100644 --- a/src/lib/export/restore-backup.ts +++ b/src/lib/export/restore-backup.ts @@ -251,6 +251,12 @@ export interface RestoreBackupInput { ipAddress: string | null; restoreInstanceSettings: boolean; progress?: RestoreProgressSink; + /** + * Awaited right after the transaction commits, before the rollup rebuild. + * The caller records that the account now holds the restored data, so a + * restore interrupted after this point is never run a second time. + */ + onCommitted?: () => Promise; /** * Epoch milliseconds by which the restore has to be over. When the * transaction's own time limit would run past it, the restore is refused @@ -2258,7 +2264,8 @@ export async function restoreBackup( } const { cleared, skipped } = outcome; - report("rebuilding"); + report("rebuilding", true); + await input.onCommitted?.(); // Pinned shape, not free text: a dashboard can alert on // `restoreSkippedLinks > 0` and the key list says which catalogue drifted. diff --git a/src/lib/jobs/backup-restore.ts b/src/lib/jobs/backup-restore.ts index 38ccd6db5..dc5b225e3 100644 --- a/src/lib/jobs/backup-restore.ts +++ b/src/lib/jobs/backup-restore.ts @@ -14,11 +14,17 @@ * What stays true from the synchronous restore: * * - Every check still happens before the first delete, and the replacement - * is still one transaction. A failed job leaves the account as it was. + * is still one transaction. A job that fails before the commit leaves the + * account as it was. After the commit only the rollup rebuild remains, + * and a job that fails there says the data was restored + * (`failed_after_commit`). * - While it runs, the account keeps reading its current data: nothing the * transaction writes is visible to anyone until it commits. Other writes - * to the account are neither refused nor held, exactly as before; a reading - * that arrives mid-restore stays next to the restored ones. + * to the account are not refused, exactly as before. A new row (a reading + * that arrives mid-restore) is written at once and stays next to the + * restored ones. A write that updates or deletes a row the restore has + * already deleted waits on that row's lock until the restore commits or + * rolls back, and then finds the row gone or back. * * What the job adds: * @@ -33,7 +39,12 @@ * - Resuming after a restart. The job writes a heartbeat every few seconds. * A worker that stops mid-restore rolls the transaction back with it, and * the boot sweep finds the row whose heartbeat went stale and queues it - * again from the start, at most twice. The stored copy it reads is the + * again from the start. A job is started at most + * {@link BACKUP_RESTORE_MAX_ATTEMPTS} times, so an interrupted restore is + * restarted once; the second interruption fails it. A job whose + * transaction had already committed (`committedAt`) is never restarted: + * a second run would delete what the account gained since. The stored + * copy it reads is the * `DataBackup` row, which stays where it is whatever happens, so no retry * ever needs the file again. */ @@ -299,6 +310,19 @@ const INTERRUPTED: BackupRestoreFailure = { "The restore stopped when the server restarted and was rolled back. Nothing was changed, and the backup is kept: start the restore again. If it stops again, the server likely ran out of memory.", }; +/** + * A job that stopped after its transaction committed. The account holds the + * restored data, so saying "nothing was changed" would be false, and running + * the restore again would delete whatever the account gained since. What did + * not finish is the rebuild of the chart tiers, which the nightly and boot + * passes rebuild on their own. + */ +const FAILED_AFTER_COMMIT: BackupRestoreFailure = { + code: "failed_after_commit", + message: + "The data was restored, but a step after it did not finish, so charts and summaries may take until the next nightly run to catch up. The restore is not run again, so nothing written since is lost.", +}; + const NOT_STARTED: BackupRestoreFailure = { code: "not_started", message: @@ -315,12 +339,24 @@ async function releaseAbandonedJobs(userId: string, now: Date): Promise { const unclaimedBefore = new Date( now.getTime() - BACKUP_RESTORE_UNCLAIMED_AFTER_MS, ); - await prisma.backupRestoreJob.updateMany({ - where: { - userId, - status: "running", - OR: [{ heartbeatAt: { lt: staleBefore } }, { heartbeatAt: null }], + const stale = { + userId, + status: "running", + OR: [{ heartbeatAt: { lt: staleBefore } }, { heartbeatAt: null }], + }; + // Committed first: those changed the account and are closed as such. + const afterCommit = await prisma.backupRestoreJob.updateMany({ + where: { ...stale, committedAt: { not: null } }, + data: { + status: "failed", + phase: null, + failure: failureJson(FAILED_AFTER_COMMIT), + completedAt: now, }, + }); + if (afterCommit.count > 0) invalidateUserData(userId); + await prisma.backupRestoreJob.updateMany({ + where: { ...stale, committedAt: null }, data: { status: "failed", phase: null, @@ -495,6 +531,8 @@ export async function runBackupRestoreJob( const timer = setInterval(writeProgress, BACKUP_RESTORE_PROGRESS_WRITE_MS); timer.unref?.(); + // Set once the transaction has committed (see `onCommitted` below). + let committed = false; const finish = async ( status: "succeeded" | "failed", data: { result?: BackupRestoreResult; failure?: BackupRestoreFailure }, @@ -548,6 +586,14 @@ export async function runBackupRestoreJob( ipAddress: null, restoreInstanceSettings: row.restoreInstanceSettings, deadline: options.deadline, + onCommitted: async () => { + committed = true; + const committedAt = new Date(); + await prisma.backupRestoreJob.updateMany({ + where: { id: row.id, status: "running" }, + data: { committedAt, phase: "rebuilding", heartbeatAt: committedAt }, + }); + }, progress: (nextPhase, nextProgress) => { const phaseChanged = nextPhase !== phase; phase = nextPhase; @@ -593,23 +639,18 @@ export async function runBackupRestoreJob( ? jobFailed("restore_transaction_failed") : jobDone({ refused: jobFactCode(outcome.code) }); } catch (err) { - // After "rebuilding" the transaction had committed: the data is restored - // and only a step after it failed, which the message has to say. - // (`phase` is written by the progress callback, which TypeScript cannot see.) - const committed = (phase as RestorePhase) === "rebuilding"; + // After the commit the data is restored and only a step after it + // failed, which the message has to say. await finish("failed", { failure: committed - ? { - code: "failed_after_commit", - message: - "The data was restored, but a step after it failed, so charts may take until the next nightly run to catch up. The server log names the step.", - } + ? FAILED_AFTER_COMMIT : { code: "unexpected", message: "The restore stopped on an unexpected error and was rolled back. Nothing was changed, and the backup is kept. The server log names the error.", }, }).catch(() => undefined); + if (committed) invalidateUserData(row.userId); throw err; } finally { clearInterval(timer); @@ -634,9 +675,11 @@ export async function sweepInterruptedRestores( }, select: { id: true, + userId: true, attempts: true, pgBossJobId: true, heartbeatAt: true, + committedAt: true, }, }); let requeued = 0; @@ -654,6 +697,22 @@ export async function sweepInterruptedRestores( status: "running", heartbeatAt: row.heartbeatAt, }; + // Committed: the account already holds the restored data. Running the + // restore again would delete what it gained since, so it is closed. + if (row.committedAt) { + const done = await prisma.backupRestoreJob.updateMany({ + where: guard, + data: { + status: "failed", + phase: null, + failure: failureJson(FAILED_AFTER_COMMIT), + completedAt: now, + }, + }); + if (done.count > 0) invalidateUserData(row.userId); + failed += done.count; + continue; + } if (!boss || row.attempts >= BACKUP_RESTORE_MAX_ATTEMPTS) { const done = await prisma.backupRestoreJob.updateMany({ where: guard, diff --git a/src/lib/openapi/routes/admin-backups.ts b/src/lib/openapi/routes/admin-backups.ts index 59964b4b5..ed78f583c 100644 --- a/src/lib/openapi/routes/admin-backups.ts +++ b/src/lib/openapi/routes/admin-backups.ts @@ -125,7 +125,7 @@ const restoreJob = z .meta({ id: "AdminBackupRestoreJob", description: - "One restore job. `phase` and `progress` describe a running job; `result` is set once it `succeeded` (the same report the synchronous restore used to answer with, less `restored`); `failure` once it `failed`. `attempts` counts the starts: a job whose worker stopped is started again, at most twice.", + "One restore job. `phase` and `progress` describe a running job; `result` is set once it `succeeded` (the same report the synchronous restore used to answer with, less `restored`); `failure` once it `failed`. `attempts` counts the starts: a job whose worker stopped before the data was committed is started once more; one that stopped after the commit is closed as `failed_after_commit` and never run again.", }); /** diff --git a/tests/integration/backup-restore-job.test.ts b/tests/integration/backup-restore-job.test.ts index d58283807..11e228980 100644 --- a/tests/integration/backup-restore-job.test.ts +++ b/tests/integration/backup-restore-job.test.ts @@ -464,6 +464,81 @@ describe("backup restore as a background job", () => { expect(gaveUp?.failure?.code).toBe("interrupted"); }); + it("never runs a committed restore again when its worker stopped in the rebuild", async () => { + const admin = await seedAdmin(); + const backup = await storeBackup(admin.id, ["m-a", "m-b"]); + const prisma = getPrismaClient(); + + // Run the restore for real, so the commit marker is written by the code + // that writes it, then put the row back the way a worker that died in the + // rollup rebuild leaves it: running, phase rebuilding, heartbeat stale. + const queued = await requestRestore(backup.id); + const { data } = (await queued.json()) as { data: { jobId: string } }; + await runBackupRestoreJob(data.jobId); + const committed = await prisma.backupRestoreJob.findUniqueOrThrow({ + where: { id: data.jobId }, + }); + expect(committed.committedAt).not.toBeNull(); + const stale = new Date(Date.now() - 10 * 60_000); + await prisma.backupRestoreJob.update({ + where: { id: data.jobId }, + data: { + status: "running", + phase: "rebuilding", + heartbeatAt: stale, + completedAt: null, + result: undefined, + }, + }); + // A reading the person logged after the restore committed. + await seedMeasurements(admin.id, ["after-commit"]); + + expect(await sweepInterruptedRestores(queue.boss)).toEqual({ + requeued: 0, + failed: 1, + }); + const job = await readBackupRestoreJob(data.jobId); + expect(job?.status).toBe("failed"); + expect(job?.failure?.code).toBe("failed_after_commit"); + expect(job?.failure?.message).not.toContain("Nothing was changed"); + // Not queued again, so the reading from after the commit survives. + expect( + queue.sent.filter( + (entry) => + (entry.data as { restoreJobId?: string }).restoreJobId === data.jobId, + ), + ).toHaveLength(1); + expect(await measurementIdsOf(admin.id)).toEqual([ + "after-commit", + "m-a", + "m-b", + ]); + }); + + it("the admission check closes a committed stale job as restored, not rolled back", async () => { + const admin = await seedAdmin(); + const backup = await storeBackup(admin.id, ["m-a"]); + const prisma = getPrismaClient(); + const queued = await requestRestore(backup.id); + const { data } = (await queued.json()) as { data: { jobId: string } }; + const stale = new Date(Date.now() - 10 * 60_000); + await prisma.backupRestoreJob.update({ + where: { id: data.jobId }, + data: { + status: "running", + phase: "rebuilding", + attempts: 1, + heartbeatAt: stale, + committedAt: stale, + }, + }); + + expect((await requestRestore(backup.id)).status).toBe(202); + const job = await readBackupRestoreJob(data.jobId); + expect(job?.status).toBe("failed"); + expect(job?.failure?.code).toBe("failed_after_commit"); + }); + it("a live job's heartbeat keeps it out of the sweep", async () => { const admin = await seedAdmin(); const backup = await storeBackup(admin.id, ["m-a"]); From d7bc873691c4afa7754a748403fb253d56e1d404 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Fri, 25 Sep 2026 08:51:00 +0200 Subject: [PATCH 2/4] fix(backup): answer an upload too large to store with 413 An uploaded file whose encrypted copy passes the size one stored backup may have on this host (a fifth of the heap limit) stopped the store with BackupBlobTooLargeError, which the route let through as a 500 and reported to the error tracker. It is now a 413 with the numbers and the remedy in the message and meta.errorCode backup.upload.too_large, and the refusal is audited like the others. The store rolls back, so nothing is kept. --- docs/api/openapi.yaml | 4 +- src/app/api/admin/backups/upload/route.ts | 19 +++ src/lib/export/backup-blob.ts | 3 + src/lib/openapi/error-codes.ts | 1 + .../admin-backups-upload-too-large.test.ts | 114 ++++++++++++++++++ 5 files changed, 139 insertions(+), 2 deletions(-) create mode 100644 tests/integration/admin-backups-upload-too-large.test.ts diff --git a/docs/api/openapi.yaml b/docs/api/openapi.yaml index 64eb574d1..60ab169cf 100644 --- a/docs/api/openapi.yaml +++ b/docs/api/openapi.yaml @@ -30494,8 +30494,8 @@ components: anamnesis.fact.invalidValue; auth — auth.admin.required, auth.already_authenticated, auth.mfa.code_invalid, auth.missing, auth.refresh.invalid, auth.refresh.reuse, auth.refresh.revoked, auth.scope.insufficient, auth.stepup.required, auth.token.expired, auth.token.invalid; backup — - backup.payload.undecryptable, backup.restore.active, backup.section.missing; coach — - coach.budget.exceeded, coach.conversation.invalidTitle, coach.conversation.notFound, + backup.payload.undecryptable, backup.restore.active, backup.section.missing, backup.upload.too_large; + coach — coach.budget.exceeded, coach.conversation.invalidTitle, coach.conversation.notFound, coach.fenced.attachmentConflict, coach.fenced.attachmentLimit, coach.fenced.attachmentNotFound, coach.fenced.attachmentNotIndexed, coach.fenced.attachmentRequired, coach.fenced.attachmentUnavailable, coach.fenced.invalid, coach.request.invalid; coach-prefs — coach-prefs.body.invalid_json, diff --git a/src/app/api/admin/backups/upload/route.ts b/src/app/api/admin/backups/upload/route.ts index 8110b4bac..3b4a51811 100644 --- a/src/app/api/admin/backups/upload/route.ts +++ b/src/app/api/admin/backups/upload/route.ts @@ -38,6 +38,10 @@ import { apiHandler, HttpError, requireAdmin } from "@/lib/api-handler"; import { apiError, apiSuccess, getClientIp } from "@/lib/api-response"; import { auditLog } from "@/lib/auth/audit"; import { BackupJsonError, scanBackupJson } from "@/lib/export/backup-json-scan"; +import { + BACKUP_UPLOAD_TOO_LARGE_CODE, + BackupBlobTooLargeError, +} from "@/lib/export/backup-blob"; import { storeBackupBlob } from "@/lib/export/store-backup-blob"; import { StreamedBackupInvalidError } from "@/lib/export/streamed-backup"; import { annotate } from "@/lib/logging/context"; @@ -332,6 +336,21 @@ export const POST = apiHandler(async (request: NextRequest) => { await denied(err.details.reason as string, err.details); return apiError(err.answer, err.status, err.meta); } + // The file was fine; its encrypted copy is larger than one stored backup + // may be on this host (a fifth of the heap limit). That is the operator's + // to act on, with the numbers in the message, and not a server fault for + // the error reporter. The store rolled back, so nothing was kept. + if (err instanceof BackupBlobTooLargeError) { + await denied("stored_copy_too_large", { + bytes: err.bytes, + limitBytes: err.limitBytes, + }); + return apiError( + `This backup is too large to store on this server. ${err.message}`, + 413, + { errorCode: BACKUP_UPLOAD_TOO_LARGE_CODE }, + ); + } throw err; } diff --git a/src/lib/export/backup-blob.ts b/src/lib/export/backup-blob.ts index 0c152ba45..745832139 100644 --- a/src/lib/export/backup-blob.ts +++ b/src/lib/export/backup-blob.ts @@ -99,6 +99,9 @@ export function defaultBackupBlobLimit(): number { * is about the record, and it is true: raising the heap raises the limit with * it, since the limit is derived from the heap. */ +/** The stable code of the 413 an upload too large to store is answered with. */ +export const BACKUP_UPLOAD_TOO_LARGE_CODE = "backup.upload.too_large"; + export class BackupBlobTooLargeError extends Error { readonly bytes: number; readonly limitBytes: number; diff --git a/src/lib/openapi/error-codes.ts b/src/lib/openapi/error-codes.ts index 7b94581ef..b3a1e4d1b 100644 --- a/src/lib/openapi/error-codes.ts +++ b/src/lib/openapi/error-codes.ts @@ -69,6 +69,7 @@ export const ERROR_CODE_CATALOGUE: Readonly> = "backup.payload.undecryptable", "backup.restore.active", "backup.section.missing", + "backup.upload.too_large", ], coach: [ "coach.budget.exceeded", diff --git a/tests/integration/admin-backups-upload-too-large.test.ts b/tests/integration/admin-backups-upload-too-large.test.ts new file mode 100644 index 000000000..f288cfa02 --- /dev/null +++ b/tests/integration/admin-backups-upload-too-large.test.ts @@ -0,0 +1,114 @@ +/** + * An upload whose encrypted copy is too large to store is a 413, not a 500. + * + * One stored backup may take a fifth of the process's heap limit + * (`defaultBackupBlobLimit`); past it the packer stops with + * `BackupBlobTooLargeError`. The upload route let that escape as a server + * fault, so the operator saw "internal error" and the error reporter was + * paged for a file that is simply too large for this host. The limit is + * lowered here through the store's own option so a small file crosses it, + * and everything else runs as it does in production. + */ +import { beforeEach, describe, expect, it, vi } from "vitest"; + +process.env.ENCRYPTION_KEY ??= + "0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef"; + +import { cookieJar, headerJar } from "./mock-next-headers"; +import { getPrismaClient, truncateAllTables } from "./setup"; + +vi.mock("next/headers", async () => { + const { cookieJar, headerJar } = await import("./mock-next-headers"); + return { + headers: vi.fn(async () => ({ + get: (name: string) => headerJar.get(name.toLowerCase()) ?? null, + })), + cookies: vi.fn(async () => ({ + get: (name: string) => { + const value = cookieJar.get(name); + return value ? { name, value } : undefined; + }, + set: (name: string, value: string) => { + cookieJar.set(name, value); + }, + delete: (name: string) => { + cookieJar.delete(name); + }, + })), + }; +}); +vi.mock("@/lib/db-compat", () => ({ + ensureDbCompatibility: vi.fn().mockResolvedValue(undefined), +})); +vi.mock("@/lib/export/store-backup-blob", async (importOriginal) => { + const actual = + await importOriginal(); + return { + ...actual, + storeBackupBlob: ((prisma, input, producer) => + actual.storeBackupBlob(prisma, input, producer, { + maxBytes: 256, + })) as typeof actual.storeBackupBlob, + }; +}); + +beforeEach(async () => { + await truncateAllTables(getPrismaClient()); + cookieJar.clear(); + headerJar.clear(); +}); + +describe("POST /api/admin/backups/upload — a copy too large to store", () => { + it("answers 413 with the reason and stores nothing", async () => { + const prisma = getPrismaClient(); + const admin = await prisma.user.create({ + data: { + username: "upload-large-admin", + email: "upload-large-admin@example.test", + role: "ADMIN", + }, + }); + const session = await prisma.session.create({ + data: { userId: admin.id, expiresAt: new Date(Date.now() + 60_000) }, + }); + cookieJar.set("healthlog_session", session.id); + + const file = JSON.stringify({ + schemaVersion: "2", + exportedAt: "2026-09-20T00:00:00.000Z", + userId: admin.id, + measurements: Array.from({ length: 200 }, (_, i) => ({ + id: `m-${i}`, + type: "PULSE", + value: 60 + (i % 30), + unit: "bpm", + measuredAt: new Date(Date.UTC(2026, 8, 1, 0, i)).toISOString(), + source: "MANUAL", + })), + }); + + const { POST } = await import("@/app/api/admin/backups/upload/route"); + const res = await POST( + new Request("http://localhost/api/admin/backups/upload", { + method: "POST", + headers: { "content-type": "application/json" }, + body: file, + }) as never, + ); + + expect(res.status).toBe(413); + const body = (await res.json()) as { + error: string; + meta?: { errorCode?: string }; + }; + expect(body.error).toContain("too large to store"); + expect(body.meta?.errorCode).toBe("backup.upload.too_large"); + expect(await prisma.dataBackup.count()).toBe(0); + const denied = await prisma.auditLog.findFirstOrThrow({ + where: { action: "admin.backups.upload.denied" }, + }); + expect(JSON.parse(denied.details ?? "{}").reason).toBe( + "stored_copy_too_large", + ); + }); +}); From 4897752c3cd275d394c771959553782768c1a711 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Fri, 25 Sep 2026 08:53:38 +0200 Subject: [PATCH 3/4] fix(backup): date a restored medication by its earliest record when the file has no date Portable files exported before v1.39.1 carry no creation date for a medication, so the restore stamped the restore time. The dose history reads that date as the day the medication began to exist, and every miss before it, including the day before the restore, dropped out of the record. When the file has no creation date, the restore now uses the earliest thing the file records for the medication: its first dose (scheduled, taken or written), the start of its first schedule revision, its course start, its first pause, dose change or side effect, and never a date after the restore. A file that records nothing about the medication keeps the old default. --- .../__tests__/medication-created-at.test.ts | 99 +++++++++++++++++++ src/lib/export/medication-created-at.ts | 64 ++++++++++++ src/lib/export/restore-backup.ts | 14 ++- tests/integration/backup-restore-job.test.ts | 42 ++++++++ 4 files changed, 218 insertions(+), 1 deletion(-) create mode 100644 src/lib/export/__tests__/medication-created-at.test.ts create mode 100644 src/lib/export/medication-created-at.ts diff --git a/src/lib/export/__tests__/medication-created-at.test.ts b/src/lib/export/__tests__/medication-created-at.test.ts new file mode 100644 index 000000000..8a25de309 --- /dev/null +++ b/src/lib/export/__tests__/medication-created-at.test.ts @@ -0,0 +1,99 @@ +/** + * A medication restored from a file without `createdAt` is dated by the + * earliest thing the file says happened to it, never later than the restore. + * + * Mutation check: return `undefined` whenever the file has no `createdAt` + * (the old behaviour) and the evidence cases go red; drop the cap at `now` + * and the future-course case goes red. + */ +import { describe, expect, it } from "vitest"; + +import { restoredMedicationCreatedAt } from "@/lib/export/medication-created-at"; +import { backupPayloadSchema } from "@/lib/validations/backup"; + +const NOW = new Date("2026-09-25T12:00:00.000Z"); + +function parse( + medication: Record, + intakeEvents: unknown[] = [], +) { + const payload = backupPayloadSchema.parse({ + schemaVersion: "1", + exportedAt: "2026-09-20T00:00:00.000Z", + userId: "user-1", + medications: [ + { name: "Ramipril", dose: "5mg", schedules: [], ...medication }, + ], + intakeEvents, + }); + return { + medication: payload.medications[0]!, + intakeEvents: payload.intakeEvents, + }; +} + +describe("restoredMedicationCreatedAt", () => { + it("keeps the file's own creation date", () => { + const { medication, intakeEvents } = parse({ + createdAt: "2024-01-02T00:00:00.000Z", + }); + expect(restoredMedicationCreatedAt(medication, intakeEvents, NOW)).toEqual( + new Date("2024-01-02T00:00:00.000Z"), + ); + }); + + it("takes the earliest dose of the medication when the file has no date", () => { + const { medication, intakeEvents } = parse({}, [ + { + medication: "Ramipril", + scheduledFor: "2025-03-10T08:00:00.000Z", + takenAt: "2025-03-10T08:05:00.000Z", + }, + { + medication: "Ramipril", + scheduledFor: "2025-03-09T08:00:00.000Z", + autoMissed: true, + }, + // Another medication's dose is not evidence for this one. + { medication: "Other", scheduledFor: "2020-01-01T08:00:00.000Z" }, + ]); + expect(restoredMedicationCreatedAt(medication, intakeEvents, NOW)).toEqual( + new Date("2025-03-09T08:00:00.000Z"), + ); + }); + + it("takes an earlier schedule revision or course start over the doses", () => { + const { medication, intakeEvents } = parse( + { + startsOn: "2025-02-01T00:00:00.000Z", + scheduleRevisions: [ + { + validFrom: "2025-01-15T00:00:00.000Z", + validUntil: "2025-02-01T00:00:00.000Z", + payload: {}, + }, + ], + }, + [{ medication: "Ramipril", scheduledFor: "2025-03-09T08:00:00.000Z" }], + ); + expect(restoredMedicationCreatedAt(medication, intakeEvents, NOW)).toEqual( + new Date("2025-01-15T00:00:00.000Z"), + ); + }); + + it("is never later than the restore", () => { + const { medication, intakeEvents } = parse({ + startsOn: "2026-10-01T00:00:00.000Z", + }); + expect(restoredMedicationCreatedAt(medication, intakeEvents, NOW)).toEqual( + NOW, + ); + }); + + it("leaves the default when the file says nothing about the medication", () => { + const { medication, intakeEvents } = parse({}); + expect( + restoredMedicationCreatedAt(medication, intakeEvents, NOW), + ).toBeUndefined(); + }); +}); diff --git a/src/lib/export/medication-created-at.ts b/src/lib/export/medication-created-at.ts new file mode 100644 index 000000000..c52385466 --- /dev/null +++ b/src/lib/export/medication-created-at.ts @@ -0,0 +1,64 @@ +/** + * The creation date a restored medication gets when the file does not say. + * + * Portable files written before v1.39.1 carry no `createdAt` for a + * medication, and the restore used to let the column default to the moment + * of the restore. The dose history reads that date as the day the + * medication began to exist: `reconstructDoseHistory` and migration 0350 + * treat every slot before it as belonging to no medication, so the misses in + * the day before the restore (and everything earlier) disappeared from the + * record. + * + * The earliest thing the file itself says happened to the medication is the + * closest honest stand-in: its first recorded dose (scheduled, taken or + * written), the start of its first schedule revision, its course start, its + * first pause, dose change or side effect. Never later than the restore: + * a course that starts next week was still created by now. + */ +import type { BackupPayload } from "@/lib/validations/backup"; + +type BackupMedication = BackupPayload["medications"][number]; +type BackupIntakeEvent = BackupPayload["intakeEvents"][number]; + +/** + * The file's own creation date when it has one; otherwise the earliest + * evidence, capped at `now`; otherwise `undefined`, which leaves the column + * to its default (the restore time) because the file says nothing at all. + */ +export function restoredMedicationCreatedAt( + medication: BackupMedication, + intakeEvents: readonly BackupIntakeEvent[], + now: Date, +): Date | undefined { + if (medication.createdAt) return new Date(medication.createdAt); + + const instants: Array = []; + for (const event of intakeEvents) { + // Mirrors how the restore attaches an event: by id when the file names + // one, by name otherwise. + const belongs = event.medicationId + ? event.medicationId === medication.id || + (!medication.id && event.medication === medication.name) + : event.medication === medication.name; + if (!belongs) continue; + instants.push(event.scheduledFor, event.takenAt, event.createdAt); + } + for (const revision of medication.scheduleRevisions) { + instants.push(revision.validFrom); + } + instants.push(medication.startsOn); + for (const era of medication.pauseEras) instants.push(era.pausedAt); + for (const change of medication.doseChanges) { + instants.push(change.effectiveFrom); + } + for (const effect of medication.sideEffects) instants.push(effect.occurredAt); + + let earliest = Number.POSITIVE_INFINITY; + for (const instant of instants) { + if (!instant) continue; + const ms = Date.parse(instant); + if (Number.isFinite(ms) && ms < earliest) earliest = ms; + } + if (!Number.isFinite(earliest)) return undefined; + return new Date(Math.min(earliest, now.getTime())); +} diff --git a/src/lib/export/restore-backup.ts b/src/lib/export/restore-backup.ts index e9dad974f..0814e1187 100644 --- a/src/lib/export/restore-backup.ts +++ b/src/lib/export/restore-backup.ts @@ -87,6 +87,7 @@ import { restoreDocumentFilingData } from "@/lib/export/document-filing-backup"; import { restoreAwardsData } from "@/lib/export/awards-backup"; import { restoreEnvironmentData } from "@/lib/export/environment-backup"; import { restoreEcgData } from "@/lib/export/ecg-backup"; +import { restoredMedicationCreatedAt } from "@/lib/export/medication-created-at"; import { invalidateUserData } from "@/lib/cache/invalidate"; import { foldLegacyCoachAvailability } from "@/lib/modules/operator-availability"; @@ -887,6 +888,7 @@ export async function restoreBackup( const unresolvedRevisionLinks: string[] = []; let medicationIndex = 0; reportSection("medications"); + const restoreStartedAt = new Date(); for (const m of payload.medications) { const created = await tx.medication.create({ data: { @@ -920,7 +922,17 @@ export async function restoreBackup( reorderLeadDays: m.reorderLeadDays ?? null, externalSource: m.externalSource ?? null, externalId: m.externalId ?? null, - ...(m.createdAt ? { createdAt: new Date(m.createdAt) } : {}), + // A file from before v1.39.1 carries no creation date, and the + // restore time would hide every dose-history miss before it. + // The earliest thing the file records for the drug stands in. + ...(() => { + const createdAt = restoredMedicationCreatedAt( + m, + payload.intakeEvents, + restoreStartedAt, + ); + return createdAt ? { createdAt } : {}; + })(), ...(m.updatedAt ? { updatedAt: new Date(m.updatedAt) } : {}), schedules: { create: m.schedules.map((s) => ({ diff --git a/tests/integration/backup-restore-job.test.ts b/tests/integration/backup-restore-job.test.ts index 11e228980..d21403c4b 100644 --- a/tests/integration/backup-restore-job.test.ts +++ b/tests/integration/backup-restore-job.test.ts @@ -539,6 +539,48 @@ describe("backup restore as a background job", () => { expect(job?.failure?.code).toBe("failed_after_commit"); }); + it("dates a medication from a file without a creation date by its earliest dose", async () => { + const admin = await seedAdmin(); + const prisma = getPrismaClient(); + // A portable file from before v1.39.1: no medication createdAt. + const payload = backupPayloadSchema.parse({ + schemaVersion: "1", + exportedAt: "2026-09-20T00:00:00.000Z", + userId: admin.id, + medications: [{ name: "Ramipril", dose: "5mg", schedules: [] }], + intakeEvents: [ + { + medication: "Ramipril", + scheduledFor: "2025-03-10T08:00:00.000Z", + takenAt: "2025-03-10T08:04:00.000Z", + }, + { + medication: "Ramipril", + scheduledFor: "2025-03-09T08:00:00.000Z", + autoMissed: true, + }, + ], + }); + const backup = await prisma.dataBackup.create({ + data: { + userId: admin.id, + type: "MANUAL_UPLOAD_OLD_PORTABLE", + data: encrypt(JSON.stringify(payload)), + }, + }); + const queued = await requestRestore(backup.id); + const { data } = (await queued.json()) as { data: { jobId: string } }; + await runBackupRestoreJob(data.jobId); + expect((await readBackupRestoreJob(data.jobId))?.status).toBe("succeeded"); + + const medication = await prisma.medication.findFirstOrThrow({ + where: { userId: admin.id }, + }); + // Not the restore time: the dose history reads this as the day the + // medication began, and every miss before it would vanish. + expect(medication.createdAt.toISOString()).toBe("2025-03-09T08:00:00.000Z"); + }); + it("a live job's heartbeat keeps it out of the sweep", async () => { const admin = await seedAdmin(); const backup = await storeBackup(admin.id, ["m-a"]); From 0a5fa4b2ae30d9ede9ede8b9ce757546e8319f14 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Fri, 25 Sep 2026 09:17:25 +0200 Subject: [PATCH 4/4] fix(crypto): page the key-rotation walks by id, not by cursor The corpus walk and the rotation script paged with Prisma's cursor and skip. Prisma resolves that cursor by reading the page's last row again, so when that row was hard-deleted before the next page (a backup replaced, a cached response expired), the next page came back empty and the walk ended early. The scan then counted fewer rows than the database holds, which could read as nothing left on the old key while rows it never reached still were. Both walks now ask for the rows whose id is greater than the last one read, which needs no row to still exist. --- scripts/rotate-encryption-key.ts | 9 ++- .../rotation-walk-keyset-guard.test.ts | 34 +++++++++ .../__tests__/encryption-corpus-blob.test.ts | 17 ++--- .../__tests__/encryption-corpus.test.ts | 17 +++-- src/lib/crypto/encryption-corpus.ts | 7 +- ...cryption-corpus-cursor-row-deleted.test.ts | 74 +++++++++++++++++++ 6 files changed, 133 insertions(+), 25 deletions(-) create mode 100644 src/__tests__/rotation-walk-keyset-guard.test.ts create mode 100644 tests/integration/encryption-corpus-cursor-row-deleted.test.ts diff --git a/scripts/rotate-encryption-key.ts b/scripts/rotate-encryption-key.ts index 58a23e4f4..744436a92 100644 --- a/scripts/rotate-encryption-key.ts +++ b/scripts/rotate-encryption-key.ts @@ -114,8 +114,7 @@ interface PagedDelegate { select: Record; orderBy: { id: "asc" }; take: number; - cursor?: { id: string }; - skip?: number; + where?: { id: { gt: string } }; }) => Promise>>; update: (args: { where: { id: string }; @@ -142,7 +141,9 @@ async function* pagedRows( select: { id: true, [field]: true }, orderBy: { id: "asc" }, take: PAGE_SIZE, - ...(cursor ? { cursor: { id: cursor }, skip: 1 } : {}), + // `id > last`, not Prisma's `cursor` + `skip`: the cursor form looks + // the last row up again, and a row deleted between pages ends the walk. + ...(cursor ? { where: { id: { gt: cursor } } } : {}), }); if (rows.length === 0) return; yield* rows; @@ -786,7 +787,7 @@ async function main() { select: { id: true, textEncrypted: true, verbatimTextEncrypted: true }, orderBy: { id: "asc" }, take: 100, - ...(cursor ? { cursor: { id: cursor }, skip: 1 } : {}), + ...(cursor ? { where: { id: { gt: cursor } } } : {}), }); if (rows.length === 0) break; for (const row of rows) { diff --git a/src/__tests__/rotation-walk-keyset-guard.test.ts b/src/__tests__/rotation-walk-keyset-guard.test.ts new file mode 100644 index 000000000..ee5b53a5c --- /dev/null +++ b/src/__tests__/rotation-walk-keyset-guard.test.ts @@ -0,0 +1,34 @@ +/** + * The key-rotation walks page by `id > last`, never by Prisma's cursor. + * + * `cursor: { id }, skip: 1` looks the last row of a page up again. When that + * row was hard-deleted between pages, Prisma answers the next page with + * nothing, the walk stops early, and the scan reports a corpus smaller than + * the one on disk, which can read as "nothing left on the old key". The + * library walk is proven against Postgres in + * `tests/integration/encryption-corpus-cursor-row-deleted.test.ts`; the + * rotation script calls `process.exit` on import and cannot be driven from a + * test, so its walks are held to the same shape here. + * + * Mutation check: put `cursor: { id: cursor }, skip: 1` back in either file + * and this goes red. + */ +import { readFileSync } from "node:fs"; +import { describe, expect, it } from "vitest"; + +const WALKS = [ + "scripts/rotate-encryption-key.ts", + "src/lib/crypto/encryption-corpus.ts", +] as const; + +describe("rotation walks page by key", () => { + it.each(WALKS)("%s pages with `id > last`, not cursor + skip", (path) => { + const code = readFileSync(path, "utf8") + .split("\n") + .filter((line) => !line.trim().startsWith("//")) + .join("\n"); + expect(code).not.toMatch(/cursor\s*:\s*\{[^}]*\}\s*,\s*skip\s*:/); + // Non-zero proof: the walk is still there and still pages by key. + expect(code).toMatch(/\{\s*gt\s*:\s*cursor\s*\}/); + }); +}); diff --git a/src/lib/crypto/__tests__/encryption-corpus-blob.test.ts b/src/lib/crypto/__tests__/encryption-corpus-blob.test.ts index 57cb3820e..c436f83b8 100644 --- a/src/lib/crypto/__tests__/encryption-corpus-blob.test.ts +++ b/src/lib/crypto/__tests__/encryption-corpus-blob.test.ts @@ -45,13 +45,12 @@ interface FindManyArgs { select: Record; orderBy?: Record; take?: number; - cursor?: Record; - skip?: number; + where?: Record; } /** - * Pagination-honouring fake delegate: applies orderBy(id) + cursor + skip + - * take exactly like Prisma keyset pagination, and records every findMany + * Pagination-honouring fake delegate: applies orderBy(id) + `id > last` + + * take exactly like the keyset pagination the walk sends, and records every findMany * call so the test can assert the batch boundedness. */ function makeDocClient(rows: DocRow[]): { @@ -68,10 +67,8 @@ function makeDocClient(rows: DocRow[]): { findMany: async (args: FindManyArgs) => { findManyCalls.push(args); let list = [...store].sort((a, b) => a.id.localeCompare(b.id)); - if (args.cursor) { - const idx = list.findIndex((r) => r.id === args.cursor!.id); - list = list.slice(idx + (args.skip ?? 0)); - } + const after = args.where?.id?.gt; + if (after !== undefined) list = list.filter((r) => r.id > after); if (args.take !== undefined) list = list.slice(0, args.take); return list.map((row) => { const out: Record = {}; @@ -181,8 +178,8 @@ describe("codec-dispatched blob rotation (bounded batches)", () => { expect(call.orderBy).toEqual({ id: "asc" }); } // Cursor advanced between pages. - expect(findManyCalls[0].cursor).toBeUndefined(); - expect(findManyCalls[1].cursor).toEqual({ id: pad(24) }); + expect(findManyCalls[0].where).toBeUndefined(); + expect(findManyCalls[1].where).toEqual({ id: { gt: pad(24) } }); // Every row now reads under the active key, each in its OWN codec. for (const row of store) { diff --git a/src/lib/crypto/__tests__/encryption-corpus.test.ts b/src/lib/crypto/__tests__/encryption-corpus.test.ts index db764a92e..4698853da 100644 --- a/src/lib/crypto/__tests__/encryption-corpus.test.ts +++ b/src/lib/crypto/__tests__/encryption-corpus.test.ts @@ -45,15 +45,16 @@ function makeClient(seed: Record): { if (client[key]) continue; const model = col.model; client[key] = { - // `take` / `cursor` are honoured so the batched-column walk terminates - // here the way it does against Postgres. - findMany: async ({ select, take, cursor, skip }) => { + // `take` / `id > last` are honoured so the batched-column walk + // terminates here the way it does against Postgres. + findMany: async ({ select, take, where }) => { const fields = Object.keys(select); - let rows = store[model]; - if (cursor) { - const at = rows.findIndex((r) => r.id === cursor.id); - rows = at < 0 ? [] : rows.slice(at + (skip ?? 0)); - } + let rows = [...store[model]].sort((a, b) => + String(a.id).localeCompare(String(b.id)), + ); + const after = where?.id?.gt; + if (after !== undefined) + rows = rows.filter((r) => String(r.id) > after); if (take !== undefined) rows = rows.slice(0, take); return rows.map((row) => { const out: Record = {}; diff --git a/src/lib/crypto/encryption-corpus.ts b/src/lib/crypto/encryption-corpus.ts index 4efc0d46d..82ebf6bfc 100644 --- a/src/lib/crypto/encryption-corpus.ts +++ b/src/lib/crypto/encryption-corpus.ts @@ -69,8 +69,7 @@ interface ColumnDelegate { select: Record; orderBy?: Record; take?: number; - cursor?: Record; - skip?: number; + where?: Record; }) => Promise>>; update: (args: { where: Record; @@ -190,7 +189,9 @@ async function walkColumn( }, orderBy: { [pk]: "asc" }, take: batchSize, - ...(cursor ? { cursor: { [pk]: cursor }, skip: 1 } : {}), + // `id > last`, not Prisma's `cursor` + `skip`: the cursor form looks + // the last row up again, and a row deleted between pages ends the walk. + ...(cursor ? { where: { [pk]: { gt: cursor } } } : {}), }); if (rows.length === 0) break; for (const row of rows) { diff --git a/tests/integration/encryption-corpus-cursor-row-deleted.test.ts b/tests/integration/encryption-corpus-cursor-row-deleted.test.ts new file mode 100644 index 000000000..0c1db9744 --- /dev/null +++ b/tests/integration/encryption-corpus-cursor-row-deleted.test.ts @@ -0,0 +1,74 @@ +/** + * A key-rotation walk that loses the row it paged from still reads the rest. + * + * The corpus walk and the rotation script paged with Prisma's + * `cursor: { id }, skip: 1`. Prisma resolves that cursor by looking the row up + * again, so when the row a page ended on was hard-deleted before the next + * page (a backup replaced, an idempotency entry expired), the next page came + * back empty. The walk ended early and the scan reported fewer rows, possibly + * "nothing left on the old key", while rows it never read were still under + * it. The walks page by `id > last id` now, which needs no row to exist. + * + * Mutation check: put the `cursor`/`skip` paging back in `walkColumn` and the + * scan counts one page of rows instead of all of them. + */ +import { beforeEach, describe, expect, it } from "vitest"; + +import { encrypt } from "@/lib/crypto"; +import { ENCRYPTED_COLUMNS } from "@/lib/crypto/encrypted-columns"; +import { + BLOB_ROTATION_BATCH_SIZE, + scanColumn, + type CorpusClient, +} from "@/lib/crypto/encryption-corpus"; +import { getPrismaClient, truncateAllTables } from "./setup"; + +beforeEach(async () => { + await truncateAllTables(getPrismaClient()); +}); + +describe("encryption corpus walk", () => { + it("reads every row even when the row a page ended on is deleted", async () => { + const prisma = getPrismaClient(); + const user = await prisma.user.create({ + data: { username: "cursor-walk", email: "cursor-walk@example.test" }, + }); + const count = BLOB_ROTATION_BATCH_SIZE + 5; + await prisma.dataBackup.createMany({ + data: Array.from({ length: count }, (_, i) => ({ + id: `backup-${String(i).padStart(3, "0")}`, + userId: user.id, + type: `MANUAL_UPLOAD_${i}`, + data: encrypt(`{"n":${i}}`), + })), + }); + + let pages = 0; + const client = { + dataBackup: { + findMany: async (args: never) => { + const rows = (await prisma.dataBackup.findMany(args)) as Array<{ + id: string; + }>; + pages += 1; + // The first page's last row disappears before the second is read. + if (pages === 1 && rows.length > 0) { + await prisma.dataBackup.delete({ where: { id: rows.at(-1)!.id } }); + } + return rows; + }, + update: (args: never) => prisma.dataBackup.update(args), + }, + } as unknown as CorpusClient; + + const col = ENCRYPTED_COLUMNS.find( + (c) => c.model === "DataBackup" && c.field === "data", + )!; + const scan = await scanColumn(client, col); + + // Every row was read once: the deleted one on the first page, the rest + // on the pages after it. + expect(scan.total).toBe(count); + expect(pages).toBeGreaterThan(1); + }); +});