From 8df121128d3a989d76dd7338e4b95c29332aa37a Mon Sep 17 00:00:00 2001 From: Mike Preston Date: Sat, 29 Aug 2026 00:54:12 +0100 Subject: [PATCH 1/3] feat: report why a unit failed in its Slack alert `OnFailure=` only told the alert which unit failed. For the health check that is the least useful half of the story: every critical check exits 1, so a page read "orbit-data-check.service failed" whether the volume had filled up or CelesTrak had started refusing requests, and the actual cause stayed on the host until someone SSH'd in. The alert unit now passes systemd's own verdict ($MONITOR_SERVICE_RESULT and $MONITOR_EXIT_STATUS, which separate a critical check from an OOM kill or a timeout) and the journal of the invocation that failed. `alert-slack` reduces that journal to the records that explain the failure: error-level records first, unstructured output when the container never got far enough to log one, warnings only when nothing failed outright. The excerpt is scoped by _SYSTEMD_INVOCATION_ID rather than by unit, so the previous healthy run cannot leak into it, and it travels as a command argument because stdin belongs to the webhook credential. Everything in the capture path is tolerant of failure: a manager without $MONITOR_* or an unreadable journal costs detail, never the alert. The unit's command line is now exercised directly in the deployment tests, with podman and journalctl faked, because nothing else runs that shell line -- systemd specifiers, backticks, and a redirect -- until something has already gone wrong at 04:00. Co-Authored-By: Claude Opus 5 --- deploy/README.md | 30 ++++++ deploy/systemd/orbit-data-alert@.service | 25 ++++- src/orbit_data/alerts.py | 131 ++++++++++++++++++++--- src/orbit_data/cli.py | 15 ++- tests/test_alerts.py | 116 +++++++++++++++++++- tests/test_cli.py | 50 +++++++++ tests/test_deployment.py | 129 ++++++++++++++++++++++ 7 files changed, 480 insertions(+), 16 deletions(-) diff --git a/deploy/README.md b/deploy/README.md index 59ab627..0b8dd4b 100644 --- a/deploy/README.md +++ b/deploy/README.md @@ -235,6 +235,36 @@ duplicate pages, while a failed `orbit-data-alert@…` unit remains visible to the operator. If the credential is absent, the alert unit is skipped and the original failure remains in its journal. +It also reports why the unit failed. systemd's own verdict — +`$MONITOR_SERVICE_RESULT` and `$MONITOR_EXIT_STATUS`, which need systemd 251 or +newer — arrives as `Result: exit-code (status 1)`, separating a critical check +from an out-of-memory kill or a timeout. That is not enough on its own, because +every critical health check exits 1, so the alert unit also reads the journal of +the failed invocation and the container reduces it to the records that explain +the failure: + +``` +*Cause:* +health check check=gp:active severity=critical detail=41.2h old; last error: HTTP 503 +health check check=storage severity=critical detail=384 MiB free +``` + +Warnings are shown only when nothing failed at error level, and unstructured +output is used when the application never got far enough to log — an image pull +that cannot reach GHCR leaves only podman's own message, and that message is the +whole story. The excerpt is scoped to the one failed invocation rather than to +the unit, so the previous healthy run cannot leak into it, and it is passed to +the container as a command argument: it is the service's own log output, and the +credential keeps standard input to itself. On a manager without `$MONITOR_*` the +alert still delivers, with those fields omitted. + +The alert unit and the application image upgrade independently: the unit passes +arguments only a build carrying this change understands, and `--pull=never` +means it uses whatever `:latest` is already on the host. Installing the units +ahead of the image leaves `orbit-data-alert@…` failing visibly — with the +original failure still in its own journal — until the next `Pull=newer` start +refreshes the image. + Thresholds live in the optional `[health]` table of `/etc/orbit-data.toml` (18h/36h for GP, 36h/72h for the catalogue, 2 GiB/512 MiB free). The GP thresholds are looser than the 6-hour timer implies on purpose: `last_success` diff --git a/deploy/systemd/orbit-data-alert@.service b/deploy/systemd/orbit-data-alert@.service index 9270e0e..69ac30f 100644 --- a/deploy/systemd/orbit-data-alert@.service +++ b/deploy/systemd/orbit-data-alert@.service @@ -17,5 +17,28 @@ Type=oneshot # argument, or container mount. That keeps the webhook out of `podman inspect` # and lets the alert container stay unprivileged. LoadCredential=slack-webhook-url:/etc/orbit-data/credentials/slack-webhook-url -ExecStart=/bin/sh -ec 'exec /usr/bin/podman run --pull=never --rm --interactive --read-only --cap-drop=all --security-opt=no-new-privileges --pids-limit=64 --network=systemd-orbit-egress --user=10001:10001 ghcr.io/darkflib/orbit-data:latest alert-slack --unit "%i" --host "%H" --webhook-stdin < "$CREDENTIALS_DIRECTORY/slack-webhook-url"' +# `$MONITOR_*` is what systemd tells an `OnFailure=` unit about the failure it +# is reacting to (v251+): the result, the exit status, and the invocation of +# the run that failed. Instantiating this template per `%n` is what keeps them +# available — systemd omits them when one alert unit is triggered by several +# services at once, which a shared instance would be. +# +# `--result` alone cannot say *why* a check failed: every critical health check +# exits 1, so the alert would read "exit-code (status 1)" whether the volume +# filled up or CelesTrak went away. The journal of that one invocation carries +# the per-check records that answer it, and `alert-slack` reduces them to the +# failing lines. The excerpt is passed as an argument rather than on stdin, +# which the credential owns; it is this service's own log output, and anything +# genuinely secret must not be logged in the first place. +# +# 60 lines covers a whole health-check pass (one record per check, currently +# 18) with room for podman's pull progress ahead of it; the container keeps +# only the handful that explain the failure. +# +# Backticks, not `$(…)`: systemd expands `$` in command lines itself, so the +# `${MONITOR_*}` references resolve whichever layer gets to them first, while +# command substitution must reach `/bin/sh` untouched. Every failure here is +# tolerated — an alert that says less is worth far more than one that does not +# arrive because `journalctl` was unhappy. +ExecStart=/bin/sh -ec 'exec /usr/bin/podman run --pull=never --rm --interactive --read-only --cap-drop=all --security-opt=no-new-privileges --pids-limit=64 --network=systemd-orbit-egress --user=10001:10001 ghcr.io/darkflib/orbit-data:latest alert-slack --unit "%i" --host "%H" --result "${MONITOR_SERVICE_RESULT}" --exit-status "${MONITOR_EXIT_STATUS}" --cause "`journalctl --quiet --no-pager --output=cat --lines=60 _SYSTEMD_INVOCATION_ID=${MONITOR_INVOCATION_ID} || true`" --webhook-stdin < "$CREDENTIALS_DIRECTORY/slack-webhook-url"' TimeoutStartSec=30s diff --git a/src/orbit_data/alerts.py b/src/orbit_data/alerts.py index 4dc4c75..267ef87 100644 --- a/src/orbit_data/alerts.py +++ b/src/orbit_data/alerts.py @@ -4,19 +4,32 @@ import logging import sys -from dataclasses import dataclass +from dataclasses import dataclass, field from datetime import UTC, datetime from pathlib import Path -from typing import TextIO +from typing import Any, TextIO from urllib.parse import urlsplit import httpx +import orjson LOGGER = logging.getLogger("orbit_data.alerts") _SLACK_WEBHOOK_HOSTS = {"hooks.slack.com", "hooks.slack-gov.com"} +# Slack accepts far more than this, but an alert is read on a phone. Eight +# lines is enough for every critical check in one pass and short enough that +# the unit, host, and result stay on the first screen. +_CAUSE_LINES = 8 +_CAUSE_LINE_CHARS = 200 +_FAILURE_LEVELS = {"error", "critical"} +# Rendered separately by `_describe_record`, or noise beside the unit and the +# alert's own timestamp. +_RENDERED_FIELDS = {"timestamp", "level", "logger", "message"} + +# Every field is one thing the notification has to carry to be actionable. +# pylint: disable=too-many-instance-attributes @dataclass(frozen=True, slots=True) class Alert: """The stable event shape used by the first alert delivery path.""" @@ -27,21 +40,85 @@ class Alert: unit: str host: str occurred_at: datetime + # systemd's own verdict, from $MONITOR_SERVICE_RESULT and + # $MONITOR_EXIT_STATUS. Empty when the manager did not supply it, which is + # the case on a manual `systemctl start orbit-data-alert@…` and on systemd + # older than v251. + result: str = "" + exit_status: str = "" + # Lines from the failed invocation's journal, already reduced by + # `summarize_journal`. + cause: tuple[str, ...] = field(default_factory=tuple) + + def outcome(self) -> str: + """How systemd decided the unit failed, in one phrase.""" + + if not self.result: + return "" + if self.exit_status: + return f"{self.result} (status {self.exit_status})" + return self.result def slack_text(self) -> str: """Render a compact, copyable alert for Slack.""" - return "\n".join( - ( - ":rotating_light: *Orbit Data alert*", - f"*Severity:* {self.severity.upper()}", - f"*Event:* `{_escape_slack(self.event)}`", - f"*Unit:* `{_escape_slack(self.unit)}`", - f"*Host:* `{_escape_slack(self.host)}`", - f"*Time:* {self.occurred_at.astimezone(UTC).isoformat()}", - f"Inspect with: `journalctl -u {_escape_slack(self.unit)} -n 100 --no-pager`", - ) - ) + lines = [ + ":rotating_light: *Orbit Data alert*", + f"*Severity:* {self.severity.upper()}", + f"*Event:* `{_escape_slack(self.event)}`", + f"*Unit:* `{_escape_slack(self.unit)}`", + f"*Host:* `{_escape_slack(self.host)}`", + ] + outcome = self.outcome() + if outcome: + lines.append(f"*Result:* `{_escape_slack(outcome)}`") + lines.append(f"*Time:* {self.occurred_at.astimezone(UTC).isoformat()}") + # The cause is what makes the alert actionable rather than merely + # timely: "exit-code (status 1)" is true of every failed check run, + # and only these lines say which check went critical. + if self.cause: + body = "\n".join(_escape_slack(line) for line in self.cause) + lines.append(f"*Cause:*\n```\n{body}\n```") + lines.append(f"Inspect with: `journalctl -u {_escape_slack(self.unit)} -n 100 --no-pager`") + return "\n".join(lines) + + +def summarize_journal(text: str, *, limit: int = _CAUSE_LINES) -> tuple[str, ...]: + """Reduce a failed unit's journal output to the lines that explain it. + + Every job here logs one JSON object per line, so a failing run is a few + error records among the routine ones — for the health check, exactly the + checks that reached critical. Those are preferred over everything else. + + Unstructured output is the fallback because it means the application never + got far enough to log: an image pull that could not reach GHCR leaves only + podman's own message, and that message is the whole story. It cannot be + preferred over the JSON records, because `Pull=newer` writes routine + progress lines to the same journal on every successful pull. + """ + + failures: list[str] = [] + unstructured: list[str] = [] + warnings: list[str] = [] + routine: list[str] = [] + for raw in text.splitlines(): + line = raw.strip() + if not line: + continue + document = _json_object(line) + if document is None: + unstructured.append(_clip(line)) + continue + level = str(document.get("level", "")).lower() + rendered = _describe_record(document) + if level in _FAILURE_LEVELS: + failures.append(rendered) + elif level == "warning": + warnings.append(rendered) + else: + routine.append(rendered) + selected = failures or unstructured or warnings or routine + return tuple(selected[-limit:]) def send_slack_alert( @@ -70,6 +147,7 @@ def send_slack_alert( "severity": alert.severity, "unit": alert.unit, "host": alert.host, + "result": alert.outcome(), }, ) @@ -127,6 +205,33 @@ def _safe_error_detail(exc: OSError | ValueError | httpx.HTTPError) -> str: return str(exc) +def _json_object(line: str) -> dict[str, Any] | None: + try: + document = orjson.loads(line) + except orjson.JSONDecodeError: + return None + return document if isinstance(document, dict) else None + + +def _describe_record(document: dict[str, Any]) -> str: + """Flatten one structured log record onto a single readable line. + + Deliberately generic rather than keyed on the health check's own field + names: the same alert path carries the GP and catalogue units, and a + renderer that only understands one job's fields silently drops the others. + """ + + message = str(document.get("message", "")).strip() + fields = " ".join( + f"{key}={value}" for key, value in document.items() if key not in _RENDERED_FIELDS + ) + return _clip(f"{message} {fields}".strip()) + + +def _clip(value: str, *, limit: int = _CAUSE_LINE_CHARS) -> str: + return value if len(value) <= limit else f"{value[: limit - 1]}…" + + def _escape_slack(value: str) -> str: """Keep systemd-derived text literal in Slack's mrkdwn rendering.""" diff --git a/src/orbit_data/cli.py b/src/orbit_data/cli.py index 219ffbe..eb9ee38 100644 --- a/src/orbit_data/cli.py +++ b/src/orbit_data/cli.py @@ -9,7 +9,7 @@ from pathlib import Path from orbit_data import __version__ -from orbit_data.alerts import Alert, cli_send_slack_alert +from orbit_data.alerts import Alert, cli_send_slack_alert, summarize_journal from orbit_data.catalog import CatalogUpdater from orbit_data.config import ConfigError, load_config from orbit_data.gp import GpUpdater @@ -38,6 +38,16 @@ def _parser() -> argparse.ArgumentParser: alert.add_argument("--severity", default="critical", choices=("warning", "critical")) alert.add_argument("--unit", required=True) alert.add_argument("--host", required=True) + # systemd hands the triggered unit $MONITOR_SERVICE_RESULT and + # $MONITOR_EXIT_STATUS; both are optional here so a hand-run alert, or one + # from a manager predating them, still delivers. + alert.add_argument("--result", default="", help="systemd result, e.g. exit-code or oom-kill") + alert.add_argument("--exit-status", default="", help="exit status or signal name") + alert.add_argument( + "--cause", + default="", + help="journal output from the failed invocation, summarized into the alert", + ) credential = alert.add_mutually_exclusive_group(required=True) credential.add_argument("--webhook-file", type=Path) credential.add_argument("--webhook-stdin", action="store_true") @@ -60,6 +70,9 @@ def run( # pylint: disable=too-many-return-statements unit=args.unit, host=args.host, occurred_at=datetime.now(tz=UTC), + result=args.result.strip(), + exit_status=args.exit_status.strip(), + cause=summarize_journal(args.cause), ), webhook_file=args.webhook_file, ) diff --git a/tests/test_alerts.py b/tests/test_alerts.py index c90b7c4..ba522ed 100644 --- a/tests/test_alerts.py +++ b/tests/test_alerts.py @@ -4,6 +4,7 @@ from __future__ import annotations +from dataclasses import replace from datetime import UTC, datetime from io import StringIO from pathlib import Path @@ -11,7 +12,13 @@ import httpx import pytest -from orbit_data.alerts import Alert, cli_send_slack_alert, read_webhook, send_slack_alert +from orbit_data.alerts import ( + Alert, + cli_send_slack_alert, + read_webhook, + send_slack_alert, + summarize_journal, +) def _alert() -> Alert: @@ -99,3 +106,110 @@ def failed_send(*_args: object, **_kwargs: object) -> None: assert cli_send_slack_alert(_alert(), webhook_file=credential) == 1 assert webhook not in caplog.text assert "Slack returned HTTP 500" in caplog.text + + +def _record(level: str, check: str, severity: str, detail: str) -> str: + return ( + f'{{"timestamp":"2026-08-15T12:00:00+00:00","level":"{level}","logger":"orbit_data",' + f'"message":"health check","check":"{check}","severity":"{severity}","detail":"{detail}"}}' + ) + + +def test_summarize_journal_keeps_only_the_records_that_failed_the_unit() -> None: + text = "\n".join( + ( + _record("info", "storage", "ok", "9000 MiB free"), + _record("warning", "gp-run", "warning", "daily byte budget spent"), + _record("error", "gp:active", "critical", "41.2h old; last error: HTTP 503"), + '{"level":"info","message":"health summary","severity":"critical"}', + ) + ) + + assert summarize_journal(text) == ( + "health check check=gp:active severity=critical detail=41.2h old; last error: HTTP 503", + ) + + +def test_summarize_journal_ignores_pull_progress_beside_a_structured_failure() -> None: + """`Pull=newer` writes progress lines on every run, failed or not.""" + + text = "\n".join( + ( + "Trying to pull ghcr.io/darkflib/orbit-data:latest...", + "Getting image source signatures", + _record("error", "public-tree", "critical", "manifest reports no records"), + ) + ) + + assert summarize_journal(text) == ( + "health check check=public-tree severity=critical detail=manifest reports no records", + ) + + +def test_summarize_journal_falls_back_to_output_from_a_container_that_never_ran() -> None: + """An unreachable registry leaves podman's message and nothing else.""" + + text = ( + "Trying to pull ghcr.io/darkflib/orbit-data:latest...\n" + "Error: initializing source docker://ghcr.io/...: reading manifest: connection refused\n" + ) + + assert summarize_journal(text) == ( + "Trying to pull ghcr.io/darkflib/orbit-data:latest...", + "Error: initializing source docker://ghcr.io/...: reading manifest: connection refused", + ) + + +def test_summarize_journal_reports_warnings_only_when_nothing_failed() -> None: + text = _record("warning", "gp-run", "warning", "daily byte budget spent") + + assert summarize_journal(text) == ( + "health check check=gp-run severity=warning detail=daily byte budget spent", + ) + + +def test_summarize_journal_keeps_the_last_lines_within_the_limit() -> None: + text = "\n".join(_record("error", f"gp:{index}", "critical", "stale") for index in range(12)) + + summary = summarize_journal(text, limit=3) + + assert len(summary) == 3 + assert summary[-1].startswith("health check check=gp:11") + + +def test_summarize_journal_of_empty_output_is_empty() -> None: + assert not summarize_journal("") + + +def test_slack_text_reports_the_systemd_result_and_the_failing_checks() -> None: + alert = replace( + _alert(), + unit="orbit-data-check.service", + result="exit-code", + exit_status="1", + cause=("health check check=gp:active severity=critical detail=41.2h old",), + ) + + text = alert.slack_text() + + assert "*Result:* `exit-code (status 1)`" in text + assert ( + "*Cause:*\n```\nhealth check check=gp:active severity=critical detail=41.2h old\n```" + ) in text + + +def test_slack_text_omits_a_cause_it_was_not_given() -> None: + text = _alert().slack_text() + + assert "*Cause:*" not in text + assert "*Result:*" not in text + + +def test_slack_text_keeps_journal_text_literal_in_slack_markup() -> None: + alert = replace(_alert(), cause=("cannot stat & retry",)) + + assert "cannot stat </srv/orbit-data> & retry" in alert.slack_text() + + +def test_result_without_an_exit_status_is_reported_alone() -> None: + assert replace(_alert(), result="oom-kill").outcome() == "oom-kill" diff --git a/tests/test_cli.py b/tests/test_cli.py index 3958324..dcddae3 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -52,6 +52,12 @@ def fake_send(*args: object, **kwargs: object) -> int: "orbit-data-gp.service", "--host", "example-host", + "--result", + "exit-code", + "--exit-status", + "1", + "--cause", + '{"level":"error","message":"GP update failed","error":"HTTP 503"}\n', "--webhook-file", str(webhook), ] @@ -68,9 +74,53 @@ def fake_send(*args: object, **kwargs: object) -> int: assert alert.severity == "critical" assert alert.unit == "orbit-data-gp.service" assert alert.host == "example-host" + assert alert.result == "exit-code" + assert alert.exit_status == "1" + assert alert.cause == ("GP update failed error=HTTP 503",) assert keywords == {"webhook_file": webhook} +def test_alert_slack_tolerates_a_manager_that_reported_no_cause( + tmp_path: Path, monkeypatch: Any +) -> None: + """systemd omits `$MONITOR_*` before v251, and on a hand-run alert.""" + + webhook = tmp_path / "slack-webhook" + webhook.write_text("https://hooks.slack.com/services/example", encoding="utf-8") + calls: list[Alert] = [] + + def fake_send(alert: Alert, **_keywords: object) -> int: + calls.append(alert) + return 0 + + monkeypatch.setattr("orbit_data.cli.cli_send_slack_alert", fake_send) + + assert ( + run( + [ + "--config", + str(tmp_path / "missing.toml"), + "alert-slack", + "--unit", + "orbit-data-check.service", + "--host", + "example-host", + "--result", + "", + "--exit-status", + "", + "--cause", + "", + "--webhook-file", + str(webhook), + ] + ) + == 0 + ) + assert calls[0].outcome() == "" + assert calls[0].cause == () + + def test_invalid_config_returns_two(tmp_path: Path) -> None: assert run(["--config", str(tmp_path / "missing"), "validate-config"]) == 2 diff --git a/tests/test_deployment.py b/tests/test_deployment.py index 4f7416f..2087be0 100644 --- a/tests/test_deployment.py +++ b/tests/test_deployment.py @@ -4,6 +4,7 @@ import configparser import os +import shlex import subprocess from pathlib import Path @@ -136,6 +137,134 @@ def test_alert_service_passes_the_slack_credential_only_on_standard_input() -> N assert ":/run/credentials" not in command +def test_alert_service_reports_why_the_unit_failed() -> None: + command = _unit("orbit-data-alert@.service", directory=SYSTEMD_UNITS)["Service"]["ExecStart"] + + # systemd's own verdict, which distinguishes a critical check from an + # out-of-memory kill or a timeout. + assert '--result "${MONITOR_SERVICE_RESULT}"' in command + assert '--exit-status "${MONITOR_EXIT_STATUS}"' in command + # Scoped to the invocation that failed: `--unit` would mix in lines from + # the previous, healthy run. + assert "_SYSTEMD_INVOCATION_ID=${MONITOR_INVOCATION_ID}" in command + assert "--lines=60" in command + # systemd expands `$` in command lines itself, so command substitution has + # to reach /bin/sh as backticks to survive. + assert "$(" not in command + # A journal that cannot be read costs detail, never the alert itself. + assert "|| true" in command + + +def test_alert_command_sends_the_failed_run_without_the_credential(tmp_path: Path) -> None: + """Run the unit's own command line, with podman and journalctl faked. + + The alert is a single shell line built out of systemd specifiers, systemd + variables, backticks, and a redirect, and nothing else in the deployment + exercises it until something has already gone wrong at 04:00. + """ + + record = ( + '{"level":"error","message":"health check","check":"gp:active",' + '"severity":"critical","detail":"41.2h old"}' + ) + binaries = tmp_path / "bin" + binaries.mkdir() + (binaries / "journalctl").write_text( + f"#!/bin/sh\ncase \"$*\" in\n *_SYSTEMD_INVOCATION_ID=inv-1*) echo '{record}' ;;\n" + " *) echo 'Failed to add match' >&2; exit 1 ;;\nesac\n", + encoding="utf-8", + ) + (binaries / "podman").write_text( + '#!/bin/sh\nfor argument in "$@"; do printf \'%s\\n\' "$argument"; done > "$ARGV_FILE"\n' + 'cat > "$STDIN_FILE"\n', + encoding="utf-8", + ) + for name in ("journalctl", "podman"): + (binaries / name).chmod(0o755) + credentials = tmp_path / "credentials" + credentials.mkdir() + (credentials / "slack-webhook-url").write_text( + "https://hooks.slack.com/services/example\n", encoding="utf-8" + ) + argv_file = tmp_path / "argv" + stdin_file = tmp_path / "stdin" + + command = _unit("orbit-data-alert@.service", directory=SYSTEMD_UNITS)["Service"]["ExecStart"] + interpreter, options, script = shlex.split(command) + # Stand in for the specifier expansion and absolute path the manager gives + # this line; everything else runs exactly as deployed. + script = ( + script.replace("%i", "orbit-data-check.service") + .replace("%H", "example-host") + .replace("/usr/bin/podman", str(binaries / "podman")) + ) + environment = { + "PATH": f"{binaries}:{os.environ['PATH']}", + "CREDENTIALS_DIRECTORY": str(credentials), + "MONITOR_SERVICE_RESULT": "exit-code", + "MONITOR_EXIT_STATUS": "1", + "MONITOR_INVOCATION_ID": "inv-1", + "ARGV_FILE": str(argv_file), + "STDIN_FILE": str(stdin_file), + } + subprocess.run([interpreter, options, script], check=True, env=environment, capture_output=True) + + argv = argv_file.read_text(encoding="utf-8").splitlines() + assert argv[argv.index("--unit") + 1] == "orbit-data-check.service" + assert argv[argv.index("--result") + 1] == "exit-code" + assert argv[argv.index("--exit-status") + 1] == "1" + assert argv[argv.index("--cause") + 1] == record + # The webhook reaches the container on stdin and nowhere else. + assert stdin_file.read_text(encoding="utf-8").strip() == ( + "https://hooks.slack.com/services/example" + ) + assert not [value for value in argv if "hooks.slack.com" in value or "credentials" in value] + + +def test_alert_command_still_delivers_when_no_cause_can_be_read(tmp_path: Path) -> None: + """An unreadable journal, or a manager with no `$MONITOR_*`, degrades quietly.""" + + binaries = tmp_path / "bin" + binaries.mkdir() + (binaries / "journalctl").write_text( + "#!/bin/sh\necho 'Failed to add match' >&2\nexit 1\n", encoding="utf-8" + ) + (binaries / "podman").write_text( + '#!/bin/sh\nfor argument in "$@"; do printf \'%s\\n\' "$argument"; done > "$ARGV_FILE"\n' + "cat > /dev/null\n", + encoding="utf-8", + ) + for name in ("journalctl", "podman"): + (binaries / name).chmod(0o755) + credentials = tmp_path / "credentials" + credentials.mkdir() + (credentials / "slack-webhook-url").write_text("https://example", encoding="utf-8") + argv_file = tmp_path / "argv" + + command = _unit("orbit-data-alert@.service", directory=SYSTEMD_UNITS)["Service"]["ExecStart"] + interpreter, options, script = shlex.split(command) + script = ( + script.replace("%i", "orbit-data-check.service") + .replace("%H", "example-host") + .replace("/usr/bin/podman", str(binaries / "podman")) + ) + result = subprocess.run( + [interpreter, options, script], + check=False, + env={ + "PATH": f"{binaries}:{os.environ['PATH']}", + "CREDENTIALS_DIRECTORY": str(credentials), + "ARGV_FILE": str(argv_file), + }, + capture_output=True, + ) + + assert result.returncode == 0 + argv = argv_file.read_text(encoding="utf-8").splitlines() + assert argv[argv.index("--cause") + 1] == "" + assert argv[argv.index("--result") + 1] == "" + + def test_web_mount_preserves_release_symlink_targets() -> None: container = _unit("orbit-data-web.container")["Container"] caddyfile = (ROOT / "deploy" / "Caddyfile").read_text(encoding="utf-8") From 9418165eaa2ebc17ded38d0d99a3b46f7569c17c Mon Sep 17 00:00:00 2001 From: Mike Preston Date: Sat, 29 Aug 2026 01:08:45 +0100 Subject: [PATCH 2/3] test: prove the credential stays off argv with a sentinel CodeQL read `"hooks.slack.com" in value` as an incomplete URL host check (py/incomplete-url-substring-sanitization, high). The assertion is the opposite of sanitization -- it proves the credential is absent from the command line -- but podman is faked in this test, so the value never has to look like a webhook at all. A sentinel says what the assertion means and leaves no hostname substring to misread. Co-Authored-By: Claude Opus 5 --- tests/test_deployment.py | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/tests/test_deployment.py b/tests/test_deployment.py index 2087be0..8c269a8 100644 --- a/tests/test_deployment.py +++ b/tests/test_deployment.py @@ -183,9 +183,11 @@ def test_alert_command_sends_the_failed_run_without_the_credential(tmp_path: Pat (binaries / name).chmod(0o755) credentials = tmp_path / "credentials" credentials.mkdir() - (credentials / "slack-webhook-url").write_text( - "https://hooks.slack.com/services/example\n", encoding="utf-8" - ) + # A sentinel rather than a webhook URL: podman is faked here, so the value + # never reaches Slack and only has to be distinctive enough to prove where + # the credential did and did not travel. + secret = "credential-value-that-must-not-reach-the-command-line" + (credentials / "slack-webhook-url").write_text(f"{secret}\n", encoding="utf-8") argv_file = tmp_path / "argv" stdin_file = tmp_path / "stdin" @@ -214,11 +216,9 @@ def test_alert_command_sends_the_failed_run_without_the_credential(tmp_path: Pat assert argv[argv.index("--result") + 1] == "exit-code" assert argv[argv.index("--exit-status") + 1] == "1" assert argv[argv.index("--cause") + 1] == record - # The webhook reaches the container on stdin and nowhere else. - assert stdin_file.read_text(encoding="utf-8").strip() == ( - "https://hooks.slack.com/services/example" - ) - assert not [value for value in argv if "hooks.slack.com" in value or "credentials" in value] + # The credential reaches the container on stdin and nowhere else. + assert stdin_file.read_text(encoding="utf-8").strip() == secret + assert not [value for value in argv if secret in value or "credentials" in value] def test_alert_command_still_delivers_when_no_cause_can_be_read(tmp_path: Path) -> None: From e2ad188cac01a49971488d91e1dd0a6da645d596 Mon Sep 17 00:00:00 2001 From: Mike Preston Date: Sat, 29 Aug 2026 01:12:42 +0100 Subject: [PATCH 3/3] fix: rank warnings above podman's preamble in an alert cause A GP dataset cut off at the daily byte budget counts as failed, so the unit exits non-zero, but it is logged at warning level (gp.py:217). On a `Pull=newer` start that also wrote pull progress into the same invocation, the previous ordering picked those progress lines and reported image-pull noise as the cause, hiding the warning that actually explained the failure. Raised in review on #36. Warnings now outrank unstructured output, and unstructured output is read by position instead: before the application's first record it is podman's preamble -- routine progress, or, when the pull never reached GHCR, the only thing left to report -- and after it, the application has stopped logging through its own logger, so a traceback or a runtime kill is treated like an error record rather than ranked below a stale warning. Also gives the sample block in the deployment notes a language (MD040). Co-Authored-By: Claude Opus 5 --- deploy/README.md | 24 +++++++++++++++--------- src/orbit_data/alerts.py | 33 +++++++++++++++++++++------------ tests/test_alerts.py | 37 +++++++++++++++++++++++++++++++++++++ 3 files changed, 73 insertions(+), 21 deletions(-) diff --git a/deploy/README.md b/deploy/README.md index 0b8dd4b..c8b865d 100644 --- a/deploy/README.md +++ b/deploy/README.md @@ -243,20 +243,26 @@ every critical health check exits 1, so the alert unit also reads the journal of the failed invocation and the container reduces it to the records that explain the failure: -``` +```text *Cause:* health check check=gp:active severity=critical detail=41.2h old; last error: HTTP 503 health check check=storage severity=critical detail=384 MiB free ``` -Warnings are shown only when nothing failed at error level, and unstructured -output is used when the application never got far enough to log — an image pull -that cannot reach GHCR leaves only podman's own message, and that message is the -whole story. The excerpt is scoped to the one failed invocation rather than to -the unit, so the previous healthy run cannot leak into it, and it is passed to -the container as a command argument: it is the service's own log output, and the -credential keeps standard input to itself. On a manager without `$MONITOR_*` the -alert still delivers, with those fields omitted. +Warnings come next, because a run can fail on warnings alone: a GP dataset cut +off at the daily byte budget counts as failed, and so exits the unit non-zero, +while logging at warning level. Unstructured output is read by position. Before +the application's first record it is podman's preamble, which on a `Pull=newer` +start is routine progress — unless the pull never reached GHCR, in which case +that message is the whole story and the only thing left to report. After the +first record it means the application stopped logging through its own logger, +so a traceback or a runtime kill is treated like an error record. + +The excerpt is scoped to the one failed invocation rather than to the unit, so +the previous healthy run cannot leak into it, and it is passed to the container +as a command argument: it is the service's own log output, and the credential +keeps standard input to itself. On a manager without `$MONITOR_*` the alert +still delivers, with those fields omitted. The alert unit and the application image upgrade independently: the unit passes arguments only a build carrying this change understands, and `--pull=never` diff --git a/src/orbit_data/alerts.py b/src/orbit_data/alerts.py index 267ef87..c25956b 100644 --- a/src/orbit_data/alerts.py +++ b/src/orbit_data/alerts.py @@ -86,29 +86,38 @@ def slack_text(self) -> str: def summarize_journal(text: str, *, limit: int = _CAUSE_LINES) -> tuple[str, ...]: """Reduce a failed unit's journal output to the lines that explain it. - Every job here logs one JSON object per line, so a failing run is a few - error records among the routine ones — for the health check, exactly the - checks that reached critical. Those are preferred over everything else. - - Unstructured output is the fallback because it means the application never - got far enough to log: an image pull that could not reach GHCR leaves only - podman's own message, and that message is the whole story. It cannot be - preferred over the JSON records, because `Pull=newer` writes routine - progress lines to the same journal on every successful pull. + Every job here logs one JSON object per line, so a failing run is usually a + few error records among the routine ones — for the health check, exactly + the checks that reached critical. + + Warnings come next, and they must outrank podman's own output rather than + the other way around: a GP dataset cut off at the daily byte budget counts + as failed, and so exits the unit non-zero, while logging at warning level. + A run that fails on warnings alone is not a hypothetical. + + What unstructured output means depends on where it falls. Before the + application's first record it is podman's preamble — pull progress on a + `Pull=newer` start, and, if the pull never reached GHCR, the message that + is then the whole story. After that first record the application has + stopped logging through its own logger, which means a traceback or a + runtime kill, and that explains the failure as surely as an error record + does. """ failures: list[str] = [] - unstructured: list[str] = [] warnings: list[str] = [] + preamble: list[str] = [] routine: list[str] = [] + logging_started = False for raw in text.splitlines(): line = raw.strip() if not line: continue document = _json_object(line) if document is None: - unstructured.append(_clip(line)) + (failures if logging_started else preamble).append(_clip(line)) continue + logging_started = True level = str(document.get("level", "")).lower() rendered = _describe_record(document) if level in _FAILURE_LEVELS: @@ -117,7 +126,7 @@ def summarize_journal(text: str, *, limit: int = _CAUSE_LINES) -> tuple[str, ... warnings.append(rendered) else: routine.append(rendered) - selected = failures or unstructured or warnings or routine + selected = failures or warnings or preamble or routine return tuple(selected[-limit:]) diff --git a/tests/test_alerts.py b/tests/test_alerts.py index ba522ed..39f01ed 100644 --- a/tests/test_alerts.py +++ b/tests/test_alerts.py @@ -160,6 +160,43 @@ def test_summarize_journal_falls_back_to_output_from_a_container_that_never_ran( ) +def test_summarize_journal_keeps_a_warning_that_pull_progress_would_have_buried() -> None: + """A GP dataset cut off at the byte budget fails the unit at warning level.""" + + text = "\n".join( + ( + "Trying to pull ghcr.io/darkflib/orbit-data:latest...", + "Getting image source signatures", + "Copying blob sha256:abc", + '{"level":"warning","message":"GP dataset aborted at the daily byte budget",' + '"dataset":"active","error":"daily byte budget exhausted after 104857600 bytes"}', + ) + ) + + assert summarize_journal(text) == ( + "GP dataset aborted at the daily byte budget dataset=active " + "error=daily byte budget exhausted after 104857600 bytes", + ) + + +def test_summarize_journal_treats_output_after_the_first_record_as_a_failure() -> None: + """Once the application has logged, unstructured output is it coming apart.""" + + text = "\n".join( + ( + "Trying to pull ghcr.io/darkflib/orbit-data:latest...", + '{"level":"info","message":"health check","check":"storage","severity":"ok"}', + "Traceback (most recent call last):", + "MemoryError", + ) + ) + + assert summarize_journal(text) == ( + "Traceback (most recent call last):", + "MemoryError", + ) + + def test_summarize_journal_reports_warnings_only_when_nothing_failed() -> None: text = _record("warning", "gp-run", "warning", "daily byte budget spent")