Public: anyone can read this; the crew can change it.
A restore drill that runs out of time says which phase it hung in and how far it got #2621
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/2618-a-restore-drill-that-runs-out-of-time-sa → main 1 commit fork 2 threads · 2 unresolved
3 files
changed +46
−5
src/snapshot/drill.ts +17 −3
| @@ -16,7 +16,7 @@ import { join } from "node:path"; | ||
| 16 | 16 | import { bootRestored } from "./boot.ts"; |
| 17 | 17 | import { forgetKey, open } from "../kernel/secret.ts"; |
| 18 | 18 | import { countRows, mismatched, type DrillCounts } from "./counts.ts"; |
| 19 | import { restoreSnapshot } from "./restore.ts"; | |
| 19 | import { restoreSnapshot, type Progress } from "./restore.ts"; | |
| 20 | 20 | import { listSnapshots } from "./snapshot.ts"; |
| 21 | 21 | import type { Store } from "./store.ts"; |
| 22 | 22 | |
| @@ -97,6 +97,12 @@ export interface DrillResult { | ||
| 97 | 97 | |
| 98 | 98 | class StepTimeout extends Error {} |
| 99 | 99 | |
| 100 | /** Where a restore got to, for people: "bundles (37 of 212 cloned, 1.8 GiB fetched)". */ | |
| 101 | export function describeProgress(p: Progress): string { | |
| 102 | const unit = p.phase === "bundles" ? ["cloned", "fetched"] : ["done", "so far"]; | |
| 103 | return `${p.phase} (${p.done} of ${p.total} ${unit[0]}, ${formatBytes(p.bytes)} ${unit[1]})`; | |
| 104 | } | |
| 105 | ||
| 100 | 106 | /** Race `work` against `ms`; a loss says `budget`, the whole drill's, not what was left of it. */ |
| 101 | 107 | function within<T>(work: Promise<T>, ms: number, budget: () => string): Promise<T> { |
| 102 | 108 | let timer: ReturnType<typeof setTimeout>; |
| @@ -121,6 +127,7 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> { | ||
| 121 | 127 | let step: DrillStep = "fetch"; |
| 122 | 128 | let scratch: string | undefined; |
| 123 | 129 | let reason: string | null = null; |
| 130 | let progress: Progress | undefined; | |
| 124 | 131 | let health: DrillResult["health"] = "unreached"; |
| 125 | 132 | try { |
| 126 | 133 | // One clock for the whole drill, so a hang in any step ends it red. |
| @@ -137,7 +144,12 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> { | ||
| 137 | 144 | scratch = mkdtempSync(join(parent, "restore-")); |
| 138 | 145 | const target = join(scratch, "data"); |
| 139 | 146 | await within( |
| 140 | restore(deps.store, newest.name, target, { passphrase: deps.passphrase }), | |
| 147 | restore(deps.store, newest.name, target, { | |
| 148 | passphrase: deps.passphrase, | |
| 149 | onProgress: (p) => { | |
| 150 | progress = p; | |
| 151 | }, | |
| 152 | }), | |
| 141 | 153 | left(), |
| 142 | 154 | budget, |
| 143 | 155 | ); |
| @@ -200,7 +212,9 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> { | ||
| 200 | 212 | if (!booted.ok) throw new Error(booted.reason); |
| 201 | 213 | } catch (error) { |
| 202 | 214 | reason = |
| 203 | error instanceof StepTimeout | |
| 215 | error instanceof StepTimeout && step === "restore" && progress !== undefined | |
| 216 | ? `restore timed out in ${describeProgress(progress)} after its ${formatBudget(budgetMs)} budget` | |
The new message drops the "for a N MiB snapshot" part that the generic timeout text carries. Reuse the budget() string so the size stays. Also the nested ternary is mis-indented; split it into an if/else. |
||
| 217 | : error instanceof StepTimeout | |
| 204 | 218 | ? `${step} timed out: ${error.message}` |
| 205 | 219 | : error instanceof Error |
| 206 | 220 | ? error.message |
test/snapshot-drill-page.test.ts +14 −2
| @@ -36,6 +36,7 @@ describe("the drill on the Backups page", () => { | ||
| 36 | 36 | return (r.headers.get("set-cookie") ?? "").split(";")[0]!; |
| 37 | 37 | }; |
| 38 | 38 | |
| 39 | let redReason = "a sealed value does not open"; | |
| 39 | 40 | beforeAll(async () => { |
| 40 | 41 | root = mkdtempSync(join(tmpdir(), "forge-drillpage-")); |
| 41 | 42 | app = createApp({ dataDir: root, port: 0 }); |
| @@ -67,7 +68,7 @@ describe("the drill on the Backups page", () => { | ||
| 67 | 68 | health: verdict === "green" ? "ok" : "unreached", |
| 68 | 69 | verdict, |
| 69 | 70 | failedStep: verdict === "green" ? null : "unseal", |
| 70 | reason: verdict === "green" ? null : "a sealed value does not open", | |
| 71 | reason: verdict === "green" ? null : redReason, | |
| 71 | 72 | }; |
| 72 | 73 | }, |
| 73 | 74 | }); |
| @@ -103,6 +104,17 @@ describe("the drill on the Backups page", () => { | ||
| 103 | 104 | expect(app.db.query("SELECT count(*) AS n FROM drill").get()).toEqual({ n: 1 }); |
| 104 | 105 | }); |
| 105 | 106 | |
| 107 | test("a red drill's reason shows verbatim, escaped", async () => { | |
| 108 | const cookie = await login("alice", "a-good-passphrase"); | |
| 109 | verdict = "red"; | |
| 110 | redReason = "restore timed out in bundles (37 of 212 cloned, 1.8 GiB fetched) after its 14 min budget <b>x</b>"; | |
| 111 | await post(cookie); | |
| 112 | const html = await page(cookie); | |
| 113 | redReason = "a sealed value does not open"; | |
| 114 | expect(html).toContain("restore timed out in bundles (37 of 212 cloned, 1.8 GiB fetched) after its 14 min budget <b>x</b>"); | |
| 115 | expect(html).not.toContain("<b>x</b>"); | |
| 116 | }); | |
| 117 | ||
| 106 | 118 | test("a red drill names the failing step", async () => { |
| 107 | 119 | const cookie = await login("alice", "a-good-passphrase"); |
| 108 | 120 | verdict = "red"; |
| @@ -110,7 +122,7 @@ describe("the drill on the Backups page", () => { | ||
| 110 | 122 | const html = await page(cookie); |
| 111 | 123 | expect(html).toContain("failed at"); |
| 112 | 124 | expect(html).toContain("unseal"); |
| 113 | expect(app.db.query("SELECT count(*) AS n FROM drill").get()).toEqual({ n: 2 }); | |
| 125 | expect(app.db.query("SELECT count(*) AS n FROM drill").get()).toEqual({ n: 3 }); | |
| 114 | 126 | }); |
| 115 | 127 | |
| 116 | 128 | test("a non-admin is refused, and so is a cross-origin post", async () => { |
test/snapshot-drill.test.ts +15
| @@ -193,6 +193,21 @@ describe("the restore drill", () => { | ||
| 193 | 193 | expect(scratchLeft()).toEqual([]); |
| 194 | 194 | }); |
| 195 | 195 | |
| 196 | test("a restore that reports progress and then hangs names the phase and the counts", async () => { | |
| 197 | const r = await runDrill( | |
| 198 | deps({ | |
| 199 | timeoutMs: 1500, | |
| 200 | restore: (async (_s: unknown, _n: unknown, _t: unknown, o: { onProgress?: (p: unknown) => void }) => { | |
| 201 | o.onProgress?.({ phase: "files", done: 3, total: 3, bytes: 100 }); | |
| 202 | o.onProgress?.({ phase: "bundles", done: 37, total: 212, bytes: Math.round(1.8 * 1024 ** 3) }); | |
| 203 | await new Promise(() => {}); | |
| 204 | }) as never, | |
| 205 | }), | |
| 206 | ); | |
| 207 | expect(r.failedStep).toBe("restore"); | |
| 208 | expect(r.reason).toBe("restore timed out in bundles (37 of 212 cloned, 1.8 GiB fetched) after its 1.5 s budget"); | |
| 209 | }); | |
| 210 | ||
| 196 | 211 | test("a step that times out names its budget and the snapshot's size, never a raw float of ms", async () => { |
| 197 | 212 | const r = await runDrill(deps({ timeoutMs: 1500.75, restore: () => new Promise(() => {}) })); |
| 198 | 213 | expect(r.reason).toMatch(/^restore timed out: no answer within its 1\.5 s budget for a [\d.]+ (B|KiB|MiB) snapshot$/); |
new above
offline
describeProgress is exported but nothing else imports it. Make it module-private, or test it directly for the non-bundles units (done / so far), which no test asserts today.