Public: anyone can read this; the crew can change it.
The restore drill records how long download, decompress, open and migrate each took #2748
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/2742-the-restore-drill-records-how-long-downl → main 3 commits fork 3 threads · 3 unresolved
9 files
changed +176
−19
README.md +6 −2
| @@ -1018,8 +1018,12 @@ The terminal has no backups view, so it has no readout. | ||
| 1018 | 1018 | **Run a drill** on the same page (admins only) restores the newest snapshot |
| 1019 | 1019 | into scratch, opens it, counts what is there and unseals a value; the page |
| 1020 | 1020 | waits for it, up to 10 minutes, and the last drill shows there as one line, |
| 1021 | ending with the drill's time against its budget and each phase's time ("6 min | |
| 1022 | 12 s of its 14 min budget: files 58 s, …"); drills from before this show none. | |
| 1021 | ending with the drill's time against its budget and each part's time, longest first ("6 min | |
| 1022 | 12 s of its 14 min budget: clone 4 min, download 58 s, …"); drills from before this show none. | |
| 1023 | The parts are download, decompress, clone, open, and start and migrate (the | |
| 1024 | whole side-boot of the restored forge, process start included). The same words, | |
| 1025 | slowest named, are in the drill's log line and in a red drill's card | |
| 1026 | ("… (download about 8 min, decompress 40 s, …; download was the slowest)"). | |
| 1023 | 1027 | Only one runs at a time. See `docs/SNAPSHOT.md`. |
| 1024 | 1028 | |
| 1025 | 1029 | The forge also runs one itself every Sunday 09:00 UTC (a forge that was down |
src/snapshot/drill.ts +37 −2
| @@ -75,9 +75,36 @@ export function formatSpan(ms: number): string { | ||
| 75 | 75 | return s % 60 === 0 ? `${m} min` : `${m} min ${s % 60} s`; |
| 76 | 76 | } |
| 77 | 77 | |
| 78 | /** What people call each phase; the manifest read counts as download. */ | |
| 79 | const PART_WORD: Record<PhaseTime["phase"], string> = { | |
| 80 | manifest: "download", | |
| 81 | files: "download", | |
| 82 | unpack: "decompress", | |
| 83 | bundles: "clone", | |
| 84 | key: "key", | |
| 85 | open: "open", | |
| 86 | boot: "start and migrate", | |
| 87 | }; | |
| 88 | ||
| 89 | /** The drill's time by part, longest first: download, decompress, clone, open, migrate. Parts that share a word are added. */ | |
| 90 | export function timeByPart(phases: readonly PhaseTime[]): { part: string; ms: number }[] { | |
| 91 | const sums = new Map<string, number>(); | |
| 92 | for (const p of phases) sums.set(PART_WORD[p.phase], (sums.get(PART_WORD[p.phase]) ?? 0) + p.ms); | |
| 93 | return [...sums].map(([part, ms]) => ({ part, ms })).sort((a, b) => b.ms - a.ms); | |
| 94 | } | |
| 95 | ||
| 96 | /** "download about 8 min, decompress 40 s, open 2 s; download was the slowest"; empty when nothing was timed. */ | |
| 97 | export function describeTimes(phases: readonly PhaseTime[]): string { | |
| 98 | const parts = timeByPart(phases).filter((p) => p.part !== "key"); | |
| 99 | if (parts.length === 0) return ""; | |
| 100 | const words = parts.map((p) => `${p.part} ${p.ms >= 60_000 ? "about " : ""}${formatSpan(p.ms)}`); | |
| 101 | return `${words.join(", ")}; ${parts[0]!.part} was the slowest`; | |
| 102 | } | |
| 103 | ||
| 78 | 104 | /** One restore phase and the milliseconds it took. */ |
| 79 | 105 | export interface PhaseTime { |
| 80 | readonly phase: Progress["phase"]; | |
| 106 | /** A restore phase, then `open` (the database read) and `boot` (the restored forge starting and migrating). */ | |
| 107 | readonly phase: Progress["phase"] | "open" | "boot"; | |
| 81 | 108 | readonly ms: number; |
| 82 | 109 | } |
| 83 | 110 | |
| @@ -151,6 +178,7 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> { | ||
| 151 | 178 | // When each restore phase was first reported, and when the restore ended. |
| 152 | 179 | const began: { phase: Progress["phase"]; at: number }[] = []; |
| 153 | 180 | let restoreEnd: number | undefined; |
| 181 | let bootStart: number | undefined; | |
| 154 | 182 | let health: DrillResult["health"] = "unreached"; |
| 155 | 183 | try { |
| 156 | 184 | // One clock for the whole drill, so a hang in any step ends it red. |
| @@ -228,6 +256,7 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> { | ||
| 228 | 256 | } |
| 229 | 257 | |
| 230 | 258 | step = "health"; |
| 259 | bootStart = performance.now(); | |
| 231 | 260 | const booted = await within( |
| 232 | 261 | (deps.boot ?? bootRestored)(target, left()), |
| 233 | 262 | left(), |
| @@ -255,10 +284,16 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> { | ||
| 255 | 284 | |
| 256 | 285 | function finish(failedStep: DrillStep | null): DrillResult { |
| 257 | 286 | const end = restoreEnd ?? performance.now(); |
| 258 | const phases = began.map((b, i) => ({ | |
| 287 | const phases: PhaseTime[] = began.map((b, i) => ({ | |
| 259 | 288 | phase: b.phase, |
| 260 | 289 | ms: Math.max(0, Math.round((began[i + 1]?.at ?? end) - b.at)), |
| 261 | 290 | })); |
| 291 | // The database read, then the restored forge's start and migration. | |
| 292 | if (restoreEnd !== undefined) { | |
| 293 | const now = performance.now(); | |
| 294 | phases.push({ phase: "open", ms: Math.round((bootStart ?? now) - restoreEnd) }); | |
| 295 | if (bootStart !== undefined) phases.push({ phase: "boot", ms: Math.round(now - bootStart) }); | |
| 296 | } | |
| 262 | 297 | return { |
| 263 | 298 | at, |
| 264 | 299 | snapshotId, |
src/snapshot/drills.ts +1 −1
| @@ -22,7 +22,7 @@ interface Row { | ||
| 22 | 22 | phases: string | null; |
| 23 | 23 | } |
| 24 | 24 | |
| 25 | const PHASES = new Set(["manifest", "files", "unpack", "bundles", "key"]); | |
| 25 | const PHASES = new Set(["manifest", "files", "unpack", "bundles", "key", "open", "boot"]); | |
Add a test that stores a drill with open and boot phases and reads it back. Without one, dropping them from this set goes unnoticed. |
||
| 26 | 26 | |
| 27 | 27 | /** The stored JSON as phases; anything that is not a list of known phases with whole ms reads as none. */ |
| 28 | 28 | export function parsePhases(raw: string | null): { phases: PhaseTime[]; budgetMs: number } { |
src/snapshot/service.ts +2 −2
| @@ -21,7 +21,7 @@ import { | ||
| 21 | 21 | type Manifest, |
| 22 | 22 | type Progress, |
| 23 | 23 | } from "./snapshot.ts"; |
| 24 | import { runDrill, type DrillDeps, type DrillResult } from "./drill.ts"; | |
| 24 | import { describeTimes, runDrill, type DrillDeps, type DrillResult } from "./drill.ts"; | |
| 25 | 25 | import { BOOT_RED_FLOOR_MS, drillDue, RED_RETRY_MS } from "./due.ts"; |
| 26 | 26 | import { lastDrill, recordDrill } from "./drills.ts"; |
| 27 | 27 | import { lastMirror, mirrorPass, MIRROR_EVERY_MS, recordMirror, type MirrorState } from "./mirror.ts"; |
| @@ -244,7 +244,7 @@ export function startSnapshots( | ||
| 244 | 244 | // The card and the recovery issue hear of every drill, whoever asked. |
| 245 | 245 | const posted = await reportVerdict(app.config.dataDir, result); |
| 246 | 246 | app.bus.append({ kind: "drill.finished", payload: { verdict: result.verdict, step: result.failedStep } }); |
| 247 | log.info("restore drill", { verdict: result.verdict, step: result.failedStep ?? "none", posted }); | |
| 247 | log.info("restore drill", { verdict: result.verdict, step: result.failedStep ?? "none", posted, times: describeTimes(result.phases) }); | |
| 248 | 248 | return result; |
| 249 | 249 | })().finally(() => { |
| 250 | 250 | drilling = undefined; |
src/snapshot/verdict.ts +5 −4
| @@ -9,7 +9,7 @@ | ||
| 9 | 9 | |
| 10 | 10 | import { mkdirSync, readFileSync, renameSync, writeFileSync } from "node:fs"; |
| 11 | 11 | import { join } from "node:path"; |
| 12 | import { formatSpan, type DrillResult, type DrillStep, type PhaseTime } from "./drill.ts"; | |
| 12 | import { describeTimes, formatSpan, timeByPart, type DrillResult, type DrillStep } from "./drill.ts"; | |
| 13 | 13 | |
| 14 | 14 | const STEPS: readonly DrillStep[] = ["fetch", "restore", "open", "count", "unseal", "health"]; |
| 15 | 15 | |
| @@ -38,7 +38,8 @@ export function lastVerdict(dataDir: string): DrillResult | undefined { | ||
| 38 | 38 | /** The inbox card's sentence for a red drill; undefined for a green one. */ |
| 39 | 39 | export function failedSentence(r: DrillResult | undefined): string | undefined { |
| 40 | 40 | if (r === undefined || r.verdict !== "red") return undefined; |
| 41 | return `The restore drill failed at ${r.failedStep ?? "an unknown step"}${r.reason ? `: ${r.reason}` : ""}. Snapshot ${r.snapshotId ?? "none"}; docs/RECOVERY.md says what to do.`; | |
| 41 | const times = describeTimes(r.phases); | |
slowSentence still names the raw phase ("boot took…", "files took…"). Use the plain part words that PART_WORD gives, so the board and the red card agree. Good: key is left out and an empty times string drops the parentheses. The Backups page line should read from the same timeByPart so the words agree. |
||
| 42 | return `The restore drill failed at ${r.failedStep ?? "an unknown step"}${r.reason ? `: ${r.reason}` : ""}${times ? ` (${times})` : ""}. Snapshot ${r.snapshotId ?? "none"}; docs/RECOVERY.md says what to do.`; | |
| 42 | 43 | } |
| 43 | 44 | |
| 44 | 45 | /** A green drill that used more than this share of its budget is a warning. */ |
| @@ -52,9 +53,9 @@ export const DRILL_SLOW_SHARE = 0.8; | ||
| 52 | 53 | export function slowSentence(r: DrillResult | undefined): string | undefined { |
| 53 | 54 | if (r === undefined || r.verdict !== "green") return undefined; |
| 54 | 55 | if (!(r.budgetMs > 0) || !(r.ms > r.budgetMs * DRILL_SLOW_SHARE)) return undefined; |
| 55 | const slowest = r.phases.reduce<PhaseTime | undefined>((a, p) => (a === undefined || p.ms > a.ms ? p : a), undefined); | |
| 56 | const slowest = timeByPart(r.phases)[0]; | |
| 56 | 57 | const spare = `${formatSpan(Math.max(0, r.budgetMs - r.ms))} to spare`; |
| 57 | return `The last restore drill passed with ${spare}${slowest ? `; ${slowest.phase} took ${formatSpan(slowest.ms)} of it` : ""}.`; | |
| 58 | return `The last restore drill passed with ${spare}${slowest ? `; ${slowest.part} took ${formatSpan(slowest.ms)} of it` : ""}.`; | |
| 58 | 59 | } |
| 59 | 60 | |
| 60 | 61 | const firstFile =(dataDir: string): string => join(dataDir, "drill", "first-seen"); |
src/web/pages/backups.ts +4 −4
| @@ -18,7 +18,7 @@ import { forgetMirror, saveMirror } from "../../actions/mirror.ts"; | ||
| 18 | 18 | import { mirrorSealedSet, mirrorNeed, MIRROR_SEALED } from "../../snapshot/mirror.ts"; |
| 19 | 19 | import { resolveDestination, sealedSet } from "../../snapshot/destination.ts"; |
| 20 | 20 | import { keyOf } from "../../snapshot/snapshot.ts"; |
| 21 | import { formatBudget, formatSpan, type DrillResult } from "../../snapshot/drill.ts"; | |
| 21 | import { formatBudget, formatSpan, timeByPart, type DrillResult } from "../../snapshot/drill.ts"; | |
| 22 | 22 | import { lastDrill } from "../../snapshot/drills.ts"; |
| 23 | 23 | import { snapshotsOf } from "../../snapshot/service.ts"; |
| 24 | 24 | import { lastSnapshotOutcome } from "../../snapshot/outcome.ts"; |
| @@ -90,11 +90,11 @@ function keyNote( | ||
| 90 | 90 | </p>`; |
| 91 | 91 | } |
| 92 | 92 | |
| 93 | /** "6 min 12 s of its 14 min budget: files 58 s, ..."; empty for a drill that kept no phases. */ | |
| 93 | /** "6 min 12 s of its 14 min budget: clone 4 min, download 58 s, ..."; empty for a drill that kept no phases. */ | |
| 94 | 94 | function drillTiming(d: DrillResult): string { |
| 95 | 95 | if (d.phases.length === 0 || d.budgetMs <= 0) return ""; |
| 96 | return `${formatSpan(d.ms)} of its ${formatBudget(d.budgetMs)} budget: ${d.phases | |
| 97 | .map((p) => `${p.phase} ${formatSpan(p.ms)}`) | |
| 96 | return `${formatSpan(d.ms)} of its ${formatBudget(d.budgetMs)} budget: ${timeByPart(d.phases) | |
| 97 | .map((p) => `${p.part} ${formatSpan(p.ms)}`) | |
| 98 | 98 | .join(", ")}`; |
| 99 | 99 | } |
| 100 | 100 |
test/drill-parts.test.ts added +106
| @@ -0,0 +1,106 @@ | ||
| 1 | /** | |
| 2 | * The drill times download, decompress, open and migrate (#2748): a red | |
| 3 | * card names them in words, and a slow download is named the slowest part. | |
| 4 | */ | |
| 5 | import { afterAll, beforeAll, expect, test } from "bun:test"; | |
| 6 | import { mkdtempSync, rmSync } from "node:fs"; | |
| 7 | import { tmpdir } from "node:os"; | |
| 8 | import { join } from "node:path"; | |
| 9 | import { createApp, type App } from "../src/app.ts"; | |
| 10 | import { createUser } from "../src/core/users.ts"; | |
| 11 | import { describeTimes, runDrill, timeByPart } from "../src/snapshot/drill.ts"; | |
| 12 | import { takeSnapshot } from "../src/snapshot/snapshot.ts"; | |
| 13 | import { dirStore, type Store } from "../src/snapshot/store.ts"; | |
| 14 | import { failedSentence, slowSentence } from "../src/snapshot/verdict.ts"; | |
| 15 | import { quietLogs } from "./helpers/globals.ts"; | |
| 16 | ||
| 17 | quietLogs(); | |
| 18 | ||
| 19 | let root = ""; | |
| 20 | let app: App; | |
| 21 | ||
| 22 | beforeAll(async () => { | |
| 23 | root = mkdtempSync(join(tmpdir(), "forge-drillparts-")); | |
| 24 | app = createApp({ dataDir: root, port: 0 }); | |
| 25 | const u = await createUser(app.db, { | |
| 26 | origin: "seed", | |
| 27 | trusted: true, | |
| 28 | username: "alice", | |
| 29 | email: "[email protected]", | |
| 30 | password: "a-good-passphrase", | |
| 31 | adminIfFirst: true, | |
| 32 | }); | |
| 33 | if (!u.ok) throw new Error(u.error); | |
| 34 | await takeSnapshot( | |
| 35 | { db: app.db, dataDir: root, reposRoot: app.reposRoot, version: "t" }, | |
| 36 | dirStore(join(root, "store")), | |
| 37 | new Date("2026-10-18T08:00:00Z"), | |
| 38 | ); | |
| 39 | }); | |
| 40 | afterAll(() => { | |
| 41 | app.close(); | |
| 42 | rmSync(root, { recursive: true, force: true }); | |
| 43 | }); | |
| 44 | ||
| 45 | test("a fake store with a slow download gives a card naming download the slowest", async () => { | |
| 46 | const inner = dirStore(join(root, "store")); | |
| 47 | const slow: Store = { | |
| 48 | ...inner, | |
| 49 | get: async (key) => { | |
| 50 | await new Promise((r) => setTimeout(r, 60)); | |
| 51 | return inner.get(key); | |
| 52 | }, | |
| 53 | }; | |
| 54 | const r = await runDrill({ | |
| 55 | store: slow, | |
| 56 | dataDir: join(root, "drill-data"), | |
| 57 | boot: async () => ({ ok: false, reason: "health never answered" }), | |
| 58 | }); | |
| 59 | expect(r.verdict).toBe("red"); | |
| 60 | const parts = r.phases.map((p) => p.phase); | |
| 61 | expect(parts).toContain("files"); | |
| 62 | expect(parts.slice(-2)).toEqual(["open", "boot"]); | |
| 63 | const card = failedSentence(r)!; | |
| 64 | expect(card).toContain("health never answered"); | |
| 65 | expect(card).toMatch(/download \d+ (ms|s)/); | |
| 66 | expect(card).toContain("download was the slowest"); | |
| 67 | expect(card).toContain("migrate"); | |
| 68 | }); | |
| 69 | ||
| 70 | test("times read in words, longest first, with the minutes rounded to about", () => { | |
| 71 | expect( | |
| 72 | describeTimes([ | |
| 73 | { phase: "manifest", ms: 1_000 }, | |
| 74 | { phase: "files", ms: 479_000 }, | |
| 75 | { phase: "unpack", ms: 40_000 }, | |
| 76 | { phase: "open", ms: 2_000 }, | |
| 77 | { phase: "boot", ms: 3_000 }, | |
| 78 | ]), | |
| 79 | ).toBe("download about 8 min, decompress 40 s, start and migrate 3 s, open 2 s; download was the slowest"); | |
| 80 | expect(describeTimes([])).toBe(""); | |
| 81 | }); | |
| 82 | ||
| 83 | test("every phase has its plain word: clone for bundles, key kept apart, boot as migrate", () => { | |
| 84 | const parts = timeByPart([ | |
| 85 | { phase: "bundles", ms: 9_000 }, | |
| 86 | { phase: "key", ms: 1 }, | |
| 87 | { phase: "boot", ms: 5_000 }, | |
| 88 | ]); | |
| 89 | expect(parts).toEqual([ | |
| 90 | { part: "clone", ms: 9_000 }, | |
| 91 | { part: "start and migrate", ms: 5_000 }, | |
| 92 | { part: "key", ms: 1 }, | |
| 93 | ]); | |
| 94 | expect(describeTimes([{ phase: "key", ms: 1 }])).toBe(""); | |
| 95 | }); | |
| 96 | ||
| 97 | test("the board's slow line says migrate, not boot", () => { | |
| 98 | const r = { | |
| 99 | at: "2026-10-18T09:00:00.000Z", snapshotId: "s", ms: 9 * 60_000, | |
| 100 | counts: { repositories: 0, issues: 0, users: 0, pulls: 0, apps: 0 }, | |
| 101 | health: "ok" as const, verdict: "green" as const, failedStep: null, | |
| 102 | phases: [{ phase: "files" as const, ms: 1_000 }, { phase: "boot" as const, ms: 8 * 60_000 }], | |
| 103 | budgetMs: 10 * 60_000, reason: null, | |
| 104 | }; | |
| 105 | expect(slowSentence(r)).toContain("start and migrate took 8 min"); | |
| 106 | }); |
test/drill-slow.test.ts +2 −2
| @@ -23,9 +23,9 @@ const drill = (over: Partial<DrillResult>): DrillResult => ({ | ||
| 23 | 23 | test("81% of the budget warns, naming the slowest phase", () => { |
| 24 | 24 | const r = drill({ ms: 9 * MIN, budgetMs: 11 * MIN }); |
| 25 | 25 | expect(slowSentence(drill({ ms: 8.91 * MIN }))).toBe( |
| 26 | "The last restore drill passed with 2 min 5 s to spare; bundles took 9 min of it.", | |
| 26 | "The last restore drill passed with 2 min 5 s to spare; clone took 9 min of it.", | |
| 27 | 27 | ); |
| 28 | expect(slowSentence(r)).toContain("bundles took 9 min"); | |
| 28 | expect(slowSentence(r)).toContain("clone took 9 min"); | |
| 29 | 29 | const need = drillNeed(r, Date.parse(r.at) + MIN); |
| 30 | 30 | expect(need?.sentence).toBe(slowSentence(r)); |
| 31 | 31 | }); |
test/snapshot-drill-phases.test.ts +13 −2
| @@ -71,7 +71,7 @@ describe("drill phases", () => { | ||
| 71 | 71 | expect(r.verdict).toBe("green"); |
| 72 | 72 | expect(r.budgetMs).toBeGreaterThanOrEqual(600_000); |
| 73 | 73 | expect(r.budgetMs).toBeLessThan(601_000); |
| 74 | expect(r.phases.map((p) => p.phase)).toEqual(["files", "unpack", "key"]); | |
| 74 | expect(r.phases.map((p) => p.phase)).toEqual(["files", "unpack", "key", "open", "boot"]); | |
| 75 | 75 | expect(r.phases[0]!.ms).toBeGreaterThanOrEqual(25); |
| 76 | 76 | expect(r.phases[1]!.ms).toBeGreaterThanOrEqual(25); |
| 77 | 77 | }); |
| @@ -101,6 +101,8 @@ describe("drill phases", () => { | ||
| 101 | 101 | phases: [ |
| 102 | 102 | { phase: "files", ms: 58_000 }, |
| 103 | 103 | { phase: "bundles", ms: 290_000 }, |
| 104 | { phase: "open", ms: 2_000 }, | |
| 105 | { phase: "boot", ms: 3_000 }, | |
| 104 | 106 | ], |
| 105 | 107 | budgetMs: 840_000, |
| 106 | 108 | reason: null, |
| @@ -167,12 +169,14 @@ describe("the Backups page line", () => { | ||
| 167 | 169 | { phase: "unpack", ms: 20_000 }, |
| 168 | 170 | { phase: "bundles", ms: 290_000 }, |
| 169 | 171 | { phase: "key", ms: 1_000 }, |
| 172 | { phase: "open", ms: 2_000 }, | |
| 173 | { phase: "boot", ms: 3_000 }, | |
| 170 | 174 | ], |
| 171 | 175 | budgetMs: 840_000, |
| 172 | 176 | reason: null, |
| 173 | 177 | ...over, |
| 174 | 178 | }); |
| 175 | const LINE = "6 min 12 s of its 14 min budget: files 58 s, unpack 20 s, bundles 4 min 50 s, key 1 s"; | |
| 179 | const LINE = "6 min 12 s of its 14 min budget: clone 4 min 50 s, download 58 s, decompress 20 s, start and migrate 3 s, open 2 s, key 1 s"; | |
| 176 | 180 | const backups = async (): Promise<string> => { |
| 177 | 181 | const r = await fetch(`${servers.url}/signin`, { |
| 178 | 182 | method: "POST", |
| @@ -184,6 +188,13 @@ describe("the Backups page line", () => { | ||
| 184 | 188 | return (await fetch(`${servers.url}/settings/backups`, { headers: { cookie } })).text(); |
| 185 | 189 | }; |
| 186 | 190 | |
| 191 | test("the line says the plain words, not the raw phase names", async () => { | |
| 192 | recordDrill(app.db, kept({})); | |
| 193 | const page = await backups(); | |
| 194 | expect(page).toContain("start and migrate 3 s"); | |
| 195 | expect(page).not.toMatch(/boot \d|unpack \d|files \d|manifest \d|bundles \d/); | |
| 196 | }); | |
| 197 | ||
| 187 | 198 | test("a green drill shows the time against the budget with each phase", async () => { |
| 188 | 199 | recordDrill(app.db, kept({})); |
| 189 | 200 | expect(await backups()).toContain(LINE); |
new above
offline
The word "migrate" is the whole boot of the restored forge, process start included. Name it for what it measures, or say so in the README.