Public: anyone can read this; the crew can change it.
A rollback records how long it took, and the release card shows it beside the stage timings #11928
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/11919-a-rollback-records-how-long-it-took-and → main 2 commits fork 2 threads · 2 unresolved
7 files
changed +67
−10
src/core/migration-pins/20261113180000-keeper-rollback-time.pin added +1
| @@ -0,0 +1,1 @@ | ||
| 1 | 364c334854b9f2610f7a3fdecb602d90ff2b1c45b262de8f115669ec8f253cfe |
src/core/migrations/20261113180000-keeper-rollback-time.ts added +6
| @@ -0,0 +1,6 @@ | ||
| 1 | // Undone in one step, under a minute (#11839, #11919): a rolled-back release keeps how long | |
| 2 | // the rollback took, from the swap asked to the known-good tree serving. Null for a release | |
| 3 | // that was not rolled back or not timed. Additive: one new nullable column. | |
| 4 | export default ` | |
| 5 | ALTER TABLE keeper_release ADD COLUMN rollback_ms INTEGER; | |
| 6 | `; |
src/keeper/landed.ts +9 −3
| @@ -69,6 +69,8 @@ export interface Stages { | ||
| 69 | 69 | readonly interruptedRuns: number | null; |
| 70 | 70 | /** The new version answering to its verdict. */ |
| 71 | 71 | readonly verifyMs: number | null; |
| 72 | /** The rollback, asked to the known-good tree serving (#11919). */ | |
| 73 | readonly rollbackMs: number | null; | |
| 72 | 74 | } |
| 73 | 75 | |
| 74 | 76 | const between = (from: string | null, to: string | null): number | null => { |
| @@ -77,7 +79,7 @@ const between = (from: string | null, to: string | null): number | null => { | ||
| 77 | 79 | return Number.isFinite(ms) ? Math.max(0, ms) : null; |
| 78 | 80 | }; |
| 79 | 81 | |
| 80 | export function stagesOf(r: Pick<KeeperRelease, "cutAt" | "liveAt" | "finishedAt" | "buildMs" | "proofMs" | "switchMs"> & Partial<Pick<KeeperRelease, "interruptedRuns">>): Stages { | |
| 82 | export function stagesOf(r: Pick<KeeperRelease, "cutAt" | "liveAt" | "finishedAt" | "buildMs" | "proofMs" | "switchMs"> & Partial<Pick<KeeperRelease, "interruptedRuns" | "rollbackMs">>): Stages { | |
| 81 | 83 | return { |
| 82 | 84 | cutToLiveMs: between(r.cutAt, r.liveAt), |
| 83 | 85 | buildMs: r.buildMs, |
| @@ -85,13 +87,17 @@ export function stagesOf(r: Pick<KeeperRelease, "cutAt" | "liveAt" | "finishedAt | ||
| 85 | 87 | switchMs: r.switchMs, |
| 86 | 88 | interruptedRuns: r.interruptedRuns ?? null, |
| 87 | 89 | verifyMs: between(r.liveAt, r.finishedAt), |
| 90 | rollbackMs: r.rollbackMs ?? null, | |
| 88 | 91 | }; |
| 89 | 92 | } |
| 90 | 93 | |
| 91 | /** "cut→live 1 min 2 s · build 4 s · proof 3 s · switch 1 s · verify 10 min 0 s"; a stage not measured is left out. */ | |
| 94 | /** | |
| 95 | * "cut→live 1 min 2 s · build 4 s · proof 3 s · switch 1 s · verify 10 min 0 s · | |
| 96 | * rolled back in 40 s"; a stage not measured is left out. | |
| 97 | */ | |
| 92 | 98 | export function stagesLine(s: Stages): string { |
| 93 | 99 | const w = (name: string, ms: number | null) => (ms === null ? [] : [`${name} ${secondsWords(Math.round(ms / 1000))}`]); |
| 94 | return [...w("cut→live", s.cutToLiveMs), ...w("build", s.buildMs), ...w("proof", s.proofMs), ...w("switch", s.switchMs), ...(s.interruptedRuns === null ? [] : [`interrupted ${s.interruptedRuns} ${s.interruptedRuns === 1 ? "run" : "runs"}`]), ...w("verify", s.verifyMs)].join(" · "); | |
| 100 | return [...w("cut→live", s.cutToLiveMs), ...w("build", s.buildMs), ...w("proof", s.proofMs), ...w("switch", s.switchMs), ...(s.interruptedRuns === null ? [] : [`interrupted ${s.interruptedRuns} ${s.interruptedRuns === 1 ? "run" : "runs"}`]), ...w("verify", s.verifyMs), ...w("rolled back in", s.rollbackMs)].join(" · "); | |
| 95 | 101 | } |
| 96 | 102 | |
| 97 | 103 | export function withLandedToLive(db: Database, releases: readonly KeeperRelease[]): LandedRelease[] { |
src/keeper/record.ts +16
| @@ -38,6 +38,11 @@ export interface KeeperRelease { | ||
| 38 | 38 | readonly buildMs: number | null; |
| 39 | 39 | readonly proofMs: number | null; |
| 40 | 40 | readonly switchMs: number | null; |
| 41 | /** | |
| 42 | * How long the rollback took, from the swap asked to the known-good tree serving (#11919); | |
| 43 | * null when none was timed. | |
| 44 | */ | |
| 45 | readonly rollbackMs: number | null; | |
| 41 | 46 | /** Crew runs running in the drained process at the switch (#11917); null when not counted. */ |
| 42 | 47 | readonly interruptedRuns: number | null; |
| 43 | 48 | /** Why a person cut this release now, outside the spacing; empty for a cut on cadence. */ |
| @@ -66,6 +71,7 @@ interface Row { | ||
| 66 | 71 | build_ms: number | null; |
| 67 | 72 | proof_ms: number | null; |
| 68 | 73 | switch_ms: number | null; |
| 74 | rollback_ms: number | null; | |
| 69 | 75 | interrupted_runs: number | null; |
| 70 | 76 | hotfix: string; |
| 71 | 77 | } |
| @@ -91,6 +97,7 @@ const toRelease = (r: Row): KeeperRelease => ({ | ||
| 91 | 97 | buildMs: r.build_ms, |
| 92 | 98 | proofMs: r.proof_ms, |
| 93 | 99 | switchMs: r.switch_ms, |
| 100 | rollbackMs: r.rollback_ms ?? null, | |
| 94 | 101 | interruptedRuns: r.interrupted_runs, |
| 95 | 102 | hotfix: r.hotfix, |
| 96 | 103 | }); |
| @@ -127,6 +134,15 @@ export function keepTimings(db: Database, id: number, t: { buildMs: number; proo | ||
| 127 | 134 | ); |
| 128 | 135 | } |
| 129 | 136 | |
| 137 | /** | |
| 138 | * How long the rollback of the release in flight took: its own column, so the forward | |
| 139 | * timings stay as they were. | |
| 140 | */ | |
| 141 | export function keepRollback(db: Database, id: number, ms: number): void { | |
| 142 | const n = Number.isFinite(ms) ? Math.max(0, Math.round(ms)) : 0; | |
| 143 | db.query(`UPDATE keeper_release SET rollback_ms = ?2 WHERE id = ?1 AND stage IN ('rolling', 'verifying')`).run(id, n); | |
| 144 | } | |
| 145 | ||
| 130 | 146 | /** How many crew runs the old process still had running when the switch drained it: kept on the release still rolling. */ |
| 131 | 147 | export function keepInterrupted(db: Database, id: number, runs: number): void { |
| 132 | 148 | const n = Number.isFinite(runs) ? Math.max(0, Math.round(runs)) : 0; |
src/keeper/swapper.ts +13 −3
| @@ -70,8 +70,11 @@ export interface SwapperInput { | ||
| 70 | 70 | readonly drain: () => void; |
| 71 | 71 | readonly probe?: Readonly<Record<string, string>>; |
| 72 | 72 | readonly budgetMs?: number; |
| 73 | /** Told how long each stage of a forward swap took, just before this process drains (#11839). */ | |
| 74 | readonly timed?: (t: { buildMs: number; proofMs: number; switchMs: number }) => void; | |
| 73 | /** | |
| 74 | * Told how long each stage of a forward swap took, or how long a rollback took end to end, | |
| 75 | * just before this process drains (#11839, #11919). | |
| 76 | */ | |
| 77 | readonly timed?: (t: Timing) => void; | |
| 75 | 78 | readonly now?: () => number; |
| 76 | 79 | } |
| 77 | 80 | |
| @@ -91,6 +94,12 @@ export function dependencyChange(dir: string): string | undefined { | ||
| 91 | 94 | return undefined; |
| 92 | 95 | } |
| 93 | 96 | |
| 97 | /** | |
| 98 | * A forward swap's stages, or a rollback's whole time: from the swap asked to the | |
| 99 | * known-good tree serving. | |
| 100 | */ | |
| 101 | export type Timing = { buildMs: number; proofMs: number; switchMs: number } | { rollbackMs: number }; | |
| 102 | ||
| 94 | 103 | export function swapper(i: SwapperInput): Deployer { |
| 95 | 104 | const now = i.now ?? Date.now; |
| 96 | 105 | /** Set once this process has handed over: what it then reports as running, so the keeper does not promote again. */ |
| @@ -201,6 +210,7 @@ export function swapper(i: SwapperInput): Deployer { | ||
| 201 | 210 | if (m === null) throw new Error("not a tree reference"); |
| 202 | 211 | const [, sha, version] = m as unknown as [string, string, string]; |
| 203 | 212 | if (handedTo === ref) return; |
| 213 | const began = now(); | |
| 204 | 214 | // A tree that has served (pinned when it was swapped away from) is a rollback and is not checked again; any other is admitted, as at the cut. |
| 205 | 215 | const backward = existsSync(join(releaseDir(i.dataDir, sha), LIVE_MARK)); |
| 206 | 216 | const dir = await prepare(sha, !backward); |
| @@ -227,7 +237,7 @@ export function swapper(i: SwapperInput): Deployer { | ||
| 227 | 237 | }); |
| 228 | 238 | if (!started.ok) throw new Error(started.line); |
| 229 | 239 | swapped = true; |
| 230 | if (!backward) i.timed?.({ ...stages, switchMs: now() - switching }); | |
| 240 | i.timed?.(backward ? { rollbackMs: now() - began } : { ...stages, switchMs: now() - switching }); | |
| 231 | 241 | } finally { |
| 232 | 242 | endSwap(swapped); |
| 233 | 243 | } |
src/keeper/wire.ts +4 −3
| @@ -34,9 +34,9 @@ import { handover } from "../release/swap.ts"; | ||
| 34 | 34 | import { runningChildren } from "../boards/sampler.ts"; |
| 35 | 35 | import { snapshotsOf } from "../snapshot/service.ts"; |
| 36 | 36 | import { kubeDeployer } from "./deploy.ts"; |
| 37 | import { inFlight, keepInterrupted, keepTimings } from "./record.ts"; | |
| 37 | import { inFlight, keepInterrupted, keepRollback, keepTimings } from "./record.ts"; | |
| 38 | 38 | import { runningAgentRuns } from "../crew/running.ts"; |
| 39 | import { swapper } from "./swapper.ts"; | |
| 39 | import { swapper, type Timing } from "./swapper.ts"; | |
| 40 | 40 | import type { KeeperPorts } from "./keeper.ts"; |
| 41 | 41 | import { timedGet, verifyUnderLoad } from "./verify.ts"; |
| 42 | 42 | import { phoneGate, probeCentre } from "./covered.ts"; |
| @@ -86,10 +86,11 @@ export function loadPages(repo: Pick<Repo, "ownerName" | "name">): string[] { | ||
| 86 | 86 | * What the swap reports just before this process drains (#11839, #11917): the stage timings, and the crew |
| 87 | 87 | * runs still running here, the ones the switch interrupts, kept on the release still rolling. |
| 88 | 88 | */ |
| 89 | export function switched(db: Database, runs: () => number): (t: { buildMs: number; proofMs: number; switchMs: number }) => void { | |
| 89 | export function switched(db: Database, runs: () => number): (t: Timing) => void { | |
| 90 | 90 | return (t) => { |
| 91 | 91 | const flying = inFlight(db); |
| 92 | 92 | if (flying === undefined) return; |
| 93 | if ("rollbackMs" in t) return keepRollback(db, flying.id, t.rollbackMs); | |
| 93 | 94 | keepTimings(db, flying.id, t); |
| 94 | 95 | keepInterrupted(db, flying.id, runs()); |
| 95 | 96 | }; |
test/release-keeper-swap.test.ts +18 −1
| @@ -17,7 +17,9 @@ import { standingHolds } from "../src/keeper/hold.ts"; | ||
| 17 | 17 | import { landedToLive, newestLive, secondsWords } from "../src/keeper/landed.ts"; |
| 18 | 18 | import { tick } from "../src/keeper/keeper.ts"; |
| 19 | 19 | import { listKeeperReleases } from "../src/keeper/record.ts"; |
| 20 | import { keeperEnv, SWAP_INTERVAL_MS } from "../src/keeper/wire.ts"; | |
| 20 | import { keeperEnv, SWAP_INTERVAL_MS, switched } from "../src/keeper/wire.ts"; | |
| 21 | import { keeperAnswer } from "../src/keeper/landed.ts"; | |
Second import from ../src/keeper/landed.ts; fold keeperAnswer into the existing landed.ts import on line 17. |
||
| 22 | import { keeperPanel } from "../src/web/pages/keeper-panel.ts"; | |
| 21 | 23 | import { swapper, dependencyChange } from "../src/keeper/swapper.ts"; |
| 22 | 24 | import { keepGood, lastGood } from "../src/release/launch.ts"; |
| 23 | 25 | import { releaseDir } from "../src/release/checkout.ts"; |
| @@ -93,6 +95,11 @@ async function hosted(landed: Record<string, { main?: string; pkg?: string; pref | ||
| 93 | 95 | const now = { commit: A as string, version: "0.7.283" }; |
| 94 | 96 | let before: number | undefined = undefined; |
| 95 | 97 | const drained: string[] = []; |
| 98 | /** | |
| 99 | * The swapper's clock: still, except that checking out a tree that has served (a rollback) | |
| 100 | * takes 40 s. | |
| 101 | */ | |
| 102 | const clock = { t: 1_700_000_000_000 }; | |
| 96 | 103 | const build = () => swapper({ |
| 97 | 104 | dataDir, |
| 98 | 105 | port, |
| @@ -104,6 +111,7 @@ async function hosted(landed: Record<string, { main?: string; pkg?: string; pref | ||
| 104 | 111 | const spec = landed[sha]; |
| 105 | 112 | if (spec === undefined) return err("no such commit"); |
| 106 | 113 | const dir = releaseDir(dataDir, sha); |
| 114 | if (existsSync(join(dir, ".was-live"))) clock.t += 40_000; | |
| 107 | 115 | if (!existsSync(dir)) tree(dir, spec.main, spec.pkg); |
| 108 | 116 | return ok(dir); |
| 109 | 117 | }, |
| @@ -111,6 +119,8 @@ async function hosted(landed: Record<string, { main?: string; pkg?: string; pref | ||
| 111 | 119 | const sha = dir.split("/").pop()!; |
| 112 | 120 | return landed[sha]?.preflight === false ? { ok: false, line: "boot failed: (fixture)" } : { ok: true, line: "preflight ok" }; |
| 113 | 121 | }, |
| 122 | now: () => clock.t, | |
| 123 | timed: switched(f.app.db, () => 0), | |
| 114 | 124 | drain: () => { |
| 115 | 125 | drained.push(now.commit); |
| 116 | 126 | // The process that handed over lets go of the port; the one before it, started by a swap, is stopped. |
| @@ -201,6 +211,13 @@ describe("the keeper swaps main's tree in; a pod restart comes back on it", () = | ||
| 201 | 211 | const back = await (async () => { for (let i = 0; i < 60; i++) { const g = await health(h.port); if (g?.commit === B && g.version === "0.7.284") return g; await Bun.sleep(50); } })(); |
| 202 | 212 | expect(back).toMatchObject({ commit: B, version: "0.7.284" }); |
| 203 | 213 | expect(standingHolds(f.app.db)[0]).toMatchObject({ kind: "failed", version: "0.7.285" }); |
| 214 | // The rollback is timed (#11919): the clock moved 40 s between the swap asked and the | |
| 215 | // known-good tree serving. | |
| 216 | const rolled = listKeeperReleases(f.app.db)[0]!; | |
| 217 | expect(rolled).toMatchObject({ version: "0.7.285", stage: "rolled_back", rollbackMs: 40_000 }); | |
| 218 | expect(listKeeperReleases(f.app.db)[1]!.rollbackMs).toBeNull(); | |
| 219 | expect(keeperAnswer(f.app.db).releases[0]!.stages.rollbackMs).toBe(40_000); | |
| 220 | expect(String(keeperPanel(f.app.db))).toContain("rolled back in 40 s"); | |
| 204 | 221 | // What a restart would run is still the verified B, not the bad C and not the image. |
| 205 | 222 | expect(lastGood(h.dataDir)).toMatchObject({ version: "0.7.284", commit: B, base: "0.7.283" }); |
| 206 | 223 |
new above
offline
The ?? null is redundant: the column is nullable and the row type says number | null.