diff --git a/scripts/poller-health-alert.mjs b/scripts/poller-health-alert.mjs index c2885d3..0fb562b 100644 --- a/scripts/poller-health-alert.mjs +++ b/scripts/poller-health-alert.mjs @@ -17,27 +17,53 @@ // IAK_ALERT_TIMEOUT_MS (default 15000; a stalled POST must not block the // supervisor loop - codex review of PR #87). import { existsSync, statSync, readFileSync, writeFileSync, unlinkSync } from 'node:fs'; - -const key = process.env.IAK_ALERT_KEY; -const heartbeat = process.env.IAK_POLLER_HEARTBEAT || '/tmp/iak-poller.heartbeat'; -const maxAge = Number(process.env.IAK_POLLER_MAX_AGE_SEC || 180); -const errLog = process.env.IAK_POLLER_ERR_LOG || ''; -const room = process.env.IAK_ALERT_ROOM || 'thinkoff-development'; -const stateFile = process.env.IAK_ALERT_STATE || '/tmp/iak-poller-alert.state'; -const base = (process.env.IAK_ALERT_BASE || 'https://groupmind.one/api/v1').replace(/\/$/, ''); -const label = process.env.IAK_ALERT_LABEL || 'room poller'; -const timeoutMs = Number(process.env.IAK_ALERT_TIMEOUT_MS || 15000); - -if (!key) { - console.error('poller-health-alert: IAK_ALERT_KEY missing'); - process.exit(2); -} +import { execFileSync } from 'node:child_process'; +import { pathToFileURL } from 'node:url'; export function heartbeatAge(path, now = Date.now()) { if (!existsSync(path)) return Infinity; return Math.round((now - statSync(path).mtimeMs) / 1000); } +// Gap shape (claudeMB, 2026-09-02): a stale heartbeat while the poller's +// err log has NOT grown since the heartbeat stopped means the process was +// suspended (the MacBook slept 15 of every 16 minutes on Maintenance Sleep +// that night), not failing. A failing poller keeps writing errors. +export function errLogQuietSince(errPath, heartbeatPath) { + try { + if (!errPath || !existsSync(errPath) || !existsSync(heartbeatPath)) return false; + return statSync(errPath).mtimeMs <= statSync(heartbeatPath).mtimeMs; + } catch { + return false; + } +} + +// Independent sleep evidence (codex review of PR #94): a quiet err log also +// follows a silent exit or SIGKILL, so "the host slept" is claimed only when +// the OS says so - a pmset sleep/wake event timestamped after the heartbeat +// stopped. macOS only; elsewhere there is no evidence and no claim. +export function sleepEvidenceSince(sinceMs, run = execFileSync) { + if (process.platform !== 'darwin') return ''; + try { + const out = run('pmset', ['-g', 'log'], { encoding: 'utf8', timeout: 5000 }); + const hits = out.split('\n').filter((l) => /Entering Sleep|DarkWake|Wake from|Wake Requests/.test(l)); + for (let i = hits.length - 1; i >= 0; i--) { + const m = hits[i].match(/^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}(?: [+-]\d{4})?)/); + if (!m) continue; + const t = Date.parse(m[1].replace(' +', '+').replace(' -', '-')); + if (Number.isFinite(t) && t >= sinceMs - 60_000) return hits[i].trim().slice(0, 200); + } + return ''; + } catch { + return ''; + } +} + +// Kept for callers that only want the last line, evidence or not. +export function lastSleepLine(run = execFileSync) { + return sleepEvidenceSince(0, run); +} + export function lastLine(path) { try { const lines = readFileSync(path, 'utf8').split('\n').filter(Boolean); @@ -47,38 +73,69 @@ export function lastLine(path) { } } -async function post(body) { - const res = await fetch(`${base}/rooms/${encodeURIComponent(room)}/messages`, { - method: 'POST', - headers: { 'X-API-Key': key, 'Content-Type': 'application/json' }, - body: JSON.stringify({ body }), - signal: AbortSignal.timeout(timeoutMs) - }); - if (!res.ok) throw new Error(`room post failed: HTTP ${res.status}`); -} -const age = heartbeatAge(heartbeat); -const down = age > maxAge; -const alerted = existsSync(stateFile); +// Importable without running (tests import the helpers): the script body +// runs only when executed directly. +async function main() { + const key = process.env.IAK_ALERT_KEY; + const heartbeat = process.env.IAK_POLLER_HEARTBEAT || '/tmp/iak-poller.heartbeat'; + const maxAge = Number(process.env.IAK_POLLER_MAX_AGE_SEC || 180); + const errLog = process.env.IAK_POLLER_ERR_LOG || ''; + const room = process.env.IAK_ALERT_ROOM || 'thinkoff-development'; + const stateFile = process.env.IAK_ALERT_STATE || '/tmp/iak-poller-alert.state'; + const base = (process.env.IAK_ALERT_BASE || 'https://groupmind.one/api/v1').replace(/\/$/, ''); + const label = process.env.IAK_ALERT_LABEL || 'room poller'; + const timeoutMs = Number(process.env.IAK_ALERT_TIMEOUT_MS || 15000); + + if (!key) { + console.error('poller-health-alert: IAK_ALERT_KEY missing'); + process.exit(2); + } -// A failed or timed-out post leaves the state untouched, so the next loop -// simply tries again; the supervisor never waits longer than timeoutMs. -try { - if (down && !alerted) { - const err = errLog ? lastLine(errLog) : ''; - const since = age === Infinity ? 'no heartbeat file' : `last heartbeat ${age}s ago`; - await post(`⚠️ ${label} is down (${since}, heartbeat ${heartbeat}).` + (err ? `\nLast error: ${err}` : '') + - '\nGUI nudges are suspended until it heartbeats again; this alert is posted once.'); - writeFileSync(stateFile, new Date().toISOString() + '\n'); - console.log('alert posted'); - } else if (!down && alerted) { - await post(`✅ ${label} is back (heartbeat ${age}s old).`); - unlinkSync(stateFile); - console.log('all-clear posted'); - } else { - console.log(down ? 'down, already alerted' : 'healthy'); + async function post(body) { + const res = await fetch(`${base}/rooms/${encodeURIComponent(room)}/messages`, { + method: 'POST', + headers: { 'X-API-Key': key, 'Content-Type': 'application/json' }, + body: JSON.stringify({ body }), + signal: AbortSignal.timeout(timeoutMs) + }); + if (!res.ok) throw new Error(`room post failed: HTTP ${res.status}`); } -} catch (e) { - console.error(`poller-health-alert: post failed, will retry next loop: ${e.message}`); - process.exit(1); + + const age = heartbeatAge(heartbeat); + const down = age > maxAge; + const alerted = existsSync(stateFile); + + // A failed or timed-out post leaves the state untouched, so the next loop + // simply tries again; the supervisor never waits longer than timeoutMs. + try { + if (down && !alerted) { + const err = errLog ? lastLine(errLog) : ''; + const since = age === Infinity ? 'no heartbeat file' : `last heartbeat ${age}s ago`; + const quiet = errLog && age !== Infinity && errLogQuietSince(errLog, heartbeat); + const sleepLine = quiet ? sleepEvidenceSince(Date.now() - age * 1000) : ''; + const shape = quiet && sleepLine + ? `\nLooks like the host slept rather than the poller failing: the err log has not grown since the heartbeat stopped and the OS logged a sleep/wake in that window (pmset: ${sleepLine}).` + : quiet + ? '\nThe err log has not grown since the heartbeat stopped: the process exited silently, was killed, or the host was suspended (no OS sleep evidence found).' + : (err ? `\nLast error: ${err}` : ''); + await post(`⚠️ ${label} is down (${since}, heartbeat ${heartbeat}).` + shape + + '\nGUI nudges are suspended until it heartbeats again; this alert is posted once.'); + writeFileSync(stateFile, new Date().toISOString() + '\n'); + console.log('alert posted'); + } else if (!down && alerted) { + await post(`✅ ${label} is back (heartbeat ${age}s old).`); + unlinkSync(stateFile); + console.log('all-clear posted'); + } else { + console.log(down ? 'down, already alerted' : 'healthy'); + } + } catch (e) { + console.error(`poller-health-alert: post failed, will retry next loop: ${e.message}`); + process.exit(1); + } +} + +if (process.argv[1] && import.meta.url === pathToFileURL(process.argv[1]).href) { + await main(); } diff --git a/test/poller-health.test.mjs b/test/poller-health.test.mjs index 4dd7061..8e786d1 100644 --- a/test/poller-health.test.mjs +++ b/test/poller-health.test.mjs @@ -12,6 +12,7 @@ import { createServer } from 'node:http'; import test from 'node:test'; import { fileURLToPath } from 'node:url'; import { writeHeartbeat, startRoomPoller } from '../src/team-relay/room-poller.mjs'; +import { errLogQuietSince, lastSleepLine, sleepEvidenceSince } from '../scripts/poller-health-alert.mjs'; const repoRoot = path.resolve(path.dirname(fileURLToPath(import.meta.url)), '..'); const nudge = path.join(repoRoot, 'tools', 'codex_gui_nudge.sh'); @@ -130,3 +131,47 @@ test('poller-health-alert gives up on a stalled POST within the timeout and keep assert.ok(!existsSync(state), 'no state file after a failed post, so the next loop retries'); } finally { server.closeAllConnections?.(); server.close(); rmSync(dir, { recursive: true, force: true }); } }); + +test('down-alert says "host slept" when the err log stopped before the heartbeat did, "Last error" when it kept failing', async () => { + const dir = mkdtempSync(path.join(tmpdir(), 'iak-slept-')); + const posts = []; + const server = createServer((req, res) => { let raw = ''; req.on('data', (c) => { raw += c; }); req.on('end', () => { posts.push(JSON.parse(raw).body); res.writeHead(200); res.end('{}'); }); }); + await new Promise((r) => server.listen(0, '127.0.0.1', r)); + const base = `http://127.0.0.1:${server.address().port}`; + try { + const hb = path.join(dir, 'hb'); const err = path.join(dir, 'err.log'); + const old = new Date(Date.now() - 900_000); + writeFileSync(err, 'boot\n'); utimesSync(err, new Date(old.getTime() - 60_000), new Date(old.getTime() - 60_000)); + writeFileSync(hb, ''); utimesSync(hb, old, old); + const env = (state) => ({ ...process.env, IAK_ALERT_KEY: 'k', IAK_POLLER_HEARTBEAT: hb, IAK_POLLER_ERR_LOG: err, IAK_ALERT_STATE: path.join(dir, state), IAK_ALERT_BASE: base, IAK_ALERT_ROOM: 'r', IAK_ALERT_LABEL: 'p' }); + await execFileP('node', [alert], { encoding: 'utf8', env: env('s1') }); + // no pmset evidence in a test process -> neutral wording, never a sleep claim + assert.match(posts[0], /exited silently, was killed, or the host was suspended \(no OS sleep evidence found\)/); + assert.ok(!/Looks like the host slept/.test(posts[0])); + assert.ok(!/Last error/.test(posts[0])); + writeFileSync(err, 'boot\nError: poller.rooms must be set\n'); + await execFileP('node', [alert], { encoding: 'utf8', env: env('s2') }); + assert.match(posts[1], /Last error: Error: poller\.rooms must be set/); + assert.ok(!/host slept/.test(posts[1])); + } finally { server.closeAllConnections?.(); server.close(); rmSync(dir, { recursive: true, force: true }); } +}); + +test('errLogQuietSince and lastSleepLine helpers', () => { + const dir = mkdtempSync(path.join(tmpdir(), 'iak-helpers-')); + try { + const hb = path.join(dir, 'hb'); const err = path.join(dir, 'err'); + writeFileSync(err, 'x'); const t = new Date(Date.now() - 100_000); utimesSync(err, t, t); + writeFileSync(hb, 'x'); + assert.equal(errLogQuietSince(err, hb), true); + assert.equal(errLogQuietSince(path.join(dir, 'missing'), hb), false); + const fake = () => 'noise\n2026-09-02 01:54:05 +0000 Sleep Entering Sleep state due to Maintenance Sleep: 921 secs\nother\n'; + const sleepAt = Date.parse('2026-09-02T01:54:05Z'); + if (process.platform === 'darwin') { + assert.match(sleepEvidenceSince(sleepAt - 600_000, fake), /Entering Sleep state/, 'sleep inside the stale window counts'); + assert.equal(sleepEvidenceSince(sleepAt + 3_600_000, fake), '', 'an older sleep is not evidence for a later gap'); + assert.match(lastSleepLine(fake), /Entering Sleep state/); + } else { + assert.equal(sleepEvidenceSince(0, fake), ''); + } + } finally { rmSync(dir, { recursive: true, force: true }); } +});