diff --git a/services/althing-notify-failure/README.md b/services/althing-notify-failure/README.md index ee117ba..1117a1d 100644 --- a/services/althing-notify-failure/README.md +++ b/services/althing-notify-failure/README.md @@ -29,8 +29,44 @@ delivery, a blind spot in the notification path every other alarm depends on. `OnFailure` does not fire on a clean restart or a deliberate stop. svos-dev's four restarts and three deploys in one day would have produced **zero** alerts. -With `Restart=on-failure`, a unit enters failed state only after exhausting its -start-limit burst, so a crash-loop yields **one** message per episode. + +### Duplicate suppression, and a claim I had to correct + +This README originally asserted that a crash-loop "yields one message per +episode". svos-dev challenged it with a measurement: one 2026-09-19 boot-gate +refusal on `svos.service` produced **five** transitions into `failed`, and the +operator got five messages. + +Measured here before accepting or rejecting it: a unit with +`Restart=on-failure`, burst 3, interval 30s produced **7 journal failure lines +and exactly 1 notifier invocation**. So the multiplier is *not* universal — it +needs retries spanning start-limit windows, or an external restarter. svos.service +has `StartLimitIntervalSec=5min`, which is how it accumulated five. + +Both conditions exist on this box, so there is now a **cooldown** (900s default, +`NOTIFY_COOLDOWN_SECONDS`) — cheap insurance rather than a fix for something +proven here. Two properties it must have, both tested: + +- **Keyed on the CAUSE, not the unit.** A genuinely different failure inside the + window is a new fact and still pages. Suppressing by unit name alone would + hide a second, worse failure behind the first. +- **Suppression is logged** (`suppressed.log`), never silent. An alarm that + quietly declines to fire is indistinguishable from one that is broken, and + this whole mechanism exists because something that looked fine was not. + +Verified: same cause fired 3× → 1 sent, 2 suppressed and logged; a different +cause inside the same window → sent. + +### Restart policy decides the exposure + +| policy | units | +|---|---| +| `Restart=always` | althing-po-herald, hermes-gateway, lrpg-demo, ttyd-caddy, ttyd-ro, ttyd-rw | +| `Restart=on-failure` | althing-seat-page, booth, peedlar, svos, wherethef, zellij-web | + +`hermes-gateway` has `StartLimitIntervalUSec=0` — start limiting disabled, so it +retries forever and may never reach `failed` at all. Worth knowing before +trusting this alarm to cover it. ## Two traps, both hit during the build diff --git a/services/althing-notify-failure/althing-notify-failure b/services/althing-notify-failure/althing-notify-failure index 7f0162a..aa89e87 100755 --- a/services/althing-notify-failure/althing-notify-failure +++ b/services/althing-notify-failure/althing-notify-failure @@ -67,6 +67,50 @@ Triage: EOF ) +# ---- duplicate suppression --------------------------------------------------- +# +# OnFailure fires on every transition INTO failed, not once per incident. +# svos-dev measured five such transitions for one 2026-09-19 boot-gate refusal +# on svos.service (StartLimitBurst=3, StartLimitIntervalSec=5min), and the +# operator saw five messages for one outage. +# +# MEASURED HERE, because the claim deserved checking rather than adopting: a +# simple crash-loop inside ONE start-limit window fires the notifier exactly +# ONCE -- a unit with Restart=on-failure, burst 3, interval 30s produced 7 +# journal failure lines and 1 notifier invocation. So the multiplier is not +# universal; it needs retries that span windows, or an external restarter. +# Both exist on this box, so the guard is cheap insurance rather than a fix for +# something already proven here. +# +# KEYED ON THE CAUSE, NOT THE UNIT. A genuinely different failure inside the +# window is a NEW FACT and must still page -- suppressing by unit name alone +# would hide a second, worse failure behind the first. The fingerprint is the +# unit plus its result, exit status, and the shape of its last error lines. +# +# SUPPRESSION IS LOGGED, NEVER SILENT. An alarm that quietly declines to fire is +# indistinguishable from one that is broken, and this whole mechanism exists +# because a thing that looked fine was not. +COOLDOWN="${NOTIFY_COOLDOWN_SECONDS:-900}" +mkdir -p "$SPOOL" +fingerprint=$(printf '%s|%s|%s|%s' "$UNIT" "${result:-}" "${code:-}" \ + "$(journalctl --user -u "$UNIT" -n 10 --no-pager -o cat 2>/dev/null \ + | grep -iE 'error|fail|refus|cannot|denied' | head -5)" \ + | sha256sum | cut -c1-16) +guard="${SPOOL}/.cooldown-${fingerprint}" +now=$(date +%s) +if [ -f "$guard" ]; then + last=$(cat "$guard" 2>/dev/null || echo 0) + age=$(( now - last )) + if [ "$age" -lt "$COOLDOWN" ]; then + printf 'SUPPRESSED duplicate for %s (same cause %s, %ss into a %ss cooldown); not sending\n' \ + "$UNIT" "$fingerprint" "$age" "$COOLDOWN" + printf '%s suppressed %s age=%ss\n' "$(date -Is)" "$UNIT" "$age" \ + >> "${SPOOL}/suppressed.log" + exit 0 + fi +fi +printf '%s' "$now" > "$guard" + # Durable local record FIRST, so the signal survives a post-office outage. # postbox has no outbox: a send that cannot reach the post office is dropped, # and this alarm exists precisely for the cases nobody is watching.