diff --git a/lift_status/alert.py b/lift_status/alert.py index b3f3fce..489c795 100644 --- a/lift_status/alert.py +++ b/lift_status/alert.py @@ -37,7 +37,7 @@ BANNER_WIDTH = 78 -# How long before an unchanged banner is worth pushing again. +# How long before the same kind of fault is worth pushing again. ALERT_REPEAT_SECONDS = 24 * 60 * 60 # Consecutive clean runs (two hours at the 30-minute cadence) before the same @@ -170,8 +170,8 @@ def database_banner(data_dir, detail: str) -> str: "This run's response WAS written to the raw log, so nothing has been", "lost yet, but the database is not being updated. By the error above:", "", - " 'locked': something else holds it, usually 'lift rebuild' or", - " 'lift stats'. It clears when that finishes.", + " 'locked': another process holds it. Find it with:", + f" sudo fuser -v {data_dir}/lift_status.db", "", f" 'full' or 'No space': the SD card is full. Check: df -h {data_dir}", "", @@ -188,82 +188,87 @@ def _marker_path() -> Path: return Path(state_dir) / ".last-alert.json" -def _digest(message: str) -> str: - return hashlib.sha256(message.encode("utf-8")).hexdigest() +def _key(kind: str) -> str: + return hashlib.sha256(kind.encode("utf-8")).hexdigest() -def _suppressed(message: str) -> bool: - """True if this exact banner was already *delivered* within the repeat window. +def _read_marker() -> dict: + """The marker as {"sent": {kind: sent_at}, "clean_runs": n}, or empty. - A stuck condition would otherwise push every 30 minutes until someone - patches the code, teaching the user to mute the topic. Best-effort: any - problem reading the marker means send. + Best-effort: a marker that is missing, unreadable, not an object or in an + older shape reads as empty, so the worst it can cause is an extra alert. """ try: state = json.loads(_marker_path().read_text(encoding="utf-8")) - sent_at = float(state.get("sent_at", 0)) - if state.get("digest") == _digest(message) and time.time() - sent_at < ALERT_REPEAT_SECONDS: - return True - except (OSError, ValueError, TypeError, AttributeError): - # AttributeError: the file parsed but is not an object (`null`, a list, - # a bare string), so .get is not there. Best-effort means send, not die - # here - notify()'s own guard starts after this call. - pass - return False - - -def _mark_delivered(message: str) -> None: + sent = {str(k): float(v) for k, v in state["sent"].items()} + return {"sent": sent, "clean_runs": int(state.get("clean_runs", 0))} + except (OSError, ValueError, TypeError, AttributeError, KeyError): + return {} + + +def _write_marker(state: dict) -> None: + with contextlib.suppress(OSError): + _marker_path().write_text(json.dumps(state), encoding="utf-8") + + +def _suppressed(kind: str) -> bool: + """True if this kind of fault was already *delivered* within the repeat window. + + A stuck condition would otherwise push every 30 minutes until someone + patches the code, teaching the user to mute the topic. Each kind has its + own window, so two faults at once do not take turns un-suppressing each + other. + """ + sent_at = _read_marker().get("sent", {}).get(_key(kind)) + return sent_at is not None and time.time() - sent_at < ALERT_REPEAT_SECONDS + + +def _mark_delivered(kind: str) -> None: """Start the repeat window, and only once the webhook has actually taken it. Writing this on the attempt instead silences the next 24 hours on a webhook blip, which lands hardest at the only moment that matters: the first alert of a collector that has stopped. """ - _write_marker({"digest": _digest(message), "sent_at": time.time(), "clean_runs": 0}) - - -def _write_marker(state: dict) -> None: - with contextlib.suppress(OSError): - _marker_path().write_text(json.dumps(state), encoding="utf-8") + state = _read_marker() + sent = {**state.get("sent", {}), _key(kind): time.time()} + _write_marker({"sent": sent, "clean_runs": state.get("clean_runs", 0)}) def _restart_recovery() -> None: - with contextlib.suppress(OSError, ValueError, TypeError, AttributeError): - state = json.loads(_marker_path().read_text(encoding="utf-8")) - if state.get("clean_runs"): - _write_marker({**state, "clean_runs": 0}) + state = _read_marker() + if state.get("clean_runs"): + _write_marker({**state, "clean_runs": 0}) def note_clean_run() -> None: """Close the repeat window once collection has stayed clean, so the same fault coming back later is a new incident rather than sitting out the day.""" path = _marker_path() - try: - state = json.loads(path.read_text(encoding="utf-8")) - clean_runs = int(state.get("clean_runs", 0)) + 1 - except FileNotFoundError: + if not path.exists(): return - except (OSError, ValueError, TypeError, AttributeError): - clean_runs = RECOVERED_AFTER_CLEAN_RUNS - if clean_runs >= RECOVERED_AFTER_CLEAN_RUNS: + state = _read_marker() + clean_runs = state.get("clean_runs", 0) + 1 + if not state or clean_runs >= RECOVERED_AFTER_CLEAN_RUNS: with contextlib.suppress(OSError): path.unlink(missing_ok=True) else: _write_marker({**state, "clean_runs": clean_runs}) -def notify(message: str, dedup: bool = True) -> bool: +def notify(message: str, dedup: bool = True, kind: str | None = None) -> bool: """Push to LIFT_STATUS_ALERT_WEBHOOK. Returns whether it was delivered. Best-effort by design: a webhook failure must never mask the underlying - problem or change the exit code. An unchanged banner is suppressed for - ALERT_REPEAT_SECONDS unless dedup=False (test-alert always sends). + problem or change the exit code. A fault of the same kind (the whole + message, unless one is given) is suppressed for ALERT_REPEAT_SECONDS + unless dedup=False (test-alert always sends). """ url = os.environ.get("LIFT_STATUS_ALERT_WEBHOOK") if not url: return False - if dedup and _suppressed(message): - _restart_recovery() + kind = message if kind is None else kind + if dedup and _suppressed(kind): return False try: if "ntfy" in url: @@ -274,15 +279,21 @@ def notify(message: str, dedup: bool = True) -> bool: req = urllib.request.Request(url, data=data, headers=headers, method="POST") urllib.request.urlopen(req, timeout=10).close() if dedup: - _mark_delivered(message) + _mark_delivered(kind) return True except Exception as exc: # pragma: no cover - never let alerting break the run print(f"warning: alert webhook failed: {exc}", file=sys.stderr) return False -def fail(message: str, code: int) -> int: - """Print a fatal banner to stderr, fire the optional webhook, return the code.""" +def fail(message: str, code: int, detail: str = "") -> int: + """Print a fatal banner to stderr, fire the optional webhook, return the code. + + The exit code is the kind of fault, not the banner's text, which carries a + raw error that differs between two failures of the same kind. `detail` + splits a kind where a difference is news, such as a second rejected key. + """ print(message, file=sys.stderr) - notify(message) + _restart_recovery() + notify(message, kind=f"exit {code} {detail}") return code diff --git a/lift_status/poll.py b/lift_status/poll.py index 9e81ff2..8634459 100644 --- a/lift_status/poll.py +++ b/lift_status/poll.py @@ -186,23 +186,21 @@ def _run(data_dir: Path, client: MessagesClient) -> int: problem = f"cannot append to the raw log: {exc}" return alert.fail(alert.storage_banner(data_dir, problem), alert.EXIT_STORAGE) + fetch_failure = classify_fetch_failure(http_status, body_text, network_error) try: with Store(data_dir) as store: result = apply_response( store, run_uuid, fetched_at, http_status, body_text, network_error ) except (sqlite3.Error, OSError) as exc: - fetch_failure = classify_fetch_failure(http_status, body_text, network_error) + # With nothing collected the fetch is the news; the database alerts on + # the first run that has a response to lose. if fetch_failure: - # Nothing was collected, so the fetch is the news; the database - # alerts on the first run that has a response to lose. return _fetch_failure_alert(client, *fetch_failure) return alert.fail(alert.database_banner(data_dir, repr(exc)), alert.EXIT_DATABASE) - if result.outcome in ("auth_error", "unreachable"): - return _fetch_failure_alert( - client, result.outcome, result.error_detail or "", result.exit_code - ) + if fetch_failure: + return _fetch_failure_alert(client, *fetch_failure) if result.outcome in ("parse_error", "not_a_list"): return alert.fail(alert.schema_root_banner(), result.exit_code) @@ -221,7 +219,8 @@ def _run(data_dir: Path, client: MessagesClient) -> int: def _fetch_failure_alert(client: MessagesClient, outcome, detail, exit_code) -> int: if outcome == "auth_error": - return alert.fail(alert.auth_banner(client.masked_key, detail), exit_code) + banner = alert.auth_banner(client.masked_key, detail) + return alert.fail(banner, exit_code, client.masked_key) return alert.fail(alert.unreachable_banner(detail), exit_code) @@ -237,7 +236,8 @@ def run_check(client: MessagesClient | None = None) -> int: try: items = client.get_messages() except AuthError as exc: - return alert.fail(alert.auth_banner(client.masked_key, str(exc)), alert.EXIT_AUTH) + banner = alert.auth_banner(client.masked_key, str(exc)) + return alert.fail(banner, alert.EXIT_AUTH, client.masked_key) except (TransientError, ApiError) as exc: return alert.fail(alert.unreachable_banner(str(exc)), alert.EXIT_UNREACHABLE) diff --git a/notes/collector-review.md b/notes/collector-review.md index e9566da..c55e938 100644 --- a/notes/collector-review.md +++ b/notes/collector-review.md @@ -58,9 +58,9 @@ Ten findings. Eight were fixed, one was not a real path, and one is left for now be stamped up to an hour before runs already in the same file, and a rebuild applies it before them where the live run applied it after. Line order only ever covered part of that, since a stamp that crosses midnight already lands - in the wrong day's file, and it cannot survive a merge at all. On 2026-09-24 all 2,224 real lines were already in - time order within their files, so no rebuild moved. The owner's call: - merging logs has to work. + in the wrong day's file, and it cannot survive a merge at all. On + 2026-09-24 all 2,224 real lines were already in time order within their + files, so no rebuild moved. The owner's call: merging logs has to work. ## Not a real path @@ -80,3 +80,41 @@ Ten findings. Eight were fixed, one was not a real path, and one is left for now to avoid. Left as it is by the owner on 2026-09-24. If it is taken up, the shape is a poll that checks whether the clock is synced and still writes the line, flagged, rather than one that waits or skips. + +## The review of the review - 2026-09-24 + +The commit that acted on the PR's review was merged without a review of its +own, and one found ten more. The root of three was the dedup marker: it held a +single digest of the whole banner, raw error included. The fixes were reviewed +in turn before they shipped, and that round changed the first of them. + +- **Two faults at once took turns to alert.** With the database broken and the + API flapping, the database and unreachable banners alternated, and each + change of digest was delivered. Each kind now has its own window. +- **The same fault with different words was never suppressed.** 'timed out' + then 'connection refused', or `lift check` wording the error with `str()` + where the poll uses `repr()`, hashed apart. The kind is now the exit code, + plus a detail where a difference is news: a rejected key carries the masked + key, so a second key rejected within the day is pushed. Keying on the + banner's title was tried first and rejected in review for exactly that: it + would have sat on a newly captured key that was also refused. Schema root + and schema drift share an exit code and so a window; the first push already + said the shape moved. +- **A failure that was not delivered did not break the clean stretch.** The + count was reset only when an alert was suppressed, so a fault lost to a + webhook blip counted as clean. `fail()` resets it on every failure. +- **The database banner blamed `lift rebuild` for a lock.** A rebuild holds the + poll lock, so a poll never sees its lock, and `lift stats` holds its read + lock for far less than the 5s busy timeout. It says to find the holder with + `fuser`. +- **The backup's TERM alert said nothing of the cause**, INT reported 143, and + a TERM landing on a curl mid-alert lost the alert. 143 now always alerts, + naming the timeout or a stop or shutdown; `on_exit` ignores TERM, which its + curl inherits, so the cgroup-wide TERM cannot kill it; INT is 130. +- Three copies of the marker read became `_read_marker`, and `_run` classifies + the fetch before opening the database rather than again inside the error + handler. A marker in the older shape reads as empty, so the first failure + after deploying can send one extra alert. + +The finding that replay order no longer reproduces a live run after a +fake-hwclock jump is the trade-off above, restated, and stands. diff --git a/scripts/backup-to-git.sh b/scripts/backup-to-git.sh index ea2125c..cbe31a7 100755 --- a/scripts/backup-to-git.sh +++ b/scripts/backup-to-git.sh @@ -29,7 +29,15 @@ notify() { # So a `set -e` abort anywhere below still alerts instead of failing silently. on_exit() { status=$? - if [ "$status" -ne 0 ] && [ "$notified" -eq 0 ]; then + # Ignored, not trapped, so the alert's curl inherits it and survives the + # TERM systemd sends to the whole cgroup. + trap '' TERM + if [ "$status" -eq 143 ]; then + notify "lift-status backup: stopped by SIGTERM before it finished: the +unit's 15-minute timeout if a git fetch or push hung, or a stop or shutdown +mid-backup. Nothing new may be offsite. Check: + journalctl -u lift-status-backup.service -n 30" + elif [ "$status" -ne 0 ] && [ "$notified" -eq 0 ]; then notify "lift-status backup: failed unexpectedly (exit $status) in $DATA_DIR. Nothing new is offsite. Check: journalctl -u lift-status-backup.service -n 30" @@ -38,8 +46,10 @@ Nothing new is offsite. Check: } trap on_exit EXIT # dash skips the EXIT trap on a signal it does not trap, and TERM is how the -# unit's TimeoutStartSec ends a stalled push. -trap 'exit 143' TERM INT +# unit's TimeoutStartSec ends a stalled push. It can also kill a curl that was +# mid-alert, which is why 143 always alerts rather than checking `notified`. +trap 'exit 143' TERM +trap 'exit 130' INT cd "$DATA_DIR" || { notify "lift-status backup: $DATA_DIR does not exist. Nothing is being backed up." diff --git a/tests/test_alert.py b/tests/test_alert.py index 54e93b9..152f6c9 100644 --- a/tests/test_alert.py +++ b/tests/test_alert.py @@ -1,7 +1,7 @@ """The repeat window, and the one thing it must not do: swallow a first alert. -An unchanged banner is suppressed for a day so a stuck condition does not push -every 30 minutes until the user mutes the topic. The window therefore has to +A fault of the same kind is suppressed for a day so a stuck condition does not +push every 30 minutes until the user mutes the topic. The window therefore has to open on delivery and not on the attempt, because the attempt most likely to fail is the first one after the collector stops. """ @@ -76,19 +76,61 @@ def test_a_recovery_that_holds_makes_the_same_fault_a_new_alert(self): self.assertFalse(alert._suppressed(BANNER)) def test_a_fault_flapping_between_clean_polls_stays_one_alert(self): - self._send() - for _ in range(3): - self._clean_runs(alert.RECOVERED_AFTER_CLEAN_RUNS - 1) - self.assertFalse(self._send()) + with mock.patch.object(urllib.request, "urlopen") as urlopen: + for _ in range(4): + alert.fail(alert.unreachable_banner("timed out"), alert.EXIT_UNREACHABLE) + self._clean_runs(alert.RECOVERED_AFTER_CLEAN_RUNS - 1) + self.assertEqual(urlopen.call_count, 1) - def test_a_different_banner_is_never_suppressed(self): + def test_a_failure_that_was_not_delivered_still_breaks_the_clean_stretch(self): self._send() - self.assertFalse(alert._suppressed("lift-status: the disk is full")) + self._clean_runs(alert.RECOVERED_AFTER_CLEAN_RUNS - 1) + with mock.patch.object(urllib.request, "urlopen", side_effect=OSError("blip")): + alert.fail("lift-status: the disk is full", alert.EXIT_STORAGE) + self._clean_runs(1) + self.assertTrue(alert._suppressed(BANNER)) + + def _fail(self, *banners_and_codes): + with mock.patch.object(urllib.request, "urlopen") as urlopen: + for args in banners_and_codes: + alert.fail(*args) + return urlopen.call_count + + def test_the_same_kind_of_fault_with_a_different_raw_error_is_one_alert(self): + delivered = self._fail( + (alert.unreachable_banner("TimeoutError('timed out')"), alert.EXIT_UNREACHABLE), + (alert.unreachable_banner("ConnectionRefusedError(111)"), alert.EXIT_UNREACHABLE), + ) + self.assertEqual(delivered, 1) + + def test_a_second_rejected_key_is_news(self): + delivered = self._fail( + (alert.auth_banner("abcdef...1234", "401"), alert.EXIT_AUTH, "abcdef...1234"), + (alert.auth_banner("abcdef...1234", "403"), alert.EXIT_AUTH, "abcdef...1234"), + (alert.auth_banner("ghijkl...5678", "401"), alert.EXIT_AUTH, "ghijkl...5678"), + ) + self.assertEqual(delivered, 2) + + def test_two_faults_at_once_do_not_take_turns_to_alert(self): + unreachable = (alert.unreachable_banner("timed out"), alert.EXIT_UNREACHABLE) + database = (alert.database_banner("/data", "malformed"), alert.EXIT_DATABASE) + self.assertEqual(self._fail(*[unreachable, database] * 4), 2) + + def test_an_older_marker_shape_means_send(self): + self.marker.write_text(json.dumps({"digest": "x", "sent_at": 1e12}), encoding="utf-8") + self.assertFalse(alert._suppressed(BANNER)) + + def test_a_different_kind_is_never_suppressed(self): + delivered = self._fail( + (alert.unreachable_banner("timed out"), alert.EXIT_UNREACHABLE), + (alert.storage_banner("/data", "No space left on device"), alert.EXIT_STORAGE), + ) + self.assertEqual(delivered, 2) def test_an_expired_window_sends_again(self): self._send() stale = json.loads(self.marker.read_text(encoding="utf-8")) - stale["sent_at"] -= alert.ALERT_REPEAT_SECONDS + 1 + stale["sent"] = {k: v - alert.ALERT_REPEAT_SECONDS - 1 for k, v in stale["sent"].items()} self.marker.write_text(json.dumps(stale), encoding="utf-8") self.assertFalse(alert._suppressed(BANNER)) diff --git a/tests/test_poll.py b/tests/test_poll.py index 2f3f79d..8bc04a9 100644 --- a/tests/test_poll.py +++ b/tests/test_poll.py @@ -221,16 +221,18 @@ def test_a_full_disk_at_the_append_is_a_storage_alert(self): class TestACleanRunClosesTheRepeatWindow(PollTestCase): - def test_clean_runs_clear_the_marker_and_a_failed_one_does_not(self): + def _clean(self, n): + for _ in range(n): + poll.run_poll(self.data_dir, client=FakeClient([(200, "[]")])) + + def test_consecutive_clean_runs_clear_the_marker_and_a_failed_one_restarts_them(self): marker = self.data_dir / ".last-alert.json" - marker.write_text("{}", encoding="utf-8") + marker.write_text(json.dumps({"sent": {"k": 1e12}, "clean_runs": 0}), encoding="utf-8") + self._clean(alert.RECOVERED_AFTER_CLEAN_RUNS - 1) poll.run_poll(self.data_dir, client=FakeClient([TransientError("down")])) + self._clean(alert.RECOVERED_AFTER_CLEAN_RUNS - 1) self.assertTrue(marker.exists()) - clean = [(200, "[]")] * alert.RECOVERED_AFTER_CLEAN_RUNS - for response in clean[:-1]: - poll.run_poll(self.data_dir, client=FakeClient([response])) - self.assertTrue(marker.exists()) - poll.run_poll(self.data_dir, client=FakeClient(clean[-1:])) + self._clean(1) self.assertFalse(marker.exists())