From 93b6c086b4766896014fd489c397e54f1a3e0d7d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Sun, 27 Sep 2026 11:24:41 +0200 Subject: [PATCH 1/3] fix(restore): let a large restore outlast the request statement timeout A restore of an account with 1.9 million readings, most of them deleted by the nightly consolidation and still awaiting the purge, was cancelled in its clearing step: `DELETE FROM measurements` ran past the 60 s statement timeout every pooled connection carries, and the whole restore rolled back with a message that named no cause (#1031). Most of that statement was not the delete. Two columns point into `measurements` with ON DELETE SET NULL and had no index, so Postgres scanned `personal_records` and `ecg_recordings` once per deleted reading: 38 of 40 s on a seeded account with 300 personal records. Migration 0362 indexes both, which also speeds up the tombstone purge and account deletion. The restore transaction now sets its own statement and idle-in-transaction limits to the transaction budget with SET LOCAL, and the budget counts the rows the account holds as well as the rows the file carries. A rolled-back restore names what the database refused it over (timeout, lock, constraint, storage, connection, other) on the job row, the console, the audit row and the wide event. --- docs/api/openapi.yaml | 17 +- messages/de.json | 5 + messages/en.json | 5 + messages/es.json | 5 + messages/fr.json | 5 + messages/it.json | 5 + messages/ko.json | 5 + messages/pl.json | 5 + .../migration.sql | 27 +++ prisma/schema.prisma | 6 + .../measurement-reference-index-guard.test.ts | 78 ++++++ .../admin/backup-restore-status.tsx | 32 ++- .../__tests__/restore-failure-cause.test.ts | 149 ++++++++++++ src/lib/export/restore-backup.ts | 61 ++++- src/lib/export/restore-failure-cause.ts | 127 ++++++++++ src/lib/jobs/backup-restore.ts | 18 +- src/lib/jobs/job-outcome.ts | 1 + src/lib/openapi/routes/admin-backups.ts | 5 +- .../backup-restore-statement-timeout.test.ts | 225 ++++++++++++++++++ 19 files changed, 763 insertions(+), 18 deletions(-) create mode 100644 prisma/migrations/0362_measurement_reference_indexes/migration.sql create mode 100644 src/__tests__/measurement-reference-index-guard.test.ts create mode 100644 src/lib/export/__tests__/restore-failure-cause.test.ts create mode 100644 src/lib/export/restore-failure-cause.ts create mode 100644 tests/integration/backup-restore-statement-timeout.test.ts diff --git a/docs/api/openapi.yaml b/docs/api/openapi.yaml index 824b25a94..be094ff8b 100644 --- a/docs/api/openapi.yaml +++ b/docs/api/openapi.yaml @@ -73187,13 +73187,24 @@ components: type: array items: type: string + cause: + type: string + enum: + - timeout + - lock + - constraint + - storage + - connection + - other required: - code - message additionalProperties: false - description: Why the restore did not happen, in a sentence an operator can act on. `sections` names the missing sections - for `backup.section.missing`; `keyIds` names the encryption key ids the file needs and this server cannot open - it with, for `backup.key.missing`. + description: "Why the restore did not happen, in a sentence an operator can act on. `sections` names the missing + sections for `backup.section.missing`; `keyIds` names the encryption key ids the file needs and this server + cannot open it with, for `backup.key.missing`; `cause` says what the database refused a `transaction_failed` + restore over: it ran out of time, waited on a lock, rejected a record, ran out of disk space or memory, lost the + connection, or something else." AdminBackupRestoreJobResponse: type: object properties: diff --git a/messages/de.json b/messages/de.json index 5fea285f0..556727976 100644 --- a/messages/de.json +++ b/messages/de.json @@ -7374,6 +7374,11 @@ "restoreFailureDocument": "Die Datei enthält Dokumente ohne deren Inhalt, wie ein portabler Export. Nimm eine Notfall-Sicherung.", "restoreFailureTimeBudget": "Dieses Backup ist zu groß, um innerhalb des Zeitlimits des Hintergrundauftrags wiederhergestellt zu werden.", "restoreFailureTransaction": "Die Datenbank hat die Wiederherstellung mittendrin abgelehnt, deshalb wurde alles zurückgerollt. Das Server-Log nennt den Fehler.", + "restoreFailureCauseTimeout": "Die Wiederherstellung hat länger gedauert, als die Datenbank zulässt, deshalb wurde alles zurückgerollt. War der Datenbank-Host ausgelastet, starte sie erneut, wenn er ruhiger ist. Das Server-Log nennt den Schritt.", + "restoreFailureCauseLock": "Die Wiederherstellung hat auf Einträge gewartet, die ein anderer Vorgang gerade geändert hat, deshalb wurde alles zurückgerollt. Starte die Wiederherstellung erneut.", + "restoreFailureCauseConstraint": "Die Datenbank hat einen Eintrag aus der Sicherung abgelehnt, deshalb wurde alles zurückgerollt. Das Server-Log nennt die Tabelle und die Regel.", + "restoreFailureCauseStorage": "Der Datenbank ist während der Wiederherstellung der Speicherplatz oder Arbeitsspeicher ausgegangen, deshalb wurde alles zurückgerollt. Schaffe Platz auf dem Datenbank-Host und starte die Wiederherstellung erneut.", + "restoreFailureCauseConnection": "Die Verbindung zur Datenbank ist während der Wiederherstellung abgerissen, deshalb wurde alles zurückgerollt. Prüfe, ob die Datenbank läuft, und starte die Wiederherstellung erneut.", "restoreFailureInterrupted": "Die Wiederherstellung wurde durch einen Neustart des Servers unterbrochen und zurückgerollt. Bricht sie erneut ab, reicht dem Server wahrscheinlich der Arbeitsspeicher nicht.", "restoreFailureNotStarted": "Der Hintergrunddienst hat die Wiederherstellung nicht übernommen. Prüfe, ob er läuft.", "restoreFailureEnqueue": "Die Wiederherstellung konnte nicht an den Hintergrunddienst übergeben werden. Prüfe, ob er läuft.", diff --git a/messages/en.json b/messages/en.json index ff67a71e9..d661f0112 100644 --- a/messages/en.json +++ b/messages/en.json @@ -7374,6 +7374,11 @@ "restoreFailureDocument": "The file carries documents without their content, as a portable export does. Use a disaster-recovery backup.", "restoreFailureTimeBudget": "This backup is too large to restore within the background job's time limit.", "restoreFailureTransaction": "The database refused the restore part-way, so everything was rolled back. The server log names the error.", + "restoreFailureCauseTimeout": "The restore ran longer than the database allowed, so everything was rolled back. If the database host was busy, start the restore again when it is quieter. The server log names the step.", + "restoreFailureCauseLock": "The restore waited on records another process was changing, so everything was rolled back. Start the restore again.", + "restoreFailureCauseConstraint": "The database rejected a record in the backup, so everything was rolled back. The server log names the table and the rule.", + "restoreFailureCauseStorage": "The database ran out of disk space or memory during the restore, so everything was rolled back. Free up space on the database host, then start the restore again.", + "restoreFailureCauseConnection": "The connection to the database was lost during the restore, so everything was rolled back. Check that the database is running, then start the restore again.", "restoreFailureInterrupted": "The restore stopped when the server restarted, and was rolled back. If it stops again, the server is likely running out of memory.", "restoreFailureNotStarted": "The background worker did not pick the restore up. Check that the worker is running.", "restoreFailureEnqueue": "The restore could not be handed to the background worker. Check that the worker is running.", diff --git a/messages/es.json b/messages/es.json index 241ebd154..fce4000c2 100644 --- a/messages/es.json +++ b/messages/es.json @@ -7374,6 +7374,11 @@ "restoreFailureDocument": "El archivo contiene documentos sin su contenido, como una exportación portátil. Usa una copia de recuperación ante desastres.", "restoreFailureTimeBudget": "Esta copia es demasiado grande para restaurarse dentro del límite de tiempo del proceso en segundo plano.", "restoreFailureTransaction": "La base de datos rechazó la restauración a mitad, así que se deshizo todo. El registro del servidor indica el error.", + "restoreFailureCauseTimeout": "La restauración tardó más de lo que permite la base de datos, así que se deshizo todo. Si el servidor de la base de datos estaba ocupado, vuelve a iniciarla cuando esté más tranquilo. El registro del servidor indica el paso.", + "restoreFailureCauseLock": "La restauración esperó a registros que otro proceso estaba modificando, así que se deshizo todo. Vuelve a iniciar la restauración.", + "restoreFailureCauseConstraint": "La base de datos rechazó un registro de la copia de seguridad, así que se deshizo todo. El registro del servidor indica la tabla y la regla.", + "restoreFailureCauseStorage": "La base de datos se quedó sin espacio en disco o sin memoria durante la restauración, así que se deshizo todo. Libera espacio en el servidor de la base de datos y vuelve a iniciar la restauración.", + "restoreFailureCauseConnection": "Se perdió la conexión con la base de datos durante la restauración, así que se deshizo todo. Comprueba que la base de datos está en marcha y vuelve a iniciar la restauración.", "restoreFailureInterrupted": "La restauración se detuvo al reiniciarse el servidor y se deshizo. Si vuelve a detenerse, probablemente al servidor le falta memoria.", "restoreFailureNotStarted": "El proceso en segundo plano no recogió la restauración. Comprueba que está en marcha.", "restoreFailureEnqueue": "No se pudo entregar la restauración al proceso en segundo plano. Comprueba que está en marcha.", diff --git a/messages/fr.json b/messages/fr.json index 64cbe69f1..d5824ab32 100644 --- a/messages/fr.json +++ b/messages/fr.json @@ -7374,6 +7374,11 @@ "restoreFailureDocument": "Le fichier contient des documents sans leur contenu, comme un export portable. Utilise une sauvegarde de reprise après sinistre.", "restoreFailureTimeBudget": "Cette sauvegarde est trop volumineuse pour être restaurée dans le temps imparti au processus en arrière-plan.", "restoreFailureTransaction": "La base de données a refusé la restauration en cours de route, tout a donc été annulé. Le journal du serveur indique l'erreur.", + "restoreFailureCauseTimeout": "La restauration a duré plus longtemps que la base de données ne l'autorise, tout a donc été annulé. Si l'hôte de la base était chargé, relancez-la quand il est plus calme. Le journal du serveur indique l'étape.", + "restoreFailureCauseLock": "La restauration a attendu des enregistrements qu'un autre processus modifiait, tout a donc été annulé. Relancez la restauration.", + "restoreFailureCauseConstraint": "La base de données a refusé un enregistrement de la sauvegarde, tout a donc été annulé. Le journal du serveur indique la table et la règle.", + "restoreFailureCauseStorage": "La base de données a manqué d'espace disque ou de mémoire pendant la restauration, tout a donc été annulé. Libérez de l'espace sur l'hôte de la base, puis relancez la restauration.", + "restoreFailureCauseConnection": "La connexion à la base de données a été perdue pendant la restauration, tout a donc été annulé. Vérifiez que la base de données tourne, puis relancez la restauration.", "restoreFailureInterrupted": "La restauration s'est arrêtée au redémarrage du serveur et a été annulée. Si elle s'arrête encore, le serveur manque probablement de mémoire.", "restoreFailureNotStarted": "Le processus en arrière-plan n'a pas pris la restauration en charge. Vérifie qu'il tourne.", "restoreFailureEnqueue": "La restauration n'a pas pu être transmise au processus en arrière-plan. Vérifie qu'il tourne.", diff --git a/messages/it.json b/messages/it.json index 404c0ba2d..673fc9238 100644 --- a/messages/it.json +++ b/messages/it.json @@ -7374,6 +7374,11 @@ "restoreFailureDocument": "Il file contiene documenti senza il loro contenuto, come un'esportazione portabile. Usa un backup di disaster recovery.", "restoreFailureTimeBudget": "Questo backup è troppo grande per essere ripristinato entro il tempo concesso al processo in background.", "restoreFailureTransaction": "Il database ha rifiutato il ripristino a metà, quindi tutto è stato annullato. Il log del server indica l'errore.", + "restoreFailureCauseTimeout": "Il ripristino è durato più di quanto il database consente, quindi tutto è stato annullato. Se l'host del database era sotto carico, riavvialo quando è più tranquillo. Il log del server indica il passaggio.", + "restoreFailureCauseLock": "Il ripristino ha atteso record che un altro processo stava modificando, quindi tutto è stato annullato. Avvia di nuovo il ripristino.", + "restoreFailureCauseConstraint": "Il database ha rifiutato un record del backup, quindi tutto è stato annullato. Il log del server indica la tabella e la regola.", + "restoreFailureCauseStorage": "Il database ha esaurito lo spazio su disco o la memoria durante il ripristino, quindi tutto è stato annullato. Libera spazio sull'host del database, poi avvia di nuovo il ripristino.", + "restoreFailureCauseConnection": "La connessione al database si è interrotta durante il ripristino, quindi tutto è stato annullato. Controlla che il database sia in funzione, poi avvia di nuovo il ripristino.", "restoreFailureInterrupted": "Il ripristino si è interrotto al riavvio del server ed è stato annullato. Se si interrompe di nuovo, probabilmente al server manca memoria.", "restoreFailureNotStarted": "Il processo in background non ha preso in carico il ripristino. Controlla che sia in esecuzione.", "restoreFailureEnqueue": "Non è stato possibile passare il ripristino al processo in background. Controlla che sia in esecuzione.", diff --git a/messages/ko.json b/messages/ko.json index 8ce36f817..47c009ce2 100644 --- a/messages/ko.json +++ b/messages/ko.json @@ -7353,6 +7353,11 @@ "restoreFailureDocument": "휴대용 내보내기처럼 내용 없이 문서만 담긴 파일이에요. 재해 복구용 백업을 사용해 주세요.", "restoreFailureTimeBudget": "이 백업은 너무 커서 백그라운드 작업의 시간 제한 안에 복원할 수 없어요.", "restoreFailureTransaction": "데이터베이스가 복원 도중에 거부해서 모든 변경을 되돌렸어요. 서버 로그에 오류가 나와 있어요.", + "restoreFailureCauseTimeout": "복원이 데이터베이스가 허용하는 시간보다 오래 걸려서 모든 변경을 되돌렸어요. 데이터베이스 호스트가 바빴다면 한가할 때 다시 시작하세요. 서버 로그에 해당 단계가 나와 있어요.", + "restoreFailureCauseLock": "다른 작업이 변경 중인 기록을 기다리다가 모든 변경을 되돌렸어요. 복원을 다시 시작하세요.", + "restoreFailureCauseConstraint": "데이터베이스가 백업의 기록 하나를 거부해서 모든 변경을 되돌렸어요. 서버 로그에 테이블과 규칙이 나와 있어요.", + "restoreFailureCauseStorage": "복원 중에 데이터베이스의 디스크 공간이나 메모리가 부족해서 모든 변경을 되돌렸어요. 데이터베이스 호스트의 공간을 확보한 뒤 복원을 다시 시작하세요.", + "restoreFailureCauseConnection": "복원 중에 데이터베이스 연결이 끊겨서 모든 변경을 되돌렸어요. 데이터베이스가 실행 중인지 확인한 뒤 복원을 다시 시작하세요.", "restoreFailureInterrupted": "서버가 다시 시작되면서 복원이 멈췄고 되돌려졌어요. 또 멈춘다면 서버 메모리가 부족할 가능성이 커요.", "restoreFailureNotStarted": "백그라운드 작업자가 복원을 가져가지 않았어요. 작업자가 실행 중인지 확인해 주세요.", "restoreFailureEnqueue": "복원을 백그라운드 작업자에게 넘기지 못했어요. 작업자가 실행 중인지 확인해 주세요.", diff --git a/messages/pl.json b/messages/pl.json index fccc01aca..ecc304072 100644 --- a/messages/pl.json +++ b/messages/pl.json @@ -7374,6 +7374,11 @@ "restoreFailureDocument": "Plik zawiera dokumenty bez ich treści, jak eksport przenośny. Użyj kopii do odtwarzania po awarii.", "restoreFailureTimeBudget": "Ta kopia jest za duża, by przywrócić ją w limicie czasu procesu w tle.", "restoreFailureTransaction": "Baza danych odrzuciła przywracanie w trakcie, więc wszystko wycofano. Dziennik serwera podaje błąd.", + "restoreFailureCauseTimeout": "Przywracanie trwało dłużej, niż pozwala baza danych, więc wszystko wycofano. Jeśli serwer bazy był obciążony, uruchom je ponownie, gdy będzie spokojniej. Dziennik serwera podaje krok.", + "restoreFailureCauseLock": "Przywracanie czekało na rekordy, które zmieniał inny proces, więc wszystko wycofano. Uruchom przywracanie ponownie.", + "restoreFailureCauseConstraint": "Baza danych odrzuciła rekord z kopii zapasowej, więc wszystko wycofano. Dziennik serwera podaje tabelę i regułę.", + "restoreFailureCauseStorage": "W trakcie przywracania bazie danych zabrakło miejsca na dysku lub pamięci, więc wszystko wycofano. Zwolnij miejsce na serwerze bazy, a potem uruchom przywracanie ponownie.", + "restoreFailureCauseConnection": "W trakcie przywracania zerwało się połączenie z bazą danych, więc wszystko wycofano. Sprawdź, czy baza działa, a potem uruchom przywracanie ponownie.", "restoreFailureInterrupted": "Przywracanie zatrzymało się przy restarcie serwera i zostało wycofane. Jeśli zatrzyma się znowu, serwerowi prawdopodobnie brakuje pamięci.", "restoreFailureNotStarted": "Proces w tle nie przejął przywracania. Sprawdź, czy działa.", "restoreFailureEnqueue": "Nie udało się przekazać przywracania do procesu w tle. Sprawdź, czy działa.", diff --git a/prisma/migrations/0362_measurement_reference_indexes/migration.sql b/prisma/migrations/0362_measurement_reference_indexes/migration.sql new file mode 100644 index 000000000..37d6f784e --- /dev/null +++ b/prisma/migrations/0362_measurement_reference_indexes/migration.sql @@ -0,0 +1,27 @@ +-- Index the two columns that point into `measurements`. +-- +-- `personal_records.source_measurement_id` and `ecg_recordings.measurement_id` +-- are foreign keys into `measurements` with ON DELETE SET NULL, and neither +-- column had an index. Postgres enforces such a key with a trigger that runs +-- once per deleted measurement and looks the referencing rows up by that +-- column. Without an index every lookup is a sequential scan of the whole +-- referencing table, so deleting N readings costs N scans. +-- +-- On a seeded account of 1.89 million readings with 300 personal records, the +-- restore's `DELETE FROM measurements WHERE user_id = $1` spent 1.5 s deleting +-- and 38 s in these two triggers. On a slower host that crossed the 60 s +-- statement timeout every connection carries (`src/lib/db.ts`), the restore +-- was cancelled in its clearing step and rolled back (#1031). The tombstone +-- purge and account deletion delete readings the same way and paid the same +-- cost per row. +-- +-- Additive only: `CREATE INDEX IF NOT EXISTS`, no data change. Not +-- CONCURRENTLY, because Prisma Migrate runs a migration in a transaction; both +-- tables are small next to `measurements`, and `migrate deploy` runs at boot +-- before the app serves traffic. + +CREATE INDEX IF NOT EXISTS "personal_records_source_measurement_id_idx" + ON "personal_records" ("source_measurement_id"); + +CREATE INDEX IF NOT EXISTS "ecg_recordings_measurement_id_idx" + ON "ecg_recordings" ("measurement_id"); diff --git a/prisma/schema.prisma b/prisma/schema.prisma index e24bf462a..8bcaf2e74 100644 --- a/prisma/schema.prisma +++ b/prisma/schema.prisma @@ -2046,6 +2046,9 @@ model EcgRecording { // makes the convergence a guarantee instead of a convention. @@unique([userId, source, recordedAt, samplingFrequency], map: "ecg_recordings_user_source_recorded_at_freq_key") @@index([userId, recordedAt(sort: Desc)]) + // The foreign key's own lookup: deleting a reading checks this column once + // per deleted row (migration 0362). + @@index([measurementId]) @@map("ecg_recordings") } @@ -2492,6 +2495,9 @@ model PersonalRecord { /// ORDER BY value DESC LIMIT 1 (MAX direction) / /// ASC LIMIT 1 (MIN direction). Index covers both. @@index([userId, metricType, value]) + // The foreign key's own lookup: deleting a reading checks this column once + // per deleted row (migration 0362). + @@index([sourceMeasurementId]) @@map("personal_records") } diff --git a/src/__tests__/measurement-reference-index-guard.test.ts b/src/__tests__/measurement-reference-index-guard.test.ts new file mode 100644 index 000000000..ebf7c28db --- /dev/null +++ b/src/__tests__/measurement-reference-index-guard.test.ts @@ -0,0 +1,78 @@ +/** + * #1031 — every column that points into `measurements` has an index. + * + * Postgres enforces a foreign key into `measurements` with a trigger that runs + * once per deleted reading and looks the referencing rows up by the + * referencing column. Without an index on that column each lookup is a + * sequential scan of the whole referencing table. Two such columns had none, + * and deleting 1.89 million readings spent 38 of its 40 seconds in those + * lookups; on a slower host the restore's clearing step ran past the + * statement timeout and rolled back. The tombstone purge and account + * deletion delete readings the same way. + * + * Read from the migrations, because one of the two keys (personal records, + * migration 0054) exists only in SQL and not as a Prisma relation: every + * foreign key into `measurements`, inline or added with ALTER TABLE, must + * have an index in some migration that leads with its column. + * + * Mutation check: delete the `personal_records` index from migration 0362 + * and this goes red naming `personal_records.source_measurement_id`. + */ +import { readdirSync, readFileSync } from "node:fs"; +import { resolve } from "node:path"; + +import { describe, expect, it } from "vitest"; + +const dir = resolve(__dirname, "../../prisma/migrations"); +const sql = readdirSync(dir, { withFileTypes: true }) + .filter((d) => d.isDirectory()) + .map((d) => d.name) + .sort() + .map((name) => readFileSync(resolve(dir, name, "migration.sql"), "utf8")) + .join("\n"); + +/** `table.column` of every foreign key into `measurements`. */ +function measurementReferences(): string[] { + const refs = new Set(); + // ALTER TABLE "t" ADD CONSTRAINT … FOREIGN KEY ("c") REFERENCES "measurements" + for (const m of sql.matchAll( + /ALTER TABLE "(\w+)"\s+ADD CONSTRAINT "\w+"\s+FOREIGN KEY \("(\w+)"\)\s+REFERENCES "measurements"/g, + )) { + refs.add(`${m[1]}.${m[2]}`); + } + // CREATE TABLE "t" ( … "c" TEXT REFERENCES "measurements" … ) + for (const table of sql.matchAll( + /CREATE TABLE (?:IF NOT EXISTS )?"(\w+)"\s*\(([\s\S]*?)\n\);/g, + )) { + for (const col of table[2]!.matchAll( + /^\s*"(\w+)"[^\n]*REFERENCES "measurements"/gm, + )) { + refs.add(`${table[1]}.${col[1]}`); + } + } + return [...refs].sort(); +} + +function hasLeadingIndex(ref: string): boolean { + const [table, column] = ref.split("."); + return new RegExp( + `CREATE (?:UNIQUE )?INDEX (?:IF NOT EXISTS )?"?\\w+"?\\s+ON "${table}"(?: USING \\w+)?\\s*\\(\\s*"${column}"`, + ).test(sql); +} + +describe("columns that point into measurements are indexed", () => { + const refs = measurementReferences(); + + it("finds the references (a matcher that finds none proves nothing)", () => { + expect(refs).toEqual( + expect.arrayContaining([ + "ecg_recordings.measurement_id", + "personal_records.source_measurement_id", + ]), + ); + }); + + it("each has an index that leads with its column", () => { + expect(refs.filter((ref) => !hasLeadingIndex(ref))).toEqual([]); + }); +}); diff --git a/src/components/admin/backup-restore-status.tsx b/src/components/admin/backup-restore-status.tsx index 3b9fed7c7..50faa8323 100644 --- a/src/components/admin/backup-restore-status.tsx +++ b/src/components/admin/backup-restore-status.tsx @@ -27,6 +27,7 @@ import { WrittenOutcomeLine } from "@/components/outcome/written-outcome-line"; import { Button } from "@/components/ui/button"; import { Progress } from "@/components/ui/progress"; import { useFormatters, useTranslations } from "@/lib/i18n/context"; +import type { RestoreFailureCause } from "@/lib/export/restore-failure-cause"; import type { BackupRestoreFailureCode, BackupRestoreJobView, @@ -72,6 +73,7 @@ function failureText( code: BackupRestoreFailureCode, t: ReturnType["t"], keyIds: readonly string[] = [], + cause?: RestoreFailureCause, ): string { switch (code) { case "backup_not_found": @@ -101,7 +103,7 @@ function failureText( case "time_budget": return t("admin.section.backups.restoreFailureTimeBudget"); case "transaction_failed": - return t("admin.section.backups.restoreFailureTransaction"); + return transactionFailureText(cause, t); case "interrupted": return t("admin.section.backups.restoreFailureInterrupted"); case "not_started": @@ -119,6 +121,32 @@ function failureText( } } +/** A rolled-back transaction, by what the database refused it over. */ +function transactionFailureText( + cause: RestoreFailureCause | undefined, + t: ReturnType["t"], +): string { + switch (cause) { + case "timeout": + return t("admin.section.backups.restoreFailureCauseTimeout"); + case "lock": + return t("admin.section.backups.restoreFailureCauseLock"); + case "constraint": + return t("admin.section.backups.restoreFailureCauseConstraint"); + case "storage": + return t("admin.section.backups.restoreFailureCauseStorage"); + case "connection": + return t("admin.section.backups.restoreFailureCauseConnection"); + case "other": + case undefined: + return t("admin.section.backups.restoreFailureTransaction"); + default: { + const unhandled: never = cause; + return unhandled; + } + } +} + /** What a running job is doing, and the share of it done when that is known. */ function runningLine( job: BackupRestoreJobView, @@ -297,7 +325,7 @@ export function RestoreJobStatus({ {t("admin.section.backups.restoreJobFailedTitle", { username })}

- {failureText(code, t, job.failure?.keyIds)} + {failureText(code, t, job.failure?.keyIds, job.failure?.cause)}

{changedNothing ? (

diff --git a/src/lib/export/__tests__/restore-failure-cause.test.ts b/src/lib/export/__tests__/restore-failure-cause.test.ts new file mode 100644 index 000000000..6c6807510 --- /dev/null +++ b/src/lib/export/__tests__/restore-failure-cause.test.ts @@ -0,0 +1,149 @@ +/** + * #1031 — a rolled-back restore names what the database refused it over. + * + * The error shapes below are the ones the Prisma client and the pg driver + * adapter actually throw, captured from a real run: a model call and a raw + * query cancelled by the statement timeout, an interactive transaction past + * its own limit, a foreign-key violation, and the plain error a session the + * server ended leaves behind. + * + * Mutation check: map `57014` to "other" in `classifyRestoreFailure` and the + * two statement-timeout rows go red; drop the `P2028` branch and the expired + * transaction row does. + */ +import { describe, expect, it } from "vitest"; + +import { + classifyRestoreFailure, + RESTORE_FAILURE_CAUSE_MESSAGES, + RESTORE_FAILURE_CAUSES, +} from "@/lib/export/restore-failure-cause"; + +function adapterError(prismaCode: string, sqlState: string, extra = {}) { + return Object.assign(new Error(`Database error. Code: \`${sqlState}\``), { + name: "PrismaClientKnownRequestError", + code: prismaCode, + meta: { + modelName: "Measurement", + driverAdapterError: { + cause: { + originalCode: sqlState, + originalMessage: "value from the database", + kind: "postgres", + ...extra, + }, + }, + }, + }); +} + +describe("classifyRestoreFailure", () => { + it.each([ + [ + "deleteMany cancelled by the statement timeout", + adapterError("P2039", "57014"), + "timeout", + "57014", + ], + [ + "raw query cancelled by the statement timeout", + adapterError("P2010", "57014"), + "timeout", + "57014", + ], + [ + "session ended idle in a transaction", + adapterError("P2010", "25P03"), + "timeout", + "25P03", + ], + ["lock not available", adapterError("P2010", "55P03"), "lock", "55P03"], + ["deadlock", adapterError("P2010", "40P01"), "lock", "40P01"], + [ + "foreign-key violation", + adapterError("P2003", "23503", { kind: "ForeignKeyConstraintViolation" }), + "constraint", + "23503", + ], + ["unique violation", adapterError("P2002", "23505"), "constraint", "23505"], + ["invalid value", adapterError("P2010", "22P02"), "constraint", "22P02"], + ["disk full", adapterError("P2010", "53100"), "storage", "53100"], + ["out of memory", adapterError("P2010", "53200"), "storage", "53200"], + [ + "server shutting down", + adapterError("P2010", "57P01"), + "connection", + "57P01", + ], + [ + "connection failure", + adapterError("P2010", "08006"), + "connection", + "08006", + ], + ["some other SQLSTATE", adapterError("P2010", "XX000"), "other", "XX000"], + ] as const)("%s", (_label, err, cause, code) => { + expect(classifyRestoreFailure(err)).toEqual({ cause, code }); + }); + + it("an interactive transaction past its own limit is a timeout", () => { + const err = Object.assign(new Error("Transaction API error: expired"), { + name: "PrismaClientKnownRequestError", + code: "P2028", + meta: { operation: "query", timeout: 498356, timeTaken: 505057 }, + }); + expect(classifyRestoreFailure(err)).toEqual({ + cause: "timeout", + code: "P2028", + }); + }); + + it("a client whose session the server ended is a lost connection", () => { + const err = new Error( + "Client has encountered a connection error and is not queryable", + ); + expect(classifyRestoreFailure(err)).toEqual({ + cause: "connection", + code: null, + }); + }); + + it("an error straight from pg carries its SQLSTATE on `code`", () => { + const err = Object.assign(new Error("canceling statement"), { + code: "57014", + }); + expect(classifyRestoreFailure(err).cause).toBe("timeout"); + }); + + it("a PL/pgSQL raise is a SQLSTATE, not a Prisma code", () => { + const err = Object.assign(new Error("raised"), { code: "P0001" }); + expect(classifyRestoreFailure(err)).toEqual({ + cause: "other", + code: "P0001", + }); + }); + + it("anything else is other, with no code", () => { + expect(classifyRestoreFailure(new Error("boom"))).toEqual({ + cause: "other", + code: null, + }); + expect(classifyRestoreFailure("boom")).toEqual({ + cause: "other", + code: null, + }); + }); + + it("never reads the cause from the message, which can quote rows", () => { + const err = new Error("canceling statement due to statement timeout"); + expect(classifyRestoreFailure(err).cause).toBe("other"); + }); + + it("every cause has a sentence that says nothing was changed", () => { + for (const cause of RESTORE_FAILURE_CAUSES) { + expect(RESTORE_FAILURE_CAUSE_MESSAGES[cause]).toMatch( + /Nothing was changed/, + ); + } + }); +}); diff --git a/src/lib/export/restore-backup.ts b/src/lib/export/restore-backup.ts index c813fd030..336fb7c14 100644 --- a/src/lib/export/restore-backup.ts +++ b/src/lib/export/restore-backup.ts @@ -102,6 +102,10 @@ 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 { + classifyRestoreFailure, + RESTORE_FAILURE_CAUSE_MESSAGES, +} from "@/lib/export/restore-failure-cause"; import { foldLegacyCoachAvailability } from "@/lib/modules/operator-availability"; export interface RestoreResponse { @@ -167,16 +171,23 @@ export interface RestoreResponse { } /** - * How long the restore transaction may run. Two minutes was the whole budget - * when a record was a few hundred thousand rows; deleting and rewriting 1.25 - * million measurements in one transaction takes longer than that (#1031). On - * the test host the whole restore of that account, reading the file twice - * included, took 94 s. The budget grows by a second per 5 000 measurements, - * which gives that account six minutes, about four times what it needed, and - * never drops below the old two minutes. + * How long the restore transaction may run, and with it every statement + * inside it (`SET LOCAL statement_timeout`, see the transaction below). + * + * The work is deleting the readings the account holds now and writing the + * ones the file carries. Both count: an account whose readings were folded + * into hourly averages still holds the originals as deleted rows until the + * nightly purge removes them, and the restore deletes those too (#1031). The + * budget is two minutes plus a second per 2 000 of those rows together. A + * seeded account of 1.89 million readings restored in 196 s on a fast host + * and in 9 min on a database held to half a CPU and 40 MB/s of writes; the + * budget gives it 33 min. */ -function restoreTransactionTimeoutMs(measurementCount: number): number { - return 120_000 + Math.ceil(measurementCount / 5); +function restoreTransactionTimeoutMs( + fileMeasurements: number, + currentMeasurements: number, +): number { + return 120_000 + Math.ceil((fileMeasurements + currentMeasurements) / 2); } function decodeEncryptedBytes(encoded: string): Uint8Array { @@ -612,8 +623,14 @@ export async function restoreBackup( // has a deadline of its own (the background job's time budget) and that // limit would run past it, the restore is refused here, above the first // delete, rather than started and cut off by the queue. + // Counted here, before the transaction, because the delete costs time in + // proportion to what the account holds, deleted rows included. + const currentMeasurements = await prisma.measurement.count({ + where: { userId: ownerId }, + }); const transactionTimeoutMs = restoreTransactionTimeoutMs( streamed.measurementCount, + currentMeasurements, ); if ( input.deadline !== undefined && @@ -651,6 +668,14 @@ export async function restoreBackup( // still writing. A second transaction waits here for the first to // commit or roll back, then replaces the account again from its own // file, which is what it was asked to do. + // Every connection carries the request limits from `src/lib/db.ts` + // (60 s per statement, 60 s idle inside a transaction). A restore is + // not a request: deleting two million readings is one statement, and + // on a slow disk it ran past 60 s, was cancelled, and the whole + // restore rolled back in its clearing step (#1031). The transaction + // has its own limit; SET LOCAL gives each statement the same one, and + // ends with the transaction. + await tx.$executeRaw`SELECT set_config('statement_timeout', ${String(transactionTimeoutMs)}, true), set_config('idle_in_transaction_session_timeout', ${String(transactionTimeoutMs)}, true)`; await tx.$executeRaw`SELECT pg_advisory_xact_lock(hashtext(${`backup-restore:${ownerId}`}))`; // Every reference this restore writes stays inside the account: the // references that leave it are counted now and again after the last @@ -2367,6 +2392,7 @@ export async function restoreBackup( // lands in the audit row (admin-readable) and the Wide Event // (operator-readable), so root-cause investigation is unaffected. const verbose = err instanceof Error ? err.message : String(err); + const classified = classifyRestoreFailure(err); await auditLog("admin.backups.restore.failed", { userId: input.actorUserId, ipAddress: input.ipAddress, @@ -2374,10 +2400,19 @@ export async function restoreBackup( backupId: backup.id, ownerId, reason: "transaction_failed", + cause: classified.cause, + code: classified.code, message: verbose, }, }); - annotate({ meta: { restoreFailReason: verbose } }); + annotate({ + meta: { + restoreFailReason: verbose, + restoreFailCause: classified.cause, + restoreFailCode: classified.code, + restoreTransactionTimeoutMs: transactionTimeoutMs, + }, + }); if (err instanceof ForeignReferenceError) { return refused(422, "backup.foreign_reference", err.message, { errorCode: "backup.foreign_reference", @@ -2392,10 +2427,14 @@ export async function restoreBackup( errorCode: refusal.code, }); } + // The wide event and the audit row carry the whole error. The job's row + // is read by whoever started the restore, so it names the cause, never + // the database's message, which can quote the rows involved. return refused( 500, "transaction_failed", - "The restore could not be written and was rolled back. Nothing was changed.", + RESTORE_FAILURE_CAUSE_MESSAGES[classified.cause], + { cause: classified.cause }, ); } diff --git a/src/lib/export/restore-failure-cause.ts b/src/lib/export/restore-failure-cause.ts new file mode 100644 index 000000000..cb1659618 --- /dev/null +++ b/src/lib/export/restore-failure-cause.ts @@ -0,0 +1,127 @@ +/** + * Why the database refused a restore transaction, as a cause an operator can + * act on. + * + * Every refusal used to read the same way: "the database refused the restore + * part-way, the server log names the error". A statement cancelled by the + * timeout, a constraint the file broke, a disk that filled up and a + * connection that dropped all look alike from the console, and each needs a + * different next step (#1031). The cause is read from the SQLSTATE the driver + * reports, or from Prisma's own code where the refusal is Prisma's, and never + * from the message text, which can quote the rows involved. + */ + +export type RestoreFailureCause = + "timeout" | "lock" | "constraint" | "storage" | "connection" | "other"; + +export const RESTORE_FAILURE_CAUSES: readonly RestoreFailureCause[] = [ + "timeout", + "lock", + "constraint", + "storage", + "connection", + "other", +]; + +export interface ClassifiedRestoreFailure { + cause: RestoreFailureCause; + /** The five-character SQLSTATE, or Prisma's `P…` code, when there is one. */ + code: string | null; +} + +function field(value: unknown, key: string): unknown { + return typeof value === "object" && value !== null + ? (value as Record)[key] + : undefined; +} + +/** + * The SQLSTATE behind a Prisma error. The pg driver adapter carries it on + * `meta.driverAdapterError.cause.originalCode`; an error thrown straight from + * `pg` carries it on `code`. + */ +function sqlState(err: unknown): string | null { + const cause = field(field(field(err, "meta"), "driverAdapterError"), "cause"); + // Prisma's own codes (`P1001`, `P2028`) have the same length as a SQLSTATE, + // so a top-level `code` counts only when it is not one of them. + const own = field(err, "code"); + for (const candidate of [ + field(cause, "originalCode"), + field(cause, "code"), + typeof own === "string" && isPrismaCode(own) ? undefined : own, + ]) { + if (typeof candidate === "string" && /^[0-9A-Z]{5}$/.test(candidate)) { + return candidate; + } + } + return null; +} + +function isPrismaCode(code: string): boolean { + return /^P[1-9]\d{3}$/.test(code); +} + +/** Prisma's own error code (`P2028`, `P1017`, …), when it has one. */ +function prismaCode(err: unknown): string | null { + const code = field(err, "code"); + return typeof code === "string" && isPrismaCode(code) ? code : null; +} + +export function classifyRestoreFailure(err: unknown): ClassifiedRestoreFailure { + const state = sqlState(err); + if (state) { + // 57014 is a cancelled statement: the statement timeout, in a restore. + if (state === "57014") return { cause: "timeout", code: state }; + // 25P03: the idle-in-transaction timeout ended the session. + if (state === "25P03") return { cause: "timeout", code: state }; + // Lock not available, deadlock, serialization failure. + if (state === "55P03" || state === "40P01" || state === "40001") { + return { cause: "lock", code: state }; + } + // Integrity constraints (23) and invalid data (22). + if (state.startsWith("23") || state.startsWith("22")) { + return { cause: "constraint", code: state }; + } + // Insufficient resources (53: disk full, out of memory) and I/O errors. + if (state.startsWith("53") || state === "58030") { + return { cause: "storage", code: state }; + } + // Connection exceptions (08) and a server shutting down (57P01-57P03). + if (state.startsWith("08") || /^57P0[1-3]$/.test(state)) { + return { cause: "connection", code: state }; + } + return { cause: "other", code: state }; + } + const prisma = prismaCode(err); + // P2028: the interactive transaction ran past its own time limit. + if (prisma === "P2028") return { cause: "timeout", code: prisma }; + if (prisma === "P2034") return { cause: "lock", code: prisma }; + if (prisma === "P1001" || prisma === "P1002" || prisma === "P1017") { + return { cause: "connection", code: prisma }; + } + // A session the server ended (the idle-in-transaction timeout, a restart) + // reaches the client as a plain error with no code at all. + const message = err instanceof Error ? err.message : ""; + if (/connection error|not queryable|Connection terminated/i.test(message)) { + return { cause: "connection", code: prisma }; + } + return { cause: "other", code: prisma }; +} + +/** The sentence the job row and the audit trail carry for each cause. */ +export const RESTORE_FAILURE_CAUSE_MESSAGES: Record< + RestoreFailureCause, + string +> = { + timeout: + "The restore ran longer than the database allowed and was rolled back. Nothing was changed.", + lock: "The restore waited on rows another process was changing and was rolled back. Nothing was changed. Start it again.", + constraint: + "The database rejected a record in the backup and the restore was rolled back. Nothing was changed.", + storage: + "The database ran out of disk space or memory during the restore and rolled it back. Nothing was changed.", + connection: + "The connection to the database was lost during the restore, which rolled it back. Nothing was changed.", + other: + "The restore could not be written and was rolled back. Nothing was changed.", +}; diff --git a/src/lib/jobs/backup-restore.ts b/src/lib/jobs/backup-restore.ts index 16519d664..b170ea1ea 100644 --- a/src/lib/jobs/backup-restore.ts +++ b/src/lib/jobs/backup-restore.ts @@ -73,6 +73,10 @@ import { type RestorePhase, type RestoreProgress, } from "@/lib/export/restore-backup"; +import { + RESTORE_FAILURE_CAUSES, + type RestoreFailureCause, +} from "@/lib/export/restore-failure-cause"; export const BACKUP_RESTORE_QUEUE = "backup-restore"; @@ -122,6 +126,8 @@ export interface BackupRestoreFailure { sections?: string[]; /** The encryption key ids a file needs and this host cannot open it with. */ keyIds?: string[]; + /** For `transaction_failed`: what the database refused the restore over. */ + cause?: RestoreFailureCause; } const failureSchema = z.object({ @@ -129,6 +135,7 @@ const failureSchema = z.object({ message: z.string(), sections: z.array(z.string()).optional(), keyIds: z.array(z.string()).optional(), + cause: z.enum(RESTORE_FAILURE_CAUSES).optional(), }); const progressSchema = z.object({ @@ -312,6 +319,7 @@ function failureJson(failure: BackupRestoreFailure) { message: failure.message, ...(failure.sections ? { sections: failure.sections } : {}), ...(failure.keyIds ? { keyIds: failure.keyIds } : {}), + ...(failure.cause ? { cause: failure.cause } : {}), }); } @@ -639,19 +647,27 @@ export async function runBackupRestoreJob( const keyIds = Array.isArray(outcome.meta?.keyIds) ? (outcome.meta.keyIds as unknown[]).map(String) : undefined; + const cause = (RESTORE_FAILURE_CAUSES as readonly unknown[]).includes( + outcome.meta?.cause, + ) + ? (outcome.meta?.cause as RestoreFailureCause) + : undefined; await finish("failed", { failure: { code: outcome.code, message: outcome.message, ...(sections ? { sections } : {}), ...(keyIds ? { keyIds } : {}), + ...(cause ? { cause } : {}), }, }); // A file refused by its checks is the operator's to fix and fails the // same way on every try; the job did what it was asked. A transaction // that could not be written is a fault, and is reported as one. return outcome.status >= 500 && outcome.code === "transaction_failed" - ? jobFailed("restore_transaction_failed") + ? jobFailed("restore_transaction_failed", undefined, { + restore_fail_cause: cause ?? "other", + }) : jobDone({ refused: jobFactCode(outcome.code) }); } catch (err) { // After the commit the data is restored and only a step after it diff --git a/src/lib/jobs/job-outcome.ts b/src/lib/jobs/job-outcome.ts index 808cbea1b..19cf6d4ce 100644 --- a/src/lib/jobs/job-outcome.ts +++ b/src/lib/jobs/job-outcome.ts @@ -185,6 +185,7 @@ export const JOB_FACT_ALLOWLIST: ReadonlySet = new Set([ "restore_drill_mood_entries", "restore_drill_plaintext_bytes", "restore_drill_stale", + "restore_fail_cause", "restore_failed", "restore_measurements", "restore_requeued", diff --git a/src/lib/openapi/routes/admin-backups.ts b/src/lib/openapi/routes/admin-backups.ts index 0c4bebf6b..673eb6912 100644 --- a/src/lib/openapi/routes/admin-backups.ts +++ b/src/lib/openapi/routes/admin-backups.ts @@ -91,11 +91,14 @@ const restoreFailure = z message: z.string(), sections: z.array(z.string()).optional(), keyIds: z.array(z.string()).optional(), + cause: z + .enum(["timeout", "lock", "constraint", "storage", "connection", "other"]) + .optional(), }) .meta({ id: "AdminBackupRestoreFailure", description: - "Why the restore did not happen, in a sentence an operator can act on. `sections` names the missing sections for `backup.section.missing`; `keyIds` names the encryption key ids the file needs and this server cannot open it with, for `backup.key.missing`.", + "Why the restore did not happen, in a sentence an operator can act on. `sections` names the missing sections for `backup.section.missing`; `keyIds` names the encryption key ids the file needs and this server cannot open it with, for `backup.key.missing`; `cause` says what the database refused a `transaction_failed` restore over: it ran out of time, waited on a lock, rejected a record, ran out of disk space or memory, lost the connection, or something else.", }); const restoreJob = z diff --git a/tests/integration/backup-restore-statement-timeout.test.ts b/tests/integration/backup-restore-statement-timeout.test.ts new file mode 100644 index 000000000..2da896255 --- /dev/null +++ b/tests/integration/backup-restore-statement-timeout.test.ts @@ -0,0 +1,225 @@ +/** + * #1031 — a restore is not bounded by the per-request statement timeout. + * + * Every pooled connection starts with `statement_timeout` and + * `idle_in_transaction_session_timeout` from `DATABASE_STATEMENT_TIMEOUT_MS` + * (`src/lib/db.ts`, 60 s by default). A restore deletes the account's + * readings in one statement, and on an account of 1.9 million readings on a + * slow host that statement ran past 60 s, was cancelled, and the restore + * rolled back in its clearing step with a message that named no cause. + * + * This file lowers the session limit to five seconds and makes the clearing + * delete take six (a statement trigger that sleeps), which is the same + * situation at a size a test can hold. Five, not one: the suite's own + * truncation between tests runs under the same limit. The first test checks the limit + * really cancels that delete outside the restore, so the second cannot pass + * because nothing was slow. The restore then has to finish and give back + * exactly the rows the backup holds. + * + * The last test makes the database refuse the clearing step with a disk-full + * error and checks the job says so, and that nothing changed. + * + * Mutation check: remove the `set_config('statement_timeout', …)` call at the + * top of the restore transaction and the restore test goes red with + * `cause: "timeout"`. + */ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; + +vi.hoisted(() => { + // Read once, when `@/lib/db` builds its pool; hoisted above every import. + process.env.DATABASE_STATEMENT_TIMEOUT_MS = "5000"; +}); + +import { cookieJar, headerJar } from "./mock-next-headers"; +import { getPrismaClient, truncateAllTables } from "./setup"; +import { streamFullBackupJson } from "@/lib/export/full-backup-stream"; +import { storeBackupBlob } from "@/lib/export/store-backup-blob"; +import { RESTORE_FAILURE_CAUSE_MESSAGES } from "@/lib/export/restore-failure-cause"; +import { readBackupRestoreJob } from "@/lib/jobs/backup-restore"; + +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), +})); + +const COUNT = 600; + +async function dropTrigger() { + const prisma = getPrismaClient(); + await prisma.$executeRawUnsafe( + `DROP TRIGGER IF EXISTS restore_test_clearing ON measurements`, + ); + await prisma.$executeRawUnsafe( + `DROP FUNCTION IF EXISTS restore_test_clearing()`, + ); +} + +/** Run `body` on every DELETE statement against `measurements`. */ +async function onMeasurementDelete(body: string) { + const prisma = getPrismaClient(); + await prisma.$executeRawUnsafe( + `CREATE FUNCTION restore_test_clearing() RETURNS trigger LANGUAGE plpgsql AS $$ BEGIN ${body} RETURN NULL; END $$`, + ); + await prisma.$executeRawUnsafe( + `CREATE TRIGGER restore_test_clearing BEFORE DELETE ON measurements FOR EACH STATEMENT EXECUTE FUNCTION restore_test_clearing()`, + ); +} + +beforeEach(async () => { + await dropTrigger(); + await truncateAllTables(getPrismaClient()); + cookieJar.clear(); + headerJar.clear(); +}); + +afterEach(async () => { + await dropTrigger(); +}); + +async function seedAccountWithBackup() { + const prisma = getPrismaClient(); + const user = await prisma.user.create({ + data: { + username: "slow-host", + email: "slow-host@example.test", + role: "ADMIN", + }, + }); + const session = await prisma.session.create({ + data: { userId: user.id, expiresAt: new Date(Date.now() + 600_000) }, + }); + cookieJar.set("healthlog_session", session.id); + const start = Date.UTC(2024, 0, 1); + await prisma.measurement.createMany({ + data: Array.from({ length: COUNT }, (_, i) => ({ + id: `m-${String(i).padStart(4, "0")}`, + userId: user.id, + type: "PULSE" as const, + value: 50 + (i % 40), + unit: "bpm", + source: "APPLE_HEALTH" as const, + measuredAt: new Date(start + i * 60_000), + externalId: `hk-${i}`, + // Most of them deleted, as after the nightly consolidation. + deletedAt: i % 8 === 0 ? null : new Date(start), + })), + }); + const { id } = await storeBackupBlob( + prisma, + { userId: user.id, type: "WEEKLY_AUTO" }, + (write) => + streamFullBackupJson(prisma, user.id, write, { + purpose: "disaster-recovery", + }), + ); + const before = await measurementsOf(user.id); + // Something for the restore to undo, without a DELETE. + await prisma.measurement.updateMany({ + where: { userId: user.id }, + data: { value: 1 }, + }); + return { user, backupId: id, before }; +} + +async function measurementsOf(userId: string) { + return getPrismaClient().measurement.findMany({ + where: { userId }, + orderBy: { id: "asc" }, + }); +} + +async function restore(id: string) { + const { POST } = await import("./restore-job-driver"); + return POST( + new Request(`http://localhost/api/admin/backups/${id}/restore`, { + method: "POST", + headers: { "content-type": "application/json" }, + body: JSON.stringify({ confirm: "RESTORE" }), + }) as never, + { params: Promise.resolve({ id }) }, + ); +} + +async function lastJob(userId: string) { + const row = await getPrismaClient().backupRestoreJob.findFirstOrThrow({ + where: { userId }, + orderBy: { createdAt: "desc" }, + select: { id: true }, + }); + return readBackupRestoreJob(row.id); +} + +describe("restore under a short statement timeout (#1031)", () => { + it("the session limit cancels the slow clearing delete outside a restore", async () => { + const { user } = await seedAccountWithBackup(); + await onMeasurementDelete("PERFORM pg_sleep(6);"); + const prisma = getPrismaClient(); + const attempt = prisma.$transaction(async (tx) => { + await tx.measurement.deleteMany({ where: { userId: user.id } }); + throw new Error("not cancelled"); + }); + await expect(attempt).rejects.toMatchObject({ + meta: { driverAdapterError: { cause: { originalCode: "57014" } } }, + }); + }); + + it("a restore whose clearing delete outlasts the session limit still completes", async () => { + const { user, backupId, before } = await seedAccountWithBackup(); + await onMeasurementDelete("PERFORM pg_sleep(6);"); + + const res = await restore(backupId); + const job = await lastJob(user.id); + expect(job?.failure ?? null).toBeNull(); + expect(res.status).toBe(200); + expect(job?.status).toBe("succeeded"); + expect(await measurementsOf(user.id)).toEqual(before); + }); + + it("a refused clearing step names its cause and changes nothing", async () => { + const { user, backupId } = await seedAccountWithBackup(); + const changed = await measurementsOf(user.id); + await onMeasurementDelete( + "RAISE EXCEPTION 'restore test' USING ERRCODE = 'disk_full';", + ); + + const res = await restore(backupId); + expect(res.status).toBe(500); + const job = await lastJob(user.id); + expect(job?.status).toBe("failed"); + expect(job?.failure).toEqual({ + code: "transaction_failed", + cause: "storage", + message: RESTORE_FAILURE_CAUSE_MESSAGES.storage, + }); + expect(await measurementsOf(user.id)).toEqual(changed); + + const audit = await getPrismaClient().auditLog.findFirstOrThrow({ + where: { action: "admin.backups.restore.failed" }, + orderBy: { createdAt: "desc" }, + }); + expect(JSON.parse(audit.details ?? "{}")).toMatchObject({ + reason: "transaction_failed", + cause: "storage", + code: "53100", + }); + }); +}); From d44b875ec62d81fe854c59695d4e7b56c87bfdba Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Sun, 27 Sep 2026 11:37:51 +0200 Subject: [PATCH 2/3] test(restore): stub the reading count the restore budget now reads --- src/lib/export/__tests__/restore-backup-round-trip.test.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/src/lib/export/__tests__/restore-backup-round-trip.test.ts b/src/lib/export/__tests__/restore-backup-round-trip.test.ts index 7bc61b871..95cb9c53a 100644 --- a/src/lib/export/__tests__/restore-backup-round-trip.test.ts +++ b/src/lib/export/__tests__/restore-backup-round-trip.test.ts @@ -35,6 +35,7 @@ vi.mock("@/lib/db", () => ({ prisma: { dataBackup: { findUnique: vi.fn() }, user: { findUnique: vi.fn() }, + measurement: { count: vi.fn().mockResolvedValue(0) }, $transaction: mocks.transaction, }, toJson: (value: T) => value, From e0b4f3c427488fb132fa165137db109a6a941069 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Sun, 27 Sep 2026 11:57:37 +0200 Subject: [PATCH 3/3] fix(restore): size the restore budget by the rows written, and keep test housekeeping off the short limit --- src/lib/export/restore-backup.ts | 14 ++++--- .../backup-restore-statement-timeout.test.ts | 39 ++++++++++++++++--- 2 files changed, 41 insertions(+), 12 deletions(-) diff --git a/src/lib/export/restore-backup.ts b/src/lib/export/restore-backup.ts index 336fb7c14..e2b317ce1 100644 --- a/src/lib/export/restore-backup.ts +++ b/src/lib/export/restore-backup.ts @@ -177,17 +177,19 @@ export interface RestoreResponse { * The work is deleting the readings the account holds now and writing the * ones the file carries. Both count: an account whose readings were folded * into hourly averages still holds the originals as deleted rows until the - * nightly purge removes them, and the restore deletes those too (#1031). The - * budget is two minutes plus a second per 2 000 of those rows together. A - * seeded account of 1.89 million readings restored in 196 s on a fast host - * and in 9 min on a database held to half a CPU and 40 MB/s of writes; the - * budget gives it 33 min. + * nightly purge removes them, and the restore deletes and rewrites those too + * (#1031). Writing is the slow half, since every reading goes into thirteen + * indexes. The budget is two minutes, plus a second per 1 000 readings in the + * file and per 10 000 in the account. A seeded account of 1.89 million + * readings restored in 196 s on a fast host and in 19 min on a database held + * to half a CPU and 40 MB/s of writes, where its transaction ran 16 min of a + * 37 min budget. */ function restoreTransactionTimeoutMs( fileMeasurements: number, currentMeasurements: number, ): number { - return 120_000 + Math.ceil((fileMeasurements + currentMeasurements) / 2); + return 120_000 + fileMeasurements + Math.ceil(currentMeasurements / 10); } function decodeEncryptedBytes(encoded: string): Uint8Array { diff --git a/tests/integration/backup-restore-statement-timeout.test.ts b/tests/integration/backup-restore-statement-timeout.test.ts index 2da896255..e58adf1f7 100644 --- a/tests/integration/backup-restore-statement-timeout.test.ts +++ b/tests/integration/backup-restore-statement-timeout.test.ts @@ -10,8 +10,7 @@ * * This file lowers the session limit to five seconds and makes the clearing * delete take six (a statement trigger that sleeps), which is the same - * situation at a size a test can hold. Five, not one: the suite's own - * truncation between tests runs under the same limit. The first test checks the limit + * situation at a size a test can hold. The first test checks the limit * really cancels that delete outside the restore, so the second cannot pass * because nothing was slow. The restore then has to finish and give back * exactly the rows the backup holds. @@ -23,13 +22,24 @@ * top of the restore transaction and the restore test goes red with * `cause: "timeout"`. */ -import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import { + afterAll, + afterEach, + beforeEach, + describe, + expect, + it, + vi, +} from "vitest"; vi.hoisted(() => { // Read once, when `@/lib/db` builds its pool; hoisted above every import. process.env.DATABASE_STATEMENT_TIMEOUT_MS = "5000"; }); +import { PrismaPg } from "@prisma/adapter-pg"; + +import { PrismaClient } from "@/generated/prisma/client"; import { cookieJar, headerJar } from "./mock-next-headers"; import { getPrismaClient, truncateAllTables } from "./setup"; import { streamFullBackupJson } from "@/lib/export/full-backup-stream"; @@ -63,8 +73,21 @@ vi.mock("@/lib/db-compat", () => ({ const COUNT = 600; +/** + * A second pool without the lowered limit, for the suite's own housekeeping: + * truncating every table between tests can take longer than five seconds on + * a busy host, and it is not what this file measures. + */ +let setupClient: PrismaClient | null = null; +function housekeeping(): PrismaClient { + setupClient ??= new PrismaClient({ + adapter: new PrismaPg({ connectionString: process.env.DATABASE_URL! }), + }); + return setupClient; +} + async function dropTrigger() { - const prisma = getPrismaClient(); + const prisma = housekeeping(); await prisma.$executeRawUnsafe( `DROP TRIGGER IF EXISTS restore_test_clearing ON measurements`, ); @@ -75,7 +98,7 @@ async function dropTrigger() { /** Run `body` on every DELETE statement against `measurements`. */ async function onMeasurementDelete(body: string) { - const prisma = getPrismaClient(); + const prisma = housekeeping(); await prisma.$executeRawUnsafe( `CREATE FUNCTION restore_test_clearing() RETURNS trigger LANGUAGE plpgsql AS $$ BEGIN ${body} RETURN NULL; END $$`, ); @@ -86,7 +109,7 @@ async function onMeasurementDelete(body: string) { beforeEach(async () => { await dropTrigger(); - await truncateAllTables(getPrismaClient()); + await truncateAllTables(housekeeping()); cookieJar.clear(); headerJar.clear(); }); @@ -95,6 +118,10 @@ afterEach(async () => { await dropTrigger(); }); +afterAll(async () => { + await setupClient?.$disconnect(); +}); + async function seedAccountWithBackup() { const prisma = getPrismaClient(); const user = await prisma.user.create({