diff --git a/CLAUDE.md b/CLAUDE.md index faca2f7..7c8a482 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -117,8 +117,8 @@ 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) | -| 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 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` (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 2464b85..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 @@ -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/__main__.py b/esb_outages/__main__.py index c26fc62..33141c4 100644 --- a/esb_outages/__main__.py +++ b/esb_outages/__main__.py @@ -3,13 +3,14 @@ from __future__ import annotations import argparse +import contextlib import os import sys from pathlib import Path 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") @@ -104,17 +105,23 @@ 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("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 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) @@ -124,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 @@ -143,8 +150,11 @@ 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, - help=f"pause between detail requests (env: ESB_POLL_DELAY_MS, default {DEFAULT_DELAY_MS})", + "--delay-ms", type=milliseconds, default=None, + 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/alert.py b/esb_outages/alert.py index 2281af9..209b47e 100644 --- a/esb_outages/alert.py +++ b/esb_outages/alert.py @@ -12,9 +12,11 @@ import json import os import sys +import urllib.error import urllib.request EXIT_OK = 0 +EXIT_CRASH = 1 EXIT_AUTH = 2 EXIT_UNREACHABLE = 3 EXIT_SCHEMA_DRIFT = 4 @@ -23,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", @@ -33,6 +36,12 @@ 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]" + def banner(title: str, lines: list[str]) -> str: # Fixed width: these end up in an email, and a long raw error message would @@ -71,7 +80,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.", "", @@ -100,13 +109,31 @@ 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:", 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}", + ], + ) + + +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}", ], ) @@ -125,29 +152,46 @@ 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: - urllib.request.urlopen(request, timeout=10).close() + # 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=DELIVERY_TIMEOUT_S).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") 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: 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 +204,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/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/esb_outages/poll.py b/esb_outages/poll.py index 6176a4f..1cf0316 100644 --- a/esb_outages/poll.py +++ b/esb_outages/poll.py @@ -11,7 +11,10 @@ import fcntl import os import signal +import sqlite3 +import sys import time +import traceback import uuid from pathlib import Path @@ -23,36 +26,47 @@ # 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 +# 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 -# 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 @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() @@ -71,32 +85,87 @@ 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 +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, 0 or more; 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. +_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, 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: - 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: 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, lock_wait_s) as acquired: + if not acquired: + 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, 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: + 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. @@ -127,14 +196,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/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/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/notes/storms.md b/notes/storms.md index b65c698..3a54ef2 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 @@ -119,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 @@ -127,3 +130,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/backup-to-git.sh b/scripts/backup-to-git.sh index 1252e86..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 @@ -15,7 +22,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 +32,13 @@ 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 +# 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." exit 1 @@ -46,48 +62,83 @@ 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 - -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 +branch="$(git symbolic-ref --short HEAD)" -# 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 ! git fetch -q origin 2>/tmp/esb-backup-fetch.err; 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 +} -$(cat /tmp/esb-backup-fetch.err)" - 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 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 + 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 && - ! 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 - 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. -$(cat /tmp/esb-backup-merge.err)" - exit 1 -fi +$err" + 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 ! git push -q origin HEAD 2>/tmp/esb-backup-push.err; 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. -$(cat /tmp/esb-backup-push.err)" - exit 1 +$err" + exit 1 + fi fi echo "backed up through $(date -u '+%Y-%m-%dT%H:%M:%SZ')" diff --git a/scripts/esb-wrapper.sh b/scripts/esb-wrapper.sh index 069090f..e3058cb 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"} \ - sh -c 'cd "$1" && shift && exec python3 -m esb_outages "$@"' _ "$PREFIX" "$@" +# 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 /usr/bin/python3 -m esb_outages "$@"' _ "$PREFIX" "$@" diff --git a/scripts/install-native.sh b/scripts/install-native.sh index bfb5c12..2dc5333 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 @@ -54,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 @@ -105,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/scripts/systemd/esb-backup.service b/scripts/systemd/esb-backup.service index 69a57a6..b77e95c 100644 --- a/scripts/systemd/esb-backup.service +++ b/scripts/systemd/esb-backup.service @@ -16,10 +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=yes -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/scripts/systemd/esb-outages.service b/scripts/systemd/esb-outages.service index bbb1f2f..c5849fa 100644 --- a/scripts/systemd/esb-outages.service +++ b/scripts/systemd/esb-outages.service @@ -22,11 +22,12 @@ 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 +# 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/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_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 889e364..f7ccabf 100644 --- a/tests/test_poll.py +++ b/tests/test_poll.py @@ -1,19 +1,36 @@ +import contextlib import copy +import errno +import io +import json import os +import re import signal import sqlite3 import tempfile +import threading import unittest import unittest.mock +import urllib.error 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 poll_lock, run_check, run_poll +from esb_outages.poll import ( + DEFAULT_DELAY_MS, + RUN_BUDGET_S, + 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 +REPO = Path(__file__).resolve().parent.parent + class PollTestCase(unittest.TestCase): def setUp(self): @@ -31,7 +48,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() @@ -218,19 +235,152 @@ 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()) +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 TestTheDelay(PollTestCase): + def poll_with_env(self, value): + os.environ["ESB_POLL_DELAY_MS"] = value + client = self.client_with("fault", "restored") + err = io.StringIO() + with contextlib.redirect_stderr(err): + code = run_poll(self.data_dir, client=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, 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") + 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: 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: @@ -385,6 +535,38 @@ 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_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")) @@ -400,6 +582,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,11 +638,40 @@ 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) 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(), []) @@ -447,6 +680,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) @@ -465,6 +711,96 @@ 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 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.""" + + 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) 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 diff --git a/tests/test_scripts.py b/tests/test_scripts.py new file mode 100644 index 0000000..58ee2ef --- /dev/null +++ b/tests/test_scripts.py @@ -0,0 +1,310 @@ +import os +import re +import signal +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" + + +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", "--all").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_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() + 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() + 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()) + + 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_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" + 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): + 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) + # 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) + + 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) + + 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.""" + + 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) + + + +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" + 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()