From 13102dc145cbda07f5190ae9a8261e28fe0b4004 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:03:57 +0000 Subject: [PATCH 01/18] Deliver alerts best effort, and never print their URLs A webhook URL missing its scheme (ntfy.sh/topic) made urllib.request.Request raise before _deliver's try, so alert.fail raised out of the run it was reporting on: exit 1 instead of the real code, no heartbeat, and a traceback naming the secret topic. The request is now built inside the guard. A failed delivery's warning printed the exception's text, and urllib and http.client quote the URL, or just its path, which is the secret (an ntfy topic, a ping id). The warning now names only the kind of error: the HTTP status, the socket error, or the exception class. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- esb_outages/alert.py | 26 +++++++++++++++++++++----- tests/test_poll.py | 35 +++++++++++++++++++++++++++++++++++ 2 files changed, 56 insertions(+), 5 deletions(-) diff --git a/esb_outages/alert.py b/esb_outages/alert.py index 2281af9..77df42d 100644 --- a/esb_outages/alert.py +++ b/esb_outages/alert.py @@ -12,6 +12,7 @@ import json import os import sys +import urllib.error import urllib.request EXIT_OK = 0 @@ -125,17 +126,33 @@ def partial_banner(failed: int, attempted: int, errors: list[str]) -> str: ) -def _deliver(request, what: str) -> bool: +def _deliver(what: str, url: str, data: bytes | None = None, headers=None) -> bool: """Best effort, in one place: a failure to report must never mask the problem being reported or change the exit code.""" try: + # Built in here: a URL missing its scheme raises from the constructor. + request = urllib.request.Request(url, data=data, headers=headers or {}) urllib.request.urlopen(request, timeout=10).close() return True except Exception as exc: - print(f"warning: {what} failed: {exc}", file=sys.stderr) + print(f"warning: {what} failed: {_describe(exc)}", file=sys.stderr) return False +def _describe(exc: Exception) -> str: + # Never str(exc): the URL is the secret (an ntfy topic, a ping id), and + # urllib and http.client quote it, or its path, in their messages. + if isinstance(exc, urllib.error.HTTPError): + return f"HTTP {exc.code}" + reason = exc.reason if isinstance(exc, urllib.error.URLError) else exc + if isinstance(reason, OSError): + return f"{type(reason).__name__}: {reason.strerror or 'no detail'}" + if isinstance(reason, ValueError): + return f"{type(reason).__name__} (check the URL's form)" + # A URLError's reason can be a bare string, which may quote the URL. + return type(reason if isinstance(reason, Exception) else exc).__name__ + + def notify(message: str) -> bool: """Push to ESB_ALERT_WEBHOOK. Returns whether it was delivered.""" url = os.environ.get("ESB_ALERT_WEBHOOK") @@ -146,8 +163,7 @@ def notify(message: str) -> bool: else: data = json.dumps({"content": message, "text": message}).encode("utf-8") headers = {"Content-Type": "application/json"} - req = urllib.request.Request(url, data=data, headers=headers, method="POST") - return _deliver(req, "alert webhook") + return _deliver("alert webhook", url, data, headers) def heartbeat() -> bool: @@ -160,7 +176,7 @@ def heartbeat() -> bool: url = os.environ.get("ESB_HEARTBEAT_URL") if not url: return False - return _deliver(url, "heartbeat ping") + return _deliver("heartbeat ping", url) def fail(message: str, code: int) -> int: diff --git a/tests/test_poll.py b/tests/test_poll.py index 889e364..b799ef4 100644 --- a/tests/test_poll.py +++ b/tests/test_poll.py @@ -1,10 +1,13 @@ +import contextlib import copy +import io import os import signal import sqlite3 import tempfile import unittest import unittest.mock +import urllib.error from pathlib import Path from esb_outages import alert @@ -400,6 +403,28 @@ def test_unreachable_webhook_does_not_raise(self): ): self.assertFalse(alert.notify("hello")) + def test_a_url_missing_its_scheme_does_not_raise(self): + with unittest.mock.patch.dict(os.environ, {"ESB_ALERT_WEBHOOK": "ntfy.sh/topic"}): + self.assertEqual(alert.fail("drift", alert.EXIT_SCHEMA_DRIFT), alert.EXIT_SCHEMA_DRIFT) + + + def test_a_failed_delivery_does_not_print_the_url(self): + for url in ( + "hc-ping.com/0f3c9a1e-secret", + # a stray space: http.client quotes the path alone + "http://127.0.0.1:9/0f3c9a1e-secret x", + "http://127.0.0.1:9/0f3c9a1e-secret", + ): + err = io.StringIO() + with contextlib.redirect_stderr(err): + self.assertFalse(alert._deliver("heartbeat ping", url)) + self.assertIn("heartbeat ping failed: ", err.getvalue()) + self.assertNotIn("secret", err.getvalue(), url) + + def test_a_reason_given_as_text_is_named_by_its_error(self): + error = urllib.error.URLError("unknown url type: secret") + self.assertEqual(alert._describe(error), "URLError") + class TestHeartbeat(PollTestCase): """The ping a dead-man's monitor waits for: sent whenever a run reached @@ -434,6 +459,16 @@ def test_a_drifted_run_still_pings(self): self.assertEqual(self.poll(client), alert.EXIT_SCHEMA_DRIFT) self.assertEqual(self.paths(), ["/hook"]) + def test_a_mistyped_webhook_does_not_cost_the_ping(self): + os.environ["ESB_ALERT_WEBHOOK"] = "ntfy.sh/topic" + body = dict(detail("fault")) + body["brandNewField"] = "surprise" + client = FakeClient( + list_body=make_list(detail("fault")), details={body["outageId"]: body} + ) + self.assertEqual(self.poll(client), alert.EXIT_SCHEMA_DRIFT) + self.assertEqual(self.paths(), ["/hook"]) + def test_a_run_cut_short_still_pings(self): # a storm that outruns every run must not read as a stopped collector self.assertEqual(self.poll(storm_client(storm(), TestStorm.BUDGET)), alert.EXIT_OK) From 2c12d33004284a6c97d8a75278fe8c91471789e2 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:05:05 +0000 Subject: [PATCH 02/18] Alert when a run fails partway, not only when the probe does The storage probe creates an empty file, which a full disk still allows, so ENOSPC arrived from the first real write and escaped the run, as did any error with no handler: exit 1, a traceback, no webhook and no heartbeat, leaving the dead-man's monitor to notice two hours later with no cause. run_poll now catches both. An OSError, or a SQLite error whose code is a full disk, an I/O error, a file it cannot open or a read-only database, is the storage alert (exit 6). Anything else is a new crash alert (exit 1) with the traceback in the journal. It names esb rebuild for every crash, because choosing from the exception's type was wrong both ways, and says a rebuild that fails the same way, or a next run that crashes again, means the code needs a fix. Neither pings. Recorded in notes/alerting.md. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- CLAUDE.md | 2 +- README.md | 3 ++- esb_outages/alert.py | 22 ++++++++++++++++- esb_outages/poll.py | 36 +++++++++++++++++++++++---- notes/alerting.md | 31 +++++++++++++++++++++++ tests/test_poll.py | 58 ++++++++++++++++++++++++++++++++++++++++++++ 6 files changed, 144 insertions(+), 8 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index faca2f7..d5b5ca8 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -117,7 +117,7 @@ Every one of these has already cost someone an hour: | Part-observed days keep their colour and say so in the tooltip | `notes/grading.md` § Short days say so | | 2.5M customer denominator, and which DAPR figures are comparable | `notes/grading.md` § The customer denominator | | Each run logs two lines to `runs-*.jsonl`: the list before any detail is fetched, and an `"event": "end"` line (`Store.finish_run`) carrying what a rebuild cannot derive - status, exit code, finish time, skipped count, errors. Older runs have no end line and replay from the start line alone | `notes/storms.md` § The run's end is logged after all (2026-09-24) | -| The collector pings `ESB_HEARTBEAT_URL` after every run that reached the feed, drifted or partial ones included, and never after a rejected key, an unreachable feed or a skipped trigger; a dead-man's monitor alerts on silence (period 30 min, grace 90). `test-alert` proves both channels | `notes/alerting.md` § The heartbeat (2026-09-06) | +| The collector pings `ESB_HEARTBEAT_URL` after every run that reached the feed, drifted or partial ones included, and never after a rejected key, an unreachable feed, a storage failure, a crash or a skipped trigger; a dead-man's monitor alerts on silence (period 30 min, grace 90). `test-alert` proves both channels | `notes/alerting.md` § The heartbeat (2026-09-06); § A run that fails partway (2026-09-24) | | A storm can list more than a run can fetch: `ids_needing_detail` ranks by what a purge would take (listed Restored and still needing a fetch, then live never-fetched, then re-checks), every detail is committed as it lands, a run stops itself at `RUN_BUDGET_S` (24 min) and records `cut_short` (exit 0, heartbeat sent, no webhook), SIGTERM from the service unit's backstop ends the loop the same way, and the pause is 500 ms. In list order a cut-short run re-fetched the same head every run and never reached the tail | `notes/storms.md` (2026-09-06) | | The Pi pushes every six hours and `esb-data` dispatches the site build on each push; the two crons are a fallback only, because scheduled runs here have landed 4-10h behind their cron time. The stale banner trips at 10h - above the widest legitimate age (~7h), below a missed push (13h+) | `notes/publish-cadence.md`; `STALE_AFTER` in `esb_site/render.py` | | The banner states the data's *age* ("Updated 17 hours ago"), not its timestamp, and names no cause: from the browser a stalled build and a stalled collector look identical. A healthy overnight gap is a big number, so the warning, not the wording, carries it | `freshness()` in statusui's `ui.js`; `notes/publish-cadence.md` § The banner blamed the wrong half | diff --git a/README.md b/README.md index 2464b85..7952745 100644 --- a/README.md +++ b/README.md @@ -128,11 +128,12 @@ banner it prints: | Exit | Meaning | | --- | --- | | 0 | Success — silent | +| 1 | The run crashed on an error it has no handling for; the traceback is in the journal | | 2 | **API key rejected (HTTP 401)** — collection has stopped | | 3 | ESB API unreachable after retries | | 4 | API response shape changed (raw data still safe) | | 5 | A broad failure of detail fetches | -| 6 | Data directory not writable | +| 6 | Data directory not writable, before the run or during it (a full disk) | Deliberately *not* alerts: a per-outage 404 (the outage was purged between the list call and its detail call — routine), and one or two isolated fetch failures. diff --git a/esb_outages/alert.py b/esb_outages/alert.py index 77df42d..6326b98 100644 --- a/esb_outages/alert.py +++ b/esb_outages/alert.py @@ -16,6 +16,7 @@ import urllib.request EXIT_OK = 0 +EXIT_CRASH = 1 EXIT_AUTH = 2 EXIT_UNREACHABLE = 3 EXIT_SCHEMA_DRIFT = 4 @@ -24,6 +25,7 @@ EXIT_MEANINGS = { EXIT_OK: "success", + EXIT_CRASH: "collector crashed", EXIT_AUTH: "API subscription key rejected", EXIT_UNREACHABLE: "ESB API unreachable", EXIT_SCHEMA_DRIFT: "API response shape changed", @@ -101,7 +103,7 @@ def storage_banner(data_dir, problem: str) -> str: [ f"{problem}", "", - "Nothing was collected. Usual causes are a full disk, or the", + "Collection has stopped. Usual causes are a full disk, or the", "directory not being owned by the user the collector runs as.", "", "Check:", @@ -112,6 +114,24 @@ def storage_banner(data_dir, problem: str) -> str: ) +def crash_banner(exc: BaseException) -> str: + return banner( + "ESB POLLER: RUN CRASHED", + [ + "The collector hit an error it has no handling for and stopped", + "partway through the run. The traceback is in the journal:", + " journalctl -u esb-outages.service -n 50", + "", + "If the database is at fault, this re-derives it from the raw", + "logs: sudo esb rebuild", + "If the rebuild fails the same way, or the next run crashes", + "again, the code needs a fix; rebuild again once it has one.", + "", + f"Raw error: {type(exc).__name__}: {exc}", + ], + ) + + def partial_banner(failed: int, attempted: int, errors: list[str]) -> str: return banner( "ESB POLLER: PARTIAL DATA LOSS", diff --git a/esb_outages/poll.py b/esb_outages/poll.py index 6176a4f..1261b5a 100644 --- a/esb_outages/poll.py +++ b/esb_outages/poll.py @@ -11,7 +11,9 @@ import fcntl import os import signal +import sqlite3 import time +import traceback import uuid from pathlib import Path @@ -77,6 +79,22 @@ def check_writable(data_dir: Path) -> str | None: return None +# The SQLite errors a disk or its permissions cause. Anything else, such as a +# column an older esb.db lacks or a malformed file, is a crash: df and chown +# will not fix it. +_STORAGE_ERRORS = { + sqlite3.SQLITE_FULL, sqlite3.SQLITE_IOERR, sqlite3.SQLITE_CANTOPEN, sqlite3.SQLITE_READONLY, +} + + +def _is_storage(exc: Exception) -> bool: + if isinstance(exc, OSError): + return True + if isinstance(exc, sqlite3.Error): + return (getattr(exc, "sqlite_errorcode", 0) & 0xFF) in _STORAGE_ERRORS + return False + + def run_poll( data_dir, client: EsbClient | None = None, @@ -92,11 +110,19 @@ def run_poll( if problem: return alert.fail(alert.storage_banner(data_dir, problem), alert.EXIT_STORAGE) - with poll_lock(data_dir) as acquired: - if not acquired: - print("another poll run holds the lock; skipping this trigger") - return alert.EXIT_OK - code = _run(data_dir, client, delay_ms, budget_s) + try: + with poll_lock(data_dir) as acquired: + if not acquired: + print("another poll run holds the lock; skipping this trigger") + return alert.EXIT_OK + code = _run(data_dir, client, delay_ms, budget_s) + # The probe above passes on a full disk, which still has inodes for an + # empty file; the first real write is what fails. + except Exception as exc: + traceback.print_exc() + if _is_storage(exc): + return alert.fail(alert.storage_banner(data_dir, str(exc)), alert.EXIT_STORAGE) + return alert.fail(alert.crash_banner(exc), alert.EXIT_CRASH) # Sent for every run that reached the feed, not only a clean one: schema # drift and partial detail loss still leave the list on disk, and the # webhook already carries them. Silence means collection has stopped. diff --git a/notes/alerting.md b/notes/alerting.md index d7d86c4..9550f79 100644 --- a/notes/alerting.md +++ b/notes/alerting.md @@ -39,3 +39,34 @@ secret, as the ntfy topic is, and lives in the same root-only file. Rejected: pinging from `backup-to-git.sh` instead. A push every six hours is too coarse to notice a stopped collector, and the backup can succeed with the collector dead, which is the exact case a heartbeat exists to catch. + +## A run that fails partway still says so - 2026-09-24 + +The only storage check was a probe before the run that creates an empty file, +which a full disk still allows: it needs an inode, not a data block. The first +real write then raised `ENOSPC` out of the run, and so did any error the code +had no handling for. Either way the run exited 1 with a traceback, sent no +webhook and no heartbeat, and the only alarm was the dead-man's monitor two +hours later, naming no cause. + +`run_poll` now catches both. An `OSError`, or a SQLite error whose code is a +full disk, an I/O error, a file it cannot open or a read-only database, is the +storage alert, exit 6. Anything else, a column an older `esb.db` lacks or a +malformed file included, is a new "run crashed" alert, exit 1, with the +traceback in the journal: the storage banner's `df` and `chown` would send the +reader the wrong way. + +The crash banner names `esb rebuild` for every crash, and says that a rebuild +which fails the same way, or a next run that crashes again, means the code +needs a fix: a bug in the poll's own path replays cleanly. Choosing from the +exception's type was wrong both ways: an older `esb.db` missing a column +raises `IndexError` from `sqlite3.Row`, which a rebuild fixes, and a code bug +can raise `sqlite3.ProgrammingError`, which it replays. Following the advice +blind costs nothing the raw logs cannot restore: a rebuild that fails leaves a +partial `esb.db`, and the next one that succeeds replaces it. Building into a +side file and renaming it in was tried and dropped: about 60 lines guarding a +disposable file, which four review rounds kept finding holes in. + +Neither the storage alert nor the crash pings: the run stored nothing +reliable, so it joins the rejected key and the unreachable feed in raising +both alarms. diff --git a/tests/test_poll.py b/tests/test_poll.py index b799ef4..bffb754 100644 --- a/tests/test_poll.py +++ b/tests/test_poll.py @@ -226,6 +226,64 @@ def test_leaves_no_probe_file_behind(self): self.assertFalse((self.data_dir / ".write-test").exists()) +class TestAFailureMidRun(PollTestCase): + """What the pre-run probe cannot see still reaches the webhook, and a run + that stored nothing sends no heartbeat.""" + + def setUp(self): + super().setUp() + self.requests = [] + url, self.server, self.thread = local_server(self.requests) + os.environ["ESB_HEARTBEAT_URL"] = url + os.environ["ESB_ALERT_WEBHOOK"] = url.replace("/hook", "/alert") + + def tearDown(self): + stop_server(self.server, self.thread) + super().tearDown() + + def poll_failing(self, method, error): + with unittest.mock.patch.object(Store, method, side_effect=error), \ + contextlib.redirect_stderr(io.StringIO()): + return self.poll(self.client_with("fault")) + + def test_a_full_disk_is_a_storage_alert(self): + code = self.poll_failing("write_run_raw", OSError(28, "No space left on device")) + self.assertEqual(code, alert.EXIT_STORAGE) + self.assertEqual([p for p, _ in self.requests], ["/alert"]) + self.assertIn("No space left on device", self.requests[0][1]) + + def test_a_full_database_is_a_storage_alert(self): + error = sqlite3.OperationalError("database or disk is full") + error.sqlite_errorcode = sqlite3.SQLITE_FULL + self.assertEqual(self.poll_failing("apply_list", error), alert.EXIT_STORAGE) + self.assertEqual([p for p, _ in self.requests], ["/alert"]) + + def test_a_database_from_older_code_is_not_a_disk_problem(self): + try: + sqlite3.connect(":memory:").execute("SELECT no_such_column FROM sqlite_master") + except sqlite3.OperationalError as caught: + error = caught + self.assertEqual(self.poll_failing("apply_list", error), alert.EXIT_CRASH) + self.assertIn("RUN CRASHED", self.requests[0][1]) + self.assertIn("sudo esb rebuild", self.requests[0][1]) + + def test_a_malformed_database_points_to_rebuild(self): + error = sqlite3.DatabaseError("database disk image is malformed") + error.sqlite_errorcode = sqlite3.SQLITE_CORRUPT + self.assertEqual(self.poll_failing("apply_list", error), alert.EXIT_CRASH) + self.assertIn("sudo esb rebuild", self.requests[0][1]) + + def test_anything_else_is_a_crash_alert(self): + code = self.poll_failing("apply_list", KeyError("i")) + self.assertEqual(code, alert.EXIT_CRASH) + self.assertEqual([p for p, _ in self.requests], ["/alert"]) + self.assertIn("RUN CRASHED", self.requests[0][1]) + self.assertIn("esb rebuild", self.requests[0][1]) + self.assertIn("rebuild again once it has one", self.requests[0][1]) + # A bug in the poll's own path replays cleanly and crashes again. + self.assertIn("or the next run crashes", self.requests[0][1]) + + class TestLocking(PollTestCase): def test_second_run_backs_off_while_first_holds_the_lock(self): with poll_lock(self.data_dir) as acquired: From 9d554dba8fc1613dbad258861079c107f59542dd Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:05:38 +0000 Subject: [PATCH 03/18] Refuse a negative or non-numeric poll delay time.sleep raises on a negative pause, so ESB_POLL_DELAY_MS=-1 wrote the list and one detail and then died, every run. poll.milliseconds now parses both the flag, which refuses a bad value, and the environment variable, which falls back to the default with a warning. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- esb_outages/__main__.py | 4 ++-- esb_outages/poll.py | 27 ++++++++++++++++++++++++++- tests/test_poll.py | 32 +++++++++++++++++++++++++++++++- 3 files changed, 59 insertions(+), 4 deletions(-) diff --git a/esb_outages/__main__.py b/esb_outages/__main__.py index c26fc62..59ce162 100644 --- a/esb_outages/__main__.py +++ b/esb_outages/__main__.py @@ -9,7 +9,7 @@ from . import __version__, alert from .client import EsbClient -from .poll import DEFAULT_DELAY_MS, poll_lock, run_check, run_poll +from .poll import DEFAULT_DELAY_MS, milliseconds, poll_lock, run_check, run_poll from .store import Store DEFAULT_DATA_DIR = os.environ.get("ESB_DATA_DIR", "/data") @@ -143,7 +143,7 @@ def main(argv=None) -> int: p_poll = sub.add_parser("poll", help="run one collection pass (the scheduled command)") p_poll.add_argument( - "--delay-ms", type=int, default=None, + "--delay-ms", type=milliseconds, default=None, help=f"pause between detail requests (env: ESB_POLL_DELAY_MS, default {DEFAULT_DELAY_MS})", ) sub.add_parser("check", help="verify the API key and connectivity; writes nothing") diff --git a/esb_outages/poll.py b/esb_outages/poll.py index 1261b5a..ca1e155 100644 --- a/esb_outages/poll.py +++ b/esb_outages/poll.py @@ -12,6 +12,7 @@ import os import signal import sqlite3 +import sys import time import traceback import uuid @@ -79,6 +80,30 @@ def check_writable(data_dir: Path) -> str | None: return None +def milliseconds(value: str) -> int: + """The poll delay, from --delay-ms or ESB_POLL_DELAY_MS.""" + ms = int(value) + if ms < 0: + # time.sleep raises on a negative pause, after the first detail. + raise ValueError(f"{value} is negative") + return ms + + +def _env_delay_ms() -> int: + raw = os.environ.get("ESB_POLL_DELAY_MS") + if raw is None: + return DEFAULT_DELAY_MS + try: + return milliseconds(raw) + except ValueError: + print( + f"warning: ESB_POLL_DELAY_MS={raw!r} is not a whole number of " + f"milliseconds; using {DEFAULT_DELAY_MS}", + file=sys.stderr, + ) + return DEFAULT_DELAY_MS + + # The SQLite errors a disk or its permissions cause. Anything else, such as a # column an older esb.db lacks or a malformed file, is a crash: df and chown # will not fix it. @@ -104,7 +129,7 @@ def run_poll( data_dir = Path(data_dir) client = client or EsbClient() if delay_ms is None: - delay_ms = int(os.environ.get("ESB_POLL_DELAY_MS", DEFAULT_DELAY_MS)) + delay_ms = _env_delay_ms() problem = check_writable(data_dir) if problem: diff --git a/tests/test_poll.py b/tests/test_poll.py index bffb754..6aeabb1 100644 --- a/tests/test_poll.py +++ b/tests/test_poll.py @@ -12,7 +12,7 @@ from esb_outages import alert from esb_outages.client import ApiError, AuthError, NotFound, TransientError -from esb_outages.poll import poll_lock, run_check, run_poll +from esb_outages.poll import DEFAULT_DELAY_MS, poll_lock, run_check, run_poll from esb_outages.store import Store from .helpers import FakeClient, detail, local_server, make_list, stop_server @@ -284,6 +284,36 @@ def test_anything_else_is_a_crash_alert(self): self.assertIn("or the next run crashes", self.requests[0][1]) +class TestTheDelay(PollTestCase): + def poll_with_env(self, value): + os.environ["ESB_POLL_DELAY_MS"] = value + client = self.client_with("fault", "restored") + with contextlib.redirect_stderr(io.StringIO()): + code = run_poll(self.data_dir, client=client) + return code, client + + def test_a_negative_delay_falls_back_to_the_default(self): + with unittest.mock.patch("esb_outages.poll.time.sleep") as sleep: + code, client = self.poll_with_env("-1") + self.assertEqual(code, alert.EXIT_OK) + self.assertEqual(len(client.detail_calls), 2) + sleep.assert_called_with(DEFAULT_DELAY_MS / 1000.0) + + def test_a_delay_that_is_not_a_number_falls_back_to_the_default(self): + with unittest.mock.patch("esb_outages.poll.time.sleep"): + code, client = self.poll_with_env("half a second") + self.assertEqual(code, alert.EXIT_OK) + self.assertEqual(len(client.detail_calls), 2) + + def test_the_flag_refuses_a_negative_delay(self): + from esb_outages.__main__ import main + + err = io.StringIO() + with self.assertRaises(SystemExit), contextlib.redirect_stderr(err): + main(["--data-dir", str(self.data_dir), "poll", "--delay-ms", "-1"]) + self.assertIn("invalid milliseconds value: '-1'", err.getvalue()) + + class TestLocking(PollTestCase): def test_second_run_backs_off_while_first_holds_the_lock(self): with poll_lock(self.data_dir) as acquired: From aa5ba05443422ade1a39207fbab4f9ccb4bae158 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:05:52 +0000 Subject: [PATCH 04/18] Do not raise a storage alarm when an overlapping run removed the probe Two runs share the .write-test name: one touches, the other touches, the first unlinks, and the second's unlink raised FileNotFoundError, which read as an unwritable directory: exit 6, a webhook, and no heartbeat. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- esb_outages/poll.py | 3 ++- tests/test_poll.py | 18 +++++++++++++++++- 2 files changed, 19 insertions(+), 2 deletions(-) diff --git a/esb_outages/poll.py b/esb_outages/poll.py index ca1e155..6fdd6b9 100644 --- a/esb_outages/poll.py +++ b/esb_outages/poll.py @@ -74,7 +74,8 @@ def check_writable(data_dir: Path) -> str | None: probe = data_dir / ".write-test" try: probe.touch() - probe.unlink() + # An overlapping run shares the name and may have removed it already. + probe.unlink(missing_ok=True) except OSError as exc: return f"cannot write inside {data_dir}: {exc}" return None diff --git a/tests/test_poll.py b/tests/test_poll.py index 6aeabb1..1258bbc 100644 --- a/tests/test_poll.py +++ b/tests/test_poll.py @@ -12,7 +12,13 @@ from esb_outages import alert from esb_outages.client import ApiError, AuthError, NotFound, TransientError -from esb_outages.poll import DEFAULT_DELAY_MS, poll_lock, run_check, run_poll +from esb_outages.poll import ( + DEFAULT_DELAY_MS, + check_writable, + poll_lock, + run_check, + run_poll, +) from esb_outages.store import Store from .helpers import FakeClient, detail, local_server, make_list, stop_server @@ -221,6 +227,16 @@ def test_readonly_directory_exits_six_without_a_traceback(self): finally: os.chmod(target, 0o700) + def test_an_overlapping_run_removing_the_probe_is_not_an_alarm(self): + touch = Path.touch + + def touched_then_removed_by_the_other_run(path, *args, **kwargs): + touch(path, *args, **kwargs) + os.unlink(path) + + with unittest.mock.patch.object(Path, "touch", touched_then_removed_by_the_other_run): + self.assertIsNone(check_writable(self.data_dir)) + def test_leaves_no_probe_file_behind(self): self.poll(self.client_with("fault")) self.assertFalse((self.data_dir / ".write-test").exists()) From 80de7d70780558b2fae93d10cfc21fd7de4d8005 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:06:08 +0000 Subject: [PATCH 05/18] Read only a held lock as held, and wait out a brief holder poll_lock caught every OSError from flock, so a filesystem that cannot lock (ENOLCK) made every run skip silently. Only BlockingIOError now means held, and any other error reaches the storage alert. A poll waits up to two minutes for the lock, counted inside its budget, so a backup committing for a few seconds no longer costs it the whole slot. The skip line and the refusal from rebuild and compact name every holder: a poll, the backup, or esb rebuild or compact. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- esb_outages/__main__.py | 11 +++++++-- esb_outages/poll.py | 51 +++++++++++++++++++++++++++-------------- tests/test_poll.py | 51 +++++++++++++++++++++++++++++++++++------ 3 files changed, 87 insertions(+), 26 deletions(-) diff --git a/esb_outages/__main__.py b/esb_outages/__main__.py index 59ce162..714433d 100644 --- a/esb_outages/__main__.py +++ b/esb_outages/__main__.py @@ -106,7 +106,11 @@ def cmd_test_alert(args) -> int: def _held_by_poll() -> int: # Both delete files a poll writes to: esb.db and its journal, or the log. - print("a poll run holds the lock; try again when it has finished", file=sys.stderr) + print( + "the lock is held (by a poll, the backup, or esb rebuild or compact);" + " try again when it has finished", + file=sys.stderr, + ) return 1 @@ -144,7 +148,10 @@ def main(argv=None) -> int: p_poll = sub.add_parser("poll", help="run one collection pass (the scheduled command)") p_poll.add_argument( "--delay-ms", type=milliseconds, default=None, - help=f"pause between detail requests (env: ESB_POLL_DELAY_MS, default {DEFAULT_DELAY_MS})", + help=( + "pause between detail requests, 0 or more " + f"(env: ESB_POLL_DELAY_MS, default {DEFAULT_DELAY_MS})" + ), ) sub.add_parser("check", help="verify the API key and connectivity; writes nothing") sub.add_parser( diff --git a/esb_outages/poll.py b/esb_outages/poll.py index 6fdd6b9..c0f0a73 100644 --- a/esb_outages/poll.py +++ b/esb_outages/poll.py @@ -31,6 +31,11 @@ # because a run systemd has to stop is a failed unit whatever it exits with. RUN_BUDGET_S = 24 * 60 +# The backup holds the lock for seconds while it commits; a poll holds it for +# its whole run. Waiting this long tells the two apart, rather than skipping a +# poll every time a backup slot meets a trigger. +LOCK_WAIT_S = 120 + # A failed detail fetch is not lost data: the outage stays in the list for the # whole retention window and is not marked final, so the next hourly run retries # it - roughly four more chances before ESB purges it. Only a broad failure is @@ -40,22 +45,29 @@ @contextlib.contextmanager -def poll_lock(data_dir: Path): +def poll_lock(data_dir: Path, wait_s: float = 0): """Exclusive lock so two runs can never interleave writes. - At one request per second a large storm could in principle push a run past - the next hourly trigger. Overlapping runs would corrupt neither file - irrecoverably, but they would duplicate work and confuse change history. + A manual run can overlap the timer's, and a storm run can outlast the 30 + minutes to the next trigger if it ever misses its budget. Overlapping runs + would corrupt neither file irrecoverably, but they would duplicate work and + confuse change history. The backup holds it too, for seconds. """ data_dir.mkdir(parents=True, exist_ok=True) lock_path = data_dir / ".poll.lock" handle = lock_path.open("w") + deadline = time.monotonic() + wait_s try: - try: - fcntl.flock(handle, fcntl.LOCK_EX | fcntl.LOCK_NB) - except OSError: - yield False - return + while True: + try: + fcntl.flock(handle, fcntl.LOCK_EX | fcntl.LOCK_NB) + break + # Only this means held; any other error must not read as a quiet skip. + except BlockingIOError: + if time.monotonic() >= deadline: + yield False + return + time.sleep(0.5) yield True finally: handle.close() @@ -99,7 +111,7 @@ def _env_delay_ms() -> int: except ValueError: print( f"warning: ESB_POLL_DELAY_MS={raw!r} is not a whole number of " - f"milliseconds; using {DEFAULT_DELAY_MS}", + f"milliseconds, 0 or more; using {DEFAULT_DELAY_MS}", file=sys.stderr, ) return DEFAULT_DELAY_MS @@ -126,7 +138,10 @@ def run_poll( client: EsbClient | None = None, delay_ms: int | None = None, budget_s: float = RUN_BUDGET_S, + lock_wait_s: float = LOCK_WAIT_S, ) -> int: + # From the start, so a wait for the lock comes out of the budget. + deadline = time.monotonic() + budget_s data_dir = Path(data_dir) client = client or EsbClient() if delay_ms is None: @@ -137,11 +152,14 @@ def run_poll( return alert.fail(alert.storage_banner(data_dir, problem), alert.EXIT_STORAGE) try: - with poll_lock(data_dir) as acquired: + with poll_lock(data_dir, lock_wait_s) as acquired: if not acquired: - print("another poll run holds the lock; skipping this trigger") + print( + f"the lock has been held for {lock_wait_s:.0f}s (by a poll, the " + "backup, or esb rebuild or compact); skipping this trigger" + ) return alert.EXIT_OK - code = _run(data_dir, client, delay_ms, budget_s) + code = _run(data_dir, client, delay_ms, deadline) # The probe above passes on a full disk, which still has inodes for an # empty file; the first real write is what fails. except Exception as exc: @@ -179,14 +197,13 @@ def _stop_on_sigterm(): signal.signal(signal.SIGTERM, previous) -def _run(data_dir: Path, client: EsbClient, delay_ms: int, budget_s: float) -> int: +def _run(data_dir: Path, client: EsbClient, delay_ms: int, deadline: float) -> int: with _stop_on_sigterm() as stop, Store(data_dir) as store: - return _collect(store, client, delay_ms, stop, budget_s) + return _collect(store, client, delay_ms, stop, deadline) -def _collect(store: Store, client: EsbClient, delay_ms: int, stop: list, budget_s: float) -> int: +def _collect(store: Store, client: EsbClient, delay_ms: int, stop: list, deadline: float) -> int: started_at = utc_now_iso() - deadline = time.monotonic() + budget_s # Timestamps are only second-resolution, so they cannot identify a run on # their own; rebuild groups observations by run_id and needs it unique. run_id = f"{started_at}-{uuid.uuid4().hex[:8]}" diff --git a/tests/test_poll.py b/tests/test_poll.py index 1258bbc..ccc6630 100644 --- a/tests/test_poll.py +++ b/tests/test_poll.py @@ -1,10 +1,12 @@ import contextlib import copy +import errno import io import os import signal import sqlite3 import tempfile +import threading import unittest import unittest.mock import urllib.error @@ -40,7 +42,7 @@ def tearDown(self): self._tmp.cleanup() def poll(self, client): - return run_poll(self.data_dir, client=client, delay_ms=0) + return run_poll(self.data_dir, client=client, delay_ms=0, lock_wait_s=0) def store(self): return Store(self.data_dir).open() @@ -304,20 +306,22 @@ class TestTheDelay(PollTestCase): def poll_with_env(self, value): os.environ["ESB_POLL_DELAY_MS"] = value client = self.client_with("fault", "restored") - with contextlib.redirect_stderr(io.StringIO()): + err = io.StringIO() + with contextlib.redirect_stderr(err): code = run_poll(self.data_dir, client=client) - return code, client + return code, client, err.getvalue() def test_a_negative_delay_falls_back_to_the_default(self): with unittest.mock.patch("esb_outages.poll.time.sleep") as sleep: - code, client = self.poll_with_env("-1") + code, client, err = self.poll_with_env("-1") + self.assertIn("0 or more", err) self.assertEqual(code, alert.EXIT_OK) self.assertEqual(len(client.detail_calls), 2) sleep.assert_called_with(DEFAULT_DELAY_MS / 1000.0) def test_a_delay_that_is_not_a_number_falls_back_to_the_default(self): with unittest.mock.patch("esb_outages.poll.time.sleep"): - code, client = self.poll_with_env("half a second") + code, client, _ = self.poll_with_env("half a second") self.assertEqual(code, alert.EXIT_OK) self.assertEqual(len(client.detail_calls), 2) @@ -335,9 +339,42 @@ def test_second_run_backs_off_while_first_holds_the_lock(self): with poll_lock(self.data_dir) as acquired: self.assertTrue(acquired) client = self.client_with("fault") - # Exits 0: an overlapping trigger is not a failure worth emailing about. - self.assertEqual(self.poll(client), alert.EXIT_OK) + out = io.StringIO() + with contextlib.redirect_stdout(out): + # Exits 0: an overlapping trigger is not a failure worth emailing about. + self.assertEqual(self.poll(client), alert.EXIT_OK) self.assertEqual(client.list_calls, 0) + # Not only polls hold it, so the message must not blame one. + self.assertIn("the backup, or esb rebuild or compact", out.getvalue()) + + def test_a_lock_that_cannot_be_taken_is_not_a_quiet_skip(self): + error = OSError(errno.ENOLCK, "No locks available") + with unittest.mock.patch("esb_outages.poll.fcntl.flock", side_effect=error), \ + contextlib.redirect_stderr(io.StringIO()): + self.assertEqual(self.poll(self.client_with("fault")), alert.EXIT_STORAGE) + + def test_a_run_waits_out_a_brief_holder(self): + # The backup, committing: a poll that met it used to lose its slot. + held, release, acquired = threading.Event(), threading.Event(), [] + + def backup(): + with poll_lock(self.data_dir) as got: + acquired.append(got) + held.set() + release.wait(5) + + thread = threading.Thread(target=backup) + thread.start() + self.assertTrue(held.wait(5)) + self.assertEqual(acquired, [True]) + timer = threading.Timer(1, release.set) + timer.start() + client = self.client_with("fault") + code = run_poll(self.data_dir, client=client, delay_ms=0, lock_wait_s=10) + timer.join() + thread.join() + self.assertEqual(code, alert.EXIT_OK) + self.assertEqual(client.list_calls, 1) def test_lock_is_released_afterwards(self): with poll_lock(self.data_dir) as acquired: From 5674cd15bb482b17159d698cf8f73d4ee175c32c Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:06:37 +0000 Subject: [PATCH 06/18] Test the alert paths nothing held A partial run pings; a key rejected mid-run and an unwritable directory do not; the ping is a GET; ntfy gets the banner as the body with a Title, and any other webhook gets JSON; and every outcome of test-alert. No code change. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- tests/helpers.py | 10 ++-- tests/test_poll.py | 111 +++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 118 insertions(+), 3 deletions(-) diff --git a/tests/helpers.py b/tests/helpers.py index 91b617f..714cf19 100644 --- a/tests/helpers.py +++ b/tests/helpers.py @@ -28,8 +28,9 @@ def make_list(*details, extra=None): return {"outageMessage": items} -def local_server(received): - """A local HTTP server that records every request until stopped. +def local_server(received, seen=None): + """A local HTTP server that records every request until stopped, as + (path, body), and as (method, path, headers, body) in `seen` if given. Returns (url, server, thread); stop it with `stop_server`. It serves until told to stop rather than for a fixed window: a one-shot server that gave @@ -42,7 +43,10 @@ def local_server(received): class Handler(http.server.BaseHTTPRequestHandler): def _record(self): length = int(self.headers.get("Content-Length", 0)) - received.append((self.path, self.rfile.read(length).decode())) + body = self.rfile.read(length).decode() + received.append((self.path, body)) + if seen is not None: + seen.append((self.command, self.path, dict(self.headers), body)) self.send_response(200) self.end_headers() diff --git a/tests/test_poll.py b/tests/test_poll.py index ccc6630..6c4b4a0 100644 --- a/tests/test_poll.py +++ b/tests/test_poll.py @@ -2,6 +2,7 @@ import copy import errno import io +import json import os import signal import sqlite3 @@ -529,6 +530,31 @@ def test_failure_is_pushed_to_the_webhook(self): self.assertEqual(len(self.received), 1) self.assertIn("SUBSCRIPTION KEY REJECTED", self.received[0][1]) + def test_ntfy_gets_the_banner_as_the_body_with_a_title(self): + seen = [] + url, server, thread = local_server([], seen) + try: + with unittest.mock.patch.dict(os.environ, {"ESB_ALERT_WEBHOOK": url + "/ntfy"}): + self.assertTrue(alert.notify("the banner")) + finally: + stop_server(server, thread) + [(method, _, headers, body)] = seen + self.assertEqual((method, body), ("POST", "the banner")) + self.assertEqual(headers["Title"], "ESB poller failure") + + def test_any_other_webhook_gets_json(self): + seen = [] + url, server, thread = local_server([], seen) + try: + with unittest.mock.patch.dict(os.environ, {"ESB_ALERT_WEBHOOK": url}): + self.assertTrue(alert.notify("the banner")) + finally: + stop_server(server, thread) + [(method, _, headers, body)] = seen + self.assertEqual(method, "POST") + self.assertEqual(headers["Content-Type"], "application/json") + self.assertEqual(json.loads(body), {"content": "the banner", "text": "the banner"}) + def test_notify_reports_delivery(self): with unittest.mock.patch.dict(os.environ, {"ESB_ALERT_WEBHOOK": self.url}): self.assertTrue(alert.notify("hello")) @@ -615,6 +641,25 @@ def test_a_run_cut_short_still_pings(self): self.assertEqual(self.poll(storm_client(storm(), TestStorm.BUDGET)), alert.EXIT_OK) self.assertEqual(self.paths(), ["/hook"]) + def test_a_partial_run_still_pings(self): + kinds = ["fault", "planned", "restored"] + client = FakeClient( + list_body=make_list(*[detail(k) for k in kinds]), + detail_errors={detail(k)["outageId"]: TransientError("503") for k in kinds}, + ) + self.assertEqual(self.poll(client), alert.EXIT_PARTIAL) + self.assertEqual(self.paths(), ["/hook"]) + + def test_the_ping_is_a_get(self): + seen = [] + url, server, thread = local_server([], seen) + try: + os.environ["ESB_HEARTBEAT_URL"] = url + self.assertTrue(alert.heartbeat()) + finally: + stop_server(server, thread) + self.assertEqual([method for method, *_ in seen], ["GET"]) + def test_a_rejected_key_does_not_ping(self): self.poll(FakeClient(list_error=AuthError("401 rejected"))) self.assertEqual(self.paths(), []) @@ -623,6 +668,19 @@ def test_an_unreachable_feed_does_not_ping(self): self.poll(FakeClient(list_error=TransientError("connection refused"))) self.assertEqual(self.paths(), []) + def test_a_key_rejected_mid_run_does_not_ping(self): + dying = detail("fault")["outageId"] + client = FakeClient( + list_body=make_list(detail("fault")), detail_errors={dying: AuthError("401")} + ) + self.assertEqual(self.poll(client), alert.EXIT_AUTH) + self.assertEqual(self.paths(), []) + + def test_an_unwritable_directory_does_not_ping(self): + with unittest.mock.patch("esb_outages.poll.check_writable", return_value="read-only"): + self.assertEqual(self.poll(self.client_with("fault")), alert.EXIT_STORAGE) + self.assertEqual(self.paths(), []) + def test_a_skipped_trigger_does_not_ping(self): with poll_lock(self.data_dir) as acquired: self.assertTrue(acquired) @@ -641,6 +699,59 @@ def test_a_dead_monitor_does_not_change_the_exit_code(self): self.assertEqual(self.poll(self.client_with("fault")), alert.EXIT_OK) +class TestTestAlert(PollTestCase): + """`esb test-alert` is the proof both channels work, so each outcome must + say what it found.""" + + def setUp(self): + super().setUp() + self.requests = [] + self.url, self.server, self.thread = local_server(self.requests) + + def tearDown(self): + stop_server(self.server, self.thread) + super().tearDown() + + def run_it(self, **env): + from esb_outages.__main__ import main + + os.environ.update(env) + out, err = io.StringIO(), io.StringIO() + with contextlib.redirect_stdout(out), contextlib.redirect_stderr(err): + code = main(["--data-dir", str(self.data_dir), "test-alert"]) + return code, err.getvalue() + + def test_no_webhook_is_a_failure(self): + code, err = self.run_it() + self.assertEqual(code, 1) + self.assertIn("ESB_ALERT_WEBHOOK is not set", err) + self.assertEqual(self.requests, []) + + def test_a_webhook_that_cannot_be_reached_is_a_failure(self): + code, err = self.run_it(ESB_ALERT_WEBHOOK="http://127.0.0.1:9/dead") + self.assertEqual(code, 1) + self.assertIn("alert delivery FAILED", err) + + def test_no_heartbeat_passes_with_a_warning(self): + code, err = self.run_it(ESB_ALERT_WEBHOOK=self.url) + self.assertEqual(code, alert.EXIT_OK) + self.assertIn("ESB_HEARTBEAT_URL is not set", err) + self.assertEqual(len(self.requests), 1) + + def test_a_heartbeat_that_cannot_be_reached_is_a_failure(self): + code, err = self.run_it( + ESB_ALERT_WEBHOOK=self.url, ESB_HEARTBEAT_URL="http://127.0.0.1:9/dead" + ) + self.assertEqual(code, 1) + self.assertIn("heartbeat delivery FAILED", err) + + def test_both_delivered(self): + code, _ = self.run_it(ESB_ALERT_WEBHOOK=self.url, ESB_HEARTBEAT_URL=self.url) + self.assertEqual(code, alert.EXIT_OK) + self.assertEqual(len(self.requests), 2) + self.assertIn("TEST ALERT", self.requests[0][1]) + + class TestCheck(unittest.TestCase): def test_ok(self): self.assertEqual(run_check(FakeClient(list_body=make_list(detail("fault")))), alert.EXIT_OK) From 2bf8d7332ea76f0ed63023464b387ad3f4510e8d Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:07:04 +0000 Subject: [PATCH 07/18] Name the 30-minute cadence and the directory in use in the storage fix The unreachable banner promised "the next hourly run" and two comments said hourly, from before the timer moved to every 30 minutes. The storage banner's chown line hardcoded /var/lib/esb-outages beside df and ls lines that use the directory actually in use. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- esb_outages/alert.py | 4 ++-- esb_outages/poll.py | 6 +++--- tests/test_poll.py | 10 ++++++++++ 3 files changed, 15 insertions(+), 5 deletions(-) diff --git a/esb_outages/alert.py b/esb_outages/alert.py index 6326b98..09c5026 100644 --- a/esb_outages/alert.py +++ b/esb_outages/alert.py @@ -74,7 +74,7 @@ def unreachable_banner(detail: str) -> str: "ESB POLLER: API UNREACHABLE", [ "The outage list endpoint could not be reached after retries.", - "If this clears on the next hourly run, no action is needed - a", + "If this clears on the next run, no action is needed - a", "single miss is covered by the ~4h retention window. Repeated", "failures mean data is being lost.", "", @@ -109,7 +109,7 @@ def storage_banner(data_dir, problem: str) -> str: "Check:", f" df -h {data_dir}", f" ls -ld {data_dir}", - " sudo chown -R esb:esb /var/lib/esb-outages", + f" sudo chown -R esb:esb {data_dir}", ], ) diff --git a/esb_outages/poll.py b/esb_outages/poll.py index c0f0a73..3c51206 100644 --- a/esb_outages/poll.py +++ b/esb_outages/poll.py @@ -37,9 +37,9 @@ LOCK_WAIT_S = 120 # A failed detail fetch is not lost data: the outage stays in the list for the -# whole retention window and is not marked final, so the next hourly run retries -# it - roughly four more chances before ESB purges it. Only a broad failure is -# worth an email, so both a proportion and an absolute floor must be exceeded. +# whole retention window and is not marked final, so every run until ESB purges +# it retries it. Only a broad failure is worth an email, so both a proportion +# and an absolute floor must be exceeded. PARTIAL_FAILURE_THRESHOLD = 0.25 PARTIAL_FAILURE_MIN = 3 diff --git a/tests/test_poll.py b/tests/test_poll.py index 6c4b4a0..0d68b3c 100644 --- a/tests/test_poll.py +++ b/tests/test_poll.py @@ -699,6 +699,16 @@ def test_a_dead_monitor_does_not_change_the_exit_code(self): self.assertEqual(self.poll(self.client_with("fault")), alert.EXIT_OK) +class TestBanners(unittest.TestCase): + def test_the_storage_fix_names_the_directory_in_use(self): + text = alert.storage_banner(Path("/data"), "full") + self.assertIn("chown -R esb:esb /data\n", text) + self.assertNotIn("/var/lib", text) + + def test_the_unreachable_banner_does_not_promise_an_hourly_run(self): + self.assertNotIn("hourly", alert.unreachable_banner("timeout")) + + class TestTestAlert(PollTestCase): """`esb test-alert` is the proof both channels work, so each outcome must say what it found.""" From b3d16c799d798684b852fd4d36b5a5d448a00999 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:07:30 +0000 Subject: [PATCH 08/18] Cap the error text an alert can carry AuthError and TransientError embedded the whole response body, so a 5xx HTML page went into the partial-loss banner ten times over and into the run log's error_summary. Discord rejects a message over 2,000 characters, so that alert would never arrive. The body is now cut to 200 characters, and the webhook message to 1,900 with a note that the journal has the rest. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- esb_outages/alert.py | 6 ++++++ esb_outages/client.py | 5 +++++ tests/test_client.py | 16 ++++++++++++++++ tests/test_poll.py | 7 +++++++ 4 files changed, 34 insertions(+) diff --git a/esb_outages/alert.py b/esb_outages/alert.py index 09c5026..f9008d6 100644 --- a/esb_outages/alert.py +++ b/esb_outages/alert.py @@ -36,6 +36,10 @@ BANNER_WIDTH = 78 +# Discord rejects a message over 2,000 characters outright; ntfy allows 4,096. +MAX_ALERT_CHARS = 1900 +TRUNCATED = "\n[truncated; the full text is in the journal]" + def banner(title: str, lines: list[str]) -> str: # Fixed width: these end up in an email, and a long raw error message would @@ -178,6 +182,8 @@ def notify(message: str) -> bool: url = os.environ.get("ESB_ALERT_WEBHOOK") if not url: return False + if len(message) > MAX_ALERT_CHARS: + message = message[: MAX_ALERT_CHARS - len(TRUNCATED)] + TRUNCATED if "ntfy" in url: data, headers = message.encode("utf-8"), {"Title": "ESB poller failure"} else: diff --git a/esb_outages/client.py b/esb_outages/client.py index 55e2cc3..957cd7a 100644 --- a/esb_outages/client.py +++ b/esb_outages/client.py @@ -33,6 +33,7 @@ DEFAULT_TIMEOUT = 15.0 DEFAULT_RETRIES = 3 +ERROR_BODY_CHARS = 200 class EsbError(Exception): @@ -115,6 +116,10 @@ def _request(self, url: str) -> str: body = _decode(exc.read(), exc.headers) except Exception: # pragma: no cover - body is best-effort context pass + # A 5xx can be a whole HTML page, and this text reaches the alert + # and the run log's error_summary. + if len(body) > ERROR_BODY_CHARS: + body = body[:ERROR_BODY_CHARS] + "..." if exc.code == 401: raise AuthError(f"401 rejected key {self.masked_key}: {body}") from exc if exc.code == 404: diff --git a/tests/test_client.py b/tests/test_client.py index bc813c5..cd9f271 100644 --- a/tests/test_client.py +++ b/tests/test_client.py @@ -1,6 +1,8 @@ import gzip import http.client +import io import unittest +import urllib.error from unittest import mock from esb_outages.client import ApiError, EsbClient, TransientError @@ -49,5 +51,19 @@ def test_a_body_that_is_not_utf8_is_an_api_error(self): self.request(_Response(lambda: b"\xff\xfe", encoding="")) +class TestErrorText(unittest.TestCase): + def test_a_server_error_page_is_cut_short_in_the_message(self): + page = "" + "x" * 50_000 + "" + error = urllib.error.HTTPError( + "https://api.esb.ie/outages", 503, "Service Unavailable", {}, + io.BytesIO(page.encode()), + ) + client = EsbClient(retries=1, sleep=lambda s: None) + with mock.patch("urllib.request.urlopen", side_effect=error), \ + self.assertRaises(TransientError) as caught: + client.get_json("/outages") + self.assertLess(len(str(caught.exception)), 400) + + if __name__ == "__main__": unittest.main() diff --git a/tests/test_poll.py b/tests/test_poll.py index 0d68b3c..edef57a 100644 --- a/tests/test_poll.py +++ b/tests/test_poll.py @@ -555,6 +555,13 @@ def test_any_other_webhook_gets_json(self): self.assertEqual(headers["Content-Type"], "application/json") self.assertEqual(json.loads(body), {"content": "the banner", "text": "the banner"}) + def test_a_long_alert_fits_discord(self): + with unittest.mock.patch.dict(os.environ, {"ESB_ALERT_WEBHOOK": self.url}): + self.assertTrue(alert.notify("x" * 10_000)) + content = json.loads(self.received[0][1])["content"] + self.assertLessEqual(len(content), 2000) + self.assertTrue(content.endswith("the full text is in the journal]")) + def test_notify_reports_delivery(self): with unittest.mock.patch.dict(os.environ, {"ESB_ALERT_WEBHOOK": self.url}): self.assertTrue(alert.notify("hello")) From effffc5ca22cc166cf6f8c0cd14e42236e38459b Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:08:30 +0000 Subject: [PATCH 09/18] Leave room under the backstop for the last fetch, the webhook and the ping The 24-minute budget is checked only between fetches, and after it come the slowest fetch, the webhook a partial or drifted run sends, and the heartbeat. Each request can time out connecting to an IPv4 and an IPv6 address and then on the read: 200 seconds in all, past the 25-minute TimeoutStartSec. In a storm with a degraded API systemd would fail the unit and kill the heartbeat mid-send. The budget is now 22 minutes and the backstop 26, which with the timer's three minutes of jitter still ends before the next trigger. TestTheBackstop recomputes both from the constants and the unit files. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- CLAUDE.md | 2 +- README.md | 2 +- esb_outages/alert.py | 4 +++- esb_outages/poll.py | 7 +++---- notes/storms.md | 24 +++++++++++++++++++++- scripts/systemd/esb-outages.service | 8 +++----- tests/test_poll.py | 32 +++++++++++++++++++++++++++++ 7 files changed, 66 insertions(+), 13 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index d5b5ca8..7c8a482 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -118,7 +118,7 @@ Every one of these has already cost someone an hour: | 2.5M customer denominator, and which DAPR figures are comparable | `notes/grading.md` § The customer denominator | | Each run logs two lines to `runs-*.jsonl`: the list before any detail is fetched, and an `"event": "end"` line (`Store.finish_run`) carrying what a rebuild cannot derive - status, exit code, finish time, skipped count, errors. Older runs have no end line and replay from the start line alone | `notes/storms.md` § The run's end is logged after all (2026-09-24) | | The collector pings `ESB_HEARTBEAT_URL` after every run that reached the feed, drifted or partial ones included, and never after a rejected key, an unreachable feed, a storage failure, a crash or a skipped trigger; a dead-man's monitor alerts on silence (period 30 min, grace 90). `test-alert` proves both channels | `notes/alerting.md` § The heartbeat (2026-09-06); § A run that fails partway (2026-09-24) | -| A storm can list more than a run can fetch: `ids_needing_detail` ranks by what a purge would take (listed Restored and still needing a fetch, then live never-fetched, then re-checks), every detail is committed as it lands, a run stops itself at `RUN_BUDGET_S` (24 min) and records `cut_short` (exit 0, heartbeat sent, no webhook), SIGTERM from the service unit's backstop ends the loop the same way, and the pause is 500 ms. In list order a cut-short run re-fetched the same head every run and never reached the tail | `notes/storms.md` (2026-09-06) | +| A storm can list more than a run can fetch: `ids_needing_detail` ranks by what a purge would take (listed Restored and still needing a fetch, then live never-fetched, then re-checks), every detail is committed as it lands, a run stops itself at `RUN_BUDGET_S` (22 min, four short of the backstop) and records `cut_short` (exit 0, heartbeat sent, no webhook), SIGTERM from the service unit's backstop ends the loop the same way, and the pause is 500 ms. In list order a cut-short run re-fetched the same head every run and never reached the tail | `notes/storms.md` (2026-09-06) | | The Pi pushes every six hours and `esb-data` dispatches the site build on each push; the two crons are a fallback only, because scheduled runs here have landed 4-10h behind their cron time. The stale banner trips at 10h - above the widest legitimate age (~7h), below a missed push (13h+) | `notes/publish-cadence.md`; `STALE_AFTER` in `esb_site/render.py` | | The banner states the data's *age* ("Updated 17 hours ago"), not its timestamp, and names no cause: from the browser a stalled build and a stalled collector look identical. A healthy overnight gap is a big number, so the warning, not the wording, carries it | `freshness()` in statusui's `ui.js`; `notes/publish-cadence.md` § The banner blamed the wrong half | | The exact horizon left the footer (owner call, 2026-08-26) and then the county page's header (2026-08-28); it survives only as the age chip's hover title on the index. A county page's currency signal is the month table's `to 27 Aug` caveat | `notes/design-alignment.md` § The county page became an archive | diff --git a/README.md b/README.md index 7952745..f8bf3ba 100644 --- a/README.md +++ b/README.md @@ -32,7 +32,7 @@ change of outage type forces an immediate detail fetch however long that outage has been dormant. Only a quiet outage's descriptive fields are ever delayed. A storm can list more outages than one run can fetch. A run stops itself at -24 minutes, about 2,800 details, records itself as cut short, and the next run +22 minutes, about 2,550 details, records itself as cut short, and the next run fetches first whatever a purge would take: outages listed as restored that still need their detail, then live ones never seen, then re-checks. Every detail is committed as it lands, so even a run killed outright leaves the database diff --git a/esb_outages/alert.py b/esb_outages/alert.py index f9008d6..209b47e 100644 --- a/esb_outages/alert.py +++ b/esb_outages/alert.py @@ -36,6 +36,8 @@ BANNER_WIDTH = 78 +DELIVERY_TIMEOUT_S = 10 + # Discord rejects a message over 2,000 characters outright; ntfy allows 4,096. MAX_ALERT_CHARS = 1900 TRUNCATED = "\n[truncated; the full text is in the journal]" @@ -156,7 +158,7 @@ def _deliver(what: str, url: str, data: bytes | None = None, headers=None) -> bo try: # Built in here: a URL missing its scheme raises from the constructor. request = urllib.request.Request(url, data=data, headers=headers or {}) - urllib.request.urlopen(request, timeout=10).close() + urllib.request.urlopen(request, timeout=DELIVERY_TIMEOUT_S).close() return True except Exception as exc: print(f"warning: {what} failed: {_describe(exc)}", file=sys.stderr) diff --git a/esb_outages/poll.py b/esb_outages/poll.py index 3c51206..1cf0316 100644 --- a/esb_outages/poll.py +++ b/esb_outages/poll.py @@ -26,10 +26,9 @@ # Half a second is courtesy, not a limit ESB states. DEFAULT_DELAY_MS = 500 -# A run stops itself here, about 2,800 details at the pace above, and records -# what it left. systemd's TimeoutStartSec sits a minute beyond as a backstop, -# because a run systemd has to stop is a failed unit whatever it exits with. -RUN_BUDGET_S = 24 * 60 +# About 2,550 details at the pace above; the gap to the unit's TimeoutStartSec +# is set in notes/storms.md and held by tests/test_poll.py::TestTheBackstop. +RUN_BUDGET_S = 22 * 60 # The backup holds the lock for seconds while it commits; a poll holds it for # its whole run. Waiting this long tells the two apart, rather than skipping a diff --git a/notes/storms.md b/notes/storms.md index b65c698..0331416 100644 --- a/notes/storms.md +++ b/notes/storms.md @@ -54,7 +54,8 @@ Four things, one PR, because they are one fix. fetched, so the ranking has something to rank against. The raw log already carried the truth; this is about the next run not repeating the last one. - **The run stops itself, and SIGTERM stops the loop instead of the process.** - A run ends its fetching at `RUN_BUDGET_S`, 24 minutes, records itself with + A run ends its fetching at `RUN_BUDGET_S`, 24 minutes (22 since + 2026-09-24, below), records itself with status `cut_short` and exit 0, and `run_poll` sends the heartbeat as for any run that reached the feed. A storm long enough to stop every run is a collector working flat out, not a stopped one, and must not raise the @@ -127,3 +128,24 @@ start line was lost replays as a run with no list, started at the time its run id carries, so its observations keep their place. Two copies of the same line, from a merge without `sort -u` or a `compact` that crashed before removing what it had archived, are read once. + +## The budget leaves room for the last fetch - 2026-09-24 + +`RUN_BUDGET_S` was 24 minutes against a `TimeoutStartSec` of 25, but the +budget is checked only between fetches. After it come the slowest fetch, the +webhook for a partial or drifted run, and the heartbeat. Each request can +time out on connect to two addresses (IPv4 and IPv6) and then on the read, so +one fetch attempt can take three 15-second timeouts, three attempts plus about +five seconds of backoff come to 140 seconds, and the webhook and the ping add +30 each: 200 seconds past the budget. That is a storm with a degraded API, +exactly when runs reach the budget, and systemd would fail the unit and kill +the heartbeat mid-send. + +The budget is now 22 minutes and the backstop 26: 1,520 seconds at worst, +inside 1,560. The backstop cannot grow further, because the timer's three +minutes of jitter plus the backstop must end before the next trigger, 30 +minutes on. A poll also waits up to two minutes for the lock while the backup +commits, and the budget counts from the start, so that wait comes out of it +rather than pushing the end later. 22 minutes is about 2,550 details at 500 ms. +`TestTheBackstop` recomputes all of this from the client's, the alert's and +the poll's constants and the two unit files. diff --git a/scripts/systemd/esb-outages.service b/scripts/systemd/esb-outages.service index bbb1f2f..0d03c53 100644 --- a/scripts/systemd/esb-outages.service +++ b/scripts/systemd/esb-outages.service @@ -22,11 +22,9 @@ EnvironmentFile=-/etc/esb-outages.env WorkingDirectory=/opt/esb-outages ExecStart=/usr/bin/python3 -m esb_outages poll -# The collector stops itself at 24 minutes (poll.RUN_BUDGET_S) and records -# what a storm left for the next run. This is the backstop a minute beyond, -# and it is a failed unit if it ever fires; the collector catches the SIGTERM -# and still closes the run out (notes/storms.md). -TimeoutStartSec=1500 +# The backstop behind poll.RUN_BUDGET_S, and a failed unit if it ever fires +# (notes/storms.md). +TimeoutStartSec=1560 # It reads its own code and writes one state directory. Nothing else. NoNewPrivileges=true diff --git a/tests/test_poll.py b/tests/test_poll.py index edef57a..f7ccabf 100644 --- a/tests/test_poll.py +++ b/tests/test_poll.py @@ -4,6 +4,7 @@ import io import json import os +import re import signal import sqlite3 import tempfile @@ -14,9 +15,11 @@ from pathlib import Path from esb_outages import alert +from esb_outages import client as esb_client from esb_outages.client import ApiError, AuthError, NotFound, TransientError from esb_outages.poll import ( DEFAULT_DELAY_MS, + RUN_BUDGET_S, check_writable, poll_lock, run_check, @@ -26,6 +29,8 @@ from .helpers import FakeClient, detail, local_server, make_list, stop_server +REPO = Path(__file__).resolve().parent.parent + class PollTestCase(unittest.TestCase): def setUp(self): @@ -716,6 +721,33 @@ def test_the_unreachable_banner_does_not_promise_an_hourly_run(self): self.assertNotIn("hourly", alert.unreachable_banner("timeout")) +class TestTheBackstop(unittest.TestCase): + systemd = REPO / "scripts" / "systemd" + + def setting(self, unit, name): + [value] = re.findall(rf"^{name}=(\d+)$", (self.systemd / unit).read_text(), re.M) + return int(value) + + def test_the_slowest_end_of_a_run_is_before_systemd_stops_it(self): + # A request can time out connecting to two addresses, then reading. + def request(timeout): + return 3 * timeout + + attempts = esb_client.DEFAULT_RETRIES + backoff = sum(2**n + 1 for n in range(attempts - 1)) + fetch = attempts * request(esb_client.DEFAULT_TIMEOUT) + backoff + webhook_then_ping = 2 * request(alert.DELIVERY_TIMEOUT_S) + backstop = self.setting("esb-outages.service", "TimeoutStartSec") + self.assertLessEqual(RUN_BUDGET_S + fetch + webhook_then_ping, backstop) + + def test_a_stopped_run_is_over_before_the_next_trigger(self): + timer = (self.systemd / "esb-outages.timer").read_text() + self.assertIn("OnCalendar=*:0/30", timer) + jitter = self.setting("esb-outages.timer", "RandomizedDelaySec") + backstop = self.setting("esb-outages.service", "TimeoutStartSec") + self.assertLessEqual(jitter + backstop, 30 * 60) + + class TestTestAlert(PollTestCase): """`esb test-alert` is the proof both channels work, so each outcome must say what it found.""" From 1f5e8c8e618b3556cc5e8d4c034aca46b53bb012 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:36:59 +0000 Subject: [PATCH 10/18] Let rebuild and compact work beside a malformed database esb rebuild opened the store before rebuilding, and opening a malformed esb.db raises before rebuild() can delete it, so the command the crash alert names failed on exactly the database it exists to replace. compact opened it too, though it only touches raw/. Neither opens it now, and Store.open() keeps its connection only once the file has opened. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- esb_outages/__main__.py | 15 +++++++++------ esb_outages/store.py | 27 ++++++++++++++++----------- tests/test_rebuild.py | 37 +++++++++++++++++++++++++++++++++++++ 3 files changed, 62 insertions(+), 17 deletions(-) diff --git a/esb_outages/__main__.py b/esb_outages/__main__.py index 714433d..33141c4 100644 --- a/esb_outages/__main__.py +++ b/esb_outages/__main__.py @@ -3,6 +3,7 @@ from __future__ import annotations import argparse +import contextlib import os import sys from pathlib import Path @@ -104,7 +105,7 @@ def cmd_test_alert(args) -> int: return alert.EXIT_OK -def _held_by_poll() -> int: +def _lock_held() -> int: # Both delete files a poll writes to: esb.db and its journal, or the log. print( "the lock is held (by a poll, the backup, or esb rebuild or compact);" @@ -117,8 +118,10 @@ def _held_by_poll() -> int: def cmd_rebuild(args) -> int: with poll_lock(Path(args.data_dir)) as acquired: if not acquired: - return _held_by_poll() - with Store(args.data_dir) as store: + return _lock_held() + # Not opened first: a malformed esb.db fails the moment it is opened, + # and rebuild deletes it unread. + with contextlib.closing(Store(args.data_dir)) as store: result = store.rebuild(verbose=True) if result["runs"] == 0 and result["observations"] == 0: print("nothing to replay: no raw logs found", file=sys.stderr) @@ -128,9 +131,9 @@ def cmd_rebuild(args) -> int: def cmd_compact(args) -> int: with poll_lock(Path(args.data_dir)) as acquired: if not acquired: - return _held_by_poll() - with Store(args.data_dir) as store: - done = store.compact() + return _lock_held() + # Only raw/, so not opened: a malformed esb.db must not stop it. + done = Store(args.data_dir).compact() print(f"compacted {len(done)} file(s): {', '.join(done) or 'none'}") return alert.EXIT_OK diff --git a/esb_outages/store.py b/esb_outages/store.py index ec2098e..f9614f4 100644 --- a/esb_outages/store.py +++ b/esb_outages/store.py @@ -182,17 +182,22 @@ def __init__(self, data_dir: str | os.PathLike): def open(self) -> Store: self.raw_dir.mkdir(parents=True, exist_ok=True) - self._conn = sqlite3.connect(self.db_path) - self._conn.row_factory = sqlite3.Row - # WAL survives an abrupt NAS power cut far better than the default. - self._conn.execute("PRAGMA journal_mode=WAL") - self._conn.execute("PRAGMA synchronous=FULL") - self._conn.executescript(SCHEMA) - self._conn.execute( - "INSERT OR IGNORE INTO meta(key, value) VALUES ('schema_version', ?)", - (str(SCHEMA_VERSION),), - ) - self._conn.commit() + conn = sqlite3.connect(self.db_path) + try: + conn.row_factory = sqlite3.Row + # WAL survives an abrupt NAS power cut far better than the default. + conn.execute("PRAGMA journal_mode=WAL") + conn.execute("PRAGMA synchronous=FULL") + conn.executescript(SCHEMA) + conn.execute( + "INSERT OR IGNORE INTO meta(key, value) VALUES ('schema_version', ?)", + (str(SCHEMA_VERSION),), + ) + conn.commit() + except BaseException: + conn.close() + raise + self._conn = conn return self def close(self) -> None: diff --git a/tests/test_rebuild.py b/tests/test_rebuild.py index 07831ab..84f8139 100644 --- a/tests/test_rebuild.py +++ b/tests/test_rebuild.py @@ -5,7 +5,10 @@ dependent on state that only exists inside a database file. """ +import contextlib +import io import json +import sqlite3 import tempfile import unittest from pathlib import Path @@ -271,6 +274,40 @@ def runs(st): self.assertTrue({"cut_short", "partial", "auth_error"} <= statuses, statuses) self.assertEqual(before, after) + def test_rebuild_recovers_a_malformed_database(self): + from esb_outages.__main__ import main + + self.run_a_realistic_history() + with Store(self.data_dir) as st: + before = st.snapshot() + (self.data_dir / "esb.db").write_bytes(b"not a database" * 100) + with contextlib.redirect_stdout(io.StringIO()): + self.assertEqual(main(["--data-dir", str(self.data_dir), "rebuild"]), 0) + with Store(self.data_dir) as st: + self.assertEqual(st.snapshot(), before) + + def test_a_database_that_fails_to_open_leaves_the_store_closed(self): + (self.data_dir / "esb.db").write_bytes(b"not a database" * 100) + store = Store(self.data_dir) + with self.assertRaises(sqlite3.DatabaseError): + store.open() + self.assertRaises(RuntimeError, getattr, store, "conn") + + def test_compact_does_not_need_the_database(self): + from esb_outages.__main__ import main + + self.run_a_realistic_history() + old_month = self.data_dir / "raw" / "runs-2020-01.jsonl" + old_month.write_text('{"run_id": "x"}\n') + db = self.data_dir / "esb.db" + db.write_bytes(b"not a database" * 100) + out = io.StringIO() + with contextlib.redirect_stdout(out): + self.assertEqual(main(["--data-dir", str(self.data_dir), "compact"]), 0) + self.assertIn("runs-2020-01.jsonl.gz", out.getvalue()) + self.assertFalse(old_month.exists()) + self.assertEqual(db.read_bytes(), b"not a database" * 100) + def test_rebuild_and_compact_wait_for_a_running_poll(self): from esb_outages.__main__ import main from esb_outages.poll import poll_lock From b5099ca82311b5eb2101d9c1fd83a0e221ba79f6 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:09:32 +0000 Subject: [PATCH 11/18] Announce every backup failure, not only fetch, merge and push Under set -e a failed git add, commit or rev-parse exited before any notify: a .git/index.lock left by a power cut failed every later backup with no alert, and the heartbeat does not cover the backup, so the site's stale banner was the only sign. An EXIT trap now alerts on any failure nothing else reported. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- scripts/backup-to-git.sh | 7 +++++ tests/test_scripts.py | 66 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 73 insertions(+) create mode 100644 tests/test_scripts.py diff --git a/scripts/backup-to-git.sh b/scripts/backup-to-git.sh index 1252e86..d211975 100755 --- a/scripts/backup-to-git.sh +++ b/scripts/backup-to-git.sh @@ -15,7 +15,9 @@ set -eu DATA_DIR="${ESB_DATA_DIR:-/var/lib/esb-outages}" +notified="" notify() { + notified=1 printf '%s\n' "$1" >&2 if [ -n "${ESB_ALERT_WEBHOOK:-}" ]; then curl -fsS -m 10 -H "Title: ESB backup failure" \ @@ -23,6 +25,11 @@ notify() { fi } +# set -e stops the script at any other failed step (a stale .git/index.lock +# after a power cut, a full disk), which would otherwise exit unannounced. +trap 'rc=$?; [ "$rc" -eq 0 ] || [ -n "$notified" ] || notify "ESB backup: failed (exit $rc), so what is new may not be offsite. +See: journalctl -u esb-backup.service -n 20"' EXIT + cd "$DATA_DIR" || { notify "ESB backup: $DATA_DIR does not exist. Nothing is being backed up." exit 1 diff --git a/tests/test_scripts.py b/tests/test_scripts.py new file mode 100644 index 0000000..16ef6f7 --- /dev/null +++ b/tests/test_scripts.py @@ -0,0 +1,66 @@ +import os +import subprocess +import tempfile +import unittest +from pathlib import Path + +REPO = Path(__file__).resolve().parent.parent +BACKUP = REPO / "scripts" / "backup-to-git.sh" + + +def git(cwd, *args): + return subprocess.run( + ["git", *args], cwd=cwd, check=True, capture_output=True, text=True, env=GIT_ENV + ).stdout + + +GIT_ENV = { + **os.environ, + "GIT_CONFIG_GLOBAL": os.devnull, + "GIT_CONFIG_NOSYSTEM": "1", +} + + +class BackupTestCase(unittest.TestCase): + """backup-to-git.sh against a throwaway data repo and a bare origin.""" + + def setUp(self): + self._tmp = tempfile.TemporaryDirectory() + root = Path(self._tmp.name) + self.origin = root / "origin.git" + self.data = root / "data" + git(root, "init", "-q", "--bare", "-b", "main", str(self.origin)) + git(root, "init", "-q", "-b", "main", str(self.data)) + git(self.data, "remote", "add", "origin", str(self.origin)) + (self.data / "raw").mkdir() + (self.data / "raw" / "runs-2026-09.jsonl").write_text('{"run_id": "a"}\n') + + def tearDown(self): + self._tmp.cleanup() + + def backup(self, **env): + env = {**GIT_ENV, "ESB_DATA_DIR": str(self.data), **env} + env.pop("ESB_ALERT_WEBHOOK", None) + return subprocess.run( + ["sh", str(BACKUP)], env=env, capture_output=True, text=True, timeout=60 + ) + + def pushed(self): + return git(self.origin, "log", "--format=%s", "main").splitlines() + + +class TestBackup(BackupTestCase): + def test_a_clean_backup_pushes(self): + result = self.backup() + self.assertEqual(result.returncode, 0, result.stderr) + self.assertEqual(len(self.pushed()), 1) + + def test_a_stale_index_lock_is_announced(self): + (self.data / ".git" / "index.lock").touch() + result = self.backup() + self.assertNotEqual(result.returncode, 0) + self.assertIn("ESB backup: failed", result.stderr) + + +if __name__ == "__main__": + unittest.main() From cf60cc9291c3c8479f1a82724a856d8f780ed050 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:09:50 +0000 Subject: [PATCH 12/18] Keep the backup's git errors in variables, not fixed files in /tmp /tmp/esb-backup-*.err were fixed names in a shared /tmp: a leftover file the esb user could not write made the redirection fail, so git never ran and every slot alerted with an empty body. The output is captured instead, the merge's stdout with it (git prints CONFLICT lines there), and the unit gets its own /tmp as well. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- scripts/backup-to-git.sh | 14 +++++++------- scripts/systemd/esb-backup.service | 1 + tests/test_scripts.py | 12 ++++++++++++ 3 files changed, 20 insertions(+), 7 deletions(-) diff --git a/scripts/backup-to-git.sh b/scripts/backup-to-git.sh index d211975..2538427 100755 --- a/scripts/backup-to-git.sh +++ b/scripts/backup-to-git.sh @@ -65,22 +65,22 @@ fi # Pull in anything pushed to origin from elsewhere first, so a rejected # non-fast-forward push doesn't strand local commits until someone notices. branch="$(git rev-parse --abbrev-ref HEAD)" -if ! git fetch -q origin 2>/tmp/esb-backup-fetch.err; then +if ! err=$(git fetch -q origin 2>&1); then notify "ESB backup: git fetch failed, so it's unknown whether origin has commits this checkout lacks. Data is committed locally but not pushed. -$(cat /tmp/esb-backup-fetch.err)" +$err" exit 1 fi if git rev-parse --verify -q "origin/$branch" >/dev/null && - ! git -c user.name="esb-collector" -c user.email="esb-collector@localhost" \ - merge -q --no-edit "origin/$branch" 2>/tmp/esb-backup-merge.err; then + ! err=$(git -c user.name="esb-collector" -c user.email="esb-collector@localhost" \ + merge -q --no-edit "origin/$branch" 2>&1); then git merge --abort 2>/dev/null || true notify "ESB backup: origin has commits that conflict with $DATA_DIR. Resolve manually, then re-run this script. -$(cat /tmp/esb-backup-merge.err)" +$err" exit 1 fi @@ -88,12 +88,12 @@ fi # push may have failed and left commits sitting only on this disk; treating # "nothing to commit" as "nothing to do" would report success forever while the # data was never actually offsite. Pushing an up-to-date branch is a cheap no-op. -if ! git push -q origin HEAD 2>/tmp/esb-backup-push.err; then +if ! err=$(git push -q origin HEAD 2>&1); then notify "ESB backup: git push failed. The data is committed locally but is NOT offsite, so an SD card failure would still lose everything since the last successful push. -$(cat /tmp/esb-backup-push.err)" +$err" exit 1 fi diff --git a/scripts/systemd/esb-backup.service b/scripts/systemd/esb-backup.service index 69a57a6..1042e7d 100644 --- a/scripts/systemd/esb-backup.service +++ b/scripts/systemd/esb-backup.service @@ -19,6 +19,7 @@ Environment=ESB_DATA_DIR=/var/lib/esb-outages Environment="GIT_SSH_COMMAND=ssh -i /etc/esb-outages-deploy-key -o IdentitiesOnly=yes -o UserKnownHostsFile=/etc/esb-outages-known_hosts -o StrictHostKeyChecking=accept-new" EnvironmentFile=-/etc/esb-outages.env +PrivateTmp=true ExecStart=/opt/esb-outages/scripts/backup-to-git.sh [Install] diff --git a/tests/test_scripts.py b/tests/test_scripts.py index 16ef6f7..6ddbb7f 100644 --- a/tests/test_scripts.py +++ b/tests/test_scripts.py @@ -62,5 +62,17 @@ def test_a_stale_index_lock_is_announced(self): self.assertIn("ESB backup: failed", result.stderr) + def test_a_failed_fetch_carries_git_s_own_error(self): + git(self.data, "remote", "set-url", "origin", str(self.origin) + "-gone") + result = self.backup() + self.assertNotEqual(result.returncode, 0) + self.assertIn("git fetch failed", result.stderr) + self.assertIn("does not appear to be a git repository", result.stderr) + + def test_no_fixed_file_in_the_shared_tmp(self): + # A leftover file there that the esb user cannot write failed every backup. + self.assertNotIn("/tmp/", BACKUP.read_text()) + + if __name__ == "__main__": unittest.main() From 61a20614e39dc766d562f85db776ea058075d692 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:13:49 +0000 Subject: [PATCH 13/18] Take the poll lock while the backup commits and merges The backup ran git add and git merge on the live data directory, and its slots overlap storm runs, so a line the poll was still writing could be committed and published torn, and a merge could refuse over a file mid-write with a misleading conflict alert. It now fetches outside the lock, then adds, commits and merges under it, and pushes after. Every git run under the lock closes the descriptor, or a detached auto-gc would hold the lock and every poll meanwhile would skip. A push rejected after a long wait, by another host pushing meanwhile, gets one more fetch, commit and merge. The wait is 30 minutes, above a poll's backstop plus the 90-second stop timeout the poll unit now states. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- notes/storms.md | 4 +- scripts/backup-to-git.sh | 84 +++++++++++++------ scripts/systemd/esb-outages.service | 3 + tests/test_scripts.py | 125 +++++++++++++++++++++++++++- 4 files changed, 189 insertions(+), 27 deletions(-) diff --git a/notes/storms.md b/notes/storms.md index 0331416..3a54ef2 100644 --- a/notes/storms.md +++ b/notes/storms.md @@ -120,7 +120,9 @@ died before closing itself out (an uncaught exception, a full disk, a kill the SIGTERM handler never saw): a rebuild records it as `unfinished`, where the live database has no row for it at all, rather than as a clean `ok`. The newest such run reads `in_progress` instead, because the six-hourly backup -commits `raw/` without the poll lock and often catches a run mid-flight. +commits `raw/` without the poll lock and often catches a run mid-flight. (The +backup takes the poll lock since 2026-09-24, so a new snapshot no longer does; +the label stays for the ones already pushed.) The flag, not the date of the first end line, is what decides: a merged log from a host still on the old code, or a Pi that booted with a wrong clock, would otherwise relabel every older-style run after it. An end line whose diff --git a/scripts/backup-to-git.sh b/scripts/backup-to-git.sh index 2538427..742566b 100755 --- a/scripts/backup-to-git.sh +++ b/scripts/backup-to-git.sh @@ -53,48 +53,82 @@ if [ ! -f .gitignore ]; then printf 'esb.db\nesb.db-wal\nesb.db-shm\n.poll.lock\n.write-test\n' > .gitignore fi -git add -A .gitignore raw +branch="$(git symbolic-ref --short HEAD)" -if git diff --cached --quiet; then - echo "no new data to commit" -else - git -c user.name="esb-collector" -c user.email="esb-collector@localhost" \ - commit -q -m "Outage data through $(date -u '+%Y-%m-%dT%H:%M:%SZ')" -fi - -# Pull in anything pushed to origin from elsewhere first, so a rejected +# Pull in anything pushed to origin from elsewhere, so a rejected # non-fast-forward push doesn't strand local commits until someone notices. -branch="$(git rev-parse --abbrev-ref HEAD)" -if ! err=$(git fetch -q origin 2>&1); then - notify "ESB backup: git fetch failed, so it's unknown whether origin has -commits this checkout lacks. Data is committed locally but not pushed. +# Fetched outside the lock: a poll waits only two minutes for it. +fetch_origin() { + if ! err=$(git fetch -q origin 2>&1); then + notify "ESB backup: git fetch failed, so it's unknown whether origin has +commits this checkout lacks. Nothing was pushed: the data is on this disk but +not offsite. $err" - exit 1 -fi + exit 1 + fi +} + +# The poll appends to raw/ while it holds this lock, so under it a commit never +# carries a half-written line and the merge never meets a file mid-write. A +# poll holds it for up to its unit's 26-minute backstop. Every git run under it +# closes the descriptor, or a detached auto-gc would keep the lock afterwards. +lock() { + exec 9>>.poll.lock + if ! flock -w 1800 9; then + notify "ESB backup: the poll lock was held for 30 minutes, longer than +systemd lets a poll run, so a long esb rebuild or compact is the likelier +holder. Nothing was backed up this time." + exit 1 + fi +} -if git rev-parse --verify -q "origin/$branch" >/dev/null && - ! err=$(git -c user.name="esb-collector" -c user.email="esb-collector@localhost" \ - merge -q --no-edit "origin/$branch" 2>&1); then - git merge --abort 2>/dev/null || true - notify "ESB backup: origin has commits that conflict with $DATA_DIR. +# Committed again on a retry: a poll may have appended since the first time, +# and git refuses to merge over uncommitted changes to a file origin touched. +commit_and_merge() { + git add -A .gitignore raw 9>&- + if git diff --cached --quiet 9>&-; then + echo "no new data to commit" + else + git -c user.name="esb-collector" -c user.email="esb-collector@localhost" \ + commit -q -m "Outage data through $(date -u '+%Y-%m-%dT%H:%M:%SZ')" 9>&- + fi + if git rev-parse --verify -q "origin/$branch" >/dev/null 9>&- && + ! err=$(git -c user.name="esb-collector" -c user.email="esb-collector@localhost" \ + merge -q --no-edit "origin/$branch" 2>&1 9>&-); then + git merge --abort 2>/dev/null 9>&- || true + notify "ESB backup: origin has commits that conflict with $DATA_DIR. Resolve manually, then re-run this script. $err" - exit 1 -fi + exit 1 + fi +} + +fetch_origin +lock +commit_and_merge +exec 9>&- # Push unconditionally, even when there was nothing new to commit. A previous # push may have failed and left commits sitting only on this disk; treating # "nothing to commit" as "nothing to do" would report success forever while the # data was never actually offsite. Pushing an up-to-date branch is a cheap no-op. -if ! err=$(git push -q origin HEAD 2>&1); then - notify "ESB backup: git push failed. The data is committed locally but is +# The fetch can be half an hour old after a wait for the lock, so a push another +# host made meanwhile gets one more fetch and merge before it counts as failed. +if ! git push -q origin HEAD 2>/dev/null; then + fetch_origin + lock + commit_and_merge + exec 9>&- + if ! err=$(git push -q origin HEAD 2>&1); then + notify "ESB backup: git push failed. The data is committed locally but is NOT offsite, so an SD card failure would still lose everything since the last successful push. $err" - exit 1 + exit 1 + fi fi echo "backed up through $(date -u '+%Y-%m-%dT%H:%M:%SZ')" diff --git a/scripts/systemd/esb-outages.service b/scripts/systemd/esb-outages.service index 0d03c53..c5849fa 100644 --- a/scripts/systemd/esb-outages.service +++ b/scripts/systemd/esb-outages.service @@ -25,6 +25,9 @@ ExecStart=/usr/bin/python3 -m esb_outages poll # The backstop behind poll.RUN_BUDGET_S, and a failed unit if it ever fires # (notes/storms.md). TimeoutStartSec=1560 +# systemd's default, stated because the backup's wait for the lock counts on +# it: after the SIGTERM the collector closes its run out, holding the lock. +TimeoutStopSec=90 # It reads its own code and writes one state directory. Nothing else. NoNewPrivileges=true diff --git a/tests/test_scripts.py b/tests/test_scripts.py index 6ddbb7f..1a87301 100644 --- a/tests/test_scripts.py +++ b/tests/test_scripts.py @@ -1,9 +1,13 @@ import os +import re import subprocess import tempfile +import time import unittest from pathlib import Path +from esb_outages.poll import poll_lock + REPO = Path(__file__).resolve().parent.parent BACKUP = REPO / "scripts" / "backup-to-git.sh" @@ -46,7 +50,7 @@ def backup(self, **env): ) def pushed(self): - return git(self.origin, "log", "--format=%s", "main").splitlines() + return git(self.origin, "log", "--format=%s", "--all").splitlines() class TestBackup(BackupTestCase): @@ -55,6 +59,21 @@ def test_a_clean_backup_pushes(self): self.assertEqual(result.returncode, 0, result.stderr) self.assertEqual(len(self.pushed()), 1) + def test_commits_from_another_host_are_merged_before_the_push(self): + self.assertEqual(self.backup().returncode, 0) + other = self.data.parent / "other" + git(self.data.parent, "clone", "-q", str(self.origin), str(other)) + (other / "raw" / "runs-2026-09-pi2.jsonl").write_text('{"run_id": "b"}\n') + git(other, "add", "raw") + git(other, "-c", "user.name=t", "-c", "user.email=t@t", "commit", "-qm", "standby") + git(other, "push", "-q", "origin", "main") + (self.data / "raw" / "runs-2026-09.jsonl").write_text('{"run_id": "a"}\n{"run_id": "c"}\n') + result = self.backup() + self.assertEqual(result.returncode, 0, result.stderr) + tree = git(self.origin, "ls-tree", "--name-only", "main", "raw/") + self.assertIn("runs-2026-09-pi2.jsonl", tree) + self.assertIn('"c"', git(self.origin, "show", "main:raw/runs-2026-09.jsonl")) + def test_a_stale_index_lock_is_announced(self): (self.data / ".git" / "index.lock").touch() result = self.backup() @@ -74,5 +93,109 @@ def test_no_fixed_file_in_the_shared_tmp(self): self.assertNotIn("/tmp/", BACKUP.read_text()) + def test_it_waits_for_a_poll_to_finish_writing(self): + env = {**GIT_ENV, "ESB_DATA_DIR": str(self.data)} + env.pop("ESB_ALERT_WEBHOOK", None) + with poll_lock(self.data) as acquired: + self.assertTrue(acquired) + proc = subprocess.Popen( + ["sh", str(BACKUP)], env=env, stdout=subprocess.PIPE, + stderr=subprocess.PIPE, text=True, + ) + time.sleep(2) + waiting, pushed_early = proc.poll() is None, self.pushed() + _, err = proc.communicate(timeout=60) + self.assertTrue(waiting, "finished while a poll held the lock") + self.assertEqual(pushed_early, []) + self.assertEqual(proc.returncode, 0, err) + self.assertEqual(len(self.pushed()), 1) + + def test_a_push_from_another_host_during_the_wait_is_merged(self): + self.assertEqual(self.backup().returncode, 0) + other = self.data.parent / "other" + git(self.data.parent, "clone", "-q", str(self.origin), str(other)) + # Something new to commit, so the retry's merge is a merge commit. + with (self.data / "raw" / "runs-2026-09.jsonl").open("a") as log: + log.write('{"run_id": "c"}\n') + fetched = self.data / ".git" / "FETCH_HEAD" + before = fetched.stat().st_mtime_ns + env = {**GIT_ENV, "ESB_DATA_DIR": str(self.data)} + env.pop("ESB_ALERT_WEBHOOK", None) + with poll_lock(self.data): + proc = subprocess.Popen( + ["sh", str(BACKUP)], env=env, stdout=subprocess.PIPE, + stderr=subprocess.PIPE, text=True, + ) + deadline = time.monotonic() + 30 + while fetched.stat().st_mtime_ns == before: + if time.monotonic() > deadline: + proc.kill() + proc.communicate() + self.fail("the backup never fetched") + time.sleep(0.05) + time.sleep(0.5) # the fetch has written FETCH_HEAD; let it exit + (other / "raw" / "runs-2026-09-pi2.jsonl").write_text('{"run_id": "b"}\n') + git(other, "add", "raw") + git(other, "-c", "user.name=t", "-c", "user.email=t@t", "commit", "-qm", "standby") + git(other, "push", "-q", "origin", "main") + _, err = proc.communicate(timeout=60) + self.assertEqual(proc.returncode, 0, err) + # Only the retry could have merged: the first fetch predates the push. + self.assertTrue(git(self.data, "log", "--merges", "--format=%H").strip()) + tree = git(self.origin, "ls-tree", "--name-only", "main", "raw/") + self.assertIn("runs-2026-09-pi2.jsonl", tree) + self.assertIn('"c"', git(self.origin, "show", "main:raw/runs-2026-09.jsonl")) + + def test_a_retried_push_commits_what_a_poll_wrote_meanwhile(self): + # The first push fails, as it would against a newer origin; in between + # a poll appends to a file origin also changed, far enough apart for + # git to merge the two. + runs = self.data / "raw" / "runs-2026-09.jsonl" + runs.write_text("".join(f'{{"run_id": "{n}"}}\n' for n in "adefg")) + self.assertEqual(self.backup().returncode, 0) + other = self.data.parent / "other" + git(self.data.parent, "clone", "-q", str(self.origin), str(other)) + theirs = other / "raw" / "runs-2026-09.jsonl" + theirs.write_text(theirs.read_text().replace('"a"', '"b"')) + git(other, "-c", "user.name=t", "-c", "user.email=t@t", "commit", "-qam", "standby") + hook = self.data / ".git" / "hooks" / "pre-push" + hook.write_text( + "#!/bin/sh\n" + f'if [ ! -e "{self.data}/.pushed-once" ]; then\n' + f' touch "{self.data}/.pushed-once"\n' + f' git -C "{other}" push -q origin main\n' + f' printf "%s\\n" \'{{"run_id": "c"}}\' >> "{self.data}/raw/runs-2026-09.jsonl"\n' + " exit 1\n" + "fi\n" + ) + hook.chmod(0o755) + result = self.backup() + self.assertEqual(result.returncode, 0, result.stderr) + log = git(self.origin, "show", "main:raw/runs-2026-09.jsonl") + self.assertIn('"b"', log) + self.assertIn('"c"', log) + + def test_nothing_git_leaves_running_keeps_the_lock(self): + # As a detached auto-gc would: every poll meanwhile would skip its run. + hook = self.data / ".git" / "hooks" / "post-commit" + hook.write_text("#!/bin/sh\nsleep 10 >/dev/null 2>&1 &\n") + hook.chmod(0o755) + self.assertEqual(self.backup().returncode, 0) + with poll_lock(self.data) as acquired: + self.assertTrue(acquired) + + +class TestBackupUnit(unittest.TestCase): + def test_the_backup_outwaits_any_poll_systemd_allows(self): + poll = (REPO / "scripts" / "systemd" / "esb-outages.service").read_text() + [backstop] = re.findall(r"^TimeoutStartSec=(\d+)$", poll, re.M) + # After SIGTERM the poll closes its run out, still holding the lock. + [stop] = re.findall(r"^TimeoutStopSec=(\d+)$", poll, re.M) + self.assertNotRegex(poll, r"(?m)^TimeoutSec=") + [wait] = re.findall(r"flock -w (\d+)", BACKUP.read_text()) + # A poll holding it started before the wait did, so this is margin. + self.assertGreaterEqual(int(wait), int(backstop) + int(stop) + 120) + + if __name__ == "__main__": unittest.main() From 0c96288f494c7612b581144379308ac2c08c5078 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:14:11 +0000 Subject: [PATCH 14/18] Time out a stalled backup, and say so when it does The backup unit is a oneshot with no TimeoutStartSec, which means no timeout, and ssh had no ConnectTimeout or keepalive, so a stalled fetch or push held the unit and absorbed every later slot with no alert. The unit now allows two lock waits and four network steps, ssh gives up on a dead connection, and the script turns the SIGTERM into an exit so the failure trap announces it. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- scripts/backup-to-git.sh | 7 ++++-- scripts/systemd/esb-backup.service | 7 +++++- tests/test_scripts.py | 40 +++++++++++++++++++++++++++--- 3 files changed, 48 insertions(+), 6 deletions(-) diff --git a/scripts/backup-to-git.sh b/scripts/backup-to-git.sh index 742566b..768b359 100755 --- a/scripts/backup-to-git.sh +++ b/scripts/backup-to-git.sh @@ -29,6 +29,8 @@ notify() { # after a power cut, a full disk), which would otherwise exit unannounced. trap 'rc=$?; [ "$rc" -eq 0 ] || [ -n "$notified" ] || notify "ESB backup: failed (exit $rc), so what is new may not be offsite. See: journalctl -u esb-backup.service -n 20"' EXIT +# The unit's timeout sends SIGTERM, which would otherwise skip the trap above. +trap 'exit 143' TERM cd "$DATA_DIR" || { notify "ESB backup: $DATA_DIR does not exist. Nothing is being backed up." @@ -71,8 +73,9 @@ $err" # The poll appends to raw/ while it holds this lock, so under it a commit never # carries a half-written line and the merge never meets a file mid-write. A -# poll holds it for up to its unit's 26-minute backstop. Every git run under it -# closes the descriptor, or a detached auto-gc would keep the lock afterwards. +# poll holds it for up to its unit's backstop plus its stop timeout, 27.5 +# minutes. Every git run under it closes the descriptor, or a detached auto-gc +# would keep the lock afterwards. lock() { exec 9>>.poll.lock if ! flock -w 1800 9; then diff --git a/scripts/systemd/esb-backup.service b/scripts/systemd/esb-backup.service index 1042e7d..0f9b420 100644 --- a/scripts/systemd/esb-backup.service +++ b/scripts/systemd/esb-backup.service @@ -16,11 +16,16 @@ Environment=ESB_DATA_DIR=/var/lib/esb-outages # inside the tree being backed up. # Quoted: systemd splits an unquoted Environment= value on whitespace into # separate assignments, which would set GIT_SSH_COMMAND to just "ssh". -Environment="GIT_SSH_COMMAND=ssh -i /etc/esb-outages-deploy-key -o IdentitiesOnly=yes -o UserKnownHostsFile=/etc/esb-outages-known_hosts -o StrictHostKeyChecking=accept-new" +Environment="GIT_SSH_COMMAND=ssh -i /etc/esb-outages-deploy-key -o IdentitiesOnly=yes -o UserKnownHostsFile=/etc/esb-outages-known_hosts -o StrictHostKeyChecking=accept-new -o ConnectTimeout=30 -o ServerAliveInterval=30 -o ServerAliveCountMax=4" EnvironmentFile=-/etc/esb-outages.env PrivateTmp=true ExecStart=/opt/esb-outages/scripts/backup-to-git.sh +# A oneshot has no start timeout by default, so a stalled push would hold the +# unit, and every later slot with it, silently. Room for two of the script's +# waits for the poll lock (a push retry takes it again) and four network steps. +TimeoutStartSec=4800 + [Install] WantedBy=multi-user.target diff --git a/tests/test_scripts.py b/tests/test_scripts.py index 1a87301..13735c2 100644 --- a/tests/test_scripts.py +++ b/tests/test_scripts.py @@ -1,5 +1,6 @@ import os import re +import signal import subprocess import tempfile import time @@ -80,7 +81,6 @@ def test_a_stale_index_lock_is_announced(self): self.assertNotEqual(result.returncode, 0) self.assertIn("ESB backup: failed", result.stderr) - def test_a_failed_fetch_carries_git_s_own_error(self): git(self.data, "remote", "set-url", "origin", str(self.origin) + "-gone") result = self.backup() @@ -92,7 +92,6 @@ def test_no_fixed_file_in_the_shared_tmp(self): # A leftover file there that the esb user cannot write failed every backup. self.assertNotIn("/tmp/", BACKUP.read_text()) - def test_it_waits_for_a_poll_to_finish_writing(self): env = {**GIT_ENV, "ESB_DATA_DIR": str(self.data)} env.pop("ESB_ALERT_WEBHOOK", None) @@ -175,6 +174,23 @@ def test_a_retried_push_commits_what_a_poll_wrote_meanwhile(self): self.assertIn('"b"', log) self.assertIn('"c"', log) + def test_the_unit_s_timeout_is_announced(self): + env = {**GIT_ENV, "ESB_DATA_DIR": str(self.data)} + env.pop("ESB_ALERT_WEBHOOK", None) + with poll_lock(self.data): + proc = subprocess.Popen( + ["sh", str(BACKUP)], env=env, stdout=subprocess.PIPE, + stderr=subprocess.PIPE, text=True, start_new_session=True, + ) + time.sleep(1) + # systemd signals the unit's whole control group. + os.killpg(proc.pid, signal.SIGTERM) + _, err = proc.communicate(timeout=30) + self.assertNotEqual(proc.returncode, 0) + self.assertIn("ESB backup: failed", err) + # The timeout is as likely to land on a stalled push as before it. + self.assertNotIn("before the push", err) + def test_nothing_git_leaves_running_keeps_the_lock(self): # As a detached auto-gc would: every poll meanwhile would skip its run. hook = self.data / ".git" / "hooks" / "post-commit" @@ -184,8 +200,21 @@ def test_nothing_git_leaves_running_keeps_the_lock(self): with poll_lock(self.data) as acquired: self.assertTrue(acquired) - class TestBackupUnit(unittest.TestCase): + unit = (REPO / "scripts" / "systemd" / "esb-backup.service").read_text() + + def test_a_stalled_push_cannot_hold_the_unit_forever(self): + [timeout] = re.findall(r"^TimeoutStartSec=(\d+)$", self.unit, re.M) + [wait] = re.findall(r"flock -w (\d+)", BACKUP.read_text()) + [connect] = re.findall(r"ConnectTimeout=(\d+)", self.unit) + [alive] = re.findall(r"ServerAliveInterval=(\d+)", self.unit) + [count] = re.findall(r"ServerAliveCountMax=(\d+)", self.unit) + dead_connection = int(connect) + int(alive) * int(count) + # A push retry waits for the lock a second time, and fetches and pushes + # twice; the rest is local git. + needed = 2 * int(wait) + 4 * dead_connection + 300 + self.assertGreaterEqual(int(timeout), needed) + def test_the_backup_outwaits_any_poll_systemd_allows(self): poll = (REPO / "scripts" / "systemd" / "esb-outages.service").read_text() [backstop] = re.findall(r"^TimeoutStartSec=(\d+)$", poll, re.M) @@ -196,6 +225,11 @@ def test_the_backup_outwaits_any_poll_systemd_allows(self): # A poll holding it started before the wait did, so this is margin. self.assertGreaterEqual(int(wait), int(backstop) + int(stop) + 120) + def test_ssh_gives_up_on_a_dead_connection(self): + [ssh] = re.findall(r'GIT_SSH_COMMAND=([^"]*)"', self.unit) + self.assertIn("-o ConnectTimeout=", ssh) + self.assertIn("-o ServerAliveInterval=", ssh) + if __name__ == "__main__": unittest.main() From 90474cdb65f843d1d55da89fe146ee0f5751aa1f Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:15:07 +0000 Subject: [PATCH 15/18] Pass the wrapper's secrets to sudo in the environment, not as arguments The esb wrapper put ESB_ALERT_WEBHOOK, ESB_HEARTBEAT_URL and ESB_API_KEY on sudo's command line as env VAR=value, and sudo logs the whole command to the auth log, which the adm group reads; ps showed them too. They are now exported and passed with --preserve-env. ESB_POLL_DELAY_MS rides along, which the wrapper had not forwarded at all. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- scripts/esb-wrapper.sh | 12 +++++++----- tests/test_scripts.py | 39 +++++++++++++++++++++++++++++++++++++++ 2 files changed, 46 insertions(+), 5 deletions(-) diff --git a/scripts/esb-wrapper.sh b/scripts/esb-wrapper.sh index 069090f..c44d123 100755 --- a/scripts/esb-wrapper.sh +++ b/scripts/esb-wrapper.sh @@ -27,9 +27,11 @@ if [ "$(id -u)" -ne 0 ]; then exit 1 fi -exec sudo -u "$SERVICE_USER" env \ - ESB_DATA_DIR="$DATA_DIR" \ - ${ESB_ALERT_WEBHOOK:+ESB_ALERT_WEBHOOK="$ESB_ALERT_WEBHOOK"} \ - ${ESB_HEARTBEAT_URL:+ESB_HEARTBEAT_URL="$ESB_HEARTBEAT_URL"} \ - ${ESB_API_KEY:+ESB_API_KEY="$ESB_API_KEY"} \ +# In the environment, not as arguments: sudo logs its whole command line to +# the auth log, which the adm group can read, and ps shows it to everyone. +export ESB_DATA_DIR="$DATA_DIR" ESB_ALERT_WEBHOOK ESB_HEARTBEAT_URL ESB_API_KEY \ + ESB_POLL_DELAY_MS +exec sudo \ + --preserve-env=ESB_DATA_DIR,ESB_ALERT_WEBHOOK,ESB_HEARTBEAT_URL,ESB_API_KEY,ESB_POLL_DELAY_MS \ + -u "$SERVICE_USER" \ sh -c 'cd "$1" && shift && exec python3 -m esb_outages "$@"' _ "$PREFIX" "$@" diff --git a/tests/test_scripts.py b/tests/test_scripts.py index 13735c2..58faa4b 100644 --- a/tests/test_scripts.py +++ b/tests/test_scripts.py @@ -231,5 +231,44 @@ def test_ssh_gives_up_on_a_dead_connection(self): self.assertIn("-o ServerAliveInterval=", ssh) +class TestWrapper(unittest.TestCase): + """esb-wrapper.sh with stand-ins for id and sudo that record what sudo got.""" + + def setUp(self): + self._tmp = tempfile.TemporaryDirectory() + self.bin = Path(self._tmp.name) + (self.bin / "id").write_text("#!/bin/sh\necho 0\n") + (self.bin / "sudo").write_text( + '#!/bin/sh\nprintf "%s\\n" "$@" > "$RECORD.argv"\nenv > "$RECORD.env"\n' + ) + for name in ("id", "sudo"): + (self.bin / name).chmod(0o755) + + def tearDown(self): + self._tmp.cleanup() + + def test_secrets_reach_sudo_in_the_environment_not_its_command_line(self): + secrets = { + "ESB_ALERT_WEBHOOK": "https://ntfy.sh/secret-topic", + "ESB_HEARTBEAT_URL": "https://hc-ping.com/secret-uuid", + "ESB_API_KEY": "secret-key", + } + record = self.bin / "record" + env = {**os.environ, **secrets, "RECORD": str(record), + "PATH": f"{self.bin}:{os.environ['PATH']}"} + subprocess.run( + ["sh", str(REPO / "scripts" / "esb-wrapper.sh"), "stats"], + env=env, check=True, timeout=30, + ) + argv = Path(f"{record}.argv").read_text() + self.assertNotIn("secret", argv) + self.assertIn("stats", argv.splitlines()) + [preserved] = [a for a in argv.splitlines() if a.startswith("--preserve-env=")] + passed = Path(f"{record}.env").read_text().splitlines() + for name, value in secrets.items(): + self.assertIn(name, preserved) + self.assertIn(f"{name}={value}", passed) + + if __name__ == "__main__": unittest.main() From 4b2bb30f48156758569ac774ea64b3717410fc66 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:15:31 +0000 Subject: [PATCH 16/18] Gate the interpreter the service actually runs The installer checked whichever python3 sudo's PATH found first, and that puts /usr/local/bin ahead of /usr/bin, while the unit runs /usr/bin/python3. A Pi with a newer build in /usr/local and an older system Python passed the install and then failed every timer run at import, before alert could load. The installer and the wrapper now name /usr/bin/python3 as the unit does. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- scripts/esb-wrapper.sh | 2 +- scripts/install-native.sh | 9 ++++++--- tests/test_scripts.py | 11 +++++++++++ 3 files changed, 18 insertions(+), 4 deletions(-) diff --git a/scripts/esb-wrapper.sh b/scripts/esb-wrapper.sh index c44d123..e3058cb 100755 --- a/scripts/esb-wrapper.sh +++ b/scripts/esb-wrapper.sh @@ -34,4 +34,4 @@ export ESB_DATA_DIR="$DATA_DIR" ESB_ALERT_WEBHOOK ESB_HEARTBEAT_URL ESB_API_KEY exec sudo \ --preserve-env=ESB_DATA_DIR,ESB_ALERT_WEBHOOK,ESB_HEARTBEAT_URL,ESB_API_KEY,ESB_POLL_DELAY_MS \ -u "$SERVICE_USER" \ - sh -c 'cd "$1" && shift && exec python3 -m esb_outages "$@"' _ "$PREFIX" "$@" + sh -c 'cd "$1" && shift && exec /usr/bin/python3 -m esb_outages "$@"' _ "$PREFIX" "$@" diff --git a/scripts/install-native.sh b/scripts/install-native.sh index bfb5c12..c28ac3e 100755 --- a/scripts/install-native.sh +++ b/scripts/install-native.sh @@ -13,6 +13,9 @@ PREFIX="/opt/esb-outages" DATA_DIR="/var/lib/esb-outages" ENV_FILE="/etc/esb-outages.env" SERVICE_USER="esb" +# The interpreter the service unit and the esb wrapper run, by path: sudo's +# PATH puts /usr/local/bin first, where a newer build could pass this gate. +PYTHON="/usr/bin/python3" SRC=$(cd "$(dirname "$0")/.." && pwd) @@ -22,15 +25,15 @@ if [ "$(id -u)" -ne 0 ]; then fi # The collector is standard library only, so this is the entire dependency list. -if ! python3 -c 'import sys; sys.exit(0 if sys.version_info >= (3, 11) else 1)'; then - echo "python3 3.11 or newer is required; found $(python3 -V 2>&1)" >&2 +if ! "$PYTHON" -c 'import sys; sys.exit(0 if sys.version_info >= (3, 11) else 1)'; then + echo "$PYTHON 3.11 or newer is required; found $("$PYTHON" -V 2>&1)" >&2 exit 1 fi # Timezone data must be present or every timestamp fails to parse. Standard on # Raspberry Pi OS and Debian, but worth failing loudly rather than collecting # months of outages with null times. -if ! python3 -c 'from zoneinfo import ZoneInfo; ZoneInfo("Europe/Dublin")' 2>/dev/null; then +if ! "$PYTHON" -c 'from zoneinfo import ZoneInfo; ZoneInfo("Europe/Dublin")' 2>/dev/null; then echo "Europe/Dublin timezone unavailable. Install tzdata:" >&2 echo " sudo apt-get install -y tzdata" >&2 exit 1 diff --git a/tests/test_scripts.py b/tests/test_scripts.py index 58faa4b..3071b80 100644 --- a/tests/test_scripts.py +++ b/tests/test_scripts.py @@ -270,5 +270,16 @@ def test_secrets_reach_sudo_in_the_environment_not_its_command_line(self): self.assertIn(f"{name}={value}", passed) +class TestOneInterpreter(unittest.TestCase): + def test_the_installer_gates_the_python_the_service_and_wrapper_run(self): + scripts = REPO / "scripts" + unit = (scripts / "systemd" / "esb-outages.service").read_text() + [python] = re.findall(r"^ExecStart=(\S+) -m esb_outages", unit, re.M) + self.assertIn(f"exec {python} -m esb_outages", (scripts / "esb-wrapper.sh").read_text()) + installer = (scripts / "install-native.sh").read_text() + self.assertIn(f'PYTHON="{python}"', installer) + self.assertEqual(set(re.findall(r"(\S+) -c '", installer)), {'"$PYTHON"'}) + + if __name__ == "__main__": unittest.main() From 5993d10a663245c824a9aeeb2a7d4cee3f9b1584 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:16:11 +0000 Subject: [PATCH 17/18] Stop the install on an empty host key scan, and pin the key it seeds If ssh-keyscan failed at install (no network), || true left an empty /etc/esb-outages-known_hosts, and one missing ssh-keyscan left none. ssh cannot write to that root-owned file, so with accept-new every push logged a warning and took whatever key it was shown. The install now stops unless the scan returned keys, and the unit uses StrictHostKeyChecking=yes. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- scripts/install-native.sh | 23 +++++++++++++++-------- scripts/systemd/esb-backup.service | 2 +- tests/test_scripts.py | 9 +++++++++ 3 files changed, 25 insertions(+), 9 deletions(-) diff --git a/scripts/install-native.sh b/scripts/install-native.sh index c28ac3e..f03622c 100755 --- a/scripts/install-native.sh +++ b/scripts/install-native.sh @@ -57,16 +57,23 @@ chown -R "$SERVICE_USER:$SERVICE_USER" "$DATA_DIR" echo "installing the 'esb' command to /usr/local/bin" install -m 755 "$SRC/scripts/esb-wrapper.sh" /usr/local/bin/esb -# Pre-seed the host key for the backup push. The service user's HOME is the data -# directory, and relying on ssh writing a known_hosts file there on first -# connect is both untidy and a silent trust-on-first-use. Seeding it here makes -# the backup work on its first run instead of failing with "Host key -# verification failed". +# Seed the host key for the backup push once, here, and the unit pins it +# (StrictHostKeyChecking=yes), so a changed key fails the push. The service +# user's HOME is the data directory, which is no place for a known_hosts file. +# An empty file must stop the install: ssh cannot write to this one, so with +# nothing in it every push would take whatever key it was shown. KNOWN_HOSTS="/etc/esb-outages-known_hosts" -if [ ! -s "$KNOWN_HOSTS" ] && command -v ssh-keyscan >/dev/null 2>&1; then +if [ ! -s "$KNOWN_HOSTS" ]; then echo "seeding $KNOWN_HOSTS for github.com" - ssh-keyscan -t rsa,ecdsa,ed25519 github.com > "$KNOWN_HOSTS" 2>/dev/null || true - chmod 644 "$KNOWN_HOSTS" + if ! ssh-keyscan -t rsa,ecdsa,ed25519 github.com > "$KNOWN_HOSTS.new" 2>/dev/null || + [ ! -s "$KNOWN_HOSTS.new" ]; then + rm -f "$KNOWN_HOSTS.new" + echo "could not fetch github.com's host keys (is openssh-client installed," >&2 + echo "and the network up?). Re-run this script once it is." >&2 + exit 1 + fi + chmod 644 "$KNOWN_HOSTS.new" + mv "$KNOWN_HOSTS.new" "$KNOWN_HOSTS" fi if [ ! -f "$ENV_FILE" ]; then diff --git a/scripts/systemd/esb-backup.service b/scripts/systemd/esb-backup.service index 0f9b420..b77e95c 100644 --- a/scripts/systemd/esb-backup.service +++ b/scripts/systemd/esb-backup.service @@ -16,7 +16,7 @@ Environment=ESB_DATA_DIR=/var/lib/esb-outages # inside the tree being backed up. # Quoted: systemd splits an unquoted Environment= value on whitespace into # separate assignments, which would set GIT_SSH_COMMAND to just "ssh". -Environment="GIT_SSH_COMMAND=ssh -i /etc/esb-outages-deploy-key -o IdentitiesOnly=yes -o UserKnownHostsFile=/etc/esb-outages-known_hosts -o StrictHostKeyChecking=accept-new -o ConnectTimeout=30 -o ServerAliveInterval=30 -o ServerAliveCountMax=4" +Environment="GIT_SSH_COMMAND=ssh -i /etc/esb-outages-deploy-key -o IdentitiesOnly=yes -o UserKnownHostsFile=/etc/esb-outages-known_hosts -o StrictHostKeyChecking=yes -o ConnectTimeout=30 -o ServerAliveInterval=30 -o ServerAliveCountMax=4" EnvironmentFile=-/etc/esb-outages.env PrivateTmp=true diff --git a/tests/test_scripts.py b/tests/test_scripts.py index 3071b80..e7e95a8 100644 --- a/tests/test_scripts.py +++ b/tests/test_scripts.py @@ -230,6 +230,14 @@ def test_ssh_gives_up_on_a_dead_connection(self): self.assertIn("-o ConnectTimeout=", ssh) self.assertIn("-o ServerAliveInterval=", ssh) + def test_ssh_takes_only_the_seeded_host_key(self): + self.assertIn("-o StrictHostKeyChecking=yes", self.unit) + + def test_an_empty_host_key_scan_stops_the_install(self): + installer = (REPO / "scripts" / "install-native.sh").read_text() + self.assertNotRegex(installer, r'ssh-keyscan[^\n]*> "\$KNOWN_HOSTS"') + self.assertIn('[ ! -s "$KNOWN_HOSTS.new" ]', installer) + class TestWrapper(unittest.TestCase): """esb-wrapper.sh with stand-ins for id and sudo that record what sudo got.""" @@ -270,6 +278,7 @@ def test_secrets_reach_sudo_in_the_environment_not_its_command_line(self): self.assertIn(f"{name}={value}", passed) + class TestOneInterpreter(unittest.TestCase): def test_the_installer_gates_the_python_the_service_and_wrapper_run(self): scripts = REPO / "scripts" From 0fbc9cb111d4b71ca9029297c1a604d33911e974 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 24 Sep 2026 13:16:53 +0000 Subject: [PATCH 18/18] Document the backup setup where it is pointed to The backup script sent readers to a README walkthrough that an earlier trim removed, and its setup lines ran git init as root, which git then refuses as "dubious ownership" and the script reports as "no 'origin' remote". Nothing documented the deploy key's path or mode, and the installer's next steps never mentioned the backup timer, though its push is the only way the site updates. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT --- scripts/backup-to-git.sh | 15 +++++++++++---- scripts/install-native.sh | 5 ++++- tests/test_scripts.py | 16 ++++++++++++++++ 3 files changed, 31 insertions(+), 5 deletions(-) diff --git a/scripts/backup-to-git.sh b/scripts/backup-to-git.sh index 768b359..48bfa6d 100755 --- a/scripts/backup-to-git.sh +++ b/scripts/backup-to-git.sh @@ -2,10 +2,17 @@ # # Commit and push the raw logs to a git remote, as an offsite backup. # -# One-time setup (see README for the full walkthrough): -# cd /var/lib/esb-outages -# git init -b main -# git remote add origin git@github.com:/esb-data.git +# One-time setup. git runs as the service user, or the repository is root's +# and git refuses it as "dubious ownership" from then on: +# sudo -u esb git -C /var/lib/esb-outages init -b main +# sudo -u esb git -C /var/lib/esb-outages remote add origin git@github.com:/esb-data.git +# sudo ssh-keygen -t ed25519 -N "" -C esb-backup -f /etc/esb-outages-deploy-key +# sudo chown esb:esb /etc/esb-outages-deploy-key +# sudo chmod 600 /etc/esb-outages-deploy-key +# Add /etc/esb-outages-deploy-key.pub to the data repository as a deploy key +# with write access, then: +# sudo systemctl start esb-backup.service # the first push, now +# sudo systemctl enable --now esb-backup.timer # # Only raw/ is committed. esb.db is deliberately excluded: it is a binary that # rewrites wholesale every run, so git cannot delta it, and it is rebuildable diff --git a/scripts/install-native.sh b/scripts/install-native.sh index f03622c..2dc5333 100755 --- a/scripts/install-native.sh +++ b/scripts/install-native.sh @@ -115,8 +115,11 @@ echo " 2. Prove alerts work: sudo esb test-alert" echo " 3. Check the API key: sudo esb check" echo " 4. One run now: sudo systemctl start esb-outages.service" echo " 5. Enable the timer: sudo systemctl enable --now esb-outages.timer" +echo " 6. Back up and publish: the one-time setup at the top of" +echo " $PREFIX/scripts/backup-to-git.sh, then" +echo " sudo systemctl enable --now esb-backup.timer" echo echo "Day to day:" echo " sudo esb stats what has been collected" -echo " systemctl list-timers esb-outages.timer when it next runs" +echo " systemctl list-timers 'esb-*' when they next run" echo " journalctl -u esb-outages.service -n 20 what the last runs did" diff --git a/tests/test_scripts.py b/tests/test_scripts.py index e7e95a8..58ee2ef 100644 --- a/tests/test_scripts.py +++ b/tests/test_scripts.py @@ -279,6 +279,22 @@ def test_secrets_reach_sudo_in_the_environment_not_its_command_line(self): +class TestSetupDocs(unittest.TestCase): + def test_the_installer_says_to_enable_the_backup(self): + # The backup's push is the only way the site updates. + installer = (REPO / "scripts" / "install-native.sh").read_text() + self.assertIn("enable --now esb-backup.timer", installer) + + def test_the_backup_setup_runs_git_as_the_service_user(self): + header = BACKUP.read_text().split("set -eu")[0] + self.assertNotIn("README", header) + commands = [line for line in header.splitlines() if line.startswith("# ")] + for line in commands: + if "git " in line: + self.assertIn("sudo -u esb git", line) + self.assertTrue(any("git" in line for line in commands)) + + class TestOneInterpreter(unittest.TestCase): def test_the_installer_gates_the_python_the_service_and_wrapper_run(self): scripts = REPO / "scripts"