Updater heals itself: PM2 cron revived, Update now, failure reasons

PM2's cron for autofirmer-update dies inside a live daemon (six Windows
machines in October), and nothing on the machine noticed. The app now
watches scripts/.last-check and, past 10 minutes, runs
update-check.mjs --heal: a checker PM2 still lists is restarted (which
re-registers its cron), one it lost is registered again, and one whose
errored entry still holds a live pid is left alone, since PM2 would kill
that pid. The heal scrubs PM2's per-app fields from its environment first.

The master's new 'update-now' command runs --heal --now, skipping a
failed update's retry wait. A failed pull, npm install or build records
one line of reason (or the chown to run when a file isn't ours), which
rides on .last-check to the master. A package-lock.json rewritten by npm
is put back before the pull. The fetch timeout drops under the cron's
minute. scripts/.no-auto-update opts a checkout out.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
Brandon Li
2026-10-19 00:41:04 -05:00
co-authored by Claude Opus 5.5
parent c0899620d4
commit 13e03c3d0f
6 changed files with 396 additions and 23 deletions
+276 -22
View File
@@ -33,9 +33,15 @@
* the build fails, and a failure is retried on a backoff (scripts/.update-failed)
* rather than every minute.
*
* A machine whose checker stopped firing can't notice by itself, so the app
* asks for a heal (lib/updater-watchdog.ts) once the last check goes stale, and
* the master's "Update now" asks for a heal plus an immediate check.
*
* node scripts/update-check.mjs # check; start a worker if needed
* node scripts/update-check.mjs --apply # update now, here, in the foreground
* node scripts/update-check.mjs --dry-run # report only, change nothing
* node scripts/update-check.mjs --heal # re-register a checker that stopped, then check
* node scripts/update-check.mjs --now # check without waiting out a failure's backoff
*/
import { spawn, spawnSync } from 'node:child_process';
import {
@@ -65,6 +71,14 @@ const BRANCH = process.env.AUTOFIRMER_BRANCH ?? 'master';
const INSTANCES = loadInstances();
const APPLY = process.argv.includes('--apply');
const DRY_RUN = process.argv.includes('--dry-run');
const HEAL = process.argv.includes('--heal');
const NOW = process.argv.includes('--now');
const OPT_OUT_FILE = path.join(ROOT, 'scripts', '.no-auto-update');
// The PM2 app install-autostart.* registers, and its schedule.
const CHECKER = 'autofirmer-update';
const DEFAULT_CRON = '*/1 * * * *';
// The master's UPDATER_STALE_MS: past this its dashboard says "updater not running".
const STALE_CHECK_MS = 10 * 60 * 1000;
const STALE_LOCK_MS = 2 * 60 * 60 * 1000;
const LEGACY_STALE_LOCK_MS = 10 * 60 * 1000;
const LOCK_SETTLE_MS = 1000;
@@ -76,7 +90,10 @@ const REPEAT_RETRY_MS = 60 * 60 * 1000;
// it. npm and next build are left unbounded: on Windows a timeout would kill
// only the cmd.exe in front of them, and an orphaned build still writing into
// .next is worse than a slow one.
const FETCH_TIMEOUT_MS = 2 * 60 * 1000;
// The fetch also stays under the cron's minute: a check still running at the next
// fire has to be killed by PM2, and that kill is where PM2 loses the cron
// (see heal).
const FETCH_TIMEOUT_MS = 45 * 1000;
const PM2_TIMEOUT_MS = 3 * 60 * 1000;
const LOG_MAX_BYTES = 256 * 1024;
const LOG_KEEP_LINES = 500;
@@ -120,6 +137,13 @@ function recordCheck(status) {
} catch { /* never let bookkeeping break an update */ }
}
/**
* An argument for run() as cmd.exe will see it. On Windows run() goes through
* the shell, which joins the arguments with plain spaces, so a cron string or
* a path with a space in it would arrive as several.
*/
const shellArg = (arg) => (process.platform === 'win32' && /[\s"]/.test(arg) ? `"${arg.replace(/"/g, '""')}"` : arg);
function run(cmd, args, { capture = false, timeout } = {}) {
return spawnSync(cmd, args, {
cwd: ROOT,
@@ -370,7 +394,7 @@ function releaseLock() {
}
// ── failure record ──────────────────────────────────────────────────────────
// scripts/.update-failed = { target, step, at, count, restart, clicker }.
// scripts/.update-failed = { target, step, at, count, restart, clicker, detail? }.
//
// Written when an attempt STARTS and deleted when it succeeds, so a worker
// that dies without reporting (killed, rebooted) still counts as a failed
@@ -393,6 +417,54 @@ function writeFailure(f) {
function clearFailure() {
try { rmSync(FAILED_FILE, { force: true }); } catch { /* bookkeeping */ }
}
/** Size of update-worker.log right now, so a step's own output can be told apart. */
function workerLogSize() {
try { return statSync(WORKER_LOG_FILE).size; } catch { return 0; }
}
/** What update-worker.log gained since `from` ('' when a by-hand --apply
* wrote to the terminal instead). */
function workerLogSince(from) {
try {
const buf = readFileSync(WORKER_LOG_FILE);
return buf.length > from ? buf.subarray(from).toString('utf8') : '';
} catch {
return '';
}
}
/**
* Why a step failed, from its output since `from`: the file this user can't
* replace when a permission is what stopped it, else one line of the output.
*/
function explainFailure(from) {
const text = workerLogSince(from);
return (PERMISSION_DENIED.test(text) && ownershipProblem()) || failureReason(text);
}
/**
* One line on why a step failed, from its output, or null.
*
* The full npm/next output stays on the machine. Without a reason the master
* shows only "update failed at build", and a machine failing for a cause of
* its own (a Node upgrade leaving better-sqlite3 on the old ABI, a file
* Defender holds, a full disk) can't be told from a broken push. The line
* rides on .last-check, which every app build and the master already carry.
*/
function failureReason(text) {
// eslint-disable-next-line no-control-regex
const lines = text.replace(/\x1b\[[0-9;]*m/g, '').split(/\r?\n/).map((l) => l.trim()).filter(Boolean);
// npm's own epilogue says only that the script failed, and where its log
// is; and this script's own log lines (they go to the console too) aren't
// the step's output.
const boilerplate = /^npm (ERR!|error)( (code|path|command|errno|syscall|signal|workspace|location|A complete log|Lifecycle)\b|\s*$)|^> |^\d{4}-\d\d-\d\dT\S+ {2}/;
const first = (re) => lines.find((l) => re.test(l) && !boilerplate.test(l));
const line = first(/NODE_MODULE_VERSION|ERR_DLOPEN_FAILED|\bE(PERM|BUSY|ACCES|NOSPC)\b|heap out of memory|Type error:/)
?? first(/\b[Ee]rror\b/)
?? lines.filter((l) => !boilerplate.test(l)).pop();
return line ? line.replace(/\s+/g, ' ').slice(0, 100) : null;
}
/** 15 min after the first failure, an hour after repeated ones: long enough
* that a deterministic failure (a broken push) doesn't rebuild every minute
* on a trading PC, short enough that a transient one (network, EPERM) heals
@@ -434,19 +506,28 @@ function headMovedAt() {
}
}
/** PM2's process list, or null when PM2 can't be asked. */
function pm2List() {
const r = run('pm2', ['jlist'], { capture: true, timeout: 30_000 });
if (r.status !== 0) return null;
// jlist prints the process list as one JSON line, possibly after "[PM2] ..." chatter.
const line = (r.stdout ?? '').split('\n').find((l) => /^\s*\[\s*[{\]]/.test(l));
try {
const procs = JSON.parse(line);
return Array.isArray(procs) ? procs : null;
} catch {
return null;
}
}
/**
* Names of this checkout's PM2 instances that started before `ms`, i.e. still
* running code from before the build on disk. Empty when PM2 can't be asked:
* this only sharpens a heuristic and must never block an update.
*/
function instancesStartedBefore(ms) {
const r = run('pm2', ['jlist'], { capture: true, timeout: 30_000 });
if (r.status !== 0) return [];
// jlist prints the process list as one JSON line, possibly after "[PM2] ..." chatter.
const line = (r.stdout ?? '').split('\n').find((l) => /^\s*\[\s*[{\]]/.test(l));
let procs;
try { procs = JSON.parse(line); } catch { return []; }
if (!Array.isArray(procs)) return [];
const procs = pm2List();
if (!procs) return [];
const names = new Set(INSTANCES.map((i) => i.name));
return procs
.filter((p) => names.has(p?.name) && p.pm2_env?.status === 'online' && Number(p.pm2_env.pm_uptime) < ms)
@@ -550,6 +631,65 @@ function workFor(plan) {
};
}
// ── stuck states ────────────────────────────────────────────────────────────
// Two states that fail every update until a person gets onto the machine.
/** What a step prints when it may not touch a file. */
const PERMISSION_DENIED = /permission denied|insufficient permission|\bEACCES\b|\bEPERM\b/i;
/**
* A file in the checkout this user doesn't own, as the fix to run, or null.
*
* One `sudo git pull` or `sudo npm run build` leaves files this user cannot
* replace, and from then on every update fails: the build can't clear .next,
* and a fetch can't write into .git (Ziad's Pi, 2026-10-02: ~1,800 of them).
* The failure itself only says EACCES somewhere in npm's output, so name the
* file and the one command that fixes it — the master's updater chip shows
* this line. Asked only once a step has failed on a permission: a stray
* root-owned file that blocks nothing must not stop an update. POSIX only.
*/
function ownershipProblem() {
if (typeof process.getuid !== 'function') return null;
const r = run('find', [ROOT, '!', '-user', String(process.getuid()), '-print', '-quit'], { capture: true, timeout: 20_000 });
const hit = (r.stdout ?? '').split('\n')[0].trim();
if (!hit) return null;
let owner = 'another user';
try {
const uid = lstatSync(hit).uid;
owner = uid === 0 ? 'root' : `uid ${uid}`;
} catch { /* gone since: the generic name will do */ }
return `${path.relative(ROOT, hit) || '.'} is owned by ${owner}: run sudo chown -R ${os.userInfo().username} ${ROOT}`;
}
/** inspect(), with a fetch refused by a .git this user can't write named as such. */
function inspectNamingOwnership(opts) {
try {
return inspect(opts);
} catch (err) {
const why = PERMISSION_DENIED.test(err.message) ? ownershipProblem() : null;
throw why ? new Error(why) : err;
}
}
/**
* npm install rewrites package-lock.json on some machines (another npm
* version, platform-specific optional dependencies), and that edit then
* refuses every fast-forward that touches the file. It is generated, so when
* it is the only tracked edit, put it back. Any other edit is a person's and
* stays, showing as "edited here" on the master.
*/
function restoreRewrittenLockfile() {
let changed;
try {
changed = git('diff', '--name-only', 'HEAD').split('\n').filter(Boolean);
} catch {
return;
}
if (changed.length !== 1 || changed[0] !== 'package-lock.json') return;
git('checkout', 'HEAD', '--', 'package-lock.json');
log('package-lock.json had been rewritten here (npm) — put it back before the pull');
}
// ── build ───────────────────────────────────────────────────────────────────
/**
@@ -630,6 +770,111 @@ function removePrevBuild() {
}
}
// ── heal ────────────────────────────────────────────────────────────────────
// The checker runs only while PM2 fires it, and PM2 loses it easily: a
// `pm2 stop`, a `pm2 delete all`, a reboot after a list change nobody saved.
/** How long ago the last check ran, in ms; null = never on this checkout. */
function lastCheckAge() {
try {
const at = Date.parse(readFileSync(LAST_CHECK_FILE, 'utf8').split(/\s/, 1)[0]);
return Date.now() - (Number.isFinite(at) ? at : statSync(LAST_CHECK_FILE).mtimeMs);
} catch {
return null;
}
}
const fmtAge = (ms) => (ms >= 90 * 60 * 1000 ? `${Math.round(ms / 3_600_000)} h` : `${Math.round(ms / 60_000)} min`);
/**
* The fields PM2 adds to an app's environment.
*
* PM2 hands every app the scalar fields of its own record as environment
* (name, pm_id, autorestart, …), and `pm2 start` captures the caller's
* environment for the new app, then copies it over the new app's record. A
* checker registered by a heal, which the dashboard app starts, would take
* that app's name and id, and its autorestart would override
* --no-autorestart. These are the fields PM2 put on real records, plus the
* ones only some records carry. PORT and AUTOFIRMER_DB are the instance's
* own, and the checker serves every instance.
*/
const INHERITED_FIELDS = new Set([
'NODE_APP_INSTANCE', 'automation', 'autorestart', 'autostart', 'created_at', 'cron_restart',
'exec_interpreter', 'exec_mode', 'exit_code', 'filter_env', 'instance_var', 'instances',
'kill_retry_time', 'km_link', 'merge_logs', 'name', 'namespace', 'node_version', 'pmx',
'prev_restart_delay', 'restart_time', 'status', 'stop_exit_codes', 'treekill', 'unique_id',
'unstable_restarts', 'username', 'version', 'versioning', 'vizion', 'vizion_running', 'watch',
'windowsHide', 'PORT', 'AUTOFIRMER_DB',
]);
/** Drop what PM2 (and the instance) put in this process's environment, so
* nothing started from here inherits it. */
function scrubInheritedEnv() {
// PM2 also files the app's own config under its name.
if (process.env.name) delete process.env[process.env.name];
for (const key of Object.keys(process.env)) {
if (INHERITED_FIELDS.has(key) || key.startsWith('pm_') || key.startsWith('axm_')) delete process.env[key];
}
}
/**
* Get PM2 firing this script again once its checks have stopped. Returns
* false when this checkout is opted out of updates altogether.
*
* What the fleet shows (2026-10, six Windows machines): the cron dies inside
* a live PM2 daemon, nobody involved. Every fire runs restartProcessId,
* whose first step drops the cron; only a restart that gets as far as
* launching the app registers it again. croner sometimes fires twice in
* one second, the second restart has to stop a check that is still
* launching, and a refused or timed-out stop leaves the checker `stopped`
* or `errored` with no cron at all.
*
* So a checker PM2 still lists is restarted, which registers its cron again
* with the schedule and environment it already had, and nothing is deleted:
* `pm2 delete` kills the pid an `errored` entry kept, and Windows hands pids
* out again quickly, so that could be any program by now. If that pid is
* alive, PM2 is left alone and this run checks instead. Only a checker PM2
* has lost entirely is registered again, the way install-autostart.* does.
*/
function heal() {
if (existsSync(OPT_OUT_FILE)) {
console.log('scripts/.no-auto-update is here — this checkout is not auto-updated');
return false;
}
// Before anything is started from here, the worker below included: the
// app that asked for this heal is a PM2 app, and may be instance 2.
scrubInheritedEnv();
const age = lastCheckAge();
if (age !== null && age <= STALE_CHECK_MS) return true; // checking on schedule
const why = age === null ? 'the update checker had never run here' : `the update checker had stopped (last check ${fmtAge(age)} ago)`;
const pm2 = (...args) => run('pm2', args.map(shellArg), { capture: true, timeout: PM2_TIMEOUT_MS });
const lastLine = (r) => (((r.stderr || r.stdout) ?? '').trim().split('\n').pop() || `exit ${r.status}`);
const listed = pm2List()?.find((p) => p?.name === CHECKER);
const pid = Number(listed?.pid);
if (listed && pid > 0 && pidAlive(pid)) {
log(`${why}, but PM2 still has it on pid ${pid}, which is alive — left PM2 alone (a restart would kill that pid); checking from here`);
return true;
}
let how;
if (listed && pm2('restart', CHECKER).status === 0) {
how = `restarted it in PM2 (${listed.pm2_env?.status ?? 'unknown'}), which registers its cron again`;
} else {
const cron = listed?.pm2_env?.cron_restart || DEFAULT_CRON;
if (listed) pm2('delete', CHECKER); // its restart failed, and its pid is dead
const r = pm2('start', SELF, '--name', CHECKER, '--no-autorestart', '--cron-restart', cron);
if (r.status !== 0) {
log(`${why} — ERROR: could not register it with PM2: ${lastLine(r)}`);
return true; // the check below can still update this machine
}
how = `registered it with PM2 again (${cron})`;
}
const saved = pm2('save').status === 0;
log(`${why} — ${how}${saved ? '' : ', but pm2 save failed: a reboot would lose it'}`);
return true;
}
// ── check ───────────────────────────────────────────────────────────────────
/**
@@ -688,7 +933,7 @@ function check() {
let outcome = null;
try {
const plan = inspect({ adopt: !DRY_RUN });
const plan = inspectNamingOwnership({ adopt: !DRY_RUN });
if (!plan.needsPull && !plan.needsBuild && !plan.needsRestart) {
outcome = `up to date at ${short(plan.target)}`; // silent in the log by design
if (DRY_RUN) console.log(outcome);
@@ -699,9 +944,11 @@ function check() {
return 0;
}
// Silent in update.log too: the failure itself was logged once, and a
// line a minute until the retry would bury it.
if (plan.pending && Date.now() < retryAt(plan.pending)) {
outcome = `waiting to retry ${short(plan.target)}: ${plan.pending.step} (attempt ${plan.pending.count}), next try after ${new Date(retryAt(plan.pending)).toISOString()}`;
// line a minute until the retry would bury it. --now (the master's
// "Update now") is a person asking for the retry.
if (plan.pending && !NOW && Date.now() < retryAt(plan.pending)) {
outcome = `waiting to retry ${short(plan.target)}: ${plan.pending.step} (attempt ${plan.pending.count}), next try after ${new Date(retryAt(plan.pending)).toISOString()}`
+ (plan.pending.detail ? ` — ${plan.pending.detail}` : '');
return 0;
}
const pid = startWorker();
@@ -748,15 +995,15 @@ async function apply() {
let outcome = 'interrupted';
let attempt = null;
const abort = (step, why) => {
log(`ABORTED: ${why}`);
outcome = why;
if (attempt) writeFailure({ ...attempt, step, at: Date.now() });
const abort = (step, why, detail = null) => {
log(`ABORTED: ${why}${detail ? ` (${detail})` : ''}`);
outcome = detail ? `${why}: ${detail}` : why;
if (attempt) writeFailure({ ...attempt, step, at: Date.now(), ...(detail ? { detail } : {}) });
return 1;
};
try {
const plan = inspect({ adopt: true });
const plan = inspectNamingOwnership({ adopt: true });
if (!plan.needsPull && !plan.needsBuild && !plan.needsRestart) {
outcome = `up to date at ${short(plan.target)}`;
clearFailure();
@@ -780,14 +1027,19 @@ async function apply() {
else if (plan.needsBuild) log('last build unknown — treating every file as changed');
// The exact commit the check saw, not whatever `git pull` would fetch now.
if (plan.needsPull && run('git', ['merge', '--ff-only', target]).status !== 0) {
return abort('pull', `git pull --ff-only to ${short(target)} failed — see scripts/update-worker.log`);
if (plan.needsPull) {
restoreRewrittenLockfile();
const from = workerLogSize();
if (run('git', ['merge', '--ff-only', target]).status !== 0) {
return abort('pull', `git pull --ff-only to ${short(target)} failed — see scripts/update-worker.log`, explainFailure(from));
}
}
if (plan.needsBuild) {
if (work.npmInstall) {
log(`${because('package-lock.json')} — npm install`);
if (run('npm', ['install']).status !== 0) return abort('npm install', 'npm install failed — nothing was built or restarted');
const from = workerLogSize();
if (run('npm', ['install']).status !== 0) return abort('npm install', 'npm install failed — nothing was built or restarted', explainFailure(from));
}
if (work.pythonDeps) {
log(`${because('clicker/requirements.txt')} — refreshing python deps`);
@@ -796,7 +1048,8 @@ async function apply() {
// Build BEFORE restarting. A failed build leaves the running process
// untouched, which is the whole point of doing it in this order.
if (!build()) return abort('build', 'build failed — not deployed, nothing was restarted');
const from = workerLogSize();
if (!build()) return abort('build', 'build failed — not deployed, nothing was restarted', explainFailure(from));
// .built-commit says what .next holds, so it changes the moment .next
// does. From here a failed restart must not rebuild, only restart,
@@ -898,6 +1151,7 @@ async function logHealth(instance, base) {
async function main() {
mkdirSync(path.join(ROOT, 'scripts'), { recursive: true });
trimLog();
if (HEAL && !DRY_RUN && !heal()) return 0;
return APPLY && !DRY_RUN ? apply() : check();
}