From bdacd85b36afcf95d47dc636e481efdabe65fb21 Mon Sep 17 00:00:00 2001 From: "prompt.ac/@jeffrey" Date: Fri, 11 Sep 2026 10:51:06 -0400 Subject: [PATCH] oven: the papermill starts again, and stops undoing its own bookmark MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `papers/SCORE.md` promises that a push to `papers/` rebuilds the PDFs within a minute. It has not done that since May. Nothing failed — the promise just quietly stopped being kept, and the only place that said so was a `running: false` in a JSON blob nobody reads. On 2026-05-13 at 21:36 UTC a systemd drop-in appeared on the oven, `pause-papers-poller.conf`, setting `PAPERS_POLLER_DISABLED=1`. Ten minutes later `b53eca237a` landed — "kill papers auto-build commit loop" — and two days after that `f5c79b82d6` moved the PDFs off git and onto rsync. So the brake went on, the fix went in, and the brake stayed on for four months. Nothing in this repo ever recorded that the flag exists, and `deploy.sh` rewrites `override.conf` from scratch "so stale directives do not survive deploys" while never looking at the drop-ins sitting beside it. The brake was still load-bearing, though, because the loop was never actually cured. On 2026-03-18 an over-broad `git add -A` committed `.last-papers-built-hash`, so the poller's one piece of state became a *tracked* file — and every build ends with `git checkout -- "."` to sweep up xelatex dirt, which reverts that file to the commit it was captured in. `aaa62f4a`, 2026-03-21. The poller would build the mill, lose its place, re-derive the same six-month diff on the next tick, and go again, pushing a fresh metadata commit each lap. The self-commit author guard cannot catch it: a diff that wide has plenty of human authors in it. So the marker moves into `.git/oven-state/`, the one directory that `checkout`, `reset --hard` and `clean -fd` all leave alone. State that a build reverts underneath itself is not state. The rest is making the next failure louder than this one was. The poller now reports why it is off rather than only that it is off, and whether its ticks are still landing — a timer that exists and a timer that runs look identical from `running` alone. `npm run doctor` grows a papermill check that reads all of that and says the sentence out loud, next to the knot/mirror check it is a sibling of: reachability tells you a box answers, not that it is doing its job. Build history survives a restart now, because `recent: []` meant both "never built" and "restarted since", which are not the same answer to the only question anyone asks. And a build whose PDFs never reach lith stops calling itself a success — the LaTeX was clean, the shelf is still empty, and saying "success" to that is how a broken mill looks healthy from outside. Deploys clear the pause from now on. An emergency brake is not configuration; if the loop really comes back, pull it again and write down why. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01A1xZ1BonXHyds6EzF5H9Hb --- oven/deploy.sh | 7 +++ oven/papers-builder.mjs | 72 +++++++++++++++++++++--- oven/papers-git-poller.mjs | 112 +++++++++++++++++++++++++++++++++++-- papers/SCORE.md | 24 ++++++++ toolchain/doctor.mjs | 48 ++++++++++++++++ 5 files changed, 250 insertions(+), 13 deletions(-) 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") }, -- 2.51.2