Public: anyone can read this; the crew can change it.
The restore drill's time limit grows with the size of the snapshot it restores #2620
Check · Review · Land · Live done — Landed and live in production.
torque/forge:torque/2617-the-restore-drill-s-time-limit-grows-wit → main 3 commits fork 1 thread · 1 unresolved
3 files
changed +160
−16
docs/RECOVERY.md +6 −5
| @@ -13,11 +13,12 @@ the newest; no object is called that. | ||
| 13 | 13 | ## Where the verdicts are posted |
| 14 | 14 | |
| 15 | 15 | Sundays 09:00 UTC the forge drills a restore of the newest snapshot, boots it |
| 16 | on a side port and reads `/api/v1/health`. One comment lands on the recovery | |
| 17 | issue (`FORGE_RECOVERY_ISSUE` in `FORGE_RECOVERY_REPO`): snapshot, restore | |
| 18 | time, health, counts, pass or fail. A failed drill is an inbox card naming | |
| 19 | the step (fetch, restore, open, count, unseal, health), run again at boot and | |
| 20 | every three hours until one passes. No comment this week: backups unproven. | |
| 16 | on a side port and reads `/api/v1/health`, all within 10 min plus 60 s per GiB | |
| 17 | of the snapshot's `bytes`, at most 45 min. One comment lands on the recovery | |
| 18 | issue (`FORGE_RECOVERY_ISSUE` in `FORGE_RECOVERY_REPO`): snapshot, restore time, | |
| 19 | health, counts, pass or fail. A failed drill is an inbox card naming the step | |
| 20 | (fetch, restore, open, count, unseal, health) and its budget, run again at boot | |
| 21 | and every three hours until one passes. No comment this week: backups unproven. | |
| 21 | 22 | |
| 22 | 23 | ## What a restore needs |
| 23 | 24 |
src/snapshot/drill.ts +59 −7
| @@ -7,7 +7,8 @@ | ||
| 7 | 7 | * |
| 8 | 8 | * Plain data out: when it ran, which snapshot, how long, what it counted, |
| 9 | 9 | * and a verdict. A red verdict names the step that failed; a step that |
| 10 | * hangs past the timeout is red too, naming the step it hung in. | |
| 10 | * hangs past the budget is red too, naming the step it hung in and the | |
| 11 | * budget it had. The budget grows with the snapshot (`drillBudgetMs`). | |
| 11 | 12 | */ |
| 12 | 13 | |
| 13 | 14 | import { mkdirSync, mkdtempSync, rmSync } from "node:fs"; |
| @@ -19,7 +20,50 @@ import { restoreSnapshot } from "./restore.ts"; | ||
| 19 | 20 | import { listSnapshots } from "./snapshot.ts"; |
| 20 | 21 | import type { Store } from "./store.ts"; |
| 21 | 22 | |
| 23 | /** The floor of every drill's budget, and the whole budget for finding the newest snapshot. */ | |
| 22 | 24 | export const DRILL_TIMEOUT_MS = 10 * 60_000; |
| 25 | /** What each GiB of snapshot adds to the budget. */ | |
| 26 | export const DRILL_MS_PER_GIB = 60_000; | |
| 27 | /** No snapshot is given longer than this. */ | |
| 28 | export const DRILL_MAX_MS = 45 * 60_000; | |
| 29 | const GIB = 1024 ** 3; | |
| 30 | ||
| 31 | /** | |
| 32 | * How long a drill of a snapshot of `bytes` may take, in whole ms: | |
| 33 | * 10 min + 60 s per GiB (2^30 bytes), capped at 45 min. So 0 B is 10 min, | |
| 34 | * 4 GiB is 14 min, and anything from 35 GiB up is 45 min. A size that is | |
| 35 | * not a finite count of bytes counts as 0. | |
| 36 | */ | |
| 37 | export function drillBudgetMs(bytes: number): number { | |
| 38 | const b = Number.isFinite(bytes) && bytes > 0 ? bytes : 0; | |
| 39 | return Math.min(DRILL_MAX_MS, Math.round(DRILL_TIMEOUT_MS + (b / GIB) * DRILL_MS_PER_GIB)); | |
| 40 | } | |
| 41 | ||
| 42 | /** A snapshot's size from its manifest, or the sum of its files when the total is missing. */ | |
| 43 | function snapshotBytes(m: { readonly bytes?: unknown; readonly files: readonly { readonly bytes?: unknown }[] }): number { | |
| 44 | if (typeof m.bytes === "number" && Number.isFinite(m.bytes) && m.bytes >= 0) return m.bytes; | |
| 45 | return m.files.reduce((sum, f) => sum + (typeof f.bytes === "number" && Number.isFinite(f.bytes) && f.bytes > 0 ? f.bytes : 0), 0); | |
| 46 | } | |
| 47 | ||
| 48 | /** A budget for people: "14 min", "1.5 s", never a raw float of ms. */ | |
| 49 | export function formatBudget(ms: number): string { | |
| 50 | if (ms >= 60_000) return `${Math.round(ms / 6_000) / 10} min`; | |
| 51 | if (ms >= 1_000) return `${Math.round(ms / 100) / 10} s`; | |
| 52 | return `${Math.round(ms)} ms`; | |
| 53 | } | |
| 54 | ||
| 55 | /** A size for people, binary units with one decimal: "4.1 GiB". */ | |
| 56 | export function formatBytes(bytes: number): string { | |
| 57 | const units = ["KiB", "MiB", "GiB", "TiB"] as const; | |
| 58 | if (bytes < 1024) return `${Math.round(bytes)} B`; | |
| 59 | let v = bytes / 1024; | |
| 60 | let i = 0; | |
| 61 | while (v >= 1024 && i < units.length - 1) { | |
| 62 | v /= 1024; | |
| 63 | i++; | |
| 64 | } | |
| 65 | return `${Math.round(v * 10) / 10} ${units[i]}`; | |
| 66 | } | |
| 23 | 67 | |
| 24 | 68 | export type DrillStep = "fetch" | "restore" | "open" | "count" | "unseal" | "health"; |
| 25 | 69 | |
| @@ -53,10 +97,11 @@ export interface DrillResult { | ||
| 53 | 97 | |
| 54 | 98 | class StepTimeout extends Error {} |
| 55 | 99 | |
| 56 | function within<T>(work: Promise<T>, ms: number): Promise<T> { | |
| 100 | /** Race `work` against `ms`; a loss says `budget`, the whole drill's, not what was left of it. */ | |
| 101 | function within<T>(work: Promise<T>, ms: number, budget: () => string): Promise<T> { | |
| 57 | 102 | let timer: ReturnType<typeof setTimeout>; |
| 58 | 103 | const late = new Promise<never>((_, reject) => { |
| 59 | timer = setTimeout(() => reject(new StepTimeout(`no answer in ${Math.round(ms)} ms`)), ms); | |
| 104 | timer = setTimeout(() => reject(new StepTimeout(`no answer within its ${budget()}`)), ms); | |
| 60 | 105 | }); |
| 61 | 106 | return Promise.race([work, late]).finally(() => clearTimeout(timer)); |
| 62 | 107 | } |
| @@ -65,7 +110,11 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> { | ||
| 65 | 110 | const clock = deps.now ?? (() => new Date()); |
| 66 | 111 | const started = performance.now(); |
| 67 | 112 | const at = clock().toISOString(); |
| 68 | const timeoutMs = deps.timeoutMs ?? DRILL_TIMEOUT_MS; | |
| 113 | // Until the newest snapshot is known its size is not; the floor holds. | |
| 114 | let budgetMs = deps.timeoutMs ?? DRILL_TIMEOUT_MS; | |
| 115 | let sized: number | undefined; | |
| 116 | const budget = (): string => | |
| 117 | `${formatBudget(budgetMs)} budget${sized === undefined ? "" : ` for a ${formatBytes(sized)} snapshot`}`; | |
| 69 | 118 | const restore = deps.restore ?? restoreSnapshot; |
| 70 | 119 | const counts: { -readonly [K in keyof DrillCounts]: number } = { repositories: 0, issues: 0, users: 0, pulls: 0, apps: 0 }; |
| 71 | 120 | let snapshotId: string | null = null; |
| @@ -75,11 +124,12 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> { | ||
| 75 | 124 | let health: DrillResult["health"] = "unreached"; |
| 76 | 125 | try { |
| 77 | 126 | // One clock for the whole drill, so a hang in any step ends it red. |
| 78 | const deadline = started + timeoutMs; | |
| 79 | const left = (): number => Math.max(1, deadline - performance.now()); | |
| 80 | const newest = (await within(listSnapshots(deps.store), left()))[0]; | |
| 127 | const left = (): number => Math.max(1, started + budgetMs - performance.now()); | |
| 128 | const newest = (await within(listSnapshots(deps.store), left(), budget))[0]; | |
| 81 | 129 | if (newest === undefined) throw new Error("the store holds no snapshot"); |
| 82 | 130 | snapshotId = newest.name; |
| 131 | sized = snapshotBytes(newest); | |
| 132 | if (deps.timeoutMs === undefined) budgetMs = drillBudgetMs(sized); | |
| 83 | 133 | |
| 84 | 134 | step = "restore"; |
| 85 | 135 | const parent = join(deps.dataDir, "drill"); |
| @@ -89,6 +139,7 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> { | ||
| 89 | 139 | await within( |
| 90 | 140 | restore(deps.store, newest.name, target, { passphrase: deps.passphrase }), |
| 91 | 141 | left(), |
| 142 | budget, | |
| 92 | 143 | ); |
| 93 | 144 | |
| 94 | 145 | step = "open"; |
| @@ -143,6 +194,7 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> { | ||
| 143 | 194 | const booted = await within( |
| 144 | 195 | (deps.boot ?? bootRestored)(target, left()), |
| 145 | 196 | left(), |
| 197 | budget, | |
| 146 | 198 | ); |
| 147 | 199 | health = booted.ok ? "ok" : "failed"; |
| 148 | 200 | if (!booted.ok) throw new Error(booted.reason); |
test/snapshot-drill.test.ts +95 −4
| @@ -3,7 +3,7 @@ | ||
| 3 | 3 | * counts; a corrupt one drills red naming the step; a hang ends red naming |
| 4 | 4 | * the step; the scratch directory is gone afterwards in every case. |
| 5 | 5 | */ |
| 6 | import { afterAll, beforeAll, describe, expect, test } from "bun:test"; | |
| 6 | import { afterAll, beforeAll, describe, expect, jest, test } from "bun:test"; | |
| 7 | 7 | import { existsSync, mkdtempSync, readdirSync } from "node:fs"; |
| 8 | 8 | import { rm } from "node:fs/promises"; |
| 9 | 9 | import { tmpdir } from "node:os"; |
| @@ -13,13 +13,40 @@ import { enableApp, setAppEnvVar } from "../src/actions/apps.ts"; | ||
| 13 | 13 | import { createApp, type App } from "../src/app.ts"; |
| 14 | 14 | import { createIssue } from "../src/core/issues.ts"; |
| 15 | 15 | import { createUser } from "../src/core/users.ts"; |
| 16 | import { runDrill } from "../src/snapshot/drill.ts"; | |
| 16 | import { drillBudgetMs, formatBudget, formatBytes, runDrill } from "../src/snapshot/drill.ts"; | |
| 17 | 17 | import { pack, partPath } from "../src/snapshot/parts.ts"; |
| 18 | 18 | import { takeSnapshot } from "../src/snapshot/snapshot.ts"; |
| 19 | 19 | import { dirStore } from "../src/snapshot/store.ts"; |
| 20 | 20 | |
| 21 | 21 | const PASS = "correct horse battery staple"; |
| 22 | 22 | |
| 23 | describe("the drill's budget", () => { | |
| 24 | const GiB = 1024 ** 3; | |
| 25 | test("an empty snapshot gets the 10 min floor", () => { | |
| 26 | expect(drillBudgetMs(0)).toBe(600_000); | |
| 27 | }); | |
| 28 | test("4 GiB gets 10 min + 4 × 60 s = 14 min", () => { | |
| 29 | expect(drillBudgetMs(4 * GiB)).toBe(840_000); | |
| 30 | }); | |
| 31 | test("100 GiB would be 110 min; it is capped at 45 min", () => { | |
| 32 | expect(drillBudgetMs(100 * GiB)).toBe(2_700_000); | |
| 33 | }); | |
| 34 | test("a size that is not a count of bytes counts as 0", () => { | |
| 35 | for (const b of [NaN, -5, Infinity]) expect(drillBudgetMs(b)).toBe(600_000); | |
| 36 | }); | |
| 37 | test("budgets read in min, s or whole ms, never a raw float", () => { | |
| 38 | expect(formatBudget(840_000)).toBe("14 min"); | |
| 39 | expect(formatBudget(846_000)).toBe("14.1 min"); | |
| 40 | expect(formatBudget(1500.75)).toBe("1.5 s"); | |
| 41 | expect(formatBudget(250.4)).toBe("250 ms"); | |
| 42 | }); | |
| 43 | test("sizes read in binary units with one decimal", () => { | |
| 44 | expect(formatBytes(Math.round(4.1 * GiB))).toBe("4.1 GiB"); | |
| 45 | expect(formatBytes(512)).toBe("512 B"); | |
| 46 | expect(formatBytes(1536)).toBe("1.5 KiB"); | |
| 47 | }); | |
| 48 | }); | |
| 49 | ||
| 23 | 50 | describe("the restore drill", () => { |
| 24 | 51 | let root: string; |
| 25 | 52 | let app: App; |
| @@ -166,9 +193,73 @@ describe("the restore drill", () => { | ||
| 166 | 193 | expect(scratchLeft()).toEqual([]); |
| 167 | 194 | }); |
| 168 | 195 | |
| 169 | test("a step that times out says its budget in whole milliseconds", async () => { | |
| 196 | test("a step that times out names its budget and the snapshot's size, never a raw float of ms", async () => { | |
| 170 | 197 | const r = await runDrill(deps({ timeoutMs: 1500.75, restore: () => new Promise(() => {}) })); |
| 171 | expect(r.reason).toMatch(/^restore timed out: no answer in \d+ ms$/); | |
| 198 | expect(r.reason).toMatch(/^restore timed out: no answer within its 1\.5 s budget for a [\d.]+ (B|KiB|MiB) snapshot$/); | |
| 199 | }); | |
| 200 | ||
| 201 | /** A store holding one snapshot with this manifest; its objects are never fetched. */ | |
| 202 | const holding = (manifest: object) => ({ | |
| 203 | where: "test", | |
| 204 | put: async () => {}, | |
| 205 | get: async (key: string) => | |
| 206 | key === "snapshots/2026-10-18T08-00-00Z/manifest.json" | |
| 207 | ? new TextEncoder().encode(JSON.stringify({ name: "2026-10-18T08-00-00Z", ...manifest })) | |
| 208 | : undefined, | |
| 209 | list: async () => [], | |
| 210 | names: async () => ["2026-10-18T08-00-00Z"], | |
| 211 | delete: async () => {}, | |
| 212 | }); | |
| 213 | ||
| 214 | /** Drill `manifest` with a restore that hangs, on fake timers; still waiting at `quietMs`, red by `redMs`. */ | |
| 215 | async function hang(manifest: object, quietMs: number, redMs: number) { | |
| 216 | let begun!: () => void; | |
| 217 | const restoring = new Promise<void>((resolve) => (begun = resolve)); | |
| 218 | jest.useFakeTimers(); | |
| 219 | try { | |
| 220 | let done = false; | |
| 221 | const running = runDrill( | |
| 222 | deps({ | |
| 223 | store: holding(manifest), | |
| 224 | restore: () => { | |
| 225 | begun(); | |
| 226 | return new Promise(() => {}); | |
| 227 | }, | |
| 228 | }), | |
| 229 | ).finally(() => (done = true)); | |
| 230 | await restoring; | |
| 231 | jest.advanceTimersByTime(quietMs); | |
| 232 | await Promise.resolve(); | |
| 233 | expect(done).toBe(false); | |
| 234 | jest.advanceTimersByTime(redMs - quietMs); | |
| 235 | const r = await running; | |
| 236 | expect(r.verdict).toBe("red"); | |
| 237 | expect(r.failedStep).toBe("restore"); | |
| 238 | return r; | |
| 239 | } finally { | |
| 240 | jest.useRealTimers(); | |
| 241 | expect(scratchLeft()).toEqual([]); | |
| 242 | } | |
| 243 | } | |
| 244 | ||
| 245 | test("with no timeout given, a hanging restore of a 4.1 GiB snapshot has 10 min + 60 s per GiB", async () => { | |
| 246 | const bytes = Math.round(4.1 * 1024 ** 3); | |
| 247 | // 10 + 4.1 = 14.1 min; still waiting at 14 min, red past 14.1. | |
| 248 | const r = await hang({ files: [{ path: "forge.db", bytes }], bytes }, 14 * 60_000, 14.1 * 60_000 + 1); | |
| 249 | expect(r.reason).toBe("restore timed out: no answer within its 14.1 min budget for a 4.1 GiB snapshot"); | |
| 250 | }); | |
| 251 | ||
| 252 | test("a manifest with no total, or one that is not a number, is sized by the sum of its files", async () => { | |
| 253 | const GiB = 1024 ** 3; | |
| 254 | const files = [ | |
| 255 | { path: "forge.db", bytes: 2 * GiB }, | |
| 256 | { path: "repos/a/b.bundle", bytes: 2 * GiB }, | |
| 257 | ]; | |
| 258 | // 2 + 2 GiB: 10 + 4 = 14 min; still waiting just before, red just after. | |
| 259 | for (const manifest of [{ files }, { files, bytes: "4 GiB" }]) { | |
| 260 | const r = await hang(manifest, 14 * 60_000 - 1_000, 14 * 60_000 + 1); | |
| 261 | expect(r.reason).toBe("restore timed out: no answer within its 14 min budget for a 4 GiB snapshot"); | |
| 262 | } | |
| 172 | 263 | }); |
| 173 | 264 | |
| 174 | 265 | test("an empty store is red at fetch", async () => { |
new above
offline
The fallback to summing the files when
bytesis missing is new behaviour with no test: delete this line and every test still passes. Add a drill whose manifest lacksbytesand whose files sum to a few GiB, and assert the budget in the reason.