diff --git a/oven/deploy.sh b/oven/deploy.sh index 91da01ffe..4c66d1b21 100755 --- a/oven/deploy.sh +++ b/oven/deploy.sh @@ -38,6 +38,7 @@ rsync -avz --progress --delete \ --exclude='ac-source' \ --exclude='native-git' \ --exclude='secrets' \ + --exclude='state' \ -e "ssh -i $SSH_KEY -o StrictHostKeyChecking=no" \ "$SCRIPT_DIR/" \ "root@$OVEN_HOST:$REMOTE_DIR/" @@ -298,6 +299,12 @@ fi install -m 0644 $REMOTE_DIR/infra/oven.service /etc/systemd/system/oven.service # Rewrite systemd override from scratch so stale directives do not survive deploys. mkdir -p /etc/systemd/system/oven.service.d +# Emergency pauses are not configuration. This one — PAPERS_POLLER_DISABLED=1, +# added by hand on 2026-05-13 to stop a rebuild loop — outlived its cause by +# four months, because rewriting override.conf 'from scratch' never touched the +# drop-ins beside it. Every deploy now clears it: the fix for a loop is a +# deploy, so if the loop is really back, re-add it and write down why. +rm -f /etc/systemd/system/oven.service.d/pause-papers-poller.conf cat > /etc/systemd/system/oven.service.d/override.conf < h.id !== snapshot.id)].slice( + 0, + MAX_RECENT_JOBS, + ); + try { + mkdirSync(STATE_DIR, { recursive: true }); + writeFileSync(HISTORY_FILE, JSON.stringify(history, null, 2), "utf8"); + } catch { + // A read-only or missing state dir must never take the build down. + } +} + +loadHistory(); + function nowISO() { return new Date().toISOString(); } @@ -74,6 +112,7 @@ function makeSnapshot(job, opts = {}) { finishedAt: job.finishedAt, exitCode: job.exitCode, error: job.error, + publishError: job.publishError || null, logCount: job.logs.length, elapsedMs: job.startedAt ? (job.finishedAt ? Date.parse(job.finishedAt) : Date.now()) - @@ -248,8 +287,19 @@ async function runPapersJob(job) { try { await publishToLith(job); } catch (pushErr) { - // Non-fatal — PDFs were built successfully even if publish failed - addLogLine(job, "stderr", ` PUBLISH FAILED: ${pushErr.message}${pushErr.stderr ? " | " + pushErr.stderr.trim() : ""}`); + // A build whose PDFs never reach papers.aesthetic.computer is not a + // success, however clean the xelatex runs were — reporting it as one is + // how a broken papermill looks healthy from the outside. The PDFs *did* + // build, so say exactly that and let the status endpoint carry it. + const detail = `${pushErr.message}${pushErr.stderr ? " | " + pushErr.stderr.trim() : ""}`; + addLogLine(job, "stderr", ` PUBLISH FAILED: ${detail}`); + job.publishError = detail; + job.status = "failed"; + job.stage = "publish-failed"; + job.percent = 100; + job.error = `PDFs built, but publishing to lith failed: ${detail}`; + job.finishedAt = nowISO(); + return; } job.status = "success"; @@ -263,6 +313,7 @@ async function runPapersJob(job) { job.error = err.message || String(err); } finally { if (activeJobId === job.id) activeJobId = null; + saveHistory(makeSnapshot(job)); } } @@ -309,13 +360,20 @@ export function getPapersBuild(jobId, opts = {}) { } export function getPapersBuildsSummary() { + const live = jobOrder + .map((id) => jobs.get(id)) + .filter(Boolean) + .map((j) => makeSnapshot(j)); + const liveIds = new Set(live.map((j) => j.id)); return { activeJobId, active: activeJobId ? makeSnapshot(jobs.get(activeJobId)) : null, - recent: jobOrder - .map((id) => jobs.get(id)) - .filter(Boolean) - .map((j) => makeSnapshot(j)), + // This process's jobs first, then whatever earlier runs left on disk. + recent: [...live, ...history.filter((h) => !liveIds.has(h.id))].slice( + 0, + MAX_RECENT_JOBS, + ), + lastFinished: [...live, ...history].find((j) => j.finishedAt) || null, }; } diff --git a/oven/papers-git-poller.mjs b/oven/papers-git-poller.mjs index 06ab22ee2..1c8e74c63 100644 --- a/oven/papers-git-poller.mjs +++ b/oven/papers-git-poller.mjs @@ -5,7 +5,8 @@ // successful build. If so, pulls and triggers startPapersBuild(). // // Shares the git clone at GIT_REPO_DIR with native-git-poller.mjs. -// Uses a separate hash file (.last-papers-built-hash) to track state. +// Keeps its own build marker under .git/oven-state/ — see the note below for +// why it cannot live in the worktree. import { execFile } from "child_process"; import { promises as fs } from "fs"; @@ -14,7 +15,24 @@ import path from "path"; const POLL_INTERVAL_MS = parseInt(process.env.PAPERS_POLL_INTERVAL_MS || "60000", 10); const GIT_REPO_DIR = process.env.NATIVE_GIT_DIR || "/opt/oven/native-git"; const BRANCH = process.env.NATIVE_GIT_BRANCH || "main"; -const HASH_FILE = path.join(GIT_REPO_DIR, ".last-papers-built-hash"); + +// The "already built" marker lives inside .git/, not in the worktree. +// +// It used to be /.last-papers-built-hash — and on 2026-03-18 an +// over-broad `git add -A` in the builder committed that file to main. From +// then on it was a *tracked* file holding poller state, so every cleanup the +// pipeline runs at the end of a build — `git checkout -- .` in +// papers-builder.mjs, `git reset --hard` + `git clean -fd` in +// native-git-poller.mjs — silently reverted it to the committed value +// (aaa62f4a, 2026-03-21). The poller then re-derived the same months-wide diff +// on the very next tick and rebuilt the entire mill again, pushing a fresh +// metadata commit each lap. That is the "papers auto-build commit loop" the +// poller was hand-paused for on 2026-05-13. +// +// .git/ is the one directory none of those cleanups touch, so state kept here +// survives a build instead of being undone by it. +const STATE_DIR = path.join(GIT_REPO_DIR, ".git", "oven-state"); +const HASH_FILE = path.join(STATE_DIR, "papers-last-built-hash"); // Paths that should trigger a papers rebuild (prefixes) const TRIGGER_PREFIXES = [ @@ -60,6 +78,28 @@ let timer = null; let startBuildFn = null; let logFn = (level, icon, msg) => console.log(`[papers-git-poller] ${msg}`); +// Health, reported verbatim by GET /papers-build so that "is the papermill +// alive?" is answerable without shelling into the box. `running: false` on its +// own never said *why* — that is how a systemd drop-in kept this off for four +// months without anyone noticing. +const health = { + enabled: true, + disabledReason: null, + startedAt: null, + lastPollAt: null, + lastPollOk: null, + lastError: null, + consecutiveErrors: 0, + lastBuiltHash: null, + lastTriggerAt: null, + lastTriggeredJobId: null, +}; + +function markDisabled(reason) { + health.enabled = false; + health.disabledReason = reason; +} + function git(args, cwd = GIT_REPO_DIR) { return new Promise((resolve, reject) => { execFile("git", args, { cwd, timeout: 30_000 }, (err, stdout, stderr) => { @@ -76,18 +116,29 @@ async function readLastBuiltHash() { try { return (await fs.readFile(HASH_FILE, "utf8")).trim(); } catch { + // No marker → treat as a first run and rebuild the whole mill once. The + // legacy worktree file is deliberately NOT read as a fallback: its value is + // the stale commit the loop kept restoring, so trusting it would just start + // the treadmill again. To skip the one-time full rebuild, seed this file by + // hand with the commit whose PDFs are already deployed. return null; } } async function writeLastBuiltHash(hash) { + await fs.mkdir(STATE_DIR, { recursive: true }); await fs.writeFile(HASH_FILE, hash + "\n", "utf8"); + health.lastBuiltHash = hash; } async function poll() { - if (process.env.PAPERS_POLLER_DISABLED === "1") return; + if (process.env.PAPERS_POLLER_DISABLED === "1") { + markDisabled("PAPERS_POLLER_DISABLED=1"); + return; + } if (polling) return; polling = true; + health.lastPollAt = new Date().toISOString(); try { // Fetch latest from origin @@ -95,6 +146,10 @@ async function poll() { const remoteHead = await git(["rev-parse", `origin/${BRANCH}`]); const lastBuilt = await readLastBuiltHash(); + health.lastBuiltHash = lastBuilt; + health.lastPollOk = true; + health.lastError = null; + health.consecutiveErrors = 0; if (remoteHead === lastBuilt) { polling = false; @@ -181,11 +236,13 @@ async function poll() { await writeLastBuiltHash(remoteHead); // Trigger build + health.lastTriggerAt = new Date().toISOString(); const job = await startBuildFn({ ref: remoteHead, changed_paths: papersPaths.join(","), }); + health.lastTriggeredJobId = job.id; logFn( "info", "🚀", @@ -195,10 +252,16 @@ async function poll() { if (err?.code === "PAPERS_BUILD_BUSY") { logFn("info", "⏳", "Papers build already running — will retry next poll"); } else { + health.lastPollOk = false; + health.consecutiveErrors += 1; + health.lastError = { + at: new Date().toISOString(), + message: `${err.message}${err.stderr ? " | " + err.stderr.trim() : ""}`, + }; logFn( "error", "❌", - `Papers git poll error: ${err.message}${err.stderr ? " | " + err.stderr.trim() : ""}` + `Papers git poll error (${health.consecutiveErrors} in a row): ${err.message}${err.stderr ? " | " + err.stderr.trim() : ""}` ); } } finally { @@ -213,13 +276,23 @@ export function startPoller({ startPapersBuild, addServerLog }) { if (addServerLog) logFn = addServerLog; if (process.env.PAPERS_POLLER_DISABLED === "1") { - logFn("info", "⏸️", "Papers git poller disabled via PAPERS_POLLER_DISABLED=1 — not starting"); + markDisabled("PAPERS_POLLER_DISABLED=1"); + logFn( + "error", + "⏸️", + "Papers git poller OFF — PAPERS_POLLER_DISABLED=1. Nothing in this repo " + + "sets it, so it came from the unit: check " + + "/etc/systemd/system/oven.service.d/*.conf on the oven.", + ); return; } // Check that GIT_REPO_DIR exists before starting fs.access(GIT_REPO_DIR) .then(() => { + health.enabled = true; + health.disabledReason = null; + health.startedAt = new Date().toISOString(); logFn( "info", "📄", @@ -230,6 +303,7 @@ export function startPoller({ startPapersBuild, addServerLog }) { timer = setInterval(poll, POLL_INTERVAL_MS); }) .catch(() => { + markDisabled(`repo dir not found: ${GIT_REPO_DIR}`); logFn( "error", "⚠️", @@ -247,10 +321,36 @@ export function stopPoller() { } export function getPollerStatus() { + const running = timer !== null; + const sinceLastPollMs = health.lastPollAt + ? Date.now() - Date.parse(health.lastPollAt) + : null; return { - running: timer !== null, + running, + // `enabled` is the *intent*, `running` the fact; when they disagree, + // `disabledReason` says which switch did it. + enabled: health.enabled, + disabledReason: health.disabledReason, + // A poller whose timer exists but whose ticks have stopped landing (a + // wedged git fetch, say) looks identical to a healthy one from `running` + // alone. Three missed intervals is the line. + healthy: + running && + health.enabled && + sinceLastPollMs !== null && + sinceLastPollMs < POLL_INTERVAL_MS * 3 && + health.consecutiveErrors < 3, intervalMs: POLL_INTERVAL_MS, repoDir: GIT_REPO_DIR, branch: BRANCH, + startedAt: health.startedAt, + lastPollAt: health.lastPollAt, + sinceLastPollMs, + lastPollOk: health.lastPollOk, + consecutiveErrors: health.consecutiveErrors, + lastError: health.lastError, + lastBuiltHash: health.lastBuiltHash, + lastTriggerAt: health.lastTriggerAt, + lastTriggeredJobId: health.lastTriggeredJobId, }; } diff --git a/papers/SCORE.md b/papers/SCORE.md index 2eda2fd2e..05c9eca9b 100644 --- a/papers/SCORE.md +++ b/papers/SCORE.md @@ -345,6 +345,30 @@ The pipeline polls git every 60s, detects changes, and runs `node papers/cli.mjs - **Manual trigger:** `POST oven.aesthetic.computer/papers-build` (requires admin key) - **SSE logs:** `GET oven.aesthetic.computer/papers-build/:jobId/stream` - **Source:** `oven/papers-builder.mjs`, `oven/papers-git-poller.mjs` +- **Health:** `npm run doctor` — the "oven papermill (papers/)" check fails loudly + when the poller is stopped, wedged, or its last build did not reach the site. + +#### When the mill goes quiet + +It has gone quiet before, for four months, without anything failing. On +2026-05-13 the poller was paused by hand — a systemd drop-in at +`/etc/systemd/system/oven.service.d/pause-papers-poller.conf` setting +`PAPERS_POLLER_DISABLED=1` — to stop a rebuild loop. The loop was fixed two days +later; the pause was never lifted, and nothing in this repo records it. So when +`GET /papers-build` reports `"running": false`, look at the unit drop-ins on the +oven first, not at the code: + +```bash +ssh -i aesthetic-computer-vault/oven/ssh/oven-deploy-key root@oven.aesthetic.computer \ + 'ls /etc/systemd/system/oven.service.d/ && systemctl show oven -p Environment' +``` + +The poller's "already built" marker lives at +`/.git/oven-state/papers-last-built-hash`, deliberately inside `.git/` — +the builder ends each run with `git checkout -- .`, so a marker in the worktree +gets reverted by the build it was recording, and the poller then rebuilds the +same diff forever. Deleting that marker forces one full rebuild; seeding it with +a commit SHA declares that commit's PDFs already deployed. ### Manual (Local) diff --git a/toolchain/doctor.mjs b/toolchain/doctor.mjs index 6842679e7..9582fd313 100644 --- a/toolchain/doctor.mjs +++ b/toolchain/doctor.mjs @@ -152,6 +152,53 @@ async function mirrorInSync() { `lacks and is ${behind} behind; reconcile before deploying` }; } +// Is the oven's papermill actually watching main? +// +// `papers/SCORE.md` promises that pushing to `papers/` rebuilds the PDFs within +// a minute. On 2026-05-13 the poller was hand-paused with a systemd drop-in to +// stop a runaway rebuild loop; the loop was fixed two days later, the pause +// never lifted, and for four months every papers push quietly built nothing. +// Nothing failed — the promise just stopped being kept, and the only place that +// said so was a `running: false` in a JSON blob nobody reads. +async function papersMill() { + const t0 = Date.now(); + const ctrl = new AbortController(); + const timer = setTimeout(() => ctrl.abort(), 8000); + try { + const res = await fetch("https://oven.aesthetic.computer/papers-build", { + signal: ctrl.signal, + }); + const ms = Date.now() - t0; + if (!res.ok) return { ok: false, ms, note: `oven says HTTP ${res.status}` }; + const { poller = {}, active, recent = [] } = await res.json(); + + if (poller.running !== true) + return { ok: false, ms, note: + `poller STOPPED${poller.disabledReason ? ` — ${poller.disabledReason}` : ""}` + + ` — papers pushes are not rebuilding; check ` + + `/etc/systemd/system/oven.service.d/*.conf on the oven` }; + + if (poller.healthy === false) + return { ok: false, ms, note: + `poller timer alive but not ticking (last poll ` + + `${poller.sinceLastPollMs ?? "?"}ms ago, ${poller.consecutiveErrors ?? 0} ` + + `errors in a row)${poller.lastError ? `: ${poller.lastError.message}` : ""}` }; + + if (active) return { ok: true, ms, note: `building ${active.id} (${active.stage})` }; + + const last = recent.find((j) => j.finishedAt); + if (last && last.status !== "success") + return { ok: false, ms, note: + `last build ${last.id} ${last.status}${last.error ? `: ${last.error}` : ""}` }; + if (last) return { ok: true, ms, note: `idle; last build ok ${last.finishedAt}` }; + return { ok: true, ms, note: "polling; no build recorded yet" }; + } catch (e) { + return { ok: false, ms: Date.now() - t0, note: e.name === "AbortError" ? "timeout" : (e.code || e.message) }; + } finally { + clearTimeout(timer); + } +} + // ── the checklist ──────────────────────────────────────────────────────────── // group · label · run() → {ok, ms?, note?} · critical? · scope (local|prod|tool) @@ -171,6 +218,7 @@ const CHECKS = [ // Deploy provenance — reachability says a box answers, not that it answers // with the code you shipped. { group: "Deploy", label: "knot ↔ github mirror", scope: "prod", run: () => mirrorInSync() }, + { group: "Deploy", label: "oven papermill (papers/)", scope: "prod", run: () => papersMill() }, // Host tooling — the binaries pipelines shell out to. { group: "Host tooling", label: "node", scope: "tool", run: () => bin("node") },