Merge branch 'fix/restore-large-account-clearing' into release/v1.39.4

This commit is contained in:
Marc-André Bombeck committed 2026-09-27 12:14:04 +02:00
commit 02801bdfda
20 files changed
+793 -18

No files matched your search

@@ -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<string>();
// 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([]);
});
});
+30 -2
View File
@@ -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<typeof useTranslations>["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<typeof useTranslations>["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 })}
</p>
<p className="text-xs">
{failureText(code, t, job.failure?.keyIds)}
{failureText(code, t, job.failure?.keyIds, job.failure?.cause)}
</p>
{changedNothing ? (
<p className="text-muted-foreground mt-1 text-xs">
@@ -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: <T>(value: T) => value,
@@ -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/,
);
}
});
});
+52 -11
View File
@@ -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,25 @@ 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 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(measurementCount: number): number {
return 120_000 + Math.ceil(measurementCount / 5);
function restoreTransactionTimeoutMs(
fileMeasurements: number,
currentMeasurements: number,
): number {
return 120_000 + fileMeasurements + Math.ceil(currentMeasurements / 10);
}
function decodeEncryptedBytes(encoded: string): Uint8Array<ArrayBuffer> {
@@ -612,8 +625,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 +670,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 +2394,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 +2402,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 +2429,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 },
);
}
+127
View File
@@ -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<string, unknown>)[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.",
};
+17 -1
View File
@@ -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
+1
View File
@@ -186,6 +186,7 @@ export const JOB_FACT_ALLOWLIST: ReadonlySet<string> = new Set([
"restore_drill_mood_entries",
"restore_drill_plaintext_bytes",
"restore_drill_stale",
"restore_fail_cause",
"restore_failed",
"restore_measurements",
"restore_requeued",
+4 -1
View File
@@ -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