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] 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"]);