From 1aca83882d8d8b888654c8ad9f6688c16113b057 Mon Sep 17 00:00:00 2001 From: ThinkOff Date: Wed, 2 Sep 2026 05:37:47 +0300 Subject: [PATCH 1/2] health alert: say when the host slept, not the poller failed (#90 item 9) On 2026-09-02 02:09 the alert fired on codexmb's poller while the MacBook had been in Maintenance Sleep for 921 s (pmset); the process was fine and the all-clear followed 32 s later. The alert now reads the gap shape: a stale heartbeat with an err log that has not grown since the heartbeat stopped means the host was suspended, and on macOS the last pmset sleep/wake line is quoted; a growing err log still quotes the last error. The script gained a main guard so tests can import its helpers without running it. Co-Authored-By: Claude Fable 5 --- scripts/poller-health-alert.mjs | 133 +++++++++++++++++++++----------- test/poller-health.test.mjs | 37 +++++++++ 2 files changed, 124 insertions(+), 46 deletions(-) diff --git a/scripts/poller-health-alert.mjs b/scripts/poller-health-alert.mjs index c2885d3..40081db 100644 --- a/scripts/poller-health-alert.mjs +++ b/scripts/poller-health-alert.mjs @@ -17,27 +17,39 @@ // 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; + } +} + +// macOS names the sleep directly; elsewhere there is nothing to quote. +export function lastSleepLine(run = execFileSync) { + if (process.platform !== 'darwin') return ''; + try { + const out = run('pmset', ['-g', 'log'], { encoding: 'utf8', timeout: 5000 }); + const lines = out.split('\n').filter((l) => /Entering Sleep|DarkWake|Wake from|Wake Requests/.test(l)); + return lines.length ? lines[lines.length - 1].trim().slice(0, 200) : ''; + } catch { + return ''; + } +} + export function lastLine(path) { try { const lines = readFileSync(path, 'utf8').split('\n').filter(Boolean); @@ -47,38 +59,67 @@ 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); -// 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'); + if (!key) { + console.error('poller-health-alert: IAK_ALERT_KEY missing'); + process.exit(2); } -} catch (e) { - console.error(`poller-health-alert: post failed, will retry next loop: ${e.message}`); - process.exit(1); + + 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); + + // 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 slept = errLog && age !== Infinity && errLogQuietSince(errLog, heartbeat); + const sleepLine = slept ? lastSleepLine() : ''; + const shape = slept + ? `\nLooks like the host slept rather than the poller failing: the err log has not grown since the heartbeat stopped${sleepLine ? ` (pmset: ${sleepLine})` : ''}.` + : (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..fd835d6 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 } 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,39 @@ 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') }); + assert.match(posts[0], /Looks like the host slept rather than the poller failing/); + 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 Sleep Entering Sleep state due to Maintenance Sleep: 921 secs\nother\n'; + if (process.platform === 'darwin') assert.match(lastSleepLine(fake), /Entering Sleep state/); + else assert.equal(lastSleepLine(fake), ''); + } finally { rmSync(dir, { recursive: true, force: true }); } +}); From 9d0f533c64a5401e1b09a4d2f6da72d46a55e715 Mon Sep 17 00:00:00 2001 From: ThinkOff Date: Wed, 2 Sep 2026 05:44:07 +0300 Subject: [PATCH 2/2] health alert: claim 'host slept' only with OS sleep evidence in the window (codex review of #94) A quiet err log also follows a silent exit or SIGKILL. The sleep claim now needs a pmset sleep/wake event timestamped after the heartbeat stopped (macOS); otherwise the alert stays neutral: exited silently, killed, or suspended, no OS sleep evidence found. Tests cover the window check and the neutral wording. Co-Authored-By: Claude Fable 5 --- scripts/poller-health-alert.mjs | 34 ++++++++++++++++++++++++--------- test/poller-health.test.mjs | 18 ++++++++++++----- 2 files changed, 38 insertions(+), 14 deletions(-) diff --git a/scripts/poller-health-alert.mjs b/scripts/poller-health-alert.mjs index 40081db..0fb562b 100644 --- a/scripts/poller-health-alert.mjs +++ b/scripts/poller-health-alert.mjs @@ -38,18 +38,32 @@ export function errLogQuietSince(errPath, heartbeatPath) { } } -// macOS names the sleep directly; elsewhere there is nothing to quote. -export function lastSleepLine(run = execFileSync) { +// 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 lines = out.split('\n').filter((l) => /Entering Sleep|DarkWake|Wake from|Wake Requests/.test(l)); - return lines.length ? lines[lines.length - 1].trim().slice(0, 200) : ''; + 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); @@ -98,11 +112,13 @@ async function main() { if (down && !alerted) { const err = errLog ? lastLine(errLog) : ''; const since = age === Infinity ? 'no heartbeat file' : `last heartbeat ${age}s ago`; - const slept = errLog && age !== Infinity && errLogQuietSince(errLog, heartbeat); - const sleepLine = slept ? lastSleepLine() : ''; - const shape = slept - ? `\nLooks like the host slept rather than the poller failing: the err log has not grown since the heartbeat stopped${sleepLine ? ` (pmset: ${sleepLine})` : ''}.` - : (err ? `\nLast error: ${err}` : ''); + 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'); diff --git a/test/poller-health.test.mjs b/test/poller-health.test.mjs index fd835d6..8e786d1 100644 --- a/test/poller-health.test.mjs +++ b/test/poller-health.test.mjs @@ -12,7 +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 } from '../scripts/poller-health-alert.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'); @@ -145,7 +145,9 @@ test('down-alert says "host slept" when the err log stopped before the heartbeat 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') }); - assert.match(posts[0], /Looks like the host slept rather than the poller failing/); + // 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') }); @@ -162,8 +164,14 @@ test('errLogQuietSince and lastSleepLine helpers', () => { 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 Sleep Entering Sleep state due to Maintenance Sleep: 921 secs\nother\n'; - if (process.platform === 'darwin') assert.match(lastSleepLine(fake), /Entering Sleep state/); - else assert.equal(lastSleepLine(fake), ''); + 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 }); } });