From 2910672b5aeb3b2989e8ff7f7633e55cd097ce79 Mon Sep 17 00:00:00 2001 From: Julian Cuni Date: Sun, 30 Aug 2026 18:11:23 +0200 Subject: [PATCH] fix(backup): persist last-success/error status; wall-clock-based schedule MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit BackupService tracked last-success/last-error as plain in-process fields and scheduled the daily backup via setInterval measured from process start — so any server restart (deploy/crash/OOM/reboot, routine under `restart: always`) silently reset the admin UI to "last successful backup: Never" and drifted the actual cadence, independent of whether backups were writing correctly to disk (they were — a real field incident at park-buzi showed 7 valid rotating backups on disk with the status stuck on "Never"). Persist last-success/error to new site_config columns (migration 0025) and add BackupService.isDue(), computed from the persisted timestamp instead of process uptime; server.ts now polls every 15 min and lets isDue() gate the actual run. No API/UI contract change. Claude-Session: https://claude.ai/code/session_01FWncR69HgGPuei1dLrW3cU --- apps/server/src/backup-service.test.ts | 139 ++++++++++++++++++ apps/server/src/backup-service.ts | 88 ++++++++--- apps/server/src/server.ts | 20 ++- .../db/drizzle/0025_backup_last_status.sql | 11 ++ packages/db/drizzle/meta/_journal.json | 7 + packages/db/src/schema.ts | 14 ++ wiki/concepts/backup-recovery.md | 66 ++++++++- 7 files changed, 317 insertions(+), 28 deletions(-) create mode 100644 apps/server/src/backup-service.test.ts create mode 100644 packages/db/drizzle/0025_backup_last_status.sql diff --git a/apps/server/src/backup-service.test.ts b/apps/server/src/backup-service.test.ts new file mode 100644 index 0000000..c24f895 --- /dev/null +++ b/apps/server/src/backup-service.test.ts @@ -0,0 +1,139 @@ +import { mkdtempSync, rmSync, writeFileSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { eq, siteConfig } from "@parking/db"; +import { createTestDb } from "@parking/db/testing"; +import { afterEach, beforeEach, describe, expect, it } from "vitest"; +import { BackupService } from "./backup-service.js"; + +// BackupService previously tracked last-success/last-error as plain in-process fields, so a +// server restart (a fresh BackupService instance, exactly as happens on every deploy/crash/OOM +// reboot under `restart: always`) silently reset the admin UI to "last successful backup: +// Never" — even with valid, correctly-rotating backups already on disk (2026-08-30 field +// incident, park-buzi). These tests exercise the fix: status is read from site_config, so a new +// BackupService instance pointed at the same DB sees the prior instance's last-run outcome, and +// the schedule is wall-clock-based (isDue()) rather than time-since-process-start. +// See wiki/concepts/backup-recovery.md. + +const KEY = "a-test-backup-key-that-is-long-enough"; + +let workDir: string; +let target: string; + +beforeEach(() => { + workDir = mkdtempSync(join(tmpdir(), "pk-backup-service-test-")); + target = join(workDir, "target"); + process.env.BACKUP_KEY = KEY; +}); + +afterEach(() => { + rmSync(workDir, { recursive: true, force: true }); + delete process.env.BACKUP_KEY; +}); + +function setTargetDir(db: ReturnType["db"], dir: string): void { + const existing = db.select().from(siteConfig).where(eq(siteConfig.id, 1)).get(); + if (existing) { + db.update(siteConfig).set({ backupTargetDir: dir }).where(eq(siteConfig.id, 1)).run(); + } else { + db.insert(siteConfig).values({ id: 1, backupTargetDir: dir }).run(); + } +} + +describe("BackupService — persisted status survives a restart", () => { + it("a fresh instance sees the previous instance's last success", async () => { + const t = createTestDb(); + setTargetDir(t.db, target); + + const first = new BackupService(t.db); + expect(first.status().lastSuccessAt).toBeNull(); + const result = await first.run("manual"); + + // Simulate a process restart: a brand-new BackupService over the SAME db handle (in + // production this would be a fresh process re-opening the same sqlite file). + const second = new BackupService(t.db); + const status = second.status(); + expect(status.lastSuccessAt).not.toBeNull(); + expect(status.lastResult).toEqual({ path: result.path, bytes: result.bytes, prunedFiles: result.prunedFiles }); + expect(status.lastError).toBeNull(); + + t.close(); + }); + + it("a fresh instance sees the previous instance's last error, and it clears on next success", async () => { + const t = createTestDb(); + // Target dir set, but as a FILE (not a directory) — runBackup's mkdir(recursive) will + // throw, giving us a real, deterministic failure without needing to mock anything. + const badTarget = join(workDir, "not-a-dir"); + writeFileSync(badTarget, "x"); + setTargetDir(t.db, badTarget); + + const first = new BackupService(t.db); + await expect(first.run("manual")).rejects.toThrow(); + + const second = new BackupService(t.db); + const status = second.status(); + expect(status.lastError).not.toBeNull(); + expect(status.lastErrorAt).not.toBeNull(); + expect(status.lastSuccessAt).toBeNull(); + + // Now point at a real directory and succeed — the persisted error must clear. + setTargetDir(t.db, target); + await second.run("manual"); + const third = new BackupService(t.db); + const finalStatus = third.status(); + expect(finalStatus.lastSuccessAt).not.toBeNull(); + expect(finalStatus.lastError).toBeNull(); + expect(finalStatus.lastErrorAt).toBeNull(); + + t.close(); + }); +}); + +describe("BackupService — isDue() is wall-clock-based, not process-uptime-based", () => { + it("is due immediately when no success has ever been recorded", () => { + const t = createTestDb(); + const svc = new BackupService(t.db); + expect(svc.isDue()).toBe(true); + t.close(); + }); + + it("is NOT due right after a fresh instance is constructed, if a recent success is persisted", async () => { + const t = createTestDb(); + setTargetDir(t.db, target); + const first = new BackupService(t.db); + await first.run("manual"); + + // The whole point of the fix: a brand-new instance (simulating a restart moments after a + // real backup completed) must NOT think a backup is due just because ITS OWN uptime is ~0. + const second = new BackupService(t.db); + expect(second.isDue()).toBe(false); + t.close(); + }); + + it("is due once the persisted last-success timestamp is old enough", async () => { + const t = createTestDb(); + setTargetDir(t.db, target); + const svc = new BackupService(t.db); + await svc.run("manual"); + + const almostADayLater = new Date(Date.now() + 23 * 60 * 60 * 1000); + expect(svc.isDue(almostADayLater)).toBe(false); + + const overADayLater = new Date(Date.now() + 24 * 60 * 60 * 1000 + 1000); + expect(svc.isDue(overADayLater)).toBe(true); + t.close(); + }); + + it("runScheduled() is a no-op when not yet due, even if configured", async () => { + const t = createTestDb(); + setTargetDir(t.db, target); + const svc = new BackupService(t.db); + await svc.run("manual"); + const afterFirst = svc.status().lastSuccessAt; + + await svc.runScheduled(); // not due yet — must not run again + expect(svc.status().lastSuccessAt).toBe(afterFirst); + t.close(); + }); +}); diff --git a/apps/server/src/backup-service.ts b/apps/server/src/backup-service.ts index 9a4a507..721b01b 100644 --- a/apps/server/src/backup-service.ts +++ b/apps/server/src/backup-service.ts @@ -11,6 +11,12 @@ import { DEFAULT_BACKUP_RETENTION, runBackup, type BackupResult, type BackupRete // a key must never live in the DB it backs up. Remembers the last outcome so the route + UI can // show last-success / last-error, and serializes concurrent runs (manual + timer). See // wiki/concepts/backup-recovery.md. +// +// Last-success/last-error are PERSISTED to site_config (backup_last_*), not just held in +// memory — an earlier version tracked these as plain in-process fields only, so every server +// restart (deploy, crash, OOM, host reboot — all routine under `restart: always`) silently +// reset the admin UI to "last successful backup: Never", even with valid, correctly-rotating +// backups already on disk (2026-08-30 field incident, park-buzi). See wiki/concepts/backup-recovery.md. /** The dedicated backup-encryption key, from env (NOT the DB). Separate from EVENT_SIGNING_KEY. */ export function backupKeyFromEnv(): string { @@ -65,16 +71,33 @@ export class BackupService { readonly #logger?: FastifyBaseLogger; #running = false; - #lastSuccessAt: string | null = null; - #lastResult: BackupResult | null = null; - #lastErrorAt: string | null = null; - #lastError: string | null = null; constructor(db: Db, logger?: FastifyBaseLogger) { this.#db = db; this.#logger = logger; } + /** Fresh read of the persisted row (single source of truth — no in-memory cache to go stale + * or reset on restart). */ + #row(): { backupLastSuccessAt: string | null; backupLastResultJson: string | null; backupLastErrorAt: string | null; backupLastError: string | null } | undefined { + return this.#db.select().from(siteConfig).where(eq(siteConfig.id, 1)).get(); + } + + #persist(patch: { + backupLastSuccessAt?: string | null; + backupLastResultJson?: string | null; + backupLastErrorAt?: string | null; + backupLastError?: string | null; + }): void { + const updatedAt = new Date().toISOString(); + const existing = this.#row(); + if (existing) { + this.#db.update(siteConfig).set({ ...patch, updatedAt }).where(eq(siteConfig.id, 1)).run(); + } else { + this.#db.insert(siteConfig).values({ id: 1, ...patch, updatedAt }).run(); + } + } + /** The admin-chosen target dir from site_config (null/empty = unset). Read fresh each call. */ targetDir(): string | null { const row = this.#db.select().from(siteConfig).where(eq(siteConfig.id, 1)).get(); @@ -104,6 +127,15 @@ export class BackupService { status(): BackupStatus { const r = this.retention(); + const row = this.#row(); + let lastResult: BackupStatus["lastResult"] = null; + if (row?.backupLastResultJson) { + try { + lastResult = JSON.parse(row.backupLastResultJson) as BackupStatus["lastResult"]; + } catch { + lastResult = null; // corrupt/foreign value in the column — don't let it crash status() + } + } return { configured: this.configured, targetDir: this.targetDir(), @@ -111,12 +143,10 @@ export class BackupService { keepDailyDays: r.keepDailyDays, keyPresent: this.keyPresent, running: this.#running, - lastSuccessAt: this.#lastSuccessAt, - lastResult: this.#lastResult - ? { path: this.#lastResult.path, bytes: this.#lastResult.bytes, prunedFiles: this.#lastResult.prunedFiles } - : null, - lastErrorAt: this.#lastErrorAt, - lastError: this.#lastError, + lastSuccessAt: row?.backupLastSuccessAt ?? null, + lastResult, + lastErrorAt: row?.backupLastErrorAt ?? null, + lastError: row?.backupLastError ?? null, }; } @@ -139,14 +169,17 @@ export class BackupService { try { this.#logger?.info(`backup: starting (${trigger}) → ${targetDir}`); const res = await runBackup(this.#db, { targetDir, key, retention: this.retention() }, this.#logger); - this.#lastResult = res; - this.#lastSuccessAt = new Date().toISOString(); - this.#lastError = null; + this.#persist({ + backupLastSuccessAt: new Date().toISOString(), + backupLastResultJson: JSON.stringify({ path: res.path, bytes: res.bytes, prunedFiles: res.prunedFiles }), + backupLastErrorAt: null, + backupLastError: null, + }); return res; } catch (err) { - this.#lastError = (err as Error).message; - this.#lastErrorAt = new Date().toISOString(); - this.#logger?.error(`backup: failed (${trigger}): ${this.#lastError}`); + const message = (err as Error).message; + this.#persist({ backupLastErrorAt: new Date().toISOString(), backupLastError: message }); + this.#logger?.error(`backup: failed (${trigger}): ${message}`); throw err; } finally { this.#running = false; @@ -156,13 +189,34 @@ export class BackupService { return this.#inflight; } - /** Scheduled-run wrapper: never throws (a timer must not crash the process). */ + /** + * Scheduled-run wrapper: never throws (a timer must not crash the process). Safe to call on + * a short, frequent poll (see server.ts) — it's a no-op unless `isDue()` says a full interval + * has actually elapsed since the last recorded success, so frequent polling doesn't cause + * frequent backups. + */ async runScheduled(): Promise { if (!this.configured) return; // silent no-op when backups aren't set up + if (!this.isDue()) return; try { await this.run("scheduled"); } catch { /* recorded in last-error; already logged */ } } + + /** + * Wall-clock check: has enough time elapsed since the last successful backup for a new one + * to be due? Deliberately based on the PERSISTED last-success instant, not "time since this + * process started" — a `setInterval(..., 24h)` measured from process start silently drifts + * (or skips a whole day) across every restart, since the countdown restarts from zero each + * time regardless of when the last real backup happened. See wiki/concepts/backup-recovery.md. + */ + isDue(now: Date = new Date(), intervalMs = 24 * 60 * 60 * 1000): boolean { + const lastSuccessAt = this.#row()?.backupLastSuccessAt; + if (!lastSuccessAt) return true; // never recorded a success → due immediately once configured + const last = new Date(lastSuccessAt).getTime(); + if (Number.isNaN(last)) return true; + return now.getTime() - last >= intervalMs; + } } diff --git a/apps/server/src/server.ts b/apps/server/src/server.ts index 66184b3..e540937 100644 --- a/apps/server/src/server.ts +++ b/apps/server/src/server.ts @@ -336,12 +336,20 @@ export async function buildServer(opts: BuildOptions = {}): Promise clearInterval(snapPruneTimer)); - // Scheduled encrypted backup — daily, unref'd. A no-op (silent) until BACKUP_TARGET_DIR + - // BACKUP_KEY are configured; tolerates an unreachable/unmounted target by recording the - // error and trying again next run. NOT run once at startup (a just-booted appliance after a - // power cut shouldn't immediately write to a possibly-not-yet-mounted disk; the daily cadence - // and the manual button cover it). See wiki/concepts/backup-recovery.md. - const backupTimer = setInterval(() => void backupService.runScheduled(), 24 * 60 * 60 * 1000); + // Scheduled encrypted backup — checked every 15 min, unref'd; `runScheduled()` itself is a + // no-op unless a full 24h has actually elapsed since the last PERSISTED success (isDue(), in + // backup-service.ts), so this frequent poll does not cause frequent backups. Deliberately + // NOT a `setInterval(..., 24h)` measured from process start: that design silently reset its + // own countdown on every restart (deploy/crash/OOM/reboot, all routine under `restart: + // always`), which could push a day's backup out arbitrarily far AND — before last-success was + // persisted — made the admin UI show "Never" despite valid backups already on disk + // (2026-08-30 field incident, park-buzi). A short poll against a persisted, wall-clock + // timestamp is immune to both restart timing and to any single restart cadence. A no-op + // (silent) until BACKUP_TARGET_DIR + BACKUP_KEY are configured; tolerates an + // unreachable/unmounted target by recording the error and trying again next check. NOT run + // once at startup (a just-booted appliance after a power cut shouldn't immediately write to a + // possibly-not-yet-mounted disk). See wiki/concepts/backup-recovery.md. + const backupTimer = setInterval(() => void backupService.runScheduled(), 15 * 60 * 1000); backupTimer.unref(); app.addHook("onClose", async () => clearInterval(backupTimer)); if (backupService.configured) { diff --git a/packages/db/drizzle/0025_backup_last_status.sql b/packages/db/drizzle/0025_backup_last_status.sql new file mode 100644 index 0000000..455d078 --- /dev/null +++ b/packages/db/drizzle/0025_backup_last_status.sql @@ -0,0 +1,11 @@ +-- Last-success/last-error for the encrypted DB backup were previously tracked only as +-- in-process fields on BackupService (never written to the DB) — so every server restart +-- (deploy/crash/OOM/host reboot, all routine under `restart: always`) silently reset the admin +-- UI's "last successful backup" to "Never", even with valid, correctly-rotating backups already +-- on disk (2026-08-30 field incident, park-buzi). Four additive, nullable columns; null = no +-- run recorded yet (or, for the error pair, no failure since the last success). See +-- wiki/concepts/backup-recovery.md. +ALTER TABLE `site_config` ADD `backup_last_success_at` text;--> statement-breakpoint +ALTER TABLE `site_config` ADD `backup_last_result_json` text;--> statement-breakpoint +ALTER TABLE `site_config` ADD `backup_last_error_at` text;--> statement-breakpoint +ALTER TABLE `site_config` ADD `backup_last_error` text; diff --git a/packages/db/drizzle/meta/_journal.json b/packages/db/drizzle/meta/_journal.json index 5a3fe68..b16c367 100644 --- a/packages/db/drizzle/meta/_journal.json +++ b/packages/db/drizzle/meta/_journal.json @@ -176,6 +176,13 @@ "when": 1783948800000, "tag": "0024_validation_programs", "breakpoints": true + }, + { + "idx": 25, + "version": "6", + "when": 1788078414270, + "tag": "0025_backup_last_status", + "breakpoints": true } ] } \ No newline at end of file diff --git a/packages/db/src/schema.ts b/packages/db/src/schema.ts index eff0eeb..3465191 100644 --- a/packages/db/src/schema.ts +++ b/packages/db/src/schema.ts @@ -288,6 +288,20 @@ export const siteConfig = sqliteTable("site_config", { backupKeepLast: integer("backup_keep_last"), /** Beyond keepLast, keep one backup per day for this many days. null ⇒ code default (30). */ backupKeepDailyDays: integer("backup_keep_daily_days"), + /** ISO timestamp of the last backup that actually completed successfully. Persisted here + * (not just in-process memory) so the admin UI's "last successful backup" survives a + * server restart — before this column existed, a restart silently reset that status to + * "Never" even with valid backups already on disk. null = no successful run recorded yet. + * See wiki/concepts/backup-recovery.md. */ + backupLastSuccessAt: text("backup_last_success_at"), + /** JSON-encoded { path, bytes, prunedFiles } of the last successful run, for the same + * restart-durability reason as backupLastSuccessAt. null = none recorded yet. */ + backupLastResultJson: text("backup_last_result_json"), + /** ISO timestamp of the last FAILED scheduled/manual backup attempt, persisted for the same + * reason. null = no failure recorded (or none since the last success). */ + backupLastErrorAt: text("backup_last_error_at"), + /** Error message of the last failed attempt. Cleared (set null) on the next success. */ + backupLastError: text("backup_last_error"), updatedAt: text("updated_at") .notNull() .default(sql`(current_timestamp)`), diff --git a/wiki/concepts/backup-recovery.md b/wiki/concepts/backup-recovery.md index d8c3d32..a027f0d 100644 --- a/wiki/concepts/backup-recovery.md +++ b/wiki/concepts/backup-recovery.md @@ -2,7 +2,7 @@ type: concept tags: [parking, durability, backup, recovery, security, crypto] sources: [] -updated: 2026-06-29 +updated: 2026-08-30 --- # Backup & Disaster Recovery @@ -207,12 +207,68 @@ timer + the manual route**. What landed: **SMB/NFS already work** — they're just a mounted path the admin enters as the target. **Deferred to follow-up slices:** an **SFTP** target and a **restore runbook / CLI**. +## Field bug — "last successful backup: Never" despite valid, rotating backups on disk (found + fixed 2026-08-30) + +**Symptom (park-buzi):** the admin noticed the backup directory held 7 real, correctly-sized, +correctly-rotating encrypted backups (`parking-backup-*.sqlite.enc`, retention working exactly as +designed) — yet the Backup screen's "Kopja e fundit e suksesshme" (last successful backup) showed +**"Asnjëherë" (Never)**. Separately, the most recent file was 2 days old rather than ~1. + +**Root cause — two independent, disconnected code paths, both traced to `setInterval`-since- +process-start:** + +1. **Status was never persisted.** `BackupService` tracked `lastSuccessAt`/`lastResult`/ + `lastErrorAt`/`lastError` as **plain in-process private fields** — set only inside `run()`, + read only by `status()` on the *same running instance*. Nothing wrote them to `site_config` or + anywhere else durable. The actual backup-writing engine (`backup.ts`: consistent copy → encrypt + → `pruneOldBackups`) is a completely separate code path that only touches the filesystem and + has no notion of this status object. So "7 valid files on disk" and "status says Never" were + never contradictory — they were two unrelated signals, and **any** server restart (deploy, + crash, OOM, host reboot — all routine under `restart: always` in `docker-compose.prod.yml`) + silently reset the in-memory fields to `null` regardless of what had actually happened on disk. +2. **The schedule was measured from process start, not from the last real backup.** The daily + timer was `setInterval(() => backupService.runScheduled(), 24h)` — a fixed 24h period counted + from whenever the *process* last started, not from wall-clock time or from when a backup last + actually succeeded. The exact same restart that wiped the in-memory status also reset this + countdown, which is why the cadence can silently drift or skip past a day with no error ever + surfacing anywhere. + +Both symptoms are one cause: **the server process restarted after the Aug 28 backup, and nothing +about this design was built to survive that.** + +### Fix (2026-08-30) + +- **`packages/db/src/schema.ts`** / migration `0025_backup_last_status.sql` — four new nullable + `site_config` columns: `backup_last_success_at`, `backup_last_result_json`, + `backup_last_error_at`, `backup_last_error`. Same table, same upsert pattern as + `backup_target_dir`/`backup_keep_last`/`backup_keep_daily_days` (migrations 0016/0017). +- **`backup-service.ts`** — `run()` now writes success/error outcomes to these columns (via a + `#persist` upsert helper) instead of private fields; `status()` reads them fresh from the DB on + every call. A brand-new `BackupService` instance (i.e. a fresh process) now sees exactly what + the previous instance last recorded — no more restart amnesia. +- **New `isDue(now, intervalMs = 24h)`** method: due iff `now - backupLastSuccessAt >= 24h` (or + immediately due if no success was ever recorded), computed from the **persisted** timestamp — + never from process uptime. +- **`server.ts`** — the daily `setInterval` was replaced with a **15-minute poll** calling + `runScheduled()`, which now itself no-ops unless `isDue()` is true. This makes the actual backup + cadence immune to restart timing entirely: however often the process happens to restart, the + next backup fires within 15 minutes of 24h having genuinely elapsed since the last real success + — not 24h after whatever moment the process most recently came back up. +- Covered by a new `backup-service.test.ts`: a fresh `BackupService` over the same DB handle + (simulating a restart) sees the prior instance's last success/error and its cleared-on-success + behavior; `isDue()` is exercised directly against injected timestamps rather than real sleeps. + +No change to the `BackupStatus` shape returned by `GET /api/backup/status` or to +`BackupSettings.tsx` — this was purely a durability fix underneath the same contract. + ## Status Design settled 2026-06-29; **engine + admin-configured local/mounted target + admin UI BUILT 2026-06-29** (SFTP + restore tooling pending). The target directory is **admin-chosen in the UI** (`site_config`, migration 0016), not an env var — the on-site admin picks where backups land; only -`BACKUP_KEY` stays a server secret. Resolves the *design* half of [[open-questions]] #5 and the first -build slices; records the key-custody stance that bears on #6 (signing stays decoupled from the TPM) and -#10 (snapshots bloat backups → future exclude toggle). See [[append-only-event-chain]], -[[disk-os-hardening]], [[tpm]], [[fleet-deployment-komodo]], [[reconciliation]]. +`BACKUP_KEY` stays a server secret. **Last-success/last-error status + the scheduling cadence are +now restart-durable (migration 0025, 2026-08-30)** — see field bug above. Resolves the *design* +half of [[open-questions]] #5 and the first build slices; records the key-custody stance that bears +on #6 (signing stays decoupled from the TPM) and #10 (snapshots bloat backups → future exclude +toggle). See [[append-only-event-chain]], [[disk-os-hardening]], [[tpm]], [[fleet-deployment-komodo]], +[[reconciliation]].