Skip to content

Commit 83065ae

Browse files
author
S. K. Rotwang MMMMMMMMM
committed
Ops watchdog: kill activating-window flap + fix two latent bugs
First real Telegram alert from §12.47 was a false positive — the watchdog tick landed inside the ~1ms window where the private-watch-poller oneshot was transitioning inactive/dead → activating/start → active/running → inactive/dead. Three bugs surfaced + fixed: 1. classifyUnit didn't handle transient legitimate states (activating, deactivating, reloading, refreshing, maintenance). Now trusts `service.Result=success` from the previous fire over the current `ActiveState` for timer-paired oneshots. 2. buildReport had no `unknown` bucket in the degraded summary, so the alert read literally `"DEGRADED · "` with nothing after the dot. Added the bucket plus a fallback. 3. Staleness check was silently disabled in production. `LastTriggerUSec` is human-readable by default, not raw microseconds. `Number()` returned NaN so the comparison was always false. New `parseSystemdTimestampMs()` handles all three known formats. 12 new tests, full suite 535/535 green.
1 parent 9fc5493 commit 83065ae

3 files changed

Lines changed: 266 additions & 26 deletions

File tree

scripts/seneschal-ops-monitor.mjs

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -91,11 +91,21 @@ function systemctlShow(unit) {
9191
// doesn't paginate. We also tolerate exit != 0 (e.g. unit not
9292
// found) by returning an empty parse, so the classifier sees
9393
// status=unknown and the operator gets a clear delta.
94+
//
95+
// `--timestamp=unix` makes LastTriggerUSec come back as
96+
// "@<seconds>.<micros>" instead of "Sun 2026-05-24 09:51 CEST",
97+
// which `parseSystemdTimestampMs` handles natively (no Date.parse
98+
// timezone-abbreviation guessing required). Older systemd that
99+
// doesn't recognise the flag silently ignores it and falls back
100+
// to the default human-readable form, which our parser also
101+
// handles — so this is a strict improvement either way.
94102
try {
95103
const out = execFileSync('/usr/bin/systemctl', ['show', unit,
104+
'--timestamp=unix',
96105
'-p', 'ActiveState',
97106
'-p', 'SubState',
98107
'-p', 'Result',
108+
'-p', 'ExecMainStatus',
99109
'-p', 'LastTriggerUSec',
100110
'-p', 'NRestarts',
101111
'-p', 'UnitFileState'

src/ops-monitor.js

Lines changed: 120 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,57 @@ export function parseShowOutput(text) {
4343
}
4444

4545
const TIMER_STALE_GRACE_MS = 5 * 60 * 1000;
46+
// systemd Result values that mean the most recent invocation
47+
// failed. `success` and `oneshot` (oneshot finished cleanly with
48+
// RemainAfterExit=no) both mean "ok". Anything else is a failure.
49+
const FAIL_RESULTS = new Set(['failed', 'exit-code', 'core-dump', 'timeout', 'signal', 'watchdog', 'oom-kill', 'protocol', 'resources']);
50+
// ActiveStates that are TRANSIENT and legitimate — a tick that
51+
// happens to land inside one of these (e.g. systemd just told the
52+
// unit to start, node hasn't booted yet) must not flap the
53+
// watchdog. We trust `Result` from the previous invocation
54+
// instead.
55+
const TRANSIENT_ACTIVE_STATES = new Set(['activating', 'deactivating', 'reloading', 'refreshing', 'maintenance']);
56+
57+
/**
58+
* Parse a `LastTriggerUSec` (or any `*USec`) value from
59+
* `systemctl show`. Tolerates the three known output formats:
60+
*
61+
* * `"1716543662000000"` — raw microseconds since epoch
62+
* (rare, requires `--timestamp=us`
63+
* or programmatic D-Bus reads)
64+
* * `"@1716543662.531"` — `--timestamp=unix` output
65+
* * `"Sun 2026-05-24 09:51:02 CEST"` — default human-readable
66+
*
67+
* Returns milliseconds since epoch, or `null` if the value is
68+
* absent / unparseable. Used by `classifyUnit` for the
69+
* timer-staleness check; the prior version silently returned 0
70+
* for the human-readable case, defeating the check entirely.
71+
*/
72+
export function parseSystemdTimestampMs(value) {
73+
if (value == null) return null;
74+
const s = String(value).trim();
75+
if (!s) return null;
76+
// Numeric microseconds since epoch.
77+
if (/^\d+$/.test(s)) {
78+
const n = Number(s);
79+
if (!Number.isFinite(n) || n <= 0) return null;
80+
return Math.floor(n / 1000);
81+
}
82+
// `--timestamp=unix` format: "@<seconds>[.<micros>]".
83+
if (s.startsWith('@')) {
84+
const seconds = parseFloat(s.slice(1));
85+
if (!Number.isFinite(seconds) || seconds <= 0) return null;
86+
return Math.round(seconds * 1000);
87+
}
88+
// Default human-readable. Date.parse handles most timezone
89+
// abbreviations on the common platforms; `n/a` and `0` and
90+
// other systemd "no value yet" placeholders fall through to
91+
// null below.
92+
if (s === 'n/a' || s === '0' || s === '-') return null;
93+
const ms = Date.parse(s);
94+
if (!Number.isFinite(ms) || ms <= 0) return null;
95+
return ms;
96+
}
4697

4798
/**
4899
* Classify a single unit's parsed `systemctl show` output. The
@@ -55,34 +106,79 @@ const TIMER_STALE_GRACE_MS = 5 * 60 * 1000;
55106
* `expected.intervalMs` is the expected timer cadence (e.g. 600_000
56107
* for a 10-minute timer). We add a 5-minute grace before flagging
57108
* stale.
109+
*
110+
* Decision tree:
111+
* 1. Hard failure signal: `service.Result ∈ FAIL_RESULTS` AND
112+
* `ExecMainStatus !== '0'` → failed. (A oneshot can momentarily
113+
* report `Result=exit-code` even with status=0 on some systemd
114+
* versions; honour the actual exit code.)
115+
* 2. Active+failed combo (long-running crash loop): `ActiveState=failed`.
116+
* 3. Timer-paired oneshot: trust `Result=success` as definitive
117+
* ok even if the unit is mid-`activating`. This avoids flapping
118+
* every time the watchdog tick races a timer fire.
119+
* 4. Timer-paired with stale `LastTriggerUSec` → stale.
120+
* 5. Long-running: `ActiveState=active && SubState=running` → ok.
121+
* 6. Transient ActiveStates (activating/deactivating/etc) → ok
122+
* with a noted reason; they're never "unknown".
123+
* 7. Otherwise unknown (which we still treat as degraded so it
124+
* gets investigated, but doesn't read as a flat-out failure).
58125
*/
59126
export function classifyUnit({ service, timer, expected, nowMs }) {
60127
if (!service || typeof service !== 'object') {
61128
return { status: 'unknown', reason: 'no service show data' };
62129
}
63-
if (service.ActiveState === 'failed' || service.Result === 'failed' || service.Result === 'exit-code') {
64-
// Allow Result=exit-code if the service is a oneshot that
65-
// finished cleanly (status=0). Distinguish via SubState.
66-
if (service.SubState !== 'dead' || service.Result === 'failed' || service.Result === 'exit-code') {
67-
if (service.Result !== 'success') {
68-
return { status: 'failed', reason: `ActiveState=${service.ActiveState} Result=${service.Result} SubState=${service.SubState}` };
69-
}
70-
}
130+
const exitOk = service.ExecMainStatus == null || String(service.ExecMainStatus) === '0';
131+
const resultBad = FAIL_RESULTS.has(service.Result);
132+
// 1) + 2): hard failure.
133+
if ((resultBad && !exitOk) || service.ActiveState === 'failed') {
134+
return {
135+
status: 'failed',
136+
reason: `ActiveState=${service.ActiveState} Result=${service.Result} ExecMainStatus=${service.ExecMainStatus ?? 'n/a'} SubState=${service.SubState}`
137+
};
71138
}
139+
// 3) + 4): timer-paired logic.
72140
if (timer && expected?.intervalMs) {
73-
const lastUsec = Number(timer.LastTriggerUSec ?? 0);
74-
if (lastUsec > 0) {
75-
const lastMs = Math.floor(lastUsec / 1000);
141+
const lastMs = parseSystemdTimestampMs(timer.LastTriggerUSec);
142+
if (lastMs != null) {
76143
const age = nowMs - lastMs;
77144
if (age > expected.intervalMs + TIMER_STALE_GRACE_MS) {
78-
return { status: 'stale', reason: `timer last fired ${Math.round(age / 60000)} min ago (cadence ${Math.round(expected.intervalMs / 60000)} min)` };
145+
return {
146+
status: 'stale',
147+
reason: `timer last fired ${Math.round(age / 60000)} min ago (cadence ${Math.round(expected.intervalMs / 60000)} min)`
148+
};
79149
}
80150
}
151+
// For a timer-paired oneshot, the SERVICE almost always
152+
// looks `inactive/dead` between fires. `Result=success`
153+
// from the previous fire is the strongest signal we have.
154+
if (service.Result === 'success') {
155+
return {
156+
status: 'ok',
157+
reason: `oneshot Result=success ActiveState=${service.ActiveState} SubState=${service.SubState}`
158+
};
159+
}
81160
}
82-
if (service.ActiveState === 'active' || service.ActiveState === 'inactive' || service.SubState === 'dead') {
83-
return { status: 'ok', reason: `ActiveState=${service.ActiveState} SubState=${service.SubState}` };
161+
// 5): long-running pattern.
162+
if (service.ActiveState === 'active' && service.SubState === 'running') {
163+
return { status: 'ok', reason: 'ActiveState=active SubState=running' };
84164
}
85-
return { status: 'unknown', reason: `unrecognised state ActiveState=${service.ActiveState} SubState=${service.SubState}` };
165+
// Oneshot inactive/dead with success result (e.g. data-rest
166+
// after a stop — shouldn't happen but be tolerant).
167+
if (service.ActiveState === 'inactive' && service.SubState === 'dead' && service.Result === 'success') {
168+
return { status: 'ok', reason: `ActiveState=inactive Result=success` };
169+
}
170+
// 6): transient legitimate states.
171+
if (TRANSIENT_ACTIVE_STATES.has(service.ActiveState)) {
172+
return {
173+
status: 'ok',
174+
reason: `transient ActiveState=${service.ActiveState} SubState=${service.SubState}`
175+
};
176+
}
177+
// 7): genuinely unrecognised.
178+
return {
179+
status: 'unknown',
180+
reason: `unrecognised state ActiveState=${service.ActiveState} Result=${service.Result} SubState=${service.SubState}`
181+
};
86182
}
87183

88184
/**
@@ -99,6 +195,7 @@ export function buildReport({ units = {}, scripts = {}, nowMs }) {
99195

100196
const failingUnits = unitEntries.filter(([, v]) => v.status === 'failed').map(([k]) => k);
101197
const staleUnits = unitEntries.filter(([, v]) => v.status === 'stale').map(([k]) => k);
198+
const unknownUnits = unitEntries.filter(([, v]) => v.status === 'unknown').map(([k]) => k);
102199
const missingScripts = scriptEntries.filter(([, v]) => v.status !== 'ok').map(([k]) => k);
103200

104201
let summary;
@@ -109,7 +206,15 @@ export function buildReport({ units = {}, scripts = {}, nowMs }) {
109206
const parts = [];
110207
if (failingUnits.length) parts.push(`${failingUnits.length} failed (${failingUnits.join(', ')})`);
111208
if (staleUnits.length) parts.push(`${staleUnits.length} stale (${staleUnits.join(', ')})`);
209+
if (unknownUnits.length) parts.push(`${unknownUnits.length} unknown (${unknownUnits.join(', ')})`);
112210
if (missingScripts.length) parts.push(`${missingScripts.length} script(s) missing (${missingScripts.join(', ')})`);
211+
// Defensive: if we somehow flipped to degraded with no
212+
// recognised buckets, surface that explicitly rather than
213+
// printing "DEGRADED · " (the bug the watchdog itself caught
214+
// on its first alert!).
215+
if (parts.length === 0) {
216+
parts.push(`${unitEntries.length} units + ${scriptEntries.length} scripts checked, no recognised failure bucket — investigate the full report`);
217+
}
113218
summary = `DEGRADED · ${parts.join('; ')}`;
114219
}
115220
return Object.freeze({

0 commit comments

Comments
 (0)