From f67006783c3e7b92dc2aee2826ede6338ba398b9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Sun, 4 Oct 2026 15:24:01 +0200 Subject: [PATCH 1/5] fix(backup): open legacy text ciphertext as a string and probe only counted sections A text column written before key ids existed holds the bare base64 of nonce, tag and ciphertext. The key check read such a value as an encoded Bytes column, decoded it once too often, and accused the v1 key of not opening a copy it opens. The instance's stored AI key has exactly that shape and is the shortest v1 value in every disaster-recovery copy, so it was picked as the probe and refused every restore of an account with v1 values, even with the instance settings left out of the verdict. A legacy value now reads as a string unless its decoded head is base64 text. Samples are kept per section and only the sections the verdict counts are probed; a key is unreadable when none of its probes opens. Binary values open with the label their column is sealed under, taken from the encrypted-column registry, and are not probed when no label is known. A preview stored by an earlier release is still read, and its sample's layout is derived again from the value. --- .../export/__tests__/backup-key-ids.test.ts | 107 +++++++++++- src/lib/export/backup-key-ids.ts | 160 +++++++++++++++--- src/lib/export/backup-preview.ts | 18 +- 3 files changed, 255 insertions(+), 30 deletions(-) diff --git a/src/lib/export/__tests__/backup-key-ids.test.ts b/src/lib/export/__tests__/backup-key-ids.test.ts index 386f12878..f71d22c36 100644 --- a/src/lib/export/__tests__/backup-key-ids.test.ts +++ b/src/lib/export/__tests__/backup-key-ids.test.ts @@ -10,7 +10,13 @@ import { Buffer } from "node:buffer"; import { afterEach, beforeEach, describe, expect, it } from "vitest"; -import { _resetCryptoCacheForTests, encrypt, encryptBytes } from "@/lib/crypto"; +import { + _resetCryptoCacheForTests, + encrypt, + encryptBytes, + encryptUnderKeyId, +} from "@/lib/crypto"; +import { WORKOUT_ROUTE_GEOMETRY_AAD } from "@/lib/crypto/encrypted-columns"; import { assessBackupKeys, BackupKeyIdCollector, @@ -173,6 +179,105 @@ describe("assessBackupKeys", () => { }); }); +describe("legacy values and the probe", () => { + /** + * A text column written before key ids existed: bare base64 of + * nonce, tag and ciphertext. A 14-character secret seals to 42 bytes, + * 56 characters, which is exactly the shape an instance's stored AI key + * has, and the shortest v1 value in a typical copy. + */ + const legacyText = (plain: string) => + encryptUnderKeyId(plain, "v1").slice("v1.".length); + + beforeEach(() => useKeys({ v1: K1, cur: K2 }, "v1")); + + it("reads a legacy text value as a string, not as an encoded Bytes column", () => { + const value = legacyText("sk-abcdefghijk"); + expect(value).toHaveLength(56); + expect(innerCiphertextKeyId(value)).toEqual({ + keyId: "v1", + form: "string", + }); + }); + + function drFile() { + return { + userId: "u1", + appSettings: { adminAiKeyEncrypted: legacyText("sk-abcdefghijk") }, + coachConversations: [ + { + titleEncrypted: encrypt("a conversation about sleep"), + messages: [{ contentEncrypted: encrypt("how did I sleep?") }], + }, + ], + measurements: [{ notesEncrypted: bytesString("after the run") }], + }; + } + + it("passes a copy whose legacy instance setting and v1 values the key opens", () => { + const collector = new BackupKeyIdCollector(); + collector.visit(drFile()); + for (const ignoreSections of [undefined, new Set(["appSettings"])]) { + const verdict = assessBackupKeys(collector, { ignoreSections }); + expect(verdict.keyIds).toEqual(["v1"]); + expect(verdict.missing).toEqual([]); + expect(verdict.unreadable).toEqual([]); + } + }); + + it("passes the same copy after its preview is stored and read back", () => { + const collector = new BackupKeyIdCollector(); + collector.visit(drFile()); + const stored = JSON.parse(JSON.stringify(collector.toStored())); + const verdict = assessBackupKeys(BackupKeyIdCollector.fromStored(stored), { + ignoreSections: new Set(["appSettings"]), + }); + expect(verdict.unreadable).toEqual([]); + }); + + it("does not let a section the caller ignores decide the verdict", () => { + const fine = encrypt("a note the key opens"); + useKeys({ v1: K3, cur: K2 }, "v1"); + const impostor = legacyText("sk-abcdefghijk"); + useKeys({ v1: K1, cur: K2 }, "v1"); + const collector = new BackupKeyIdCollector(); + collector.visit({ + appSettings: { adminAiKeyEncrypted: impostor }, + measurements: [{ notesEncrypted: `${fine}` }], + }); + expect( + assessBackupKeys(collector, { ignoreSections: new Set(["appSettings"]) }) + .unreadable, + ).toEqual([]); + // Asked for back, the instance settings do count, and the value there + // is the only one: the verdict still passes because the other opens. + expect(assessBackupKeys(collector).unreadable).toEqual([]); + }); + + it("opens a bound binary value with the label its column seals it under", () => { + const route = encryptBytes( + Buffer.from('{"type":"LineString","coordinates":[]}'), + WORKOUT_ROUTE_GEOMETRY_AAD, + ).toString("base64"); + const collector = new BackupKeyIdCollector(); + collector.visit({ workoutRoutes: [{ geometryEncrypted: route }] }); + expect(assessBackupKeys(collector).unreadable).toEqual([]); + }); + + it("still refuses a copy the configured v1 key genuinely does not open", () => { + const file = drFile(); + useKeys({ v1: K3, cur: K2 }, "cur"); + const collector = new BackupKeyIdCollector(); + collector.visit(file); + for (const ignoreSections of [undefined, new Set(["appSettings"])]) { + const verdict = assessBackupKeys(collector, { ignoreSections }); + expect(verdict.missing).toEqual([]); + expect(verdict.unreadable).toEqual(["v1"]); + expect(describeBackupKeyProblem(verdict)).toContain("'v1'"); + } + }); +}); + describe("createBackupKeyIdTextScanner", () => { it("finds every key id in JSON fed in arbitrary pieces", () => { const early = bytesString("written before the rotation"); diff --git a/src/lib/export/backup-key-ids.ts b/src/lib/export/backup-key-ids.ts index 88bb09ad6..04e57c790 100644 --- a/src/lib/export/backup-key-ids.ts +++ b/src/lib/export/backup-key-ids.ts @@ -21,7 +21,9 @@ * - a Bytes column, base64-encoded, holding the string codec as UTF-8; * - a Bytes column, base64-encoded, holding the binary codec * (`0x02 | keyIdLen | keyId | iv | tag | ct`); - * - a legacy value with no key id, which only the `v1` key opens. + * - a legacy value with no key id, which only the `v1` key opens: in a + * text column the bare base64 itself, in a Bytes column that base64 + * again, encoded. * * Two readers share the classification: a walk over a parsed document (the * restore, the preview, the upload and the restore drill already hold one), @@ -31,6 +33,7 @@ import { Buffer } from "node:buffer"; import { decrypt, decryptBytes, getConfiguredKeyIds } from "@/lib/crypto"; +import { ENCRYPTED_COLUMNS } from "@/lib/crypto/encrypted-columns"; /** The key id a value with no key id prefix was written under. */ export const LEGACY_INNER_KEY_ID = "v1"; @@ -39,6 +42,8 @@ const KEY_ID = /^[A-Za-z0-9_-]{1,32}$/; const VERSIONED = /^([A-Za-z0-9_-]{1,32})\.[A-Za-z0-9+/=]+$/; const BASE64 = /^[A-Za-z0-9+/]+={0,2}$/; const BASE64_TAIL = /^[A-Za-z0-9+/=]*$/; +/** Every byte of a decoded head is a base64 character. */ +const BASE64_TEXT = /^[A-Za-z0-9+/=]+$/; const BYTES_CODEC_VERSION = 0x02; const MIN_CIPHERTEXT_CHARS = 40; @@ -89,7 +94,16 @@ export function innerCiphertextKeyId(value: string): InnerCiphertext | null { return { keyId: text.slice(0, dot), form: "bytes-string" }; } // No key id anywhere: the legacy layout, which `decrypt` opens with `v1`. - return { keyId: LEGACY_INNER_KEY_ID, form: "bytes-string" }; + // Which column it came from decides how it opens. A Bytes column holding a + // legacy value carries base64 TEXT, encoded once more, so its decoded head + // reads as base64 characters. A text column holds the bare base64 of the + // nonce, tag and ciphertext, whose decoded head is random bytes: reading + // that as an encoded Bytes column would base64-decode it once too often, + // and the key that opens it would look like the wrong one. + return { + keyId: LEGACY_INNER_KEY_ID, + form: BASE64_TEXT.test(text) ? "bytes-string" : "string", + }; } /** Whether a member name holds inner ciphertext. */ @@ -123,13 +137,58 @@ export const RESTORE_SELF_VERIFIED_SECTIONS: ReadonlySet = new Set([ "vaccinations", ]); +/** + * One value kept to prove a key opens what it was written under: the + * shortest of its section, so the probe of a section the caller will not + * write never stands in for one it will. + */ +export interface KeySample { + value: string; + form: InnerCiphertextForm; + /** + * The section it was found in. Absent on a preview stored before samples + * were kept per section; such a sample is probed whatever is ignored. + */ + section?: string; + /** The member it sat under, which names the label a binary value needs. */ + member?: string; +} + interface KeyUse { /** How many values need this key. */ count: number; /** The top-level sections they sit in (`measurements`, `appSettings`, …). */ sections: Set; - /** The shortest value seen, kept to prove the key actually opens it. */ - sample: { value: string; form: InnerCiphertextForm } | null; + /** The shortest openable value of each section, keyed by section. */ + samples: Map; +} + +/** + * The associated-data label a binary value under `member` is sealed with, + * from the encrypted-column registry: `undefined` for an unlabelled column + * (a document's content), null when no binary column has that name or two + * with that name use different labels. A null value is not probed: GCM + * cannot tell a wrong label from a wrong key, so opening it without the + * right one would accuse the key. + */ +const BINARY_MEMBER_AAD: ReadonlyMap = + (() => { + const map = new Map(); + for (const column of ENCRYPTED_COLUMNS) { + if (column.codec !== "binary2" && column.codecField === undefined) { + continue; + } + if (!map.has(column.field)) map.set(column.field, column.aad); + else if (map.get(column.field) !== column.aad) + map.set(column.field, null); + } + return map; + })(); + +function binaryAad(member: string | undefined): string | undefined | null { + if (member === undefined) return null; + const aad = BINARY_MEMBER_AAD.get(member); + return aad === undefined && !BINARY_MEMBER_AAD.has(member) ? null : aad; } /** A sample longer than this is not kept; opening it proves nothing more. */ @@ -142,25 +201,30 @@ const MAX_SAMPLE_CHARS = 64 * 1024; export class BackupKeyIdCollector { private readonly uses = new Map(); - /** Record one inner value found in `section`. */ - add(section: string, value: string): void { + /** Record one inner value found in `section`, under `member`. */ + add(section: string, value: string, member?: string): void { const found = innerCiphertextKeyId(value); if (!found) return; let use = this.uses.get(found.keyId); if (!use) { - use = { count: 0, sections: new Set(), sample: null }; + use = { count: 0, sections: new Set(), samples: new Map() }; this.uses.set(found.keyId, use); } use.count += 1; use.sections.add(section); // A sample from a self-verified section proves nothing the restore needs: - // a value there that does not open is skipped, not fatal. + // a value there that does not open is skipped, not fatal. A binary value + // whose label is not known cannot prove anything either. if ( - !RESTORE_SELF_VERIFIED_SECTIONS.has(section) && - value.length <= MAX_SAMPLE_CHARS && - (!use.sample || value.length < use.sample.value.length) + RESTORE_SELF_VERIFIED_SECTIONS.has(section) || + value.length > MAX_SAMPLE_CHARS || + (found.form === "binary" && binaryAad(member) === null) ) { - use.sample = { value, form: found.form }; + return; + } + const kept = use.samples.get(section); + if (!kept || value.length < kept.value.length) { + use.samples.set(section, { value, form: found.form, section, member }); } } @@ -184,7 +248,7 @@ export class BackupKeyIdCollector { private walk(value: unknown, section: string, member: string | null): void { if (typeof value === "string") { if (member !== null && isEncryptedMember(member)) { - this.add(section, value); + this.add(section, value, member); } return; } @@ -227,7 +291,9 @@ export class BackupKeyIdCollector { keyId, count: use.count, sections: [...use.sections].sort(), - sample: use.sample ? { ...use.sample } : null, + samples: [...use.samples.values()] + .sort((a, b) => (a.section ?? "").localeCompare(b.section ?? "")) + .map((sample) => ({ ...sample })), })); } @@ -235,10 +301,16 @@ export class BackupKeyIdCollector { static fromStored(stored: readonly StoredKeyUse[]): BackupKeyIdCollector { const collector = new BackupKeyIdCollector(); for (const entry of stored) { + const samples = new Map(); + for (const sample of entry.samples ?? []) { + samples.set(sample.section ?? "", { ...sample }); + } + // A preview stored before samples were kept per section has one. + if (entry.sample) samples.set("", { ...entry.sample }); collector.uses.set(entry.keyId, { count: entry.count, sections: new Set(entry.sections), - sample: entry.sample ? { ...entry.sample } : null, + samples, }); } return collector; @@ -250,7 +322,10 @@ export interface StoredKeyUse { keyId: string; count: number; sections: string[]; - sample: { value: string; form: InnerCiphertextForm } | null; + /** The shortest openable value of each section. */ + samples?: KeySample[]; + /** The one sample a preview stored before v1.40.1 kept. */ + sample?: { value: string; form: InnerCiphertextForm } | null; } export interface BackupKeyAssessment { @@ -267,23 +342,52 @@ export interface BackupKeyAssessment { affectedValues: number; } -function openSample(sample: { value: string; form: InnerCiphertextForm }) { - switch (sample.form) { +/** + * Open one sample. The layout is read again from the value rather than taken + * from the record: a preview stored by v1.40.0 holds legacy text values + * marked as encoded Bytes columns, and must not keep accusing the key. + */ +function openSample(sample: KeySample) { + const form = innerCiphertextKeyId(sample.value)?.form ?? sample.form; + switch (form) { case "string": decrypt(sample.value); return; case "bytes-string": decrypt(Buffer.from(sample.value, "base64").toString("utf8")); return; - case "binary": - decryptBytes(Buffer.from(sample.value, "base64")); + case "binary": { + const aad = binaryAad(sample.member); + if (aad === null) throw new Error("No label known for a binary sample"); + decryptBytes(Buffer.from(sample.value, "base64"), aad); return; + } } } +function opensAny(samples: readonly KeySample[]): boolean { + for (const sample of samples) { + try { + openSample(sample); + return true; + } catch { + // The next section's sample may still prove the key. + } + } + return false; +} + /** - * Hold what the file needs against what this host has, and open one value per - * key to prove the key under that id is the right one. + * Hold what the file needs against what this host has, and open values under + * each key to prove the key under that id is the right one. + * + * The probes come only from sections the verdict counts: one per section, + * the shortest. A key is unreadable when none of them opens. One copy is + * written by one host at one moment, when each key id had one key material + * behind it, so a configured key that opens any of its values is the key the + * copy was written with; a single value that does not open is damage to that + * value, and refusing the whole restore over it would cost every other part + * of the account. * * `ignoreSections` leaves out sections the caller will not write: the * instance settings, when the operator has not asked for them back. The @@ -320,10 +424,14 @@ export function assessBackupKeys( affectedValues += use.count; continue; } - if (!use.sample) continue; - try { - openSample(use.sample); - } catch { + const probes = [...use.samples.values()].filter( + (sample) => + sample.section === undefined || + (!ignore.has(sample.section) && + !RESTORE_SELF_VERIFIED_SECTIONS.has(sample.section)), + ); + if (probes.length === 0) continue; + if (!opensAny(probes)) { unreadable.push(keyId); affectedValues += use.count; } diff --git a/src/lib/export/backup-preview.ts b/src/lib/export/backup-preview.ts index 952f3c159..2c6d040d9 100644 --- a/src/lib/export/backup-preview.ts +++ b/src/lib/export/backup-preview.ts @@ -10,8 +10,8 @@ * once anyway, on its way into the pieces, so the counts are taken there. * * What is kept. The `summarizeBackup` counts of the copy, its schema version, - * and the inner key ids with the sections they sit in and one sample value - * each. The verdicts are not kept: whether this release can restore the + * and the inner key ids with the sections they sit in and the shortest + * value of each section. The verdicts are not kept: whether this release can restore the * schema version, and whether this server holds the keys the copy needs, can * both change after the copy was written, so the route takes them again from * these inputs on every read. @@ -60,12 +60,24 @@ const storedPreviewSchema = z.object({ keyId: z.string(), count: z.number().int().nonnegative(), sections: z.array(z.string()), + samples: z + .array( + z.object({ + value: z.string(), + form: z.enum(["string", "bytes-string", "binary"]), + section: z.string().optional(), + member: z.string().optional(), + }), + ) + .optional(), + // A preview stored by v1.40.0 or earlier kept one sample per key. sample: z .object({ value: z.string(), form: z.enum(["string", "bytes-string", "binary"]), }) - .nullable(), + .nullable() + .optional(), }), ), }); From 5345c8be1e1ee84d3d39810b2f45f978baf32e8d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Sun, 4 Oct 2026 15:25:25 +0200 Subject: [PATCH 2/5] fix(backup): check every account of the newest date in the restore drill The drill read only the alphabetically last object of the newest date, so one account stood in for all of them. It now checks every object of that date one at a time, records a failure against the account it belongs to, keeps going, and pages once per failing object with its key and how many accounts were checked. --- docs/ops/backup-restore.md | 18 +- src/lib/jobs/__tests__/restore-drill.test.ts | 54 +++- src/lib/jobs/job-outcome.ts | 3 + src/lib/jobs/restore-drill.ts | 282 ++++++++++++------- 4 files changed, 233 insertions(+), 124 deletions(-) diff --git a/docs/ops/backup-restore.md b/docs/ops/backup-restore.md index 4d0a70f0e..ea7ce290c 100644 --- a/docs/ops/backup-restore.md +++ b/docs/ops/backup-restore.md @@ -441,10 +441,12 @@ the restart. Since v1.16.4 a pg-boss job (`data-restore-drill`, cron `11 4 1 * *` — 04:11 on the 1st of each month) exercises the read path end-to-end: -fetch the most recent backup object from the bucket, decrypt it under -the current `BACKUP_ENCRYPTION_KEY`, JSON-parse it, and sanity-check -the payload shape. It performs **no database restore** — it validates -the artefact, not the import path. +fetch every backup object of the most recent date from the bucket (one per +account), decrypt each under the current `BACKUP_ENCRYPTION_KEY`, JSON-parse +it, and sanity-check the payload shape. It performs **no database restore** — +it validates the artefacts, not the import path. Each account is checked and +reported on its own: one object that fails is named, and the others are still +read. Outcomes: @@ -454,14 +456,16 @@ Outcomes: uploader has stalled (or the lifecycle rule is too aggressive). The drill pages via the worker error reporter (stderr + GlitchTip). - **Failure** — empty bucket, fetch error, decryption failure (wrong or - rotated key), malformed JSON: pages the same way. A decryption + rotated key), malformed JSON: pages the same way, once per failing object, + with the object key and how many accounts were checked. A decryption failure right after a `BACKUP_ENCRYPTION_KEY` change means the new key cannot read the existing objects: put the old key into `BACKUP_ENCRYPTION_PREVIOUS_KEYS` (see "Rotating the off-host key"). - **Content under a missing application key** — the object opens, but its content was written under an `ENCRYPTION_KEYS` entry this server no longer - has, or under an id whose key material changed. The drill decrypts one value - per key id it finds, and pages naming the key. A restore of that object + has, or under an id whose key material changed. The drill decrypts the + shortest value of each section under every key id it finds, and pages naming + the key when none of them opens. A restore of that object would write back rows nobody can open; put the key back before restoring. - **Not configured** — deployments without the `BACKUP_S3_*` vars skip silently (wide-event warning only). diff --git a/src/lib/jobs/__tests__/restore-drill.test.ts b/src/lib/jobs/__tests__/restore-drill.test.ts index 41e1cc676..d223c5a45 100644 --- a/src/lib/jobs/__tests__/restore-drill.test.ts +++ b/src/lib/jobs/__tests__/restore-drill.test.ts @@ -93,11 +93,14 @@ describe("runRestoreDrill", () => { "_healthcheck/123.bin": Buffer.from([0x42]), }); const report = await runRestoreDrill(s3, new Date("2026-06-02T04:11:00Z")); - expect(report.objectKey).toBe("2026-06-01/user-abc.json.enc"); + expect(report.accounts.map((a) => a.objectKey)).toEqual([ + "2026-06-01/user-abc.json.enc", + ]); + expect(report.failed).toEqual([]); expect(report.dateKey).toBe("2026-06-01"); expect(report.ageDays).toBe(1); expect(report.stale).toBe(false); - expect(report.recordCounts).toEqual({ + expect(report.accounts[0].recordCounts).toEqual({ measurements: 2, medications: 1, intakeEvents: 0, @@ -109,6 +112,30 @@ describe("runRestoreDrill", () => { expect(s3.deleteObject).not.toHaveBeenCalled(); }); + it("checks every account of the newest date and names the one that fails", async () => { + const tampered = Buffer.from(backupObject({ userId: "user-aaa" })); + tampered[tampered.length - 1] ^= 0xff; + const s3 = makeS3Mock({ + "2026-05-31/user-old.json.enc": backupObject(), + "2026-06-01/user-aaa.json.enc": tampered, + "2026-06-01/user-mmm.json.enc": backupObject({ userId: "user-mmm" }), + // The alphabetically last object, the only one the drill used to read. + "2026-06-01/user-zzz.json.enc": backupObject({ userId: "user-zzz" }), + }); + const report = await runRestoreDrill(s3, new Date("2026-06-02T04:11:00Z")); + expect(report.accounts.map((a) => [a.objectKey, a.ok])).toEqual([ + ["2026-06-01/user-aaa.json.enc", false], + ["2026-06-01/user-mmm.json.enc", true], + ["2026-06-01/user-zzz.json.enc", true], + ]); + expect(report.failed.map((a) => a.objectKey)).toEqual([ + "2026-06-01/user-aaa.json.enc", + ]); + expect(s3.getObject).not.toHaveBeenCalledWith( + "2026-05-31/user-old.json.enc", + ); + }); + it("flags the report stale when the newest backup is older than the threshold", async () => { const s3 = makeS3Mock({ "2026-05-20/user-abc.json.enc": backupObject() }); const report = await runRestoreDrill(s3, new Date("2026-06-01T04:11:00Z")); @@ -132,13 +159,16 @@ describe("runRestoreDrill", () => { }); const now = new Date("2026-06-02T04:11:00Z"); const report = await runRestoreDrill(s3, now); - expect(report.innerKeyIds).toEqual(["old"]); + expect(report.accounts[0].innerKeyIds).toEqual(["old"]); + expect(report.failed).toEqual([]); + const failure = async () => + (await runRestoreDrill(s3, now)).failed.map((a) => a.error).join("\n"); // The rotation ran, and the operator dropped the old key. vi.stubEnv("ENCRYPTION_KEYS", JSON.stringify({ cur: "22".repeat(32) })); vi.stubEnv("ENCRYPTION_ACTIVE_KEY_ID", "cur"); _resetCryptoCacheForTests(); - await expect(runRestoreDrill(s3, now)).rejects.toThrow(/'old'/); + expect(await failure()).toMatch(/'old'/); // Same id, different key material behind it. vi.stubEnv( @@ -146,9 +176,7 @@ describe("runRestoreDrill", () => { JSON.stringify({ old: "33".repeat(32), cur: "22".repeat(32) }), ); _resetCryptoCacheForTests(); - await expect(runRestoreDrill(s3, now)).rejects.toThrow( - /does not open the values/, - ); + expect(await failure()).toMatch(/does not open the values/); vi.unstubAllEnvs(); _resetCryptoCacheForTests(); }); @@ -158,21 +186,25 @@ describe("runRestoreDrill", () => { await expect(runRestoreDrill(s3)).rejects.toThrow(/no backup objects/); }); - it("throws when the object cannot be decrypted (wrong key / tampering)", async () => { + it("fails the account whose object cannot be decrypted (wrong key / tampering)", async () => { const tampered = Buffer.from(backupObject()); tampered[tampered.length - 1] ^= 0xff; const s3 = makeS3Mock({ "2026-06-01/user-abc.json.enc": tampered }); - await expect(runRestoreDrill(s3)).rejects.toThrow(); + const report = await runRestoreDrill(s3); + expect(report.failed.map((a) => a.objectKey)).toEqual([ + "2026-06-01/user-abc.json.enc", + ]); }); - it("throws when the payload is missing core fields", async () => { + it("fails the account whose payload is missing core fields", async () => { const s3 = makeS3Mock({ "2026-06-01/user-abc.json.enc": encryptBackup( JSON.stringify({ exportedAt: "2026-06-01T02:30:00.000Z" }), KEY, ), }); - await expect(runRestoreDrill(s3)).rejects.toThrow(/missing core fields/); + const report = await runRestoreDrill(s3); + expect(report.failed[0].error).toMatch(/missing core fields/); }); it("throws OffhostBackupNotConfiguredError when the S3 vars are unset", async () => { diff --git a/src/lib/jobs/job-outcome.ts b/src/lib/jobs/job-outcome.ts index c66956a88..2ef5e5cc0 100644 --- a/src/lib/jobs/job-outcome.ts +++ b/src/lib/jobs/job-outcome.ts @@ -190,7 +190,10 @@ export const JOB_FACT_ALLOWLIST: ReadonlySet = new Set([ // v1.39.1 — the background restore of a stored backup, and the sweep that // re-queues one a stopped worker left running. Counts and a claim flag. "restore_claimed", + "restore_drill_accounts", + "restore_drill_accounts_failed", "restore_drill_age_days", + "restore_drill_date", "restore_drill_ciphertext_bytes", "restore_drill_intake_events", "restore_drill_measurements", diff --git a/src/lib/jobs/restore-drill.ts b/src/lib/jobs/restore-drill.ts index efd0baf6e..caec85d00 100644 --- a/src/lib/jobs/restore-drill.ts +++ b/src/lib/jobs/restore-drill.ts @@ -9,9 +9,10 @@ * rotation mishap or a bucket-side corruption would only surface on * the day a real restore is needed. * - * This drill closes that gap once a month: fetch the most recent - * backup object, decrypt it, JSON-parse it, and sanity-check the - * payload shape. It deliberately performs NO database restore — the + * This drill closes that gap once a month: fetch every backup object of + * the most recent date (one per account), decrypt it, JSON-parse it, + * sanity-check the payload shape, and open inner values under each + * application key it needs. Each account is reported on its own. It deliberately performs NO database restore — the * drill validates the artefact, not the import path. The result is * surfaced through the wide-event meta on success and through * `reportWorkerError` (stderr + GlitchTip) on any failure, so a broken @@ -53,11 +54,12 @@ const MAX_BACKUP_AGE_DAYS = 3; const BACKUP_KEY_PATTERN = /^(\d{4}-\d{2}-\d{2})\/user-.+\.json\.enc$/; -export interface RestoreDrillReport { +/** What the drill found for one account's object. */ +export interface RestoreDrillAccount { objectKey: string; - dateKey: string; - ageDays: number; - stale: boolean; + ok: boolean; + /** Why the object could not be restored on this server; set when not ok. */ + error?: string; ciphertextBytes: number; plaintextBytes: number; /** Application key ids the object's inner ciphertext needs, each proven to open. */ @@ -70,17 +72,108 @@ export interface RestoreDrillReport { }; } +export interface RestoreDrillReport { + dateKey: string; + ageDays: number; + stale: boolean; + /** Every object of the newest date, in key order. */ + accounts: RestoreDrillAccount[]; + /** The accounts whose object did not pass. */ + failed: RestoreDrillAccount[]; +} + function countArray(value: unknown): number { return Array.isArray(value) ? value.length : 0; } +const EMPTY_COUNTS: RestoreDrillAccount["recordCounts"] = { + measurements: 0, + medications: 0, + intakeEvents: 0, + moodEntries: 0, +}; + /** - * Fetch → decrypt → parse the most recent off-host backup object. + * Fetch → decrypt → parse → key-check one object. Throws on every failure + * mode: fetch error, bad envelope / wrong key, malformed JSON, payload + * missing its core fields, inner ciphertext this server cannot open. + */ +async function drillObject( + s3: S3Like, + cfg: NonNullable>, + objectKey: string, + account: RestoreDrillAccount, +): Promise { + const ciphertext = await s3.getObject(objectKey); + account.ciphertextBytes = ciphertext.length; + // Read as a stream, never as one string: the JSON of a large record is + // longer than any string V8 can hold (#1031). The bulk tables are counted, + // not kept. + const source = openBackupObject(ciphertext, offhostKeyRing(cfg), objectKey); + async function* counted() { + for await (const chunk of source()) { + account.plaintextBytes += chunk.byteLength; + yield chunk; + } + } + // The envelope opening proves the off-host key. It proves nothing about + // the application keys the ciphertext INSIDE was written under, and that + // is the half a key rotation breaks: a restore of this object writes those + // values back verbatim. So every inner key id is collected, and values + // under each key are actually decrypted. + const keys = new BackupKeyIdCollector(); + let scanned; + try { + scanned = await scanBackupJson(counted(), { + streamKeys: new Set(["measurements", "intakeEvents", "moodEntries"]), + onElement: (key, element) => keys.visit(element, key), + }); + } catch (err) { + if (err instanceof BackupJsonError) { + throw new Error(`decrypted but is not a JSON object: ${err.message}`); + } + throw err; + } + const payload = scanned.document; + const streamedCounts = scanned.streamedCounts; + if ( + typeof payload.exportedAt !== "string" || + typeof payload.userId !== "string" || + streamedCounts.measurements === undefined + ) { + throw new Error( + "parses but is missing core fields (exportedAt / userId / measurements).", + ); + } + account.recordCounts = { + measurements: streamedCounts.measurements, + medications: countArray(payload.medications), + intakeEvents: streamedCounts.intakeEvents ?? 0, + moodEntries: streamedCounts.moodEntries ?? 0, + }; + + keys.visit(payload); + const keyVerdict = assessBackupKeys(keys, { + ignoreSections: new Set(["appSettings"]), + }); + account.innerKeyIds = keyVerdict.keyIds; + const keyProblem = describeBackupKeyProblem(keyVerdict); + if (keyProblem) { + throw new Error( + `opens, but its content could not be restored on this server. ${keyProblem}`, + ); + } +} + +/** + * Fetch → decrypt → parse every off-host backup object of the newest date, + * one account at a time. * * Read-only against the bucket (GetObject + ListObjects — both inside - * the uploader's existing IAM grant). Throws on every failure mode: - * not configured, empty bucket, fetch error, bad envelope / wrong key, - * malformed JSON, payload missing its core fields. + * the uploader's existing IAM grant). Throws when there is nothing to check + * (not configured, empty bucket); a failure of one account's object is + * recorded against that account and the others are still checked, so one + * account cannot turn the drill red without being named, nor hide another. */ export async function runRestoreDrill( s3Override?: S3Like, @@ -95,8 +188,8 @@ export async function runRestoreDrill( const s3 = s3Override ?? (await getS3Client(cfg)); // Date-prefixed keys (`YYYY-MM-DD/user-.json.enc`) sort - // lexicographically in chronological order, so the newest object is - // simply the maximum matching key. `_healthcheck/` probes and any + // lexicographically in chronological order, so the newest date is the + // date of the maximum matching key. `_healthcheck/` probes and any // foreign objects in the bucket are filtered out by the pattern. const objects = await s3.listObjects(""); const backupKeys = objects @@ -108,62 +201,30 @@ export async function runRestoreDrill( `Restore drill found no backup objects in bucket "${cfg.bucket}" — the nightly off-host upload is not producing artefacts.`, ); } - const objectKey = backupKeys[backupKeys.length - 1]; - const dateKey = BACKUP_KEY_PATTERN.exec(objectKey)![1]; + const dateKey = BACKUP_KEY_PATTERN.exec( + backupKeys[backupKeys.length - 1], + )![1]; + const newest = backupKeys.filter((k) => k.startsWith(`${dateKey}/`)); - const ciphertext = await s3.getObject(objectKey); - // Read as a stream, never as one string: the JSON of a large record is - // longer than any string V8 can hold (#1031). The bulk tables are counted, - // not kept. - const source = openBackupObject(ciphertext, offhostKeyRing(cfg), objectKey); - let plaintextBytes = 0; - async function* counted() { - for await (const chunk of source()) { - plaintextBytes += chunk.byteLength; - yield chunk; + const accounts: RestoreDrillAccount[] = []; + for (const objectKey of newest) { + const account: RestoreDrillAccount = { + objectKey, + ok: true, + ciphertextBytes: 0, + plaintextBytes: 0, + innerKeyIds: [], + recordCounts: { ...EMPTY_COUNTS }, + }; + try { + await drillObject(s3, cfg, objectKey, account); + } catch (err) { + account.ok = false; + account.error = `Restore drill: backup object "${objectKey}" ${ + err instanceof Error ? err.message : String(err) + }`; } - } - // The envelope opening proves the off-host key. It proves nothing about - // the application keys the ciphertext INSIDE was written under, and that - // is the half a key rotation breaks: a restore of this object writes those - // values back verbatim. So every inner key id is collected, and one value - // per key is actually decrypted. - const keys = new BackupKeyIdCollector(); - let scanned; - try { - scanned = await scanBackupJson(counted(), { - streamKeys: new Set(["measurements", "intakeEvents", "moodEntries"]), - onElement: (key, element) => keys.visit(element, key), - }); - } catch (err) { - if (err instanceof BackupJsonError) { - throw new Error( - `Restore drill: backup object "${objectKey}" decrypted but is not a JSON object: ${err.message}`, - ); - } - throw err; - } - const payload = scanned.document; - const streamedCounts = scanned.streamedCounts; - if ( - typeof payload.exportedAt !== "string" || - typeof payload.userId !== "string" || - streamedCounts.measurements === undefined - ) { - throw new Error( - `Restore drill: backup object "${objectKey}" parses but is missing core fields (exportedAt / userId / measurements).`, - ); - } - - keys.visit(payload); - const keyVerdict = assessBackupKeys(keys, { - ignoreSections: new Set(["appSettings"]), - }); - const keyProblem = describeBackupKeyProblem(keyVerdict); - if (keyProblem) { - throw new Error( - `Restore drill: backup object "${objectKey}" opens, but its content could not be restored on this server. ${keyProblem}`, - ); + accounts.push(account); } const ageDays = Math.floor( @@ -173,19 +234,11 @@ export async function runRestoreDrill( ); return { - objectKey, dateKey, ageDays, stale: ageDays > MAX_BACKUP_AGE_DAYS, - ciphertextBytes: ciphertext.length, - plaintextBytes, - innerKeyIds: keyVerdict.keyIds, - recordCounts: { - measurements: streamedCounts.measurements, - medications: countArray(payload.medications), - intakeEvents: streamedCounts.intakeEvents ?? 0, - moodEntries: streamedCounts.moodEntries ?? 0, - }, + accounts, + failed: accounts.filter((a) => !a.ok), }; } @@ -203,48 +256,65 @@ export async function handleRestoreDrill( return withBackgroundEvent("job.restore_drill", async (evt) => { try { const report = await runRestoreDrill(); - evt.addMeta("restore_drill_object_key", report.objectKey); - evt.addMeta("restore_drill_age_days", report.ageDays); - evt.addMeta("restore_drill_ciphertext_bytes", report.ciphertextBytes); - evt.addMeta("restore_drill_plaintext_bytes", report.plaintextBytes); + const total = (pick: (a: RestoreDrillAccount) => number) => + report.accounts.reduce((sum, a) => sum + pick(a), 0); + const meta = { + restore_drill_date: report.dateKey, + restore_drill_age_days: report.ageDays, + restore_drill_accounts: report.accounts.length, + restore_drill_accounts_failed: report.failed.length, + restore_drill_ciphertext_bytes: total((a) => a.ciphertextBytes), + restore_drill_plaintext_bytes: total((a) => a.plaintextBytes), + restore_drill_measurements: total((a) => a.recordCounts.measurements), + restore_drill_medications: total((a) => a.recordCounts.medications), + restore_drill_intake_events: total((a) => a.recordCounts.intakeEvents), + restore_drill_mood_entries: total((a) => a.recordCounts.moodEntries), + restore_drill_stale: report.stale, + }; + for (const [key, value] of Object.entries(meta)) evt.addMeta(key, value); evt.addMeta( - "restore_drill_measurements", - report.recordCounts.measurements, + "restore_drill_inner_key_ids", + [...new Set(report.accounts.flatMap((a) => a.innerKeyIds))] + .sort() + .join(","), ); - evt.addMeta("restore_drill_medications", report.recordCounts.medications); - evt.addMeta( - "restore_drill_intake_events", - report.recordCounts.intakeEvents, - ); - evt.addMeta( - "restore_drill_mood_entries", - report.recordCounts.moodEntries, - ); - evt.addMeta("restore_drill_stale", report.stale); - evt.addMeta("restore_drill_inner_key_ids", report.innerKeyIds.join(",")); + // One page per account that did not pass, naming its object, so the + // operator sees which account it is and that the others passed. + for (const account of report.failed) { + evt.addWarning(account.error ?? `${account.objectKey} failed`); + await reportWorkerError( + RESTORE_DRILL_QUEUE, + new Error(account.error ?? `${account.objectKey} failed`), + { + objectKey: account.objectKey, + accountsChecked: report.accounts.length, + accountsFailed: report.failed.length, + }, + ); + } if (report.stale) { await reportWorkerError( RESTORE_DRILL_QUEUE, new Error( `Newest off-host backup is ${report.ageDays} days old (threshold ${MAX_BACKUP_AGE_DAYS}) — the nightly upload chain has stalled.`, ), - { objectKey: report.objectKey, ageDays: report.ageDays }, + { dateKey: report.dateKey, ageDays: report.ageDays }, + ); + } + if (report.failed.length > 0) { + // Already paged above, per account. A retry reads the same objects + // and cannot change the verdict before the next upload. + return jobFailed( + `restore drill: ${report.failed.length} of ${report.accounts.length} accounts failed`, + new Error(report.failed.map((a) => a.objectKey).join(", ")), + meta, ); } // A stale chain is a verdict about the uploader, not a failure of the - // drill: the artefact was fetched, decrypted and parsed, and the page + // drill: the artefacts were fetched, decrypted and parsed, and the page // above already reached the operator. Failing the job here would retry a // reading that cannot change until the next upload lands. - return jobDone({ - restore_drill_age_days: report.ageDays, - restore_drill_ciphertext_bytes: report.ciphertextBytes, - restore_drill_plaintext_bytes: report.plaintextBytes, - restore_drill_measurements: report.recordCounts.measurements, - restore_drill_medications: report.recordCounts.medications, - restore_drill_intake_events: report.recordCounts.intakeEvents, - restore_drill_mood_entries: report.recordCounts.moodEntries, - restore_drill_stale: report.stale, - }); + return jobDone(meta); } catch (err) { if (err instanceof OffhostBackupNotConfiguredError) { evt.addWarning(`restore-drill skipped: ${err.message}`); From d55e329c487e81eb931222de808de5c533d5e4d7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Sun, 4 Oct 2026 15:34:42 +0200 Subject: [PATCH 3/5] perf(backup): take the weekly copy's preview from the writer, not a second parse Since v1.39.6 the preview scanner parsed the JSON on its way into the pieces, kept every section but the three bulk tables, and validated the whole document at the end: a second copy of the record beside the writer's own, inside the weekly job. On an account with a document vault that is most of the record. The writer now shows each section and each bulk row to an observer just before writing it. The preview collects key uses from that and takes its counts from the writer's own FullBackupCounts; nothing is parsed or kept. An upload hands over the summary and key uses it has already validated. The round trip pins the writer's counts and key uses to a full read of the copy on an account with a row in every model, and a memory test holds what the pass keeps once the producer is done. Measured on 70,000 measurements, 3,000 mood entries and 40 one-megabyte documents under --max-old-space-size=524: held after the producer 56 MB before, 3 MB after; peak heapUsed 398 MB before, 334 MB after. --- src/app/api/admin/backups/upload/route.ts | 14 +- .../export/__tests__/backup-preview.test.ts | 80 ++++---- src/lib/export/backup-preview.ts | 187 ++++++++++-------- src/lib/export/full-backup-stream.ts | 19 +- src/lib/export/store-backup-blob.ts | 19 +- .../__tests__/backup-handlers.test.ts | 1 + src/lib/jobs/reminder/backup-handlers.ts | 20 +- .../integration/backup-preview-memory.test.ts | 183 +++++++++++++++++ tests/integration/backup-preview.test.ts | 5 +- tests/integration/backup-round-trip.test.ts | 42 +++- 10 files changed, 426 insertions(+), 144 deletions(-) create mode 100644 tests/integration/backup-preview-memory.test.ts diff --git a/src/app/api/admin/backups/upload/route.ts b/src/app/api/admin/backups/upload/route.ts index 26fea6e9e..063dbf978 100644 --- a/src/app/api/admin/backups/upload/route.ts +++ b/src/app/api/admin/backups/upload/route.ts @@ -221,6 +221,9 @@ export const POST = apiHandler(async (request: NextRequest) => { let measurementCount = 0; let owner: { id: string; username: string } | null = null; + // Filled while the file is read; the preview is the summary this route + // answers with and the key uses it already holds (`backup-preview.ts`). + const keys = new BackupKeyIdCollector(); let created: { id: string }; try { created = await storeBackupBlob( @@ -229,6 +232,16 @@ export const POST = apiHandler(async (request: NextRequest) => { userId: admin.id, type: uploadType, ownerAfterRead: () => owner!.id, + preview: () => + payload + ? { + summary: { + ...summarizeBackup(payload), + measurements: measurementCount, + }, + keys, + } + : null, }, async (write) => { // One pass: every chunk is stored as it is checked, and a check that @@ -240,7 +253,6 @@ export const POST = apiHandler(async (request: NextRequest) => { } } let firstWithoutId: number | null = null; - const keys = new BackupKeyIdCollector(); let scanned; try { scanned = await scanBackupJson(storedAsRead(), { diff --git a/src/lib/export/__tests__/backup-preview.test.ts b/src/lib/export/__tests__/backup-preview.test.ts index b22741634..688087675 100644 --- a/src/lib/export/__tests__/backup-preview.test.ts +++ b/src/lib/export/__tests__/backup-preview.test.ts @@ -1,8 +1,9 @@ /** * The preview worked out while a copy is written has to say what the preview * route used to derive by reading the stored copy: the same counts, the same - * key uses. Held here against that derivation over the same file, fed in - * pieces that split values, strings and multi-byte characters. + * key uses. Held here against that derivation over the same file; the + * integration round trip holds the writer's real counts to it on an account + * with a row in every model. */ import { afterEach, describe, expect, it } from "vitest"; @@ -14,10 +15,11 @@ import { } from "@/lib/export/backup-key-ids"; import { buildBackupPreview, - createBackupPreviewScanner, + createBackupPreviewCollector, storedCopyIdentity, storedPreviewFor, } from "@/lib/export/backup-preview"; +import type { FullBackupCounts } from "@/lib/export/full-backup-payload"; import { backupPayloadSchema, summarizeBackup } from "@/lib/validations/backup"; const ts = "2026-07-19T07:00:00.000Z"; @@ -69,52 +71,52 @@ const FILE = { ], }; -async function scan(pieces: Array) { - const scanner = createBackupPreviewScanner(); - for (const piece of pieces) await scanner.feed(piece); - return scanner.finish(); -} - -function split(text: string, size: number): Uint8Array[] { - const bytes = Buffer.from(text, "utf8"); - const out: Uint8Array[] = []; - for (let at = 0; at < bytes.length; at += size) { - out.push(bytes.subarray(at, at + size)); +/** What the weekly writer shows the collector, member by member. */ +const BULK = new Set(["measurements", "intakeEvents", "moodEntries"]); +function observeAsTheWriterDoes( + file: Record, + observe: (member: string, value: unknown) => void, +) { + for (const [member, value] of Object.entries(file)) { + if (BULK.has(member)) + for (const row of value as unknown[]) observe(member, row); + else observe(member, value); } - return out; } -describe("createBackupPreviewScanner", () => { - const json = JSON.stringify(FILE); - // What the preview route derived from a stored copy. +/** The writer's counts for FILE: every count the summary reads, and more. */ +function countsOf(file: typeof FILE): FullBackupCounts { + const summary = summarizeBackup(backupPayloadSchema.parse(file)); + const { schemaVersion, userId, exportedAt, ...counts } = summary; + void schemaVersion; + void userId; + void exportedAt; + return { ...counts, medicationPauseEras: 0 } as unknown as FullBackupCounts; +} + +describe("createBackupPreviewCollector", () => { + // What the preview route derives from a stored copy. const expected = summarizeBackup(backupPayloadSchema.parse(FILE)); const expectedKeys = new BackupKeyIdCollector(); expectedKeys.visit(FILE); - it.each([1, 7, 64, 100_000])( - "counts what the full read counts, in pieces of %i bytes", - async (size) => { - const result = await scan(split(json, size)); - expect(result).not.toBeNull(); - expect(result!.summary).toEqual(expected); - expect(result!.summary.measurements).toBe(3); - expect(result!.summary.intakeEvents).toBe(2); - expect(result!.summary.moodEntries).toBe(1); - expect(result!.summary.illnessDayLogs).toBe(2); - expect(result!.keys.toStored()).toEqual(expectedKeys.toStored()); - expect(result!.keys.keyIds()).toEqual(["v3"]); - }, - ); - - it("takes text pieces the way the weekly writer hands them over", async () => { - const result = await scan([json.slice(0, 50), json.slice(50)]); + it("says what a full read of the copy says", () => { + const collector = createBackupPreviewCollector(); + observeAsTheWriterDoes(FILE, collector.observe); + const result = collector.finish(countsOf(FILE)); + expect(result).not.toBeNull(); expect(result!.summary).toEqual(expected); + expect(result!.summary.illnessDayLogs).toBe(2); + expect(result!.keys.toStored()).toEqual(expectedKeys.toStored()); + expect(result!.keys.keyIds()).toEqual(["v3"]); }); - it("answers null for a file that is not a backup, and never holds the writer", async () => { - expect(await scan(["{ not json", "more", "and more"])).toBeNull(); - expect(await scan([JSON.stringify({ schemaVersion: 2 })])).toBeNull(); - expect(await scan([json.slice(0, 40)])).toBeNull(); + it("answers null for a copy that does not name its version, owner and date", () => { + const collector = createBackupPreviewCollector(); + const { userId, ...rest } = FILE; + void userId; + observeAsTheWriterDoes(rest, collector.observe); + expect(collector.finish(countsOf(FILE))).toBeNull(); }); }); diff --git a/src/lib/export/backup-preview.ts b/src/lib/export/backup-preview.ts index 2c6d040d9..c96be0554 100644 --- a/src/lib/export/backup-preview.ts +++ b/src/lib/export/backup-preview.ts @@ -7,7 +7,12 @@ * For an account of 1.8 million readings on slow hardware that took two * minutes, the dialog gave up long before, and the operator was told the * contents could not be read (#1031). The copy passes through this process - * once anyway, on its way into the pieces, so the counts are taken there. + * once anyway, on its way into the pieces, so the counts are taken there: + * the weekly copy's from its writer's own counts and the sections it is + * about to write, an upload's from the file the upload route has already + * validated. Neither parses the copy a second time; the v1.39.6 scanner that + * did kept every section but the bulk tables parsed beside the writer's own, + * a second copy of the record inside the weekly job. * * What is kept. The `summarizeBackup` counts of the copy, its schema version, * and the inner key ids with the sections they sit in and the shortest @@ -28,13 +33,9 @@ import { BackupKeyIdCollector, type StoredKeyUse, } from "@/lib/export/backup-key-ids"; -import { scanBackupJson } from "@/lib/export/backup-json-scan"; +import type { FullBackupCounts } from "@/lib/export/full-backup-payload"; import type { StoredBackupRef } from "@/lib/export/stored-backup"; -import { - backupPayloadSchema, - summarizeBackup, - type BackupSummary, -} from "@/lib/validations/backup"; +import type { BackupSummary } from "@/lib/validations/backup"; export interface BackupPreview { version: 1; @@ -138,98 +139,112 @@ export function storedPreviewFor( } /** - * The sections that grow with a record. Their elements are counted and their - * key ids read as they pass, and never kept, so the scan holds no more of the - * copy than the writer itself does (`full-backup-stream.ts`). + * The summary fields that are counts, each also counted by the writer + * (`FullBackupCounts`). The type below fails to compile when the summary + * gains a count the writer does not report. */ -const STREAMED = new Set(["measurements", "intakeEvents", "moodEntries"]); +const SUMMARY_COUNTS = [ + "measurements", + "medications", + "intakeEvents", + "medicationSideEffects", + "medicationEfficacyTargets", + "medicationScheduleRevisions", + "moodEntries", + "cycles", + "cycleDayLogs", + "labResults", + "nutrientDays", + "biomarkers", + "illnessEpisodes", + "illnessDayLogs", + "allergies", + "familyHistory", + "workouts", + "documents", + "documentConditionLinks", + "extractedFacts", + "healthProfile", + "healthProfileFactRevisions", + "customMetrics", + "customMetricEntries", + "correlationPatterns", + "intradayProfiles", + "healthScoreRecords", + "onboardingRecords", + "practitioners", + "encounters", + "encounterLinks", + "vaccinations", + "vaccinationLinks", + "measurementReminders", + "measurementReminderEvents", + "coachConversations", + "coachMessages", + "coachFacts", + "coachPlans", + "coachReminders", + "mentalHealthAssessments", + "consentReceipts", + "personalRecords", + "userAchievements", + "environmentContexts", + "environmentTravelLocations", + "ecgRecordings", +] as const satisfies readonly (keyof BackupSummary & keyof FullBackupCounts)[]; -export interface BackupPreviewScanner { +type UncountedSummaryField = Exclude< + keyof BackupSummary, + (typeof SUMMARY_COUNTS)[number] | "schemaVersion" | "userId" | "exportedAt" +>; +const everySummaryCountIsCounted: [UncountedSummaryField] extends [never] + ? true + : UncountedSummaryField = true; +void everySummaryCountIsCounted; + +export interface BackupPreviewCollector { + /** Pass as `observe` to `streamFullBackupJson`. */ + observe(member: string, value: unknown): void; /** - * Hand over the next piece of the JSON. Resolves once the scan has taken - * it, so a writer never runs more than a piece ahead of the scan. + * The counts and key uses, once the writer has finished; null when the + * copy did not name its schema version, owner and date. */ - feed(piece: string | Uint8Array): Promise; - /** - * The counts and key uses, once every piece has been fed; null when the - * JSON was not a backup the schema accepts. Never rejects: a copy is - * stored whether or not its preview could be worked out. - */ - finish(): Promise<{ + finish(counts: FullBackupCounts): { summary: BackupSummary; keys: BackupKeyIdCollector; - } | null>; + } | null; } /** - * Work out a preview from a copy's JSON as it is written. The counts are the - * ones the preview route derives from the stored copy (`summarizeBackup` over - * the parsed file), the three bulk sections counted rather than parsed. + * Work out a weekly copy's preview from what its writer already has in hand: + * each section as it is written, for the key uses, and the writer's own + * counts. Nothing is parsed and nothing is kept but the key samples, so the + * preview costs the pass no memory that grows with the record. */ -export function createBackupPreviewScanner(): BackupPreviewScanner { - const queue: Array<{ chunk: Uint8Array; taken: () => void }> = []; - let ended = false; - let stopped = false; - let wake: (() => void) | null = null; - const signal = () => { - const w = wake; - wake = null; - w?.(); - }; - - async function* pieces(): AsyncGenerator { - for (;;) { - const next = queue.shift(); - if (next) { - next.taken(); - yield next.chunk; - continue; - } - if (ended) return; - await new Promise((resolve) => { - wake = resolve; - }); - } - } - +export function createBackupPreviewCollector(): BackupPreviewCollector { const keys = new BackupKeyIdCollector(); - const result = scanBackupJson(pieces(), { - streamKeys: STREAMED, - onElement: (key, element) => keys.visit(element, key), - }) - .then(({ document, streamedCounts }) => { - keys.visit(document); - const parsed = backupPayloadSchema.safeParse(document); - if (!parsed.success) return null; - const summary: BackupSummary = { - ...summarizeBackup(parsed.data), - measurements: streamedCounts.measurements ?? 0, - intakeEvents: streamedCounts.intakeEvents ?? 0, - moodEntries: streamedCounts.moodEntries ?? 0, - }; - return { summary, keys }; - }) - .catch(() => null) - .finally(() => { - // A scan that stopped early takes nothing more: release the writer. - stopped = true; - for (const waiting of queue.splice(0)) waiting.taken(); - }); - + const header: Partial< + Record<"schemaVersion" | "userId" | "exportedAt", string> + > = {}; return { - feed(piece) { - if (stopped) return Promise.resolve(); - const chunk = - typeof piece === "string" ? Buffer.from(piece, "utf8") : piece; - return new Promise((taken) => { - queue.push({ chunk, taken }); - signal(); - }); + observe(member, value) { + if ( + (member === "schemaVersion" || + member === "userId" || + member === "exportedAt") && + typeof value === "string" + ) { + header[member] = value; + return; + } + keys.visit(value, member); }, - finish() { - ended = true; - signal(); - return result; + finish(counts) { + const { schemaVersion, userId, exportedAt } = header; + if (!schemaVersion || !userId || !exportedAt) return null; + const summary = { schemaVersion, userId, exportedAt } as BackupSummary; + for (const field of SUMMARY_COUNTS) summary[field] = counts[field]; + return { summary, keys }; }, }; } diff --git a/src/lib/export/full-backup-stream.ts b/src/lib/export/full-backup-stream.ts index a73e5f29c..6db5689f7 100644 --- a/src/lib/export/full-backup-stream.ts +++ b/src/lib/export/full-backup-stream.ts @@ -79,14 +79,27 @@ const PROGRESS_EVERY_ROWS = 50_000; * The counts for the three deferred tables are filled in as their rows go * past, so a caller gets the same numbers the materialising builder reports. */ +export interface StreamFullBackupOptions extends FullBackupOptions { + /** + * Shown each top-level member's value just before it is written, and each + * row of the three bulk tables as it passes, under the member's name. For + * a reader that needs to see the copy as it is written (the stored copy's + * preview, `backup-preview.ts`) without parsing the JSON a second time. + * It must not keep what it is shown: the writer releases each section as + * soon as it is written, and that is what bounds its memory. + */ + observe?: (member: string, value: unknown) => void; +} + export async function streamFullBackupJson( prisma: PrismaClient, userId: string, sink: BackupJsonSink, - options: FullBackupOptions = {}, + options: StreamFullBackupOptions = {}, ): Promise { + const { observe, ...payloadOptions } = options; const { payload, counts } = await buildFullBackupPayload(prisma, userId, { - ...options, + ...payloadOptions, deferBulk: true, }); @@ -126,6 +139,7 @@ export async function streamFullBackupJson( await write("["); let rows = 0; for await (const row of value.rows()) { + observe?.(key, row); await write( rows === 0 ? JSON.stringify(row) : `,${JSON.stringify(row)}`, ); @@ -137,6 +151,7 @@ export async function streamFullBackupJson( await write("]"); bulkCounts[key] = rows; } else { + observe?.(key, value); await write(JSON.stringify(value)); } delete payload[key]; diff --git a/src/lib/export/store-backup-blob.ts b/src/lib/export/store-backup-blob.ts index 925b0445a..2b9fe6a11 100644 --- a/src/lib/export/store-backup-blob.ts +++ b/src/lib/export/store-backup-blob.ts @@ -35,9 +35,9 @@ import { type PackBackupOptions, } from "@/lib/export/backup-blob"; import { createBackupKeyIdTextScanner } from "@/lib/export/backup-key-ids"; +import type { BackupKeyIdCollector } from "@/lib/export/backup-key-ids"; import { buildBackupPreview, - createBackupPreviewScanner, SINGLE_VALUE_IDENTITY_HEAD, singleValueIdentity, storedCopyIdentity, @@ -48,6 +48,7 @@ import { newChunkStreamId, } from "@/lib/export/backup-chunks"; import { BackupFormsConflictError } from "@/lib/export/stored-backup"; +import type { BackupSummary } from "@/lib/validations/backup"; /** * How long the storing transaction may stay open. The job around it expires @@ -79,6 +80,16 @@ export interface StoreBackupBlobInput { * the row under the wrong owner. */ ownerAfterRead?: () => string; + /** + * What the restore preview shows for the copy, asked once the producer has + * finished (`backup-preview.ts`): the producer knows the counts and the + * key uses without reading the copy back. Null, or absent, leaves the row + * without a preview, and the preview route reads the copy once instead. + */ + preview?: () => { + summary: BackupSummary; + keys: BackupKeyIdCollector; + } | null; } type Tx = Parameters[0]>[0]; @@ -126,9 +137,6 @@ export async function storeBackupBlob( // what is inside them, so this is what tells an operator how long a // retired key is still needed (`GET /api/admin/encryption/status`). const keyScanner = createBackupKeyIdTextScanner(); - // And what the restore preview shows, from the same pass, so the - // preview never has to read the copy back (`backup-preview.ts`). - const previewScanner = createBackupPreviewScanner(); const { chunks, bytes } = await packBackupChunks( async (sealed, seq) => { await tx.dataBackupChunk.create({ @@ -140,12 +148,11 @@ export async function storeBackupBlob( (write) => producer(async (chunk) => { keyScanner.feed(chunk); - await previewScanner.feed(chunk); await write(chunk); }), options, ); - const scanned = await previewScanner.finish(); + const scanned = input.preview?.() ?? null; // Again at the end: a restore may have been queued while this ran. The // window left is the few milliseconds to the commit, and a restore diff --git a/src/lib/jobs/reminder/__tests__/backup-handlers.test.ts b/src/lib/jobs/reminder/__tests__/backup-handlers.test.ts index 30b92dca3..0a6b52844 100644 --- a/src/lib/jobs/reminder/__tests__/backup-handlers.test.ts +++ b/src/lib/jobs/reminder/__tests__/backup-handlers.test.ts @@ -121,6 +121,7 @@ describe("handleDataBackup canonical DR payload", () => { expect(mocks.store.mock.calls[0]![0]).toEqual({ userId: "user-dr", type: "WEEKLY_AUTO", + preview: expect.any(Function), }); const encrypted = mocks.store.mock.calls[0]![1] as string; const payload = JSON.parse(encrypted) as { diff --git a/src/lib/jobs/reminder/backup-handlers.ts b/src/lib/jobs/reminder/backup-handlers.ts index f02714de6..67a4a0371 100644 --- a/src/lib/jobs/reminder/backup-handlers.ts +++ b/src/lib/jobs/reminder/backup-handlers.ts @@ -12,6 +12,8 @@ import { BackupBusyError, } from "@/lib/export/backup-blob"; import { storeBackupBlob } from "@/lib/export/store-backup-blob"; +import { createBackupPreviewCollector } from "@/lib/export/backup-preview"; +import type { FullBackupCounts } from "@/lib/export/full-backup-payload"; import { streamFullBackupJson } from "@/lib/export/full-backup-stream"; import { jobDone, jobFailed, type JobOutcome } from "@/lib/jobs/job-outcome"; import { withBackgroundEvent } from "@/lib/logging/background"; @@ -182,13 +184,23 @@ export async function handleDataBackup( // time, and gzip's output is sealed and stored in pieces of about a // megabyte (`storeBackupBlob`). The copy is kept as those pieces, // so its size does not depend on this process's memory (#1031). + // The restore preview is taken from the writer's own counts and + // the sections as they are written, never by parsing the copy. + const preview = createBackupPreviewCollector(); + let counts: FullBackupCounts | undefined; const { bytes: storedBytes } = await storeBackupBlob( prisma, - { userId: user.id, type: "WEEKLY_AUTO" }, - (write) => - streamFullBackupJson(prisma, user.id, write, { + { + userId: user.id, + type: "WEEKLY_AUTO", + preview: () => (counts ? preview.finish(counts) : null), + }, + async (write) => { + counts = await streamFullBackupJson(prisma, user.id, write, { purpose: "disaster-recovery", - }), + observe: preview.observe, + }); + }, ); largestBlobBytes = Math.max(largestBlobBytes, storedBytes); backed++; diff --git a/tests/integration/backup-preview-memory.test.ts b/tests/integration/backup-preview-memory.test.ts new file mode 100644 index 000000000..fbe8eb6f6 --- /dev/null +++ b/tests/integration/backup-preview-memory.test.ts @@ -0,0 +1,183 @@ +/** + * The preview a weekly copy carries is worked out from the counts the writer + * already produces, not by parsing the copy a second time. + * + * What this pins. From v1.39.6 the preview scanner parsed the JSON on its way + * into the pieces, kept every section that is not one of the three bulk tables + * (documents with their ciphertext, coach turns, profiles), and validated the + * whole document at the end. On an account with a document vault that is a + * second full copy of the record beside the writer's own, inside the weekly + * job that shares the app's heap. + * + * How it measures. Like `backup-streaming-memory.test.ts`: every reading is + * taken after a forced collection, so what is compared is what the pass + * HOLDS. The reading at the end of the producer is the one that matters: the + * writer has released its sections by then, so anything still held belongs + * to the preview. Run under `--max-old-space-size=524` (the V8 limit of a + * 1 GB container) for the production ceiling. + */ +import { randomBytes } from "node:crypto"; +import v8 from "node:v8"; +import vm from "node:vm"; + +import { afterAll, beforeAll, describe, expect, it } from "vitest"; + +import { createBackupPreviewCollector } from "@/lib/export/backup-preview"; +import type { FullBackupCounts } from "@/lib/export/full-backup-payload"; +import { storeBackupBlob } from "@/lib/export/store-backup-blob"; +import { streamFullBackupJson } from "@/lib/export/full-backup-stream"; +import { getPrismaClient, truncateAllTables } from "./setup"; + +const OWNER_ID = "backup-preview-memory-owner"; +const MEASUREMENT_ROWS = 70_000; +const MOOD_ROWS = 3_000; +const DOCUMENTS = 40; +const DOCUMENT_BYTES = 1024 * 1024; + +/** + * What the pass may still hold once the producer is done. Measured: the + * scanner that kept the sections held about twice the document vault at + * that point (the parsed sections and the base64 text inside them); the + * pass without it holds a few megabytes. + */ +const HELD_AT_END_BUDGET_BYTES = 16 * 1024 * 1024; + +const prisma = getPrismaClient(); + +const forceGc = ((): (() => void) => { + v8.setFlagsFromString("--expose-gc"); + const gc = vm.runInNewContext("gc") as () => void; + v8.setFlagsFromString("--no-expose-gc"); + return gc; +})(); + +function liveHeapBytes(): number { + forceGc(); + forceGc(); + return process.memoryUsage().heapUsed; +} + +const mb = (bytes: number): number => Math.round(bytes / 1024 / 1024); + +async function seed(): Promise { + await prisma.user.create({ + data: { id: OWNER_ID, username: "backup-preview-memory" }, + }); + await prisma.$executeRawUnsafe( + `INSERT INTO measurements ( + id, user_id, type, value, unit, source, measured_at, notes, + notes_encrypted, external_id, created_at, updated_at, sync_version) + SELECT + 'pm' || lpad(g::text, 10, '0'), $1, 'PULSE'::measurement_type, + 60 + (g % 40), 'bpm', 'APPLE_HEALTH'::measurement_source, + timestamp '2019-01-01 00:00:00' + (g * interval '30 seconds'), + CASE WHEN g % 40 = 0 THEN 'a note recorded with reading ' || g END, + CASE WHEN g % 25 = 0 + THEN decode(md5(g::text) || md5((g + 1)::text), 'hex') END, + 'preview-' || g, + timestamp '2019-01-01 00:00:00' + (g * interval '30 seconds'), + timestamp '2019-01-01 00:00:00' + (g * interval '30 seconds'), + 1 + FROM generate_series(1, ${MEASUREMENT_ROWS}) AS g`, + OWNER_ID, + ); + await prisma.$executeRawUnsafe( + `INSERT INTO mood_entries ( + id, user_id, date, mood, score, source, mood_logged_at, synced_at, + created_at, updated_at, tz, note, sync_version) + SELECT + 'pd' || lpad(g::text, 10, '0'), $1, + to_char(timestamp '2019-01-01' + (g * interval '1 day'), 'YYYY-MM-DD'), + 'okay', 3, 'MOODLOG', timestamp '2019-01-01' + (g * interval '1 day'), + now(), now(), now(), 'Europe/Berlin', 'a journal line about day ' || g, 1 + FROM generate_series(1, ${MOOD_ROWS}) AS g`, + OWNER_ID, + ); + for (let i = 0; i < DOCUMENTS; i++) { + await prisma.inboundDocument.create({ + data: { + userId: OWNER_ID, + mimeType: "application/pdf", + byteSize: DOCUMENT_BYTES, + contentEncrypted: new Uint8Array(randomBytes(DOCUMENT_BYTES)), + contentCodec: "binary2", + title: `document ${i}`, + }, + }); + } +} + +describe("weekly copy preview under a memory budget", () => { + beforeAll(async () => { + await truncateAllTables(prisma); + await seed(); + }, 240_000); + + afterAll(async () => { + await truncateAllTables(prisma); + }); + + it("holds nothing of the record once the producer is done", async () => { + const baseline = liveHeapBytes(); + let peakHeld = 0; + let heldAtEnd = 0; + let rawPeak = 0; + let chunks = 0; + const poll = setInterval(() => { + rawPeak = Math.max(rawPeak, process.memoryUsage().heapUsed); + }, 5); + // Wired exactly as the weekly job wires it (`backup-handlers.ts`). + const preview = createBackupPreviewCollector(); + let counts: FullBackupCounts | undefined; + try { + await storeBackupBlob( + prisma, + { + userId: OWNER_ID, + type: "WEEKLY_AUTO", + preview: () => (counts ? preview.finish(counts) : null), + }, + async (write) => { + counts = await streamFullBackupJson( + prisma, + OWNER_ID, + async (chunk) => { + await write(chunk); + if (chunks++ % 40 === 0) { + peakHeld = Math.max(peakHeld, liveHeapBytes() - baseline); + } + }, + { purpose: "disaster-recovery", observe: preview.observe }, + ); + heldAtEnd = liveHeapBytes() - baseline; + peakHeld = Math.max(peakHeld, heldAtEnd); + }, + ); + } finally { + clearInterval(poll); + } + rawPeak = Math.max(rawPeak, process.memoryUsage().heapUsed); + process.stderr.write( + `[preview-memory] held at end of producer ${mb(heldAtEnd)} MB, ` + + `peak held ${mb(peakHeld)} MB, raw peak heapUsed ${mb(rawPeak)} MB ` + + `(baseline ${mb(baseline)} MB), ` + + `${mb(v8.getHeapStatistics().heap_size_limit)} MB heap limit\n`, + ); + + const row = await prisma.dataBackup.findFirstOrThrow({ + where: { userId: OWNER_ID, type: "WEEKLY_AUTO" }, + select: { preview: true }, + }); + expect(row.preview).toMatchObject({ + summary: { + measurements: MEASUREMENT_ROWS, + moodEntries: MOOD_ROWS, + documents: DOCUMENTS, + }, + }); + expect( + heldAtEnd, + `the pass still held ${mb(heldAtEnd)} MB after the producer finished`, + ).toBeLessThan(HELD_AT_END_BUDGET_BYTES); + }, 600_000); +}); diff --git a/tests/integration/backup-preview.test.ts b/tests/integration/backup-preview.test.ts index cd2337422..1c99aa0e9 100644 --- a/tests/integration/backup-preview.test.ts +++ b/tests/integration/backup-preview.test.ts @@ -9,8 +9,9 @@ * and its preview kept; a key dropped after the copy was written is still * named, because the verdict is taken again at every read. * - * Mutations that must turn this red: drop the preview scanner from - * `storeBackupBlob` (no preview on the row, the route opens the copy), or + * Mutations that must turn this red: drop the `preview` the weekly job or + * the upload route hands `storeBackupBlob` (no preview on the row, the route + * opens the copy), or * answer from the stored verdict instead of taking it again (the dropped key * is not named). */ diff --git a/tests/integration/backup-round-trip.test.ts b/tests/integration/backup-round-trip.test.ts index cd3018e99..6314593f5 100644 --- a/tests/integration/backup-round-trip.test.ts +++ b/tests/integration/backup-round-trip.test.ts @@ -78,6 +78,8 @@ import { import { legacyStreamedBlobFrom } from "@/__tests__/helpers/legacy-backup-blob"; import { streamFullBackupJson } from "@/lib/export/full-backup-stream"; import { BackupKeyIdCollector } from "@/lib/export/backup-key-ids"; +import { createBackupPreviewCollector } from "@/lib/export/backup-preview"; +import { parseBackupPayload, summarizeBackup } from "@/lib/validations/backup"; import { TWO_ENDED_MODELS, USER_COLUMN_BACKUP_CLASS, @@ -1492,13 +1494,18 @@ describe("every model the plan claims two-ended survives a real restore", () => // below then covers BOTH, since the row that gets restored comes from the // streamed bytes. let streamedJson = ""; - await streamFullBackupJson( + const previewCollector = createBackupPreviewCollector(); + const streamedCounts = await streamFullBackupJson( prisma, OWNER_ID, (chunk) => { streamedJson += chunk; }, - { purpose: "disaster-recovery", exportedAt }, + { + purpose: "disaster-recovery", + exportedAt, + observe: previewCollector.observe, + }, ); expect( streamedJson, @@ -1506,6 +1513,20 @@ describe("every model the plan claims two-ended survives a real restore", () => "weekly backup no longer contains what this test proves restorable", ).toBe(JSON.stringify(payload)); + // The weekly copy's restore preview is taken from the writer's counts and + // the sections it was shown, never by reading the copy. On an account + // with a row in every model, it has to say what a full read of the copy + // says, count for count and key use for key use. + const fromWriter = previewCollector.finish(streamedCounts); + expect(fromWriter).not.toBeNull(); + expect( + fromWriter!.summary, + "the preview taken from the writer's counts disagrees with a full read", + ).toEqual(summarizeBackup(parseBackupPayload(streamedJson))); + const readBack = new BackupKeyIdCollector(); + readBack.visit(JSON.parse(streamedJson)); + expect(fromWriter!.keys.toStored()).toEqual(readBack.toStored()); + // The tombstone has to be IN the file. A disaster-recovery payload that // carries only live rows is smaller and cheaper and wrong: the restore // wipes the account first, so a deletion that is not in the file is a @@ -3757,13 +3778,26 @@ describe("every column of every two-ended model survives a real restore", () => const exportedAt = new Date("2026-08-01T00:00:00.000Z"); let json = ""; - await streamFullBackupJson( + const previewCollector = createBackupPreviewCollector(); + const counts = await streamFullBackupJson( prisma, OWNER_ID, (chunk) => { json += chunk; }, - { purpose: "disaster-recovery", exportedAt }, + { + purpose: "disaster-recovery", + exportedAt, + observe: previewCollector.observe, + }, + ); + // Every sealed column is filled here: the key uses the preview takes from + // the sections as they are written are the ones a read of the file finds. + const keysReadBack = new BackupKeyIdCollector(); + keysReadBack.visit(JSON.parse(json)); + expect(keysReadBack.keyIds().length).toBeGreaterThan(0); + expect(previewCollector.finish(counts)!.keys.toStored()).toEqual( + keysReadBack.toStored(), ); // ── No ciphertext in a portable file ────────────────────────────────── From f18e6ed34b680cf99ec7e58f4024e2b0d9515712 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Sun, 4 Oct 2026 15:49:25 +0200 Subject: [PATCH 4/5] fix(backup): notice a backup run the process died under, and take its account last A weekly or nightly backup job whose process died (a restart, a container out of memory) stayed active until its two- or four-hour expiry, and its retry walked the accounts in the same order: the account that killed it has the oldest copy, so it led again, and every account after it went without a copy for as long as that record stayed too large. Both passes now send with a five-minute pg-boss heartbeat, so a dead run fails within minutes and its retry picks it up. Each pass records when it started and finished every account (backup_pass_attempts, migration 0373); an account whose last attempt never finished goes behind all the others. The backups page shows when the run in progress started and names an account a run died under, for the weekly and the off-host card, and a heartbeat timeout reads as what it means. --- docs/ops/backup-restore.md | 16 ++ messages/de.json | 6 + messages/en.json | 6 + messages/es.json | 6 + messages/fr.json | 6 + messages/it.json | 6 + messages/ko.json | 6 + messages/pl.json | 6 + .../0373_backup_pass_attempts/migration.sql | 19 +++ prisma/schema.prisma | 29 +++- .../api/admin/backups/__tests__/route.test.ts | 59 +++++++ src/app/api/admin/backups/route.ts | 17 +- .../offhost-backups-section.test.tsx | 24 +++ src/components/admin/backup-pass-activity.tsx | 78 ++++++++++ src/components/admin/backups-section.tsx | 4 + .../admin/offhost-backups-section.tsx | 2 + src/lib/data-wipe/wipe-plan.ts | 3 + src/lib/export/backup-plan.ts | 2 + .../__tests__/data-backup-send-policy.test.ts | 24 ++- .../__tests__/job-failures-heartbeat.test.ts | 45 ++++++ src/lib/jobs/__tests__/offhost-backup.test.ts | 43 ++++++ src/lib/jobs/backup-pass-attempts.ts | 145 ++++++++++++++++++ src/lib/jobs/data-backup-policy.ts | 16 ++ src/lib/jobs/job-failures.ts | 34 ++++ src/lib/jobs/offhost-backup.ts | 44 +++++- src/lib/jobs/queue-runtime.ts | 2 +- .../__tests__/backup-handlers.test.ts | 45 ++++++ src/lib/jobs/reminder/backup-handlers.ts | 31 +++- src/lib/jobs/reminder/register-maintenance.ts | 12 +- src/types/backups.ts | 8 + tests/integration/backup-preview.test.ts | 9 ++ 31 files changed, 734 insertions(+), 19 deletions(-) create mode 100644 prisma/migrations/0373_backup_pass_attempts/migration.sql create mode 100644 src/components/admin/backup-pass-activity.tsx create mode 100644 src/lib/jobs/__tests__/job-failures-heartbeat.test.ts create mode 100644 src/lib/jobs/backup-pass-attempts.ts diff --git a/docs/ops/backup-restore.md b/docs/ops/backup-restore.md index ea7ce290c..080fb19ae 100644 --- a/docs/ops/backup-restore.md +++ b/docs/ops/backup-restore.md @@ -252,6 +252,22 @@ A run where SOME account got a copy still succeeds, with the rest counted in `offhost_backup_failed`. Failing the whole queue over one account's object would re-upload everybody's on every retry. +### A run the process died under + +Both backup jobs carry a pg-boss heartbeat of five minutes. While a run is +alive the worker refreshes it; a run whose process died (a restart, or a +container killed for memory) stops refreshing, and pg-boss fails the job with +`job heartbeat timeout` within minutes instead of leaving it `active` until its +two- or four-hour expiry. The retries the queue already allows then pick it up. + +Each pass also notes when it started and when it got past every account +(`backup_pass_attempts`). An account whose last attempt started and never +finished is the one the process died under, and the next run takes it last, so +one record too large for the container cannot keep every account after it from +a copy. **Admin console → Backups** shows when the run in progress started and +names such an account under both the weekly and the off-host card. Seeing the +same account there twice means it needs more memory than the container has. + ### Which account has no copy The counts above say how many accounts were uploaded, never which. An account diff --git a/messages/de.json b/messages/de.json index a2fc2f7b9..1330cabab 100644 --- a/messages/de.json +++ b/messages/de.json @@ -7436,6 +7436,12 @@ "scheduleFailedDescription": "{when}: {reason}", "scheduleFailedNoReason": "kein Grund aufgezeichnet", "scheduleRemedy": "Starte jetzt eine Sicherung und prüfe, ob eine frische Zeile erscheint. Schlägt sie erneut fehl, nennt das Worker-Protokoll das Konto, an dem sie stehen geblieben ist.", + "activity": { + "running": "Läuft seit {when}.", + "interruptedTitle": "Ein Lauf ist mittendrin abgebrochen und nicht zurückgekehrt", + "interruptedAccount": "{username}: begonnen {when}, nie beendet", + "interruptedRemedy": "Wahrscheinlich wurde die App neu gestartet oder ihr ging beim Schreiben dieser Kopie der Speicher aus. Der nächste Lauf nimmt diese Konten zuletzt, damit alle anderen zuerst ihre Kopie bekommen. Passiert es wieder, gib dem Container mehr Speicher." + }, "download": "Herunterladen", "downloadAria": "Backup für {username} herunterladen", "downloadFailed": "Download fehlgeschlagen", diff --git a/messages/en.json b/messages/en.json index a39eec3e0..542d5ad0e 100644 --- a/messages/en.json +++ b/messages/en.json @@ -7436,6 +7436,12 @@ "scheduleFailedDescription": "{when}: {reason}", "scheduleFailedNoReason": "no reason recorded", "scheduleRemedy": "Run a backup now and check that a fresh row appears. If it fails again, the worker log names the account it stopped on.", + "activity": { + "running": "Running since {when}.", + "interruptedTitle": "A run stopped partway and never came back", + "interruptedAccount": "{username}: started {when}, never finished", + "interruptedRemedy": "The app most likely restarted or ran out of memory while writing this copy. The next run takes these accounts last, so every other account gets its copy first. If it keeps happening, give the container more memory." + }, "download": "Download", "downloadAria": "Download backup for {username}", "downloadFailed": "Download failed", diff --git a/messages/es.json b/messages/es.json index 75868f64a..4baf7ce24 100644 --- a/messages/es.json +++ b/messages/es.json @@ -7436,6 +7436,12 @@ "scheduleFailedDescription": "{when}: {reason}", "scheduleFailedNoReason": "sin motivo registrado", "scheduleRemedy": "Ejecuta una copia ahora y comprueba que aparece una fila nueva. Si vuelve a fallar, el registro del worker indica la cuenta en la que se detuvo.", + "activity": { + "running": "En curso desde {when}.", + "interruptedTitle": "Una ejecución se detuvo a medias y no volvió", + "interruptedAccount": "{username}: empezó {when}, nunca terminó", + "interruptedRemedy": "Lo más probable es que la aplicación se reiniciara o se quedara sin memoria al escribir esta copia. La próxima ejecución deja estas cuentas para el final, así las demás reciben su copia primero. Si se repite, dale más memoria al contenedor." + }, "download": "Descargar", "downloadAria": "Descargar copia de seguridad de {username}", "downloadFailed": "La descarga falló", diff --git a/messages/fr.json b/messages/fr.json index 8eb78b68a..23a8be811 100644 --- a/messages/fr.json +++ b/messages/fr.json @@ -7436,6 +7436,12 @@ "scheduleFailedDescription": "{when} : {reason}", "scheduleFailedNoReason": "aucune raison enregistrée", "scheduleRemedy": "Lancez une sauvegarde maintenant et vérifiez qu'une nouvelle ligne apparaît. Si elle échoue à nouveau, le journal du worker indique le compte sur lequel elle s'est arrêtée.", + "activity": { + "running": "En cours depuis {when}.", + "interruptedTitle": "Une exécution s'est arrêtée en cours de route sans reprendre", + "interruptedAccount": "{username} : commencée {when}, jamais terminée", + "interruptedRemedy": "L'application a très probablement redémarré ou manqué de mémoire pendant l'écriture de cette copie. La prochaine exécution traite ces comptes en dernier, afin que tous les autres reçoivent leur copie d'abord. Si cela se reproduit, donnez plus de mémoire au conteneur." + }, "download": "Télécharger", "downloadAria": "Télécharger la sauvegarde de {username}", "downloadFailed": "Échec du téléchargement", diff --git a/messages/it.json b/messages/it.json index 8461fd0ab..acfd85e1e 100644 --- a/messages/it.json +++ b/messages/it.json @@ -7436,6 +7436,12 @@ "scheduleFailedDescription": "{when}: {reason}", "scheduleFailedNoReason": "nessun motivo registrato", "scheduleRemedy": "Avvia subito un backup e verifica che compaia una riga nuova. Se fallisce di nuovo, il log del worker indica l'account su cui si è fermato.", + "activity": { + "running": "In corso dal {when}.", + "interruptedTitle": "Un'esecuzione si è interrotta a metà e non è più ripartita", + "interruptedAccount": "{username}: iniziata {when}, mai terminata", + "interruptedRemedy": "Molto probabilmente l'app si è riavviata o ha esaurito la memoria mentre scriveva questa copia. La prossima esecuzione prende questi account per ultimi, così tutti gli altri ricevono prima la loro copia. Se succede di nuovo, assegna più memoria al container." + }, "download": "Scarica", "downloadAria": "Scarica il backup di {username}", "downloadFailed": "Download non riuscito", diff --git a/messages/ko.json b/messages/ko.json index 1857e9ad4..179978987 100644 --- a/messages/ko.json +++ b/messages/ko.json @@ -7415,6 +7415,12 @@ "scheduleFailedDescription": "{when}: {reason}", "scheduleFailedNoReason": "기록된 사유 없음", "scheduleRemedy": "지금 백업을 실행하고 새 항목이 나타나는지 확인하세요. 다시 실패하면 워커 로그에 중단된 계정이 표시됩니다.", + "activity": { + "running": "{when}부터 실행 중입니다.", + "interruptedTitle": "실행이 도중에 멈추고 다시 돌아오지 않았습니다", + "interruptedAccount": "{username}: {when}에 시작, 끝나지 않음", + "interruptedRemedy": "이 사본을 쓰는 동안 앱이 다시 시작되었거나 메모리가 부족했을 가능성이 큽니다. 다음 실행은 이 계정들을 마지막에 처리하므로 다른 계정이 먼저 사본을 받습니다. 계속 반복되면 컨테이너에 메모리를 더 할당하세요." + }, "download": "다운로드", "downloadAria": "{username}의 백업 다운로드", "downloadFailed": "다운로드하지 못했어요", diff --git a/messages/pl.json b/messages/pl.json index fb7f39017..3473223dd 100644 --- a/messages/pl.json +++ b/messages/pl.json @@ -7436,6 +7436,12 @@ "scheduleFailedDescription": "{when}: {reason}", "scheduleFailedNoReason": "nie zapisano przyczyny", "scheduleRemedy": "Uruchom kopię teraz i sprawdź, czy pojawi się nowy wiersz. Jeśli znowu się nie powiedzie, log workera wskaże konto, na którym się zatrzymał.", + "activity": { + "running": "Trwa od {when}.", + "interruptedTitle": "Przebieg przerwał się w połowie i nie wrócił", + "interruptedAccount": "{username}: rozpoczęto {when}, nigdy nie zakończono", + "interruptedRemedy": "Najpewniej aplikacja uruchomiła się ponownie albo zabrakło jej pamięci podczas zapisu tej kopii. Następny przebieg weźmie te konta na końcu, aby wszystkie pozostałe dostały kopię wcześniej. Jeśli to się powtórzy, przydziel kontenerowi więcej pamięci." + }, "download": "Pobierz", "downloadAria": "Pobierz kopię zapasową dla {username}", "downloadFailed": "Pobieranie nie powiodło się", diff --git a/prisma/migrations/0373_backup_pass_attempts/migration.sql b/prisma/migrations/0373_backup_pass_attempts/migration.sql new file mode 100644 index 000000000..f40e26b3f --- /dev/null +++ b/prisma/migrations/0373_backup_pass_attempts/migration.sql @@ -0,0 +1,19 @@ +-- One row per account and backup pass, written when the pass starts the +-- account and again when it gets past it. A start newer than the finish with +-- no run active is an attempt the process died under; the pass takes that +-- account last, and the admin backups page names it. +CREATE TABLE "backup_pass_attempts" ( + "user_id" TEXT NOT NULL, + -- The pass's queue name: data-backup or data-backup-offhost. + "pass" TEXT NOT NULL, + "started_at" TIMESTAMP(3) NOT NULL, + -- NULL until the pass has once got past this account. + "finished_at" TIMESTAMP(3), + + CONSTRAINT "backup_pass_attempts_pkey" PRIMARY KEY ("user_id", "pass") +); + +ALTER TABLE "backup_pass_attempts" + ADD CONSTRAINT "backup_pass_attempts_user_id_fkey" + FOREIGN KEY ("user_id") REFERENCES "users"("id") + ON DELETE CASCADE ON UPDATE CASCADE; diff --git a/prisma/schema.prisma b/prisma/schema.prisma index 9250aef3f..cb8d0c684 100644 --- a/prisma/schema.prisma +++ b/prisma/schema.prisma @@ -765,6 +765,7 @@ model User { dataBackups DataBackup[] backupRestoreJobs BackupRestoreJob[] offhostBackupState OffhostBackupState? + backupPassAttempts BackupPassAttempt[] achievements UserAchievement[] recommendationFeedback RecommendationFeedback[] idempotencyKeys IdempotencyKey[] @@ -5160,7 +5161,7 @@ model DataBackup { /// What the restore preview shows for this copy, worked out while the copy /// was written (`src/lib/export/backup-preview.ts`): the section counts, the /// schema version, and the inner key ids with the sections they sit in and - /// one sample value each, so the key verdict is taken again against this + /// the shortest value of each section, so the key verdict is taken again against this /// server's keys every time it is read. It names the copy it describes and /// is ignored once the copy changes. Plain JSON on purpose: counts and dates /// only, and the samples are ciphertext already, which a key rotation must @@ -5335,6 +5336,32 @@ model OffhostBackupState { @@map("offhost_backup_state") } +/// Where one account stands in a backup pass that walks every account (the +/// weekly copy, `data-backup`, and the nightly off-host upload, +/// `data-backup-offhost`): when the pass last started the account and when it +/// last got past it, stored or failed in a way the pass caught. A start newer +/// than the finish, with no run of that pass active, is an attempt the +/// process died under: a restart, or a container killed for memory by a +/// record too large for it. The pass takes such an account last, so one +/// account cannot keep every account after it from a copy, and the admin +/// backups page names it. +/// Consumers: `orderInterruptedLast()` in both passes, and +/// `readBackupPassActivity()` behind `GET /api/admin/backups`. +model BackupPassAttempt { + userId String @map("user_id") + /// The pass's queue name: `data-backup` or `data-backup-offhost`. + pass String + /// When the pass last started on this account. + startedAt DateTime @map("started_at") + /// When the pass last got past it. NULL until it has once. + finishedAt DateTime? @map("finished_at") + + user User @relation(fields: [userId], references: [id], onDelete: Cascade) + + @@id([userId, pass]) + @@map("backup_pass_attempts") +} + /// Per application key id, when the nightly off-host run last put an object /// in the bucket whose inner ciphertext needed that key. The bucket's /// lifecycle rule keeps each object for its retention, so a retired key is diff --git a/src/app/api/admin/backups/__tests__/route.test.ts b/src/app/api/admin/backups/__tests__/route.test.ts index 350c4756b..25c61fb3b 100644 --- a/src/app/api/admin/backups/__tests__/route.test.ts +++ b/src/app/api/admin/backups/__tests__/route.test.ts @@ -19,16 +19,24 @@ vi.mock("@/lib/api-handler", () => ({ vi.mock("@/lib/logging/context", () => ({ annotate: vi.fn() })); +const runningSinceMock = vi.fn( + async (_queue: string): Promise => null, +); vi.mock("@/lib/jobs/job-failures", () => ({ readLastQueueRun: vi.fn(async () => null), + readQueueRunningSince: (queue: string) => runningSinceMock(queue), })); const queryRawMock = vi.fn(); const findManyMock = vi.fn(); +const attemptsMock = vi.fn(); vi.mock("@/lib/db", () => ({ prisma: { $queryRaw: (...a: unknown[]) => queryRawMock(...a), user: { findMany: (...a: unknown[]) => findManyMock(...a) }, + backupPassAttempt: { + findMany: (...a: unknown[]) => attemptsMock(...a), + }, offhostPurgeRequest: { count: async () => 2, findFirst: async () => ({ @@ -41,6 +49,7 @@ vi.mock("@/lib/db", () => ({ const configuredMock = vi.fn(() => true); vi.mock("@/lib/jobs/offhost-backup", () => ({ + OFFHOST_BACKUP_QUEUE: "data-backup-offhost", offhostBackupConfigured: () => configuredMock(), probeOffhostLifecycle: async () => ({ state: "missing", @@ -64,6 +73,8 @@ beforeEach(() => { configuredMock.mockReturnValue(true); queryRawMock.mockResolvedValue([]); findManyMock.mockResolvedValue([]); + attemptsMock.mockResolvedValue([]); + runningSinceMock.mockResolvedValue(null); }); describe("GET /api/admin/backups — off-host freshness", () => { @@ -226,3 +237,51 @@ describe("GET /api/admin/backups — off-host freshness", () => { }); }); }); + +describe("GET /api/admin/backups — a run in progress and one a process died under", () => { + it("names the account an earlier run never came back from, and says since when one runs", async () => { + const runningSince = "2026-10-04T02:00:00.000Z"; + runningSinceMock.mockImplementation(async (queue: string) => + queue === "data-backup" ? runningSince : null, + ); + findManyMock.mockResolvedValue([ + { id: "u1", username: "account-one", offhostBackupState: null }, + { id: "u2", username: "account-two", offhostBackupState: null }, + ]); + attemptsMock.mockImplementation( + async ({ where }: { where: { pass: string } }) => + where.pass === "data-backup" + ? [ + // Died under an earlier run. + { + userId: "u1", + startedAt: new Date("2026-09-27T02:10:00.000Z"), + finishedAt: new Date("2026-09-20T02:30:00.000Z"), + }, + // The account the run in progress is on now. + { + userId: "u2", + startedAt: new Date("2026-10-04T02:05:00.000Z"), + finishedAt: null, + }, + ] + : [], + ); + + const body = await read(); + expect(body.scheduleActivity).toEqual({ + runningSince, + interrupted: [ + { + userId: "u1", + username: "account-one", + startedAt: "2026-09-27T02:10:00.000Z", + }, + ], + }); + expect(body.offhost.activity).toEqual({ + runningSince: null, + interrupted: [], + }); + }); +}); diff --git a/src/app/api/admin/backups/route.ts b/src/app/api/admin/backups/route.ts index b24339aa7..4bdad82fd 100644 --- a/src/app/api/admin/backups/route.ts +++ b/src/app/api/admin/backups/route.ts @@ -25,9 +25,14 @@ import { apiHandler, requireAdmin } from "@/lib/api-handler"; import { apiSuccess } from "@/lib/api-response"; import { annotate } from "@/lib/logging/context"; import { DATA_BACKUP_QUEUE } from "@/lib/jobs/data-backup-policy"; -import { readLastQueueRun } from "@/lib/jobs/job-failures"; +import { + readLastQueueRun, + readQueueRunningSince, +} from "@/lib/jobs/job-failures"; +import { readBackupPassActivity } from "@/lib/jobs/backup-pass-attempts"; import { summariseBackupSchedule } from "@/lib/jobs/backup-schedule-status"; import { + OFFHOST_BACKUP_QUEUE, offhostBackupConfigured, probeOffhostLifecycle, } from "@/lib/jobs/offhost-backup"; @@ -177,6 +182,14 @@ export const GET = apiHandler(async () => { lastAttemptAt: { not: null }, }, }; + const [weeklyRunningSince, offhostRunningSince] = await Promise.all([ + readQueueRunningSince(DATA_BACKUP_QUEUE), + readQueueRunningSince(OFFHOST_BACKUP_QUEUE), + ]); + const [scheduleActivity, offhostActivity] = await Promise.all([ + readBackupPassActivity(prisma, DATA_BACKUP_QUEUE, weeklyRunningSince), + readBackupPassActivity(prisma, OFFHOST_BACKUP_QUEUE, offhostRunningSince), + ]); const [purgeCount, oldestPurge, lifecycle] = await Promise.all([ prisma.offhostPurgeRequest.count({ where: stillInBucket }), prisma.offhostPurgeRequest.findFirst({ @@ -201,8 +214,10 @@ export const GET = apiHandler(async () => { lastRun: await readLastQueueRun(DATA_BACKUP_QUEUE), now, }), + scheduleActivity, offhost: { configured, + activity: offhostActivity, periodHours: OFFHOST_BACKUP_PERIOD_HOURS, // An unconfigured host has nothing to list, and the card says so rather // than painting an empty table that reads as "no problems". diff --git a/src/components/admin/__tests__/offhost-backups-section.test.tsx b/src/components/admin/__tests__/offhost-backups-section.test.tsx index 1bc8a886d..3631fe121 100644 --- a/src/components/admin/__tests__/offhost-backups-section.test.tsx +++ b/src/components/admin/__tests__/offhost-backups-section.test.tsx @@ -24,6 +24,7 @@ import { I18nProvider } from "@/lib/i18n/context"; import { OffhostBackupsSection } from "../offhost-backups-section"; const QUIET = { + activity: { runningSince: null, interrupted: [] }, pendingDeletions: { count: 0, oldestRequestedAt: null, lastFailure: null }, lifecycle: { state: "configured" as const, expirationDays: 30 }, }; @@ -126,6 +127,7 @@ describe("", () => { configured: true, periodHours: 24, rows: [], + activity: { runningSince: null, interrupted: [] }, pendingDeletions: { count: 2, oldestRequestedAt: "2026-09-20T10:00:00.000Z", @@ -149,4 +151,26 @@ describe("", () => { expect(html).toContain("after 30 days"); expect(html).not.toContain('data-slot="offhost-pending-deletions"'); }); + + it("names an account a run died under, and says since when one runs", () => { + const html = render({ + configured: true, + periodHours: 24, + rows: [], + ...QUIET, + activity: { + runningSince: "2026-10-04T02:30:00.000Z", + interrupted: [ + { + userId: "u1", + username: "account-one", + startedAt: "2026-10-03T02:31:00.000Z", + }, + ], + }, + }); + expect(html).toContain('data-slot="backup-pass-running"'); + expect(html).toContain('data-interrupted-username="account-one"'); + expect(html).toContain("never finished"); + }); }); diff --git a/src/components/admin/backup-pass-activity.tsx b/src/components/admin/backup-pass-activity.tsx new file mode 100644 index 000000000..d01c7af16 --- /dev/null +++ b/src/components/admin/backup-pass-activity.tsx @@ -0,0 +1,78 @@ +"use client"; + +/** + * What a backup pass is doing now, and which accounts a run died under. + * + * A pass whose process died (a restart, or a container out of memory) used + * to leave nothing on this page: the job sat `active` until its expiry and + * the last finished run still read fine. The run in progress and the + * accounts whose last attempt started and never finished are both recorded + * now (`backup-pass-attempts.ts`), so the page says so while it matters. + */ +import { AlertTriangle } from "lucide-react"; + +import { useFormatters, useTranslations } from "@/lib/i18n/context"; +import type { BackupPassActivity } from "@/lib/jobs/backup-pass-attempts"; + +export function BackupPassActivityNotice({ + activity, +}: { + activity: BackupPassActivity; +}) { + const { t } = useTranslations(); + const fmt = useFormatters(); + if (activity.runningSince === null && activity.interrupted.length === 0) { + return null; + } + + return ( +
+ {activity.runningSince !== null ? ( +

+ {t("admin.section.backups.activity.running", { + when: fmt.dateTime(activity.runningSince), + })} +

+ ) : null} + {activity.interrupted.length > 0 ? ( +
+
+
+
+ ) : null} +
+ ); +} diff --git a/src/components/admin/backups-section.tsx b/src/components/admin/backups-section.tsx index 22b557d71..c9c5aa862 100644 --- a/src/components/admin/backups-section.tsx +++ b/src/components/admin/backups-section.tsx @@ -35,6 +35,7 @@ import { AlertDialogTitle, AlertDialogTrigger, } from "@/components/ui/alert-dialog"; +import { BackupPassActivityNotice } from "@/components/admin/backup-pass-activity"; import { Badge } from "@/components/ui/badge"; import { QueryErrorRow } from "@/components/ui/query-error-row"; import { SettingsCardActions } from "@/components/settings/_card-actions"; @@ -1149,6 +1150,9 @@ export function BackupsSection() { {data?.schedule ? ( ) : null} + {data?.scheduleActivity ? ( + + ) : null} {/* Upload card — separate from the table so admins can ingest a backup file independently of any existing rows. The visible diff --git a/src/components/admin/offhost-backups-section.tsx b/src/components/admin/offhost-backups-section.tsx index abf408702..eb0a17ae7 100644 --- a/src/components/admin/offhost-backups-section.tsx +++ b/src/components/admin/offhost-backups-section.tsx @@ -21,6 +21,7 @@ import { useQuery } from "@tanstack/react-query"; import { CloudUpload } from "lucide-react"; +import { BackupPassActivityNotice } from "@/components/admin/backup-pass-activity"; import { SettingsCard } from "@/components/settings/settings-card"; import { SettingsCardHeader } from "@/components/settings/_card-header"; import { Badge } from "@/components/ui/badge"; @@ -182,6 +183,7 @@ export function OffhostBackupsSection() { /> ) : offhost ? (
+
    {offhost.rows.map((row) => ( diff --git a/src/lib/data-wipe/wipe-plan.ts b/src/lib/data-wipe/wipe-plan.ts index 42956e113..29a8fc1a1 100644 --- a/src/lib/data-wipe/wipe-plan.ts +++ b/src/lib/data-wipe/wipe-plan.ts @@ -242,6 +242,9 @@ export const WIPE_MODELS = [ // (`requestOffhostPurge`); this row, saying when they were written, is about // this account and goes with it. "OffhostBackupState", + // Where this account stands in the two backup passes. About this account, + // and meaningless without it. + "BackupPassAttempt", "AuditLog", "ConsentReceipt", "UserKnownDevice", diff --git a/src/lib/export/backup-plan.ts b/src/lib/export/backup-plan.ts index aa686e0df..f39b7178e 100644 --- a/src/lib/export/backup-plan.ts +++ b/src/lib/export/backup-plan.ts @@ -706,6 +706,8 @@ export const NOT_IN_BACKUP_MODELS: Readonly> = { "The record of a restore this host ran from one of its own stored copies. It names a backup row that exists only in this database, so carrying it would describe a restore the receiving host never performed.", OffhostBackupState: "When this host last put this account's copy in this operator's bucket, and how big it was. It describes one deployment's relationship with one bucket, so restoring it elsewhere would assert an off-host copy that host has never written.", + BackupPassAttempt: + "When this host's backup passes last started and finished this account, kept so a pass the process died under is taken last next time and named on the backups page. It describes this deployment's own runs, so restoring it elsewhere would report an interrupted run that host never had, or hide one it did.", DocumentImportKey: "The source keys of imported documents the person deleted and the purge then removed, kept so a re-run of the importer does not store them again. The backup carries only live documents, so the tombstones that hold the same memory before the purge do not travel either; carrying the ledger alone would restore half of one decision. After a restore, a deliberate re-import can bring such a document back, and the person deletes it again.", DocumentAiRun: diff --git a/src/lib/jobs/__tests__/data-backup-send-policy.test.ts b/src/lib/jobs/__tests__/data-backup-send-policy.test.ts index 4071cbc2b..c7e470c91 100644 --- a/src/lib/jobs/__tests__/data-backup-send-policy.test.ts +++ b/src/lib/jobs/__tests__/data-backup-send-policy.test.ts @@ -22,9 +22,14 @@ import { join } from "node:path"; import { describe, expect, it } from "vitest"; import { + BACKUP_HEARTBEAT_SECONDS, DATA_BACKUP_QUEUE, DATA_BACKUP_SEND_OPTIONS, } from "../data-backup-policy"; +import { + OFFHOST_BACKUP_QUEUE, + OFFHOST_BACKUP_SEND_OPTIONS, +} from "../offhost-backup"; const read = (file: string) => readFileSync(join(process.cwd(), file), "utf8"); @@ -39,11 +44,28 @@ describe("data-backup — pg-boss send policy", () => { ); }); - it("the weekly schedule carries the policy", () => { + it("notices a process that died under either pass within minutes, not hours", () => { + // pg-boss refuses less than ten seconds; more than a few minutes and a + // dead pass sits `active` for as long as an operator would look. + expect(BACKUP_HEARTBEAT_SECONDS).toBeGreaterThanOrEqual(10); + expect(BACKUP_HEARTBEAT_SECONDS).toBeLessThanOrEqual(10 * 60); + expect(DATA_BACKUP_SEND_OPTIONS.heartbeatSeconds).toBe( + BACKUP_HEARTBEAT_SECONDS, + ); + expect(OFFHOST_BACKUP_QUEUE).toBe("data-backup-offhost"); + expect(OFFHOST_BACKUP_SEND_OPTIONS.heartbeatSeconds).toBe( + BACKUP_HEARTBEAT_SECONDS, + ); + }); + + it("the weekly and nightly schedules carry the policy", () => { const source = read("src/lib/jobs/reminder/register-maintenance.ts"); expect(source).toMatch( /\[\s*DATA_BACKUP_QUEUE,\s*DATA_BACKUP_CRON,\s*DATA_BACKUP_SEND_OPTIONS,?\s*\]/, ); + expect(source).toMatch( + /\[\s*OFFHOST_BACKUP_QUEUE,\s*OFFHOST_BACKUP_CRON,\s*OFFHOST_BACKUP_SEND_OPTIONS,?\s*\]/, + ); }); it("the admin run-now route sends with the same policy", () => { diff --git a/src/lib/jobs/__tests__/job-failures-heartbeat.test.ts b/src/lib/jobs/__tests__/job-failures-heartbeat.test.ts new file mode 100644 index 000000000..bff9f2bfc --- /dev/null +++ b/src/lib/jobs/__tests__/job-failures-heartbeat.test.ts @@ -0,0 +1,45 @@ +/** + * A backup job whose process died is failed by pg-boss's heartbeat monitor + * with three bare words. The backups page shows the run's error, so the words + * have to say what happened and where to look. + */ +import { beforeEach, describe, expect, it, vi } from "vitest"; + +const queryRaw = vi.hoisted(() => vi.fn()); +vi.mock("@/lib/db", () => ({ + prisma: { $queryRaw: (...a: unknown[]) => queryRaw(...a) }, +})); + +import { readLastQueueRun, readQueueRunningSince } from "../job-failures"; + +beforeEach(() => queryRaw.mockReset()); + +describe("a backup run the process died under", () => { + it("explains a heartbeat timeout instead of repeating it", async () => { + queryRaw.mockResolvedValue([ + { + state: "failed", + completed_on: new Date("2026-10-04T02:40:00Z"), + output: "job heartbeat timeout", + expire_seconds: 7200, + }, + ]); + const run = await readLastQueueRun("data-backup"); + expect(run?.state).toBe("failed"); + expect(run?.error).toMatch(/^job heartbeat timeout: /); + expect(run?.error).toMatch(/restarted or ran out of memory/); + }); + + it("says since when a run is in progress, and nothing when none is", async () => { + queryRaw.mockResolvedValueOnce([ + { started_on: new Date("2026-10-04T02:30:00Z") }, + ]); + expect(await readQueueRunningSince("data-backup")).toBe( + "2026-10-04T02:30:00.000Z", + ); + queryRaw.mockResolvedValueOnce([]); + expect(await readQueueRunningSince("data-backup")).toBeNull(); + queryRaw.mockRejectedValueOnce(new Error('schema "pgboss" does not exist')); + expect(await readQueueRunningSince("data-backup")).toBeNull(); + }); +}); diff --git a/src/lib/jobs/__tests__/offhost-backup.test.ts b/src/lib/jobs/__tests__/offhost-backup.test.ts index d038b3e73..95702c8c7 100644 --- a/src/lib/jobs/__tests__/offhost-backup.test.ts +++ b/src/lib/jobs/__tests__/offhost-backup.test.ts @@ -262,6 +262,49 @@ describe("runOffhostBackup", () => { expect(first.create.lastSuccessAt).toBeInstanceOf(Date); }); + it("takes an account whose last attempt never came back last", async () => { + const s3 = makeS3Mock(); + const attempts = { + findMany: vi.fn().mockResolvedValue([ + // u1's last walk started and never finished: the process died + // under it, and walking by id would put it first again. + { + userId: "u1", + startedAt: new Date("2026-05-07T03:00:00Z"), + finishedAt: null, + }, + ]), + upsert: vi.fn().mockResolvedValue({}), + updateMany: vi.fn().mockResolvedValue({ count: 1 }), + }; + const prisma = { + ...purgeLedgerMocks(), + offhostBackupState: { upsert: vi.fn() }, + backupPassAttempt: attempts, + user: { + count: vi.fn().mockResolvedValue(1), + findMany: vi.fn().mockResolvedValue([{ id: "u1" }, { id: "u2" }]), + }, + }; + + const report = await runOffhostBackup( + // eslint-disable-next-line @typescript-eslint/no-explicit-any + prisma as any, + s3, + new Date("2026-05-08T03:00:00Z"), + ); + expect(report.uploaded).toBe(2); + expect(s3.putStream.mock.calls.map(([key]) => key)).toEqual([ + "2026-05-08/user-u2.json.enc", + "2026-05-08/user-u1.json.enc", + ]); + expect(attempts.findMany).toHaveBeenCalledWith( + expect.objectContaining({ where: { pass: "data-backup-offhost" } }), + ); + expect(attempts.upsert).toHaveBeenCalledTimes(2); + expect(attempts.updateMany).toHaveBeenCalledTimes(2); + }); + it("takes back the copy of an account deleted while it was written", async () => { const s3 = makeS3Mock(); const ledger = purgeLedgerMocks(); diff --git a/src/lib/jobs/backup-pass-attempts.ts b/src/lib/jobs/backup-pass-attempts.ts new file mode 100644 index 000000000..05c0d919b --- /dev/null +++ b/src/lib/jobs/backup-pass-attempts.ts @@ -0,0 +1,145 @@ +/** + * Where each account stands in a backup pass that walks every account, so a + * pass the process died under is noticed and does not die the same way again. + * + * Why. Both backup passes walk the accounts one after another in one job. + * When an account's record kills the process (the container runs out of + * memory), the job is left `active`, and its retry walks the accounts in the + * same order: the weekly pass takes the oldest copy first, which is the very + * account that never got a new one, and the off-host pass walks by id. The + * same account kills the retry, and every account after it goes without a + * copy for as long as that account stays too large. + * + * What this does. The pass writes `startedAt` before it starts an account and + * `finishedAt` once it is past it, whatever the outcome it caught. A start + * newer than the finish is an attempt that never came back: the next pass + * takes that account last, after everybody else has their copy, and the admin + * backups page names it. Every write and read here is best effort: the marker + * is bookkeeping about a backup, and must never be the reason one fails. + */ +import type { PrismaClient } from "@/generated/prisma/client"; + +/** The pass's queue name, which is also the marker's key. */ +export type BackupPass = "data-backup" | "data-backup-offhost"; + +type Db = Pick; + +export async function markBackupAttemptStarted( + prisma: Db, + pass: BackupPass, + userId: string, + at: Date = new Date(), +): Promise { + try { + await prisma.backupPassAttempt.upsert({ + where: { userId_pass: { userId, pass } }, + update: { startedAt: at }, + create: { userId, pass, startedAt: at }, + }); + } catch { + // Bookkeeping only; an account deleted meanwhile has no row to write. + } +} + +export async function markBackupAttemptFinished( + prisma: Db, + pass: BackupPass, + userId: string, + at: Date = new Date(), +): Promise { + try { + await prisma.backupPassAttempt.updateMany({ + where: { userId, pass }, + data: { finishedAt: at }, + }); + } catch { + // Bookkeeping only. + } +} + +/** + * The accounts whose last attempt in `pass` started and never finished, with + * when it started. Empty when the table cannot be read. + */ +export async function readInterruptedBackupAttempts( + prisma: Db, + pass: BackupPass, +): Promise> { + try { + const rows = await prisma.backupPassAttempt.findMany({ + where: { pass }, + select: { userId: true, startedAt: true, finishedAt: true }, + }); + return new Map( + rows + .filter( + (row) => row.finishedAt === null || row.finishedAt < row.startedAt, + ) + .map((row) => [row.userId, row.startedAt]), + ); + } catch { + return new Map(); + } +} + +/** + * `accounts` in their order, with every interrupted one moved behind the + * rest; among those, the one interrupted longest ago first. + */ +export function orderInterruptedLast( + accounts: readonly T[], + interrupted: ReadonlyMap, +): T[] { + const clean = accounts.filter((account) => !interrupted.has(account.id)); + const last = accounts + .filter((account) => interrupted.has(account.id)) + .sort( + (a, b) => + interrupted.get(a.id)!.getTime() - interrupted.get(b.id)!.getTime(), + ); + return [...clean, ...last]; +} + +/** What the admin backups page shows about one pass while it runs or after. */ +export interface BackupPassActivity { + /** When the run in progress started; null when none is running. */ + runningSince: string | null; + /** + * Accounts whose last attempt started and never finished, oldest first. + * The account the run in progress is on right now is not among them. + */ + interrupted: Array<{ userId: string; username: string; startedAt: string }>; +} + +export async function readBackupPassActivity( + prisma: Db & Pick, + pass: BackupPass, + runningSince: string | null, +): Promise { + const attempts = await readInterruptedBackupAttempts(prisma, pass); + const since = runningSince === null ? null : new Date(runningSince); + // An attempt the run in progress started is the account it is on now. + const stuck = [...attempts].filter( + ([, startedAt]) => since === null || startedAt < since, + ); + if (stuck.length === 0) return { runningSince, interrupted: [] }; + const names = new Map( + ( + await prisma.user.findMany({ + where: { id: { in: stuck.map(([userId]) => userId) } }, + select: { id: true, username: true }, + }) + ).map((user) => [user.id, user.username]), + ); + return { + runningSince, + interrupted: stuck + .filter(([userId]) => names.has(userId)) + .sort(([, a], [, b]) => a.getTime() - b.getTime()) + .map(([userId, startedAt]) => ({ + userId, + username: names.get(userId)!, + startedAt: startedAt.toISOString(), + })), + }; +} diff --git a/src/lib/jobs/data-backup-policy.ts b/src/lib/jobs/data-backup-policy.ts index 22baef4d1..8df42abb3 100644 --- a/src/lib/jobs/data-backup-policy.ts +++ b/src/lib/jobs/data-backup-policy.ts @@ -34,6 +34,22 @@ export const DATA_BACKUP_QUEUE = "data-backup"; +/** + * How long a backup job may go without a sign of life before pg-boss fails it + * (and retries it, within `retryLimit`). The worker refreshes the heartbeat + * every half of this while the handler runs, so only a process that died under + * the job stops it: a restart, or a container killed for memory. Without it + * such a job sat `active` until its expiry, two hours for this pass and four + * for the off-host one, and the admin page showed nothing wrong in between. + * + * Five minutes rather than pg-boss's floor of ten seconds: the refresh is a + * timer on the event loop, and serialising one large section of a record can + * hold the loop for a while. A refresh every two and a half minutes survives + * that; a crash is still noticed at the next supervision tick after five. + */ +export const BACKUP_HEARTBEAT_SECONDS = 5 * 60; + export const DATA_BACKUP_SEND_OPTIONS = { expireInSeconds: 2 * 60 * 60, + heartbeatSeconds: BACKUP_HEARTBEAT_SECONDS, } as const; diff --git a/src/lib/jobs/job-failures.ts b/src/lib/jobs/job-failures.ts index 793dae392..9332b041d 100644 --- a/src/lib/jobs/job-failures.ts +++ b/src/lib/jobs/job-failures.ts @@ -76,6 +76,9 @@ interface FailingQueueRow { */ const TIMEOUT_MESSAGE = /^(job timed out|handler execution exceeded \d+s)$/; +/** What pg-boss writes when a job with a heartbeat stopped sending one. */ +const HEARTBEAT_MESSAGE = /^job heartbeat timeout$/; + /** * Say what a bare timeout means. "job timed out" alone sent an operator * nowhere: pg-boss writes the same words for a pass that was too slow for its @@ -111,6 +114,13 @@ function presentError( if (trimmed.length === 0) return ""; if (TIMEOUT_MESSAGE.test(trimmed)) return explainTimeout(trimmed, expireSeconds); + if (HEARTBEAT_MESSAGE.test(trimmed)) { + return ( + `${trimmed}: the process running it stopped answering, most often ` + + `because the app restarted or ran out of memory while it ran; a restart ` + + `shows in the container's restart count and log.` + ); + } const redacted = redactSecrets(trimmed); return redacted.length > MAX_ERROR_CHARS ? `${redacted.slice(0, MAX_ERROR_CHARS)}…` @@ -339,3 +349,27 @@ export async function readActiveJobsStartedBefore( return null; } } + +/** + * When the run of `queue` that is in progress now started, or null when none + * is (or the queue schema cannot be read). The oldest active job, so a retry + * of a run reads as the run it continues only once it has been picked up. + */ +export async function readQueueRunningSince( + queue: string, +): Promise { + try { + const rows = await prisma.$queryRaw>` + SELECT started_on + FROM pgboss.job + WHERE name = ${queue} + AND state = 'active' + AND started_on IS NOT NULL + ORDER BY started_on ASC + LIMIT 1 + `; + return rows[0]?.started_on?.toISOString() ?? null; + } catch { + return null; + } +} diff --git a/src/lib/jobs/offhost-backup.ts b/src/lib/jobs/offhost-backup.ts index f48ab0b17..ad9cf04dd 100644 --- a/src/lib/jobs/offhost-backup.ts +++ b/src/lib/jobs/offhost-backup.ts @@ -35,6 +35,13 @@ import type { PrismaClient } from "@/generated/prisma/client"; import { createRawStreamEncryptor, decryptRawStream } from "@/lib/crypto"; import { createBackupKeyIdTextScanner } from "@/lib/export/backup-key-ids"; import { streamFullBackupJson } from "@/lib/export/full-backup-stream"; +import { + markBackupAttemptFinished, + markBackupAttemptStarted, + orderInterruptedLast, + readInterruptedBackupAttempts, +} from "@/lib/jobs/backup-pass-attempts"; +import { BACKUP_HEARTBEAT_SECONDS } from "@/lib/jobs/data-backup-policy"; import { annotate, getEvent } from "@/lib/logging/context"; import { envValue } from "@/lib/env"; @@ -51,6 +58,18 @@ const TAG_LENGTH = 16; */ export const OFFHOST_BACKUP_EXPIRE_SECONDS = 4 * 60 * 60; +export const OFFHOST_BACKUP_QUEUE = "data-backup-offhost"; + +/** + * What the nightly schedule sends with: the four hours above, and the + * heartbeat that notices a process that died under the pass within minutes + * rather than at the end of them (`BACKUP_HEARTBEAT_SECONDS`). + */ +export const OFFHOST_BACKUP_SEND_OPTIONS = { + expireInSeconds: OFFHOST_BACKUP_EXPIRE_SECONDS, + heartbeatSeconds: BACKUP_HEARTBEAT_SECONDS, +} as const; + export interface OffhostBackupConfig { endpoint: string; bucket: string; @@ -909,10 +928,17 @@ export async function runOffhostBackup( // eslint-disable-next-line healthlog/no-utc-day-key -- UTC by design: off-host object key date, the name the restore drill and the purge look up const dateKey = (runStartedAt ?? now).toISOString().slice(0, 10); - const users = await prisma.user.findMany({ - select: { id: true }, - orderBy: { id: "asc" }, - }); + // By id, with an account whose last walk never came back behind the rest: + // a record that killed the process once would otherwise lead every retry + // and keep every account after it out of the bucket + // (`backup-pass-attempts.ts`). + const users = orderInterruptedLast( + await prisma.user.findMany({ + select: { id: true }, + orderBy: { id: "asc" }, + }), + await readInterruptedBackupAttempts(prisma, OFFHOST_BACKUP_QUEUE), + ); const doneThisRun = new Set(); if (runStartedAt) { const done = await prisma.offhostBackupState.findMany({ @@ -946,6 +972,12 @@ export async function runOffhostBackup( // admin encryption view uses them to say how long a retired key is still // needed for what is in the bucket. const keyScanner = createBackupKeyIdTextScanner(); + await markBackupAttemptStarted( + prisma, + OFFHOST_BACKUP_QUEUE, + user.id, + accountStartedAt, + ); try { objectBytes = await uploadEncryptedBackup( s3, @@ -998,6 +1030,10 @@ export async function runOffhostBackup( evt?.addWarning( `offhost-backup user ${user.id} failed: ${message.slice(0, 200)}`, ); + } finally { + // Past this account, whatever the outcome: only a process that died + // under it leaves the start without a finish. + await markBackupAttemptFinished(prisma, OFFHOST_BACKUP_QUEUE, user.id); } // The per-account ledger, and deliberately NOT inside the upload's `try`. diff --git a/src/lib/jobs/queue-runtime.ts b/src/lib/jobs/queue-runtime.ts index f5bd82c3c..18177c274 100644 --- a/src/lib/jobs/queue-runtime.ts +++ b/src/lib/jobs/queue-runtime.ts @@ -259,7 +259,7 @@ export const QUEUE_RUNTIME: Readonly> = { "data-backup-offhost": { runtime: "long", expireInSeconds: OFFHOST_BACKUP_EXPIRE_SECONDS, - expiryVia: ["OFFHOST_BACKUP_EXPIRE_SECONDS"], + expiryVia: ["OFFHOST_BACKUP_SEND_OPTIONS"], stop: { file: "lib/jobs/reminder/backup-handlers.ts", fn: "handleOffhostBackup", diff --git a/src/lib/jobs/reminder/__tests__/backup-handlers.test.ts b/src/lib/jobs/reminder/__tests__/backup-handlers.test.ts index 0a6b52844..5f386a2d7 100644 --- a/src/lib/jobs/reminder/__tests__/backup-handlers.test.ts +++ b/src/lib/jobs/reminder/__tests__/backup-handlers.test.ts @@ -71,6 +71,11 @@ function buildPrismaMock( return { user: { findMany: vi.fn().mockResolvedValue(users) }, dataBackup: { findMany: vi.fn().mockResolvedValue([]) }, + backupPassAttempt: { + findMany: vi.fn().mockResolvedValue([]), + upsert: vi.fn().mockResolvedValue({}), + updateMany: vi.fn().mockResolvedValue({ count: 1 }), + }, }; } @@ -278,4 +283,44 @@ describe("handleDataBackup on a large instance", () => { did: { backed: 2, stopped_early: true }, }); }); + + it("takes an account whose last attempt never came back last, and marks every attempt", async () => { + const prisma = buildPrismaMock([ + { id: "big", username: "big" }, + { id: "small", username: "small" }, + { id: "other", username: "other" }, + ]); + // `big` has the oldest copy, so it would lead; its last attempt started + // and never finished: the process died under it. + prisma.dataBackup.findMany.mockResolvedValue([ + { userId: "big", createdAt: new Date("2026-08-01T00:00:00Z") }, + { userId: "small", createdAt: new Date("2026-09-01T00:00:00Z") }, + { userId: "other", createdAt: new Date("2026-09-02T00:00:00Z") }, + ]); + prisma.backupPassAttempt.findMany.mockResolvedValue([ + { + userId: "big", + startedAt: new Date("2026-09-28T02:00:00Z"), + finishedAt: new Date("2026-09-21T02:30:00Z"), + }, + { + userId: "small", + startedAt: new Date("2026-09-21T02:31:00Z"), + finishedAt: new Date("2026-09-21T02:32:00Z"), + }, + ]); + mocks.getWorkerPrisma.mockReturnValue(prisma); + + await handleDataBackup([]); + + const order = mocks.store.mock.calls.map( + ([input]) => (input as { userId: string }).userId, + ); + expect(order).toEqual(["small", "other", "big"]); + expect(prisma.backupPassAttempt.findMany).toHaveBeenCalledWith( + expect.objectContaining({ where: { pass: "data-backup" } }), + ); + expect(prisma.backupPassAttempt.upsert).toHaveBeenCalledTimes(3); + expect(prisma.backupPassAttempt.updateMany).toHaveBeenCalledTimes(3); + }); }); diff --git a/src/lib/jobs/reminder/backup-handlers.ts b/src/lib/jobs/reminder/backup-handlers.ts index 67a4a0371..d4bb4b1a4 100644 --- a/src/lib/jobs/reminder/backup-handlers.ts +++ b/src/lib/jobs/reminder/backup-handlers.ts @@ -23,6 +23,13 @@ import { } from "@/lib/jobs/offhost-backup"; import { getWorkerPrisma } from "./shared"; import { reportJobProgress } from "@/lib/jobs/job-observer"; +import { + markBackupAttemptFinished, + markBackupAttemptStarted, + orderInterruptedLast, + readInterruptedBackupAttempts, +} from "@/lib/jobs/backup-pass-attempts"; +import { DATA_BACKUP_QUEUE } from "@/lib/jobs/data-backup-policy"; export interface DataBackupPayload { triggeredAt: string; @@ -141,20 +148,31 @@ export async function handleDataBackup( return withBackgroundEvent("job.data_backup", async (evt) => { const prisma = getWorkerPrisma(); try { - const [accounts, copies] = await Promise.all([ + const [accounts, copies, interrupted] = await Promise.all([ prisma.user.findMany({ select: { id: true, username: true } }), prisma.dataBackup.findMany({ where: { type: "WEEKLY_AUTO" }, select: { userId: true, createdAt: true }, }), + readInterruptedBackupAttempts(prisma, DATA_BACKUP_QUEUE), ]); const copiedAt = new Map( copies.map((copy) => [copy.userId, copy.createdAt.getTime()]), ); - // No copy yet sorts first, then the oldest copy. - const users = [...accounts].sort( - (a, b) => (copiedAt.get(a.id) ?? -1) - (copiedAt.get(b.id) ?? -1), + // No copy yet sorts first, then the oldest copy. An account whose last + // attempt never came back goes behind all of them: it is the one with + // the oldest copy, so it would lead every retry, and a record that + // killed the process once would keep every account after it from a + // copy (`backup-pass-attempts.ts`). + const users = orderInterruptedLast( + [...accounts].sort( + (a, b) => (copiedAt.get(a.id) ?? -1) - (copiedAt.get(b.id) ?? -1), + ), + interrupted, ); + if (interrupted.size > 0) { + evt.addMeta("data_backup_interrupted_accounts", interrupted.size); + } let stoppedEarly = false; let backed = 0; @@ -176,6 +194,7 @@ export async function handleDataBackup( backup_users_done: backed + usersFailed + skippedRestoring, backup_users_total: users.length, }); + await markBackupAttemptStarted(prisma, DATA_BACKUP_QUEUE, user.id); try { // Streamed, compressed, then encrypted (the record contains // sensitive health information), and stored a piece at a time. @@ -226,6 +245,10 @@ export async function handleDataBackup( lastError = err; if (err instanceof BackupBlobTooLargeError) oversized++; evt.addWarning(`Failed for user ${user.id}: ${err}`); + } finally { + // Past this account, whatever the outcome: only a process that died + // under it leaves the start without a finish. + await markBackupAttemptFinished(prisma, DATA_BACKUP_QUEUE, user.id); } } diff --git a/src/lib/jobs/reminder/register-maintenance.ts b/src/lib/jobs/reminder/register-maintenance.ts index 731103a45..6fd906114 100644 --- a/src/lib/jobs/reminder/register-maintenance.ts +++ b/src/lib/jobs/reminder/register-maintenance.ts @@ -36,7 +36,10 @@ import { } from "@/lib/jobs/pr-detection"; import { jobBudget } from "@/lib/jobs/job-budget"; import { lockedPass, WHOLE_PASS } from "@/lib/jobs/long-pass"; -import { OFFHOST_BACKUP_EXPIRE_SECONDS } from "@/lib/jobs/offhost-backup"; +import { + OFFHOST_BACKUP_QUEUE, + OFFHOST_BACKUP_SEND_OPTIONS, +} from "@/lib/jobs/offhost-backup"; import { MEDICATION_INVENTORY_EXPIRE_QUEUE, MEDICATION_INVENTORY_EXPIRE_CRON, @@ -291,7 +294,6 @@ const AUDIT_LOG_CLEANUP_CRON = "15 3 * * *"; // daily at 03:15 (Europe/Berlin) const INTAKE_SLOT_DEDUP_CRON = "28 3 * * *"; -const OFFHOST_BACKUP_QUEUE = "data-backup-offhost"; // 02:30 Europe/Berlin — runs after audit-log/idempotency cleanups so old // rows are gone before they're snapshotted, but before the existing // in-DB DATA_BACKUP at 03:00 (Sundays only) so the off-host copy is @@ -568,11 +570,7 @@ const schedules: ScheduleEntry[] = [ STEP_UP_ELEVATION_CLEANUP_CRON, cronIsTheRetry, ], - [ - OFFHOST_BACKUP_QUEUE, - OFFHOST_BACKUP_CRON, - { expireInSeconds: OFFHOST_BACKUP_EXPIRE_SECONDS }, - ], + [OFFHOST_BACKUP_QUEUE, OFFHOST_BACKUP_CRON, OFFHOST_BACKUP_SEND_OPTIONS], [RESTORE_DRILL_QUEUE, RESTORE_DRILL_CRON], // Nightly backstop for the purge the deletion kicks straight away: a // request the bucket refused, or one written while the queue was down. diff --git a/src/types/backups.ts b/src/types/backups.ts index fb7b1c18d..66db2a811 100644 --- a/src/types/backups.ts +++ b/src/types/backups.ts @@ -9,6 +9,7 @@ * both sides a route-handler-independent shared type home; the route * keeps owning the HTTP contract, the component keeps owning the UI. */ +import type { BackupPassActivity } from "@/lib/jobs/backup-pass-attempts"; import type { BackupScheduleStatus } from "@/lib/jobs/backup-schedule-status"; import type { OffhostBackupFreshness } from "@/lib/jobs/offhost-backup-freshness"; @@ -54,6 +55,8 @@ export interface OffhostAccountRow { export interface OffhostBackupOverview { /** Whether this host has the variables the nightly job needs. */ configured: boolean; + /** The run in progress, and accounts a run died under. */ + activity: BackupPassActivity; /** Hours between two scheduled runs — the number behind the verdicts. */ periodHours: number; /** One row per account. Empty when off-host backup is not configured. */ @@ -87,6 +90,11 @@ export interface BackupsList { * made six weeks ago and one made on Sunday look identical in a table. */ schedule: BackupScheduleStatus; + /** + * The weekly run in progress, and accounts a run died under: a start + * without a finish, which a crash leaves and a caught failure does not. + */ + scheduleActivity: BackupPassActivity; /** * The off-host leg. A weekly row in this table says the copy that lives in * this database is current; it says nothing about whether anything reached diff --git a/tests/integration/backup-preview.test.ts b/tests/integration/backup-preview.test.ts index 1c99aa0e9..f7d984af0 100644 --- a/tests/integration/backup-preview.test.ts +++ b/tests/integration/backup-preview.test.ts @@ -157,6 +157,15 @@ describe("restore preview kept with the copy", () => { const row = await prisma.dataBackup.findFirstOrThrow({ where: { userId: admin.id, type: "WEEKLY_AUTO" }, }); + // The pass marked the account started and then finished: only a process + // that died under it would leave the start alone. + const attempt = await prisma.backupPassAttempt.findUniqueOrThrow({ + where: { userId_pass: { userId: admin.id, pass: "data-backup" } }, + }); + expect(attempt.finishedAt).not.toBeNull(); + expect(attempt.finishedAt!.getTime()).toBeGreaterThanOrEqual( + attempt.startedAt.getTime(), + ); expect(row.preview).toMatchObject({ version: 1, copy: `chunks:${row.chunkStreamId}:${row.chunkCount}`, From 3e08fd0e68935be94b889f49f04e7e086665e83e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Sun, 4 Oct 2026 15:56:53 +0200 Subject: [PATCH 5/5] fix(documents): stop queueing a thumbnail that cannot be rendered on every boot A document whose preview render fails for good (a PDF whose first page renders blank) was queued by the boot-time backfill, refused, and queued again at the next boot, without end. The thumbnail job now keeps the failure with the document (document_thumbnail_failures, migration 0374): the reason, the attempts since the last success and when the newest failed. The backfill, both the boot discovery and the per-account pass, leaves a document out after one deterministic refusal (raster-failed, empty-render, pixel-cap) or three of any other kind, until the document changes. A direct enqueue still renders it, and a preview that is made clears the record. --- .../migration.sql | 24 +++ prisma/schema.prisma | 46 +++++- src/lib/data-wipe/wipe-plan.ts | 1 + src/lib/export/backup-plan.ts | 2 + .../jobs/__tests__/document-thumbnail.test.ts | 110 ++++++++++++-- src/lib/jobs/document-thumbnail-backfill.ts | 74 ++++++++- src/lib/jobs/document-thumbnail.ts | 31 ++++ .../document-thumbnail-backfill.test.ts | 143 ++++++++++++++++++ 8 files changed, 405 insertions(+), 26 deletions(-) create mode 100644 prisma/migrations/0374_document_thumbnail_failures/migration.sql create mode 100644 tests/integration/document-thumbnail-backfill.test.ts diff --git a/prisma/migrations/0374_document_thumbnail_failures/migration.sql b/prisma/migrations/0374_document_thumbnail_failures/migration.sql new file mode 100644 index 000000000..d43029273 --- /dev/null +++ b/prisma/migrations/0374_document_thumbnail_failures/migration.sql @@ -0,0 +1,24 @@ +-- Why a document has no preview thumbnail. The boot-time backfill skips a +-- document whose render failed for good, until the document changes. +CREATE TABLE "document_thumbnail_failures" ( + "document_id" TEXT NOT NULL, + "user_id" TEXT NOT NULL, + "reason" TEXT NOT NULL, + "attempts" INTEGER NOT NULL DEFAULT 1, + "failed_at" TIMESTAMP(3) NOT NULL, + + CONSTRAINT "document_thumbnail_failures_pkey" PRIMARY KEY ("document_id") +); + +CREATE INDEX "document_thumbnail_failures_user_id_idx" + ON "document_thumbnail_failures"("user_id"); + +ALTER TABLE "document_thumbnail_failures" + ADD CONSTRAINT "document_thumbnail_failures_document_id_fkey" + FOREIGN KEY ("document_id") REFERENCES "inbound_documents"("id") + ON DELETE CASCADE ON UPDATE CASCADE; + +ALTER TABLE "document_thumbnail_failures" + ADD CONSTRAINT "document_thumbnail_failures_user_id_fkey" + FOREIGN KEY ("user_id") REFERENCES "users"("id") + ON DELETE CASCADE ON UPDATE CASCADE; diff --git a/prisma/schema.prisma b/prisma/schema.prisma index cb8d0c684..d5b691e19 100644 --- a/prisma/schema.prisma +++ b/prisma/schema.prisma @@ -766,6 +766,7 @@ model User { backupRestoreJobs BackupRestoreJob[] offhostBackupState OffhostBackupState? backupPassAttempts BackupPassAttempt[] + documentThumbnailFailures DocumentThumbnailFailure[] achievements UserAchievement[] recommendationFeedback RecommendationFeedback[] idempotencyKeys IdempotencyKey[] @@ -8396,28 +8397,29 @@ model InboundDocument { /// explicitly reads it with AI or generates its summary. aiReadDeferred Boolean @default(false) @map("ai_read_deferred") - facts ExtractedFact[] - conditionLinks DocumentConditionLink[] + facts ExtractedFact[] + conditionLinks DocumentConditionLink[] /// 1:1 blind content-search index (encrypted extracted text + HMAC token /// array). Absent until the document is indexed; cascades on delete. - contentIndex DocumentContentIndex? + contentIndex DocumentContentIndex? /// 1:1 encrypted preview thumbnail (small JPEG, AES-256-GCM at rest). /// Absent until the background thumbnail job runs; a side table (not a /// column) so the list/detail `omit: { contentEncrypted }` queries never /// drag the blob into the SELECT. Cascades on delete. - thumbnail DocumentThumbnail? + thumbnail DocumentThumbnail? + thumbnailFailure DocumentThumbnailFailure? /// v1.29.x (S7) — coach-conversation attachments (m:n via /// `CoachConversationDocument`). Deleting this document cascades its join rows /// away (its text leaves every conversation's context) but never the /// conversation itself — a fenced thread survives via its sticky flag. - chatAttachments CoachConversationDocument[] + chatAttachments CoachConversationDocument[] /// share-link memberships (m:n via `ClinicianShareLinkDocument`). /// Cascades: deleting this document removes it from every share it was on. - shareLinks ClinicianShareLinkDocument[] + shareLinks ClinicianShareLinkDocument[] /// Further import source keys that resolved to this document by content. - sourceAliases DocumentSourceAlias[] + sourceAliases DocumentSourceAlias[] /// Background AI reads of this document (v1.40). Transient; cascades. - aiRuns DocumentAiRun[] + aiRuns DocumentAiRun[] createdAt DateTime @default(now()) @map("created_at") updatedAt DateTime @updatedAt @map("updated_at") @@ -8709,6 +8711,34 @@ model DocumentThumbnail { @@map("document_thumbnails") } +/// Why a document has no preview thumbnail, kept so the boot-time backfill +/// stops queueing a document whose render cannot succeed. A PDF whose first +/// page renders blank was queued, rendered, refused and queued again at +/// every boot, without end. A deterministic refusal (`raster-failed`, +/// `empty-render`, `pixel-cap`) is final after one attempt; any other reason +/// gets three. Either way the document is tried again once it changes +/// (`updatedAt` past `failedAt`), and a direct enqueue (an upload) still +/// renders it. A preview that is made deletes the row. +/// Consumers: `runThumbnailBackfillForUser()` and +/// `enqueueBootTimeThumbnailBackfill()` in +/// `src/lib/jobs/document-thumbnail-backfill.ts`. +model DocumentThumbnailFailure { + documentId String @id @map("document_id") + userId String @map("user_id") + /// The renderer's reason (`ThumbnailSkipReason`), or `decrypt-failed`. + reason String + /// Renders that failed since the last success or change. + attempts Int @default(1) + /// When the newest of them failed. + failedAt DateTime @map("failed_at") + + document InboundDocument @relation(fields: [documentId], references: [id], onDelete: Cascade) + user User @relation(fields: [userId], references: [id], onDelete: Cascade) + + @@index([userId]) + @@map("document_thumbnail_failures") +} + // ─── Nutrient intake (v1.28) ─────────────────────────────────────── // // Micronutrient daily totals synced from Apple Health — vitamins, diff --git a/src/lib/data-wipe/wipe-plan.ts b/src/lib/data-wipe/wipe-plan.ts index 29a8fc1a1..5d0d2b9fe 100644 --- a/src/lib/data-wipe/wipe-plan.ts +++ b/src/lib/data-wipe/wipe-plan.ts @@ -153,6 +153,7 @@ export const WIPE_MODELS = [ // ── Documents ─────────────────────────────────────────────────────────── "DocumentContentIndex", "DocumentThumbnail", + "DocumentThumbnailFailure", "DocumentConditionLink", // The memory of which imported documents the person deleted (#1038). The // documents themselves go below; keeping the memory would make a fresh diff --git a/src/lib/export/backup-plan.ts b/src/lib/export/backup-plan.ts index f39b7178e..639fee095 100644 --- a/src/lib/export/backup-plan.ts +++ b/src/lib/export/backup-plan.ts @@ -620,6 +620,8 @@ export const DERIVED_MODELS: Readonly> = { "A search index over `InboundDocument` text; rebuilt by the indexer.", DocumentThumbnail: "Rendered from the stored document bytes on demand. Those bytes travel in a disaster-recovery payload, so the picture rebuilds itself on first view; a portable export carries metadata only, and there the thumbnail has nothing to rebuild from — but neither does the document, so nothing is lost that the export did not already disclose.", + DocumentThumbnailFailure: + "Why a document's preview could not be rendered on this host, kept so the boot backfill stops retrying it. The receiving host renders the restored document itself, and its own failure, if any, writes the row again; carrying this one would stop a host whose renderer can draw the page from ever trying.", ArrivalReaction: "Derived from what changed since the last visit; recomputed per visit.", DismissedPriorityItem: diff --git a/src/lib/jobs/__tests__/document-thumbnail.test.ts b/src/lib/jobs/__tests__/document-thumbnail.test.ts index 4270507d1..4ae6ef3e3 100644 --- a/src/lib/jobs/__tests__/document-thumbnail.test.ts +++ b/src/lib/jobs/__tests__/document-thumbnail.test.ts @@ -9,25 +9,37 @@ import { beforeEach, describe, expect, it, vi } from "vitest"; * never has a preview stays at info. */ -const { evt, findFirst, upsert, generateThumbnail, withBackgroundEvent } = - vi.hoisted(() => { - const evt = { addMeta: vi.fn(), elevateLevel: vi.fn() }; - return { - evt, - findFirst: vi.fn(), - upsert: vi.fn(), - generateThumbnail: vi.fn(), - withBackgroundEvent: vi.fn( - async (_name: string, fn: (e: typeof evt) => Promise) => - fn(evt), - ), - }; - }); +const { + evt, + findFirst, + upsert, + failureUpsert, + failureDelete, + generateThumbnail, + withBackgroundEvent, +} = vi.hoisted(() => { + const evt = { addMeta: vi.fn(), elevateLevel: vi.fn() }; + return { + evt, + findFirst: vi.fn(), + upsert: vi.fn(), + failureUpsert: vi.fn(), + failureDelete: vi.fn(), + generateThumbnail: vi.fn(), + withBackgroundEvent: vi.fn( + async (_name: string, fn: (e: typeof evt) => Promise) => fn(evt), + ), + }; +}); vi.mock("@/lib/db", () => ({ prisma: { inboundDocument: { findFirst }, documentThumbnail: { upsert }, + documentThumbnailFailure: { + upsert: failureUpsert, + deleteMany: failureDelete, + }, }, })); vi.mock("@/lib/documents/store", () => ({ @@ -95,4 +107,74 @@ describe("runDocumentThumbnail wide event", () => { expect(upsert).toHaveBeenCalledOnce(); expect(evt.elevateLevel).not.toHaveBeenCalled(); }); + + it("keeps a render failure so the backfill can stop queueing the document", async () => { + generateThumbnail.mockResolvedValue({ ok: false, reason: "raster-failed" }); + await runDocumentThumbnail({ userId: "user-1", documentId: "doc-1" }); + expect(failureUpsert).toHaveBeenCalledWith( + expect.objectContaining({ + where: { documentId: "doc-1" }, + create: expect.objectContaining({ + userId: "user-1", + reason: "raster-failed", + attempts: 1, + }), + update: expect.objectContaining({ attempts: { increment: 1 } }), + }), + ); + }); + + it("keeps no failure for a type that never has a preview, and clears one when a preview is made", async () => { + findFirst.mockResolvedValue({ ...DOC, mimeType: "text/plain" }); + generateThumbnail.mockResolvedValue({ + ok: false, + reason: "unsupported-type", + }); + await runDocumentThumbnail({ userId: "user-1", documentId: "doc-1" }); + expect(failureUpsert).not.toHaveBeenCalled(); + + findFirst.mockResolvedValue(DOC); + generateThumbnail.mockResolvedValue({ + ok: true, + thumbnail: { jpeg: Buffer.from([0xff, 0xd8]), width: 2, height: 3 }, + }); + await runDocumentThumbnail({ userId: "user-1", documentId: "doc-1" }); + expect(failureDelete).toHaveBeenCalledWith({ + where: { documentId: "doc-1" }, + }); + }); +}); + +describe("thumbnailRetryDue", () => { + const at = new Date("2026-10-01T00:00:00Z"); + const before = new Date("2026-09-30T00:00:00Z"); + const after = new Date("2026-10-02T00:00:00Z"); + + it("retries a document with no failure, and one that changed since", async () => { + const { thumbnailRetryDue } = + await import("../document-thumbnail-backfill"); + expect(thumbnailRetryDue(null, before)).toBe(true); + expect( + thumbnailRetryDue( + { reason: "raster-failed", attempts: 1, failedAt: at }, + after, + ), + ).toBe(true); + }); + + it("settles a deterministic refusal after one try and a throw after three", async () => { + const { thumbnailRetryDue } = + await import("../document-thumbnail-backfill"); + for (const reason of ["raster-failed", "empty-render", "pixel-cap"]) { + expect( + thumbnailRetryDue({ reason, attempts: 1, failedAt: at }, before), + ).toBe(false); + } + expect( + thumbnailRetryDue({ reason: "error", attempts: 2, failedAt: at }, before), + ).toBe(true); + expect( + thumbnailRetryDue({ reason: "error", attempts: 3, failedAt: at }, before), + ).toBe(false); + }); }); diff --git a/src/lib/jobs/document-thumbnail-backfill.ts b/src/lib/jobs/document-thumbnail-backfill.ts index cc30f88b2..9dc4b6fda 100644 --- a/src/lib/jobs/document-thumbnail-backfill.ts +++ b/src/lib/jobs/document-thumbnail-backfill.ts @@ -15,6 +15,11 @@ * drops out of the set the moment its thumbnail row lands, so the walk * converges and a re-run picks up where the cap left off. * + * A document whose render failed for good drops out too + * (`DocumentThumbnailFailure`, see {@link thumbnailRetryDue}): a PDF whose + * first page renders blank never gets a thumbnail, and without the record it + * was queued again at every boot, without end. + * * The queue MUST be registered in the maintenance registrar * (`src/lib/jobs/reminder/register-maintenance.ts`) so pg-boss provisions it. */ @@ -45,6 +50,39 @@ const THUMBNAILABLE_MIMES = [ "application/pdf", ] as const; +/** + * Render refusals that the same bytes will always get again: the first page + * renders blank, the render comes out empty, the image is past the pixel cap. + * One attempt settles them. + */ +const FINAL_THUMBNAIL_FAILURES = [ + "raster-failed", + "empty-render", + "pixel-cap", +] as const; + +/** Attempts any other failure (a throw, a key that did not open) gets. */ +export const MAX_THUMBNAIL_ATTEMPTS = 3; + +/** + * Whether a document whose render failed is due another try: never after a + * final refusal or the last attempt, unless the document changed since. The + * boot discovery's SQL states the same rule. + */ +export function thumbnailRetryDue( + failure: { reason: string; attempts: number; failedAt: Date } | null, + documentUpdatedAt: Date, +): boolean { + if (!failure) return true; + if (documentUpdatedAt > failure.failedAt) return true; + if ( + (FINAL_THUMBNAIL_FAILURES as readonly string[]).includes(failure.reason) + ) { + return false; + } + return failure.attempts < MAX_THUMBNAIL_ATTEMPTS; +} + export interface ThumbnailBackfillPayload { userId: string; enqueuedAt?: string; @@ -67,22 +105,37 @@ export async function runThumbnailBackfillForUser( for (;;) { if (enqueued >= MAX_ENQUEUES_PER_RUN) break; - const rows: { id: string }[] = await prisma.inboundDocument.findMany({ + const rows: Array<{ + id: string; + updatedAt: Date; + thumbnailFailure: { + reason: string; + attempts: number; + failedAt: Date; + } | null; + }> = await prisma.inboundDocument.findMany({ where: { userId, deletedAt: null, mimeType: { in: [...THUMBNAILABLE_MIMES] }, thumbnail: { is: null }, }, - select: { id: true }, + select: { + id: true, + updatedAt: true, + thumbnailFailure: { + select: { reason: true, attempts: true, failedAt: true }, + }, + }, orderBy: { id: "asc" }, take: PAGE_SIZE, ...(cursor ? { cursor: { id: cursor }, skip: 1 } : {}), }); if (rows.length === 0) break; - for (const { id } of rows) { + for (const { id, updatedAt, thumbnailFailure } of rows) { if (enqueued >= MAX_ENQUEUES_PER_RUN) break; + if (!thumbnailRetryDue(thumbnailFailure, updatedAt)) continue; const { enqueued: ok } = await enqueueDocumentThumbnail(userId, id); if (ok) enqueued += 1; } @@ -119,13 +172,26 @@ export async function enqueueBootTimeThumbnailBackfill(): Promise<{ // `(user_id, mime_type) WHERE deleted_at IS NULL` bounds the document-side // scan; `document_thumbnails.document_id` is already UNIQUE (the 1:1 // relation) so the `t.id IS NULL` anti-join is index-driven. + // + // A document whose render failed for good is left out by the rule + // `thumbnailRetryDue` states, so an account whose only missing previews + // cannot be made is not queued at every boot. const rows = await prisma.$queryRaw<{ user_id: string }[]>` SELECT DISTINCT d.user_id AS user_id FROM inbound_documents d LEFT JOIN document_thumbnails t ON t.document_id = d.id + LEFT JOIN document_thumbnail_failures f ON f.document_id = d.id WHERE d.deleted_at IS NULL AND d.mime_type IN (${Prisma.join([...THUMBNAILABLE_MIMES])}) - AND t.id IS NULL`; + AND t.id IS NULL + AND ( + f.document_id IS NULL + OR d.updated_at > f.failed_at + OR ( + f.reason NOT IN (${Prisma.join([...FINAL_THUMBNAIL_FAILURES])}) + AND f.attempts < ${MAX_THUMBNAIL_ATTEMPTS} + ) + )`; let enqueued = 0; for (const { user_id: userId } of rows) { diff --git a/src/lib/jobs/document-thumbnail.ts b/src/lib/jobs/document-thumbnail.ts index 1b0a1a91d..3e4dddbe1 100644 --- a/src/lib/jobs/document-thumbnail.ts +++ b/src/lib/jobs/document-thumbnail.ts @@ -105,6 +105,7 @@ async function renderThumbnail( meta: { documentId }, }); warn("decrypt-failed"); + await recordThumbnailFailure(userId, document.id, "decrypt-failed"); return; } @@ -117,6 +118,15 @@ async function renderThumbnail( // An Office or text document has no preview by design; anything else // was meant to get one. if (result.reason !== "unsupported-type") warn(result.reason); + // Kept, so the boot-time backfill stops queueing a document whose render + // cannot succeed. An unsupported type is never queued by it; a host + // without the canvas build never runs it. + if ( + result.reason !== "unsupported-type" && + result.reason !== "native-canvas-unsupported" + ) { + await recordThumbnailFailure(userId, document.id, result.reason); + } return; } @@ -144,12 +154,33 @@ async function renderThumbnail( }, }); + await prisma.documentThumbnailFailure.deleteMany({ + where: { documentId: document.id }, + }); + annotate({ action: { name: "documents.thumbnail.run" }, meta: { documentId, generated: true, byteSize: jpeg.byteLength }, }); } +/** + * Note that a render failed, counting the attempts since the last success + * (`DocumentThumbnailFailure`). `userId` comes from the scoped load. + */ +async function recordThumbnailFailure( + userId: string, + documentId: string, + reason: string, +): Promise { + const failedAt = new Date(); + await prisma.documentThumbnailFailure.upsert({ + where: { documentId }, + create: { documentId, userId, reason, attempts: 1, failedAt }, + update: { reason, attempts: { increment: 1 }, failedAt }, + }); +} + /** * Enqueue a per-document thumbnail job. Coalesced by `singletonKey` per * document so a duplicate/idempotent re-upload cannot pile up parallel runs. diff --git a/tests/integration/document-thumbnail-backfill.test.ts b/tests/integration/document-thumbnail-backfill.test.ts new file mode 100644 index 000000000..7ac445646 --- /dev/null +++ b/tests/integration/document-thumbnail-backfill.test.ts @@ -0,0 +1,143 @@ +/** + * A document whose preview cannot be rendered is not queued again on every + * boot. + * + * What this pins. The boot-time backfill queued every thumbnailable document + * without a thumbnail, and a PDF whose first page renders blank never gets + * one: it was queued, rendered, refused, and queued again at the next boot, + * forever. The failure is now kept with the document, the backfill leaves a + * document that failed for good alone, and a document that changed after the + * failure is tried once more. A preview that does get made clears it. + * + * Both ends against the real schema: the job writes the failure, the boot + * discovery and the per-account pass read it. Only the renderer and the queue + * are stand-ins, so the outcome of a render can be chosen. + */ +import { beforeEach, describe, expect, it, vi } from "vitest"; + +const generateThumbnail = vi.hoisted(() => vi.fn()); +const sends = vi.hoisted(() => [] as Array<{ queue: string; data: unknown }>); + +vi.mock("@/lib/documents/thumbnail", () => ({ generateThumbnail })); +vi.mock("@/lib/documents/native-canvas-support", () => ({ + nativeCanvasSupported: () => true, +})); +vi.mock("@/lib/jobs/boss-instance", () => ({ + getGlobalBoss: () => ({ + send: async (queue: string, data: unknown) => { + sends.push({ queue, data }); + return `job-${sends.length}`; + }, + }), +})); + +import { encryptDocumentContent } from "@/lib/documents/store"; +import { runDocumentThumbnail } from "@/lib/jobs/document-thumbnail"; +import { + enqueueBootTimeThumbnailBackfill, + runThumbnailBackfillForUser, +} from "@/lib/jobs/document-thumbnail-backfill"; +import { getPrismaClient, truncateAllTables } from "./setup"; + +const prisma = getPrismaClient(); +const USER_ID = "thumbnail-backfill-owner"; + +async function seedPdf(id: string) { + const { content, codec } = encryptDocumentContent( + Buffer.from("%PDF-1.7 a page that renders blank"), + ); + await prisma.inboundDocument.create({ + data: { + id, + userId: USER_ID, + mimeType: "application/pdf", + byteSize: 32, + contentEncrypted: content, + contentCodec: codec, + title: id, + }, + }); +} + +function queuedDocuments(): string[] { + return sends + .filter((s) => s.queue === "document-thumbnail") + .map((s) => (s.data as { documentId: string }).documentId); +} + +beforeEach(async () => { + await truncateAllTables(prisma); + sends.length = 0; + generateThumbnail.mockReset(); + await prisma.user.create({ + data: { id: USER_ID, username: "thumbnail-backfill-owner" }, + }); +}); + +describe("thumbnail backfill and a render that fails for good", () => { + it("leaves a document whose render failed for good out of every later backfill", async () => { + await seedPdf("doc-blank"); + await seedPdf("doc-fine"); + generateThumbnail.mockResolvedValue({ ok: false, reason: "raster-failed" }); + await runDocumentThumbnail({ userId: USER_ID, documentId: "doc-blank" }); + + sends.length = 0; + await runThumbnailBackfillForUser(USER_ID); + expect(queuedDocuments()).toEqual(["doc-fine"]); + + // The boot discovery still finds the account, for the other document, + // and stops finding it once that one has its preview. + sends.length = 0; + expect((await enqueueBootTimeThumbnailBackfill()).enqueued).toBe(1); + generateThumbnail.mockResolvedValue({ + ok: true, + thumbnail: { jpeg: Buffer.from([0xff, 0xd8, 0xff]), width: 2, height: 3 }, + }); + await runDocumentThumbnail({ userId: USER_ID, documentId: "doc-fine" }); + sends.length = 0; + expect((await enqueueBootTimeThumbnailBackfill()).enqueued).toBe(0); + expect(await runThumbnailBackfillForUser(USER_ID)).toEqual({ enqueued: 0 }); + }); + + it("tries a failed document again once it has changed, and forgets the failure when a preview is made", async () => { + await seedPdf("doc-blank"); + generateThumbnail.mockResolvedValue({ ok: false, reason: "raster-failed" }); + await runDocumentThumbnail({ userId: USER_ID, documentId: "doc-blank" }); + sends.length = 0; + expect(await runThumbnailBackfillForUser(USER_ID)).toEqual({ enqueued: 0 }); + + // A later edit is a change: the document is tried once more. + await new Promise((resolve) => setTimeout(resolve, 5)); + await prisma.inboundDocument.update({ + where: { id: "doc-blank" }, + data: { title: "renamed" }, + }); + expect(await runThumbnailBackfillForUser(USER_ID)).toEqual({ enqueued: 1 }); + sends.length = 0; + expect((await enqueueBootTimeThumbnailBackfill()).enqueued).toBe(1); + + generateThumbnail.mockResolvedValue({ + ok: true, + thumbnail: { jpeg: Buffer.from([0xff, 0xd8, 0xff]), width: 2, height: 3 }, + }); + await runDocumentThumbnail({ userId: USER_ID, documentId: "doc-blank" }); + expect( + await prisma.documentThumbnailFailure.count({ + where: { documentId: "doc-blank" }, + }), + ).toBe(0); + }); + + it("gives a render that failed by a throw three tries, not one", async () => { + await seedPdf("doc-flaky"); + generateThumbnail.mockResolvedValue({ ok: false, reason: "error" }); + for (let attempt = 1; attempt <= 3; attempt++) { + sends.length = 0; + expect(await runThumbnailBackfillForUser(USER_ID)).toEqual({ + enqueued: 1, + }); + await runDocumentThumbnail({ userId: USER_ID, documentId: "doc-flaky" }); + } + expect(await runThumbnailBackfillForUser(USER_ID)).toEqual({ enqueued: 0 }); + }); +});