Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
107 changes: 59 additions & 48 deletions lift_status/alert.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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}",
"",
Expand All @@ -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:
Expand All @@ -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
18 changes: 9 additions & 9 deletions lift_status/poll.py
Original file line number Diff line number Diff line change
Expand Up @@ -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)

Expand All @@ -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)


Expand All @@ -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)

Expand Down
44 changes: 41 additions & 3 deletions notes/collector-review.md
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand All @@ -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.
16 changes: 13 additions & 3 deletions scripts/backup-to-git.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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."
Expand Down
60 changes: 51 additions & 9 deletions tests/test_alert.py
Original file line number Diff line number Diff line change
@@ -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.
"""
Expand Down Expand Up @@ -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))

Expand Down
Loading
Loading