diff --git a/.gitignore b/.gitignore index 9355dcf..ad6e9e3 100644 --- a/.gitignore +++ b/.gitignore @@ -9,3 +9,4 @@ __pycache__/ # Runtime state .pending-deploys.json +.deploy-retries.json diff --git a/README.md b/README.md index 5c64e22..8392290 100644 --- a/README.md +++ b/README.md @@ -60,3 +60,89 @@ Edit `.env`: 2. Script fetches pending devices from Mender API 3. Filters by `node_id` prefix (if configured) 4. Accepts matching devices + + +## Failed-deployment retry + +Re-issues Mender deployments that failed **before the artifact reached the +node**, so an update lost to a broken download recovers without anyone +deploying it by hand. + +Hosted Mender has a "Retries" field on a deployment, but it is a paid-plan +feature: on the `os` plan, creating a deployment with one is rejected with +`403 Feature not available in your Plan.` The client's own retry does not cover +this either. It resumes a broken download, but once the CDN answers with an +unexpected HTTP status it treats that as fatal and fails the deployment with +most of its ten retries unused. + +### What it will and will not retry + +Only one failure is considered fixable: the artifact never finished arriving. +Nothing was written to the node and nothing about the node caused it, so an +identical request has an independent chance of succeeding. + +Everything else is refused, **including failures it cannot read**. The costs are +asymmetric: a missed retry costs one hand deployment, while a wrong retry +reboots a live node on a timer for a reason that will not change. So the test is +an allowlist and the default is to do nothing. + +| In the final attempt of the device log | Retried | +|---|---| +| `Unexpected status code while fetching artifact` | yes | +| `Giving up on resuming the download` | yes | +| `No space left on device`, too big, incompatible, bad signature | no | +| `Process returned non-zero exit status`, `ArtifactRollback` | no | +| Anything else, an unreadable log, no log at all | no | + +Two properties of Mender's device log make the naive version of this wrong, and +both were measured against real fleet logs: + +* **The log is cumulative across attempts.** One node's carries three attempts + at the same deployment, plus lines dated four months earlier from a clock + skew. Only the text after the final `Deployment with ID ... started` is + classified, so an old disk-full line cannot veto a retry forever, and an old + transport error cannot authorise one. +* **`Installing artifact...` does not mark the install phase.** It is printed + about a second after the deployment starts, before the download. On one node + it appears five hours before the download gives up. Phase cannot be inferred + from it. + +### Other limits + +* A retry is skipped while the device is already running a deployment, if the + artifact has landed since the failure, or if the device is no longer accepted. +* `DEPLOY_RETRY_MAX_ATTEMPTS` (2) per device+artifact, then it stops and leaves + it for a person. +* `DEPLOY_RETRY_MAX_PER_PASS` (5) caps one pass, so a fleet-wide outage cannot + become a fleet-wide burst. +* Attempt counts are written before the next deployment is created, and the pass + aborts up front if they cannot be written at all. Deployments that cannot be + counted are how a retry becomes a storm. + +### Install + +```bash +sudo cp systemd/retina-deploy-retry.* /etc/systemd/system/ +sudo systemctl daemon-reload +sudo systemctl enable --now retina-deploy-retry.timer +``` + +**The unit runs without `--apply`, so it creates nothing.** It reports a verdict +on every real failure and leaves them alone. That is deliberate: the create path +has never run against the fleet, and the classifier reads log wording that only +Mender controls, so the journal earns the trust first. + +```bash +journalctl -u retina-deploy-retry +``` + +If its verdicts match the calls you would have made, add `--apply` to +`ExecStart` and `systemctl daemon-reload`. Until then a failure it would have +retried still needs a deployment by hand. + +### Check what it would do, by hand + +```bash +cd ~/retina/node-infra/mender-auto-accept +MENDER_PAT=your-token .venv/bin/python deploy_retry.py +``` diff --git a/mender-auto-accept/.env.example b/mender-auto-accept/.env.example index c2b6f6e..f930b77 100644 --- a/mender-auto-accept/.env.example +++ b/mender-auto-accept/.env.example @@ -37,3 +37,29 @@ NODE_ID_PREFIX=ret # Where tunnel_sync records what it has provisioned (optional). # TUNNEL_STATE_FILE= + + +# --- Failed-deployment retry (deploy_retry.py) --- + +# Hosted Mender's own "Retries" field is a paid-plan feature and this tenant is +# on `os`, so a deployment created with one is rejected 403. These drive the +# replacement. Only downloads that never completed are retried; see the README. + +# How many times one device+artifact pair may be retried (optional, default 2). +# DEPLOY_RETRY_MAX_ATTEMPTS=2 + +# Ceiling on deployments one pass may create, so a fleet-wide outage cannot +# become a fleet-wide burst. The remainder is picked up next pass. +# DEPLOY_RETRY_MAX_PER_PASS=5 + +# Minimum wait between attempts on the same pair (optional, default 1800). +# DEPLOY_RETRY_BACKOFF_SECONDS=1800 + +# How far back to look for failures (optional, default 7 days). Also bounds how +# long an attempt count is remembered. +# DEPLOY_RETRY_WINDOW_DAYS=7 + +# Where attempt counts are recorded. Leave unset under systemd: the unit's +# StateDirectory= is picked up automatically. Set it only for a hand run that +# needs the counts somewhere specific. +# DEPLOY_RETRY_STATE_FILE= diff --git a/mender-auto-accept/deploy_retry.py b/mender-auto-accept/deploy_retry.py new file mode 100644 index 0000000..117ff8f --- /dev/null +++ b/mender-auto-accept/deploy_retry.py @@ -0,0 +1,466 @@ +#!/usr/bin/env python3 +"""Re-issue Mender deployments that failed before the artifact reached the node. + +Hosted Mender has a built-in "Retries" field on a deployment, but it is gated +behind a paid plan and this tenant is on `os`. Asking for it returns +403 "Feature not available in your Plan.", so the retry has to live out here. + +Why a fresh deployment rather than leaning on the client's own retry: the client +does resume a broken download, but only while the error looks like a broken +stream. Once the CDN answers with an unexpected HTTP status the client treats it +as fatal. That is how nightcrawler2 lost owl-os-pi5-v0.16.1 on 2026-09-03: two +truncated streams, then a resumed range request that R2 answered 400, and the +deployment was over three minutes after it began, with eight of its ten retries +unused. A new deployment starts the download from zero against a newly signed +URL, which is what the hand fix does. + + +WHAT COUNTS AS FIXABLE + +Only one thing: the artifact never finished arriving. Nothing was written to the +node, nothing about the node caused it, so an identical request has a genuinely +independent chance of succeeding. Everything else is refused, including failures +we cannot read, because the cost of being wrong is asymmetric. A missed retry +costs one hand deployment. A wrong retry reboots a live radar node on a timer, +repeatedly, for a reason that will not change. + +So the test is an allowlist, not a blocklist. A failure is retried only if the +log positively shows the fetch failing, with nothing to suggest the node's own +state was involved. Silence, a truncated log, an unfamiliar error and an API +error all fall through to "do not touch it". + +Two properties of Mender's device log make the naive version of this wrong, and +both were measured on real fleet logs rather than assumed: + + * The log is cumulative across attempts, not per attempt. nightcrawler1's + carries three attempts at the same deployment. Matching over the whole thing + would let a disk-full line from August veto a retry forever, and let an old + transport error authorise one. So only the final attempt is considered. + + * "Installing artifact..." is printed about a second after the deployment + starts, BEFORE the download, so it does not mark the install phase. Wilderness + A's disk-full log shows it one second in, hours before nightcrawler1's + download gave up. Phase cannot be inferred from it. + +Runs on a timer, reports by default, and only creates deployments with --apply, +matching tunnel_sync.py. + +Environment variables: + MENDER_PAT: Personal Access Token for Mender API (required) + MENDER_SERVER: Mender server URL (default: https://hosted.mender.io) + DEPLOY_RETRY_MAX_ATTEMPTS: Retries per device+artifact (default: 2) + DEPLOY_RETRY_MAX_PER_PASS: Deployments one pass may create (default: 5) + DEPLOY_RETRY_BACKOFF_SECONDS: Wait between attempts (default: 1800) + DEPLOY_RETRY_WINDOW_DAYS: How far back to consider failures (default: 7) + DEPLOY_RETRY_STATE_FILE: Where attempt counts are recorded +""" +import argparse +import json +import os +import re +import sys +import time +from datetime import datetime, timedelta, timezone + +import requests + +MENDER_SERVER = os.environ.get("MENDER_SERVER", "https://hosted.mender.io") +MENDER_PAT = os.environ.get("MENDER_PAT") +MAX_ATTEMPTS = int(os.environ.get("DEPLOY_RETRY_MAX_ATTEMPTS", "2")) +MAX_PER_PASS = int(os.environ.get("DEPLOY_RETRY_MAX_PER_PASS", "5")) +BACKOFF_SECONDS = int(os.environ.get("DEPLOY_RETRY_BACKOFF_SECONDS", "1800")) +WINDOW_DAYS = int(os.environ.get("DEPLOY_RETRY_WINDOW_DAYS", "7")) + +# systemd sets STATE_DIRECTORY from the unit's StateDirectory=. Preferring it +# means the packaged unit needs no path in its EnvironmentFile, and a hand run +# still works from the checkout. +_DEFAULT_STATE_DIR = os.environ.get("STATE_DIRECTORY") or os.path.dirname(os.path.abspath(__file__)) +STATE_FILE = os.environ.get("DEPLOY_RETRY_STATE_FILE", + os.path.join(_DEFAULT_STATE_DIR, ".deploy-retries.json")) +HEADERS = {"Authorization": f"Bearer {MENDER_PAT}"} if MENDER_PAT else {} + +# The per-device deployments endpoint rejects anything above 20 outright, with +# an error object rather than a list. Measured, not guessed. +PER_PAGE = 20 + +# A device is mid-update in any of these, so leave it alone rather than stacking +# a second deployment behind the one it is already working through. +ACTIVE_STATUSES = frozenset({ + "pending", "downloading", "installing", "rebooting", + "pause_before_installing", "pause_before_rebooting", "pause_before_committing", +}) + +# Reaching the artifact counts either way: "already-installed" is what Mender +# reports when the device turns out to have it, which is a recovery, not a miss. +LANDED_STATUSES = frozenset({"success", "already-installed"}) + +# Splits the cumulative device log into attempts. The client writes this line +# once per attempt, including repeats of the same deployment id. +ATTEMPT_START = re.compile(r"Deployment with ID \S+ started") + +# The artifact never finished arriving. These are the only failures retried, and +# both are Mender's own wording for giving up on the fetch itself. +FETCH_FAILED = [ + re.compile(r"Unexpected status code while fetching artifact", re.I), + re.compile(r"Giving up on resuming the download", re.I), +] + +# The node's own condition caused the failure and still holds, so an identical +# deployment fails identically. Overrides everything. +DEVICE_STATE = [ + (re.compile(r"No space left on device", re.I), "no disk space on the node"), + (re.compile(r"artifact_too_big|artifact is too big", re.I), "artifact too big for the device"), + (re.compile(r"not compatible with device", re.I), "artifact incompatible with the device"), + (re.compile(r"signature verification failed|invalid signature", re.I), "artifact signature rejected"), +] + +# An update module or state script ran and failed. The bytes arrived; what they +# did on the node is the problem, and repeating it repeats the problem. Vetoes a +# retry even alongside a fetch error, since a cancelled GET is a normal +# consequence of an install aborting. +PROCESS_FAILED = re.compile(r"Process returned non-zero exit status|ArtifactRollback", re.I) + + +def api(path: str, params: dict | None = None, version: str = "v1") -> list | dict | None: + """GET a management API path. Returns None rather than raising, so one bad + response cannot strand the rest of the pass. + + Deployments are v1 and devauth is v2, so the version is explicit. Defaulting + it silently would 404 every devauth call, which reads as "device is gone" + and skips the whole fleet. + """ + try: + resp = requests.get(f"{MENDER_SERVER}/api/management/{version}/{path}", headers=HEADERS, + params=params, timeout=30) + resp.raise_for_status() + return resp.json() + except (requests.RequestException, ValueError) as e: + print(f" API error on {path}: {e}", file=sys.stderr) + return None + + +def device_log(deployment_id: str, device_id: str) -> str | None: + """Fetch a device's log for one deployment. + + None means we could not read it, which is not the same as a log with nothing + interesting in it: the first must never authorise a retry. + """ + try: + resp = requests.get( + f"{MENDER_SERVER}/api/management/v1/deployments/deployments/{deployment_id}/devices/{device_id}/log", + headers=HEADERS, timeout=30, + ) + resp.raise_for_status() + return resp.text + except requests.RequestException: + return None + + +def last_attempt(log: str) -> str: + """The tail of the log from the final attempt marker onwards. + + Returns the whole log when there is no marker, which only affects clients + older than the ones in this fleet, and is still safe: the classifier is + allowlist-based, so extra text can only cause a refusal, never a retry it + would not otherwise allow. + """ + matches = list(ATTEMPT_START.finditer(log)) + return log[matches[-1].start():] if matches else log + + +def classify(log: str | None) -> tuple[bool, str]: + """Decide whether a new deployment can fix this failure. + + Returns (retry, reason). Default is False: only a positively identified + fetch failure, with no sign the node's own state was involved, is retried. + """ + if log is None: + return False, "could not read the deployment log" + + tail = last_attempt(log) + if not tail.strip(): + return False, "no deployment log to read" + + for pattern, reason in DEVICE_STATE: + if pattern.search(tail): + return False, reason + if PROCESS_FAILED.search(tail): + return False, "an update step ran and failed on the node" + if any(pattern.search(tail) for pattern in FETCH_FAILED): + return True, "the artifact never finished downloading" + return False, "failed for an unrecognised reason" + + +def parse_ts(value: str | None) -> datetime | None: + """Parse Mender's RFC3339 timestamps, which carry a Z and sub-second digits.""" + if not value: + return None + try: + return datetime.fromisoformat(value.replace("Z", "+00:00")) + except ValueError: + return None + + +def recent_failures() -> dict[tuple[str, str], dict]: + """Find each device+artifact whose most recent deployment ended in failure. + + Keyed on the pair because that is the unit a retry addresses: the same node + failing a different artifact is a separate problem with its own allowance. + Only the newest failure for a pair is kept, so an old failure cannot revive + a pair that has since failed again and been counted. + """ + deployments = api("deployments/deployments", {"per_page": 100}) + if not isinstance(deployments, list): + return {} + + cutoff = datetime.now(timezone.utc) - timedelta(days=WINDOW_DAYS) + found: dict[tuple[str, str], dict] = {} + + for dep in deployments: + if not isinstance(dep, dict): + continue + created = parse_ts(dep.get("created")) + if not created or created < cutoff: + continue + if not dep.get("statistics", {}).get("status", {}).get("failure"): + continue + + artifact = dep.get("artifact_name") + devices = api(f"deployments/deployments/{dep['id']}/devices") + if not isinstance(devices, list) or not artifact: + continue + + for dev in devices: + if not isinstance(dev, dict) or dev.get("status") != "failure": + continue + key = (dev["id"], artifact) + previous = found.get(key) + if previous and previous["created"] >= created: + continue + found[key] = { + "device_id": dev["id"], + "artifact": artifact, + "deployment_id": dep["id"], + "created": created, + } + + return found + + +def device_history(device_id: str) -> list[dict]: + """A device's deployments, newest first.""" + history = api(f"deployments/deployments/devices/{device_id}", {"per_page": PER_PAGE}) + if not isinstance(history, list): + return [] + return sorted( + (h for h in history if isinstance(h, dict)), + key=lambda h: h.get("deployment", {}).get("created") or "", + reverse=True, + ) + + +def is_busy(history: list[dict]) -> bool: + """Whether the device is already working through a deployment.""" + return any(h.get("device", {}).get("status") in ACTIVE_STATUSES for h in history) + + +def has_landed(history: list[dict], artifact: str, after: datetime) -> bool: + """Whether the artifact reached the device after the failure we are looking at. + + Guards against retrying something a person already fixed by hand, and is why + inventory's artifact_name is not used for this: a node running both a rootfs + and a docker-compose artifact reports only the most recently installed of the + two, so the OS can be a version behind while artifact_name looks current. + That is precisely nightcrawler2's state, and reading it naively would mark a + failed OS update as landed. + """ + for entry in history: + if entry.get("deployment", {}).get("artifact_name") != artifact: + continue + if entry.get("device", {}).get("status") not in LANDED_STATUSES: + continue + created = parse_ts(entry.get("deployment", {}).get("created")) + if created and created > after: + return True + return False + + +def is_accepted(device_id: str) -> bool: + """Whether Mender still holds the device as accepted. + + A network error answers True, matching auto_accept.is_device_accepted: a blip + talking to Mender is not evidence a node was decommissioned, and the next + pass will ask again. Only a definite 404 or a non-accepted status stops the + retry. + """ + try: + resp = requests.get( + f"{MENDER_SERVER}/api/management/v2/devauth/devices/{device_id}", + headers=HEADERS, + timeout=30, + ) + if resp.status_code == 404: + return False + resp.raise_for_status() + return resp.json().get("status") == "accepted" + except requests.RequestException: + return True + + +def create_retry(device_id: str, artifact: str, attempt: int) -> str | None: + """Create a single-device deployment. Returns its id, or None on failure. + + Deliberately no `retries` field: this tenant's plan rejects the whole request + with a 403 if one is present, which would fail every retry we make. + """ + name = f"retry{attempt}-{device_id[:8]}-{artifact}" + try: + resp = requests.post( + f"{MENDER_SERVER}/api/management/v1/deployments/deployments", + headers=HEADERS, + json={"name": name[:200], "artifact_name": artifact, "devices": [device_id]}, + timeout=30, + ) + resp.raise_for_status() + return resp.headers.get("Location", "").rsplit("/", 1)[-1] or "created" + except requests.RequestException as e: + print(f" Error creating retry deployment: {e}", file=sys.stderr) + return None + + +def load_state() -> dict[str, dict]: + """Load {"|": {"attempts", "last_attempt"}}.""" + try: + with open(STATE_FILE) as f: + state = json.load(f) + return state if isinstance(state, dict) else {} + except (FileNotFoundError, json.JSONDecodeError): + return {} + + +def save_state(state: dict[str, dict]) -> None: + with open(STATE_FILE, "w") as f: + json.dump(state, f, indent=1) + + +def check_state_writable() -> bool: + """Prove the attempt counts can be persisted, before anything is created. + + The counts are the only thing between a node that fails identically every + time and an unbounded loop of deployments against it. If they cannot be + written, the safe move is to do nothing at all: creating deployments and + then failing to record them is how a retry becomes a storm. This is not + hypothetical under the packaged unit, where ProtectSystem=strict leaves the + checkout read-only and only StateDirectory writable. + """ + try: + os.makedirs(os.path.dirname(STATE_FILE) or ".", exist_ok=True) + save_state(load_state()) + return True + except OSError as e: + print(f"Error: cannot write state file {STATE_FILE}: {e}", file=sys.stderr) + return False + + +def prune_state(state: dict[str, dict], live: set[str]) -> dict[str, dict]: + """Drop pairs that no longer have a failure in the window. + + Without this the file grows forever, and a node that failed months ago would + keep its exhausted count and be refused a retry the next time it genuinely + needs one. + """ + return {k: v for k, v in state.items() if k in live} + + +def main() -> int: + parser = argparse.ArgumentParser(description="Retry Mender deployments that failed to download.") + parser.add_argument("--apply", action="store_true", + help="create the deployments (default: report what would happen)") + args = parser.parse_args() + + if not MENDER_PAT: + print("Error: MENDER_PAT environment variable not set", file=sys.stderr) + return 1 + if args.apply and not check_state_writable(): + return 1 + + failures = recent_failures() + state = load_state() + + if not failures: + print(f"No failed deployments in the last {WINDOW_DAYS} days") + if args.apply: + save_state({}) + return 0 + + print(f"{len(failures)} failed device+artifact pair(s) in the last {WINDOW_DAYS} days") + now = time.time() + created = 0 + + for (device_id, artifact), failure in sorted(failures.items()): + key = f"{device_id}|{artifact}" + label = f"{device_id[:8]} {artifact}" + record = state.setdefault(key, {"attempts": 0, "last_attempt": 0}) + + retry, reason = classify(device_log(failure["deployment_id"], device_id)) + if not retry: + print(f" {label}: not retrying, {reason}") + continue + if record["attempts"] >= MAX_ATTEMPTS: + print(f" {label}: giving up after {record['attempts']} attempt(s), {reason}") + continue + + waited = now - record["last_attempt"] + if record["attempts"] and waited < BACKOFF_SECONDS: + print(f" {label}: backing off, {BACKOFF_SECONDS - waited:.0f}s left") + continue + + history = device_history(device_id) + if has_landed(history, artifact, failure["created"]): + print(f" {label}: already landed since the failure, clearing") + record["attempts"] = 0 + continue + if is_busy(history): + print(f" {label}: already running a deployment, leaving it") + continue + if not is_accepted(device_id): + print(f" {label}: not accepted on Mender, skipping") + continue + + attempt = record["attempts"] + 1 + if not args.apply: + print(f" {label}: would retry ({reason}), attempt {attempt}/{MAX_ATTEMPTS}") + continue + + # A cap on one pass, so a fleet-wide outage cannot turn into a fleet-wide + # burst of deployments. What is left over is picked up next pass. + if created >= MAX_PER_PASS: + print(f" {label}: deferred, {MAX_PER_PASS} retries already created this pass") + continue + + deployment_id = create_retry(device_id, artifact, attempt) + if not deployment_id: + continue + + # Recorded immediately, not at the end of the pass. If this process dies + # mid-loop, the attempts already made must still be counted, or the next + # pass repeats them with a fresh allowance. + record["attempts"] = attempt + record["last_attempt"] = now + created += 1 + try: + save_state(state) + except OSError as e: + print(f"Error: state write failed after creating {deployment_id}: {e}", file=sys.stderr) + return 1 + print(f" {label}: retry {attempt}/{MAX_ATTEMPTS} created ({reason}) -> {deployment_id}") + + if args.apply: + save_state(prune_state(state, {f"{d}|{a}" for d, a in failures})) + if created: + print(f"Created {created} retry deployment(s)") + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/mender-auto-accept/systemd/retina-deploy-retry.service b/mender-auto-accept/systemd/retina-deploy-retry.service new file mode 100644 index 0000000..9963174 --- /dev/null +++ b/mender-auto-accept/systemd/retina-deploy-retry.service @@ -0,0 +1,28 @@ +[Unit] +Description=Re-issue Mender deployments that failed for transient reasons +After=network-online.target +Wants=network-online.target + +[Service] +Type=oneshot +# Deliberately no --apply, so the pass reports its verdict on every real failure +# and creates nothing. The create path has never run against the fleet, and the +# classifier reads log prose that only Mender controls, so the journal earns the +# trust first. Add --apply and daemon-reload to let it act. +ExecStart=/root/retina/node-infra/mender-auto-accept/.venv/bin/python /root/retina/node-infra/mender-auto-accept/deploy_retry.py +EnvironmentFile=/root/retina/node-infra/mender-auto-accept/.env + +# Security hardening +NoNewPrivileges=yes +ProtectSystem=strict +ProtectHome=no +PrivateTmp=yes +# The attempt counts are the only thing stopping a node that fails identically +# every time from being retried forever, so they must outlive a deploy. Keeping +# them beside the script would put mutable state inside a git checkout, where a +# pull could disturb them; losing the file resets every count to zero. +# +# deploy_retry.py reads systemd's STATE_DIRECTORY for itself, so the +# EnvironmentFile needs no path. The pass refuses to create anything if this +# turns out to be unwritable, rather than making deployments it cannot count. +StateDirectory=retina-deploy-retry diff --git a/mender-auto-accept/systemd/retina-deploy-retry.timer b/mender-auto-accept/systemd/retina-deploy-retry.timer new file mode 100644 index 0000000..dbe833f --- /dev/null +++ b/mender-auto-accept/systemd/retina-deploy-retry.timer @@ -0,0 +1,15 @@ +[Unit] +Description=Retry failed Mender deployments every 15 minutes + +[Timer] +# Deliberately slower than mender-auto-accept's 30s. A failed deployment is not +# urgent, and a node that has just failed one is often still settling: rushing +# back in risks stacking a retry behind work it has not finished reporting. +# Kept well under DEPLOY_RETRY_BACKOFF_SECONDS so the backoff, not the timer, +# is what paces attempts. +OnBootSec=5min +OnUnitActiveSec=15min +AccuracySec=30s + +[Install] +WantedBy=timers.target diff --git a/mender-auto-accept/test_deploy_retry.py b/mender-auto-accept/test_deploy_retry.py new file mode 100644 index 0000000..d75f3dc --- /dev/null +++ b/mender-auto-accept/test_deploy_retry.py @@ -0,0 +1,297 @@ +"""Tests for the failed-deployment retry. + +The fixtures are trimmed from real device logs pulled from hosted Mender on +2026-09-04, because the two mistakes that matter here were both invisible in +made-up logs: + + * the log is cumulative across attempts, so nightcrawler1's carries three + attempts and lines dated April from a clock-skewed node, and + * "Installing artifact..." is printed a second after the deployment starts, + before the download, so it does not mark the install phase. + +An earlier version of this classifier failed both, and the fleet logs caught it. +""" + +import os +from datetime import datetime, timedelta, timezone + +import deploy_retry +import pytest + +FAILED_AT = datetime(2026, 9, 3, 21, 40, 57, tzinfo=timezone.utc) +ARTIFACT = "owl-os-pi5-v0.16.1" + +# nightcrawler2, deployment 71904a03. Two truncated streams, then R2 answered +# 400 to a resumed range request and the client stopped at retry 2 of 10. +NIGHTCRAWLER2 = """\ +info: Deployment with ID 71904a03 started. +info: Running State Script: /etc/mender/scripts/Download_Enter_00_retina_state +warning: end of stream: GET https://r2.cloudflarestorage.com/mender-artifacts-us/a4102b9c +info: Resuming download after 60 seconds. Retry 1/10 +warning: stream truncated: GET https://r2.cloudflarestorage.com/mender-artifacts-us/a4102b9c +info: Resuming download after 60 seconds. Retry 2/10 +error: Unexpected status code while fetching artifact: Bad Request +error: HTTP stream contains a body, but a reader has not been created for it: GET https://r2 +""" + +# Wilderness A, same rollout. Note the cancelled GET: aborting an install aborts +# the download too, so a fetch error appears in a failure a retry cannot fix. +WILDERNESS_DISK = """\ +info: Deployment with ID 71904a03 started. +info: Running State Script: /etc/mender/scripts/Download_Enter_00_retina_state +info: Installing artifact... +error: No space left on device: Failed to create directory: '/var/lib/mender/modules/v3/payloads/0000/tree/tmp' +error: Operation canceled: GET https://r2.cloudflarestorage.com/mender-artifacts-us/a4102b9c: HTTP request cancelled +""" + +# d7e24fb9, retina-node-v0.4.5.0. The update module ran and exited non-zero, +# and the rollback failed after it. +INSTALL_FAILED = """\ +info: Deployment with ID d02677b0 started. +info: Installing artifact... +error: Process returned non-zero exit status: ArtifactInstall: Process exited with status 1 +error: Process returned non-zero exit status: ArtifactRollback: Process exited with status 1 +""" + +# nightcrawler1, deployment d0c9144c, trimmed to two of its three attempts. +# "Installing artifact..." is one second in; the download gives up hours later. +CUMULATIVE = """\ +info: Deployment with ID d0c9144c started. +info: Installing artifact... +error: No space left on device: Failed to create directory +info: Deployment with ID d0c9144c started. +info: Installing artifact... +warning: Reading error, a new request will be re-scheduled. Connection reset by peer: Could not read body +error: Resume download error: Giving up on resuming the download: Tried maximum number of times: Exponential backoff +""" + + +def entry(artifact, status, created): + """One record as the per-device deployments endpoint returns it.""" + return {"deployment": {"artifact_name": artifact, "created": created.isoformat().replace("+00:00", "Z")}, + "device": {"status": status}} + + +# ── what a new deployment can fix ──────────────────────────────── + +def test_a_download_that_died_on_a_bad_status_is_retried(): + retry, reason = deploy_retry.classify(NIGHTCRAWLER2) + assert retry + assert reason == "the artifact never finished downloading" + + +def test_a_download_that_exhausted_its_backoff_is_retried(): + log = "info: Deployment with ID d0c9144c started.\nerror: Giving up on resuming the download: Tried maximum number of times" + assert deploy_retry.classify(log)[0] + + +def test_a_full_disk_is_not_retried(): + retry, reason = deploy_retry.classify(WILDERNESS_DISK) + assert not retry + assert reason == "no disk space on the node" + + +def test_a_cancelled_download_alongside_a_disk_failure_is_not_read_as_transport(): + """Aborting an install cancels the GET, so the fetch error is a symptom of + the real failure. Reading it as transport would retry a full disk forever.""" + assert "Operation canceled: GET" in WILDERNESS_DISK + assert not deploy_retry.classify(WILDERNESS_DISK)[0] + + +def test_an_update_step_that_ran_and_failed_is_not_retried(): + retry, reason = deploy_retry.classify(INSTALL_FAILED) + assert not retry + assert reason == "an update step ran and failed on the node" + + +def test_a_failed_rollback_is_never_retried(): + """The node is in a state nobody has inspected. It needs a person.""" + assert not deploy_retry.classify("started.\nerror: ArtifactRollback: Process exited with status 1")[0] + + +# ── default deny ───────────────────────────────────────────────── + +@pytest.mark.parametrize("log,expected_reason", [ + (None, "could not read the deployment log"), + ("", "no deployment log to read"), + (" \n \n", "no deployment log to read"), + ("error: something nobody has seen before", "failed for an unrecognised reason"), +]) +def test_anything_we_cannot_positively_identify_is_refused(log, expected_reason): + """A missed retry costs one hand deployment. A wrong retry reboots a live + node on a timer, so silence must never authorise one.""" + retry, reason = deploy_retry.classify(log) + assert not retry + assert reason == expected_reason + + +def test_an_api_failure_reading_the_log_is_distinct_from_an_empty_log(): + """device_log returns None on error rather than "", or a transient API + problem would look like a clean log and fall into the same bucket.""" + assert deploy_retry.classify(None)[0] is False + assert deploy_retry.classify("")[1] != deploy_retry.classify(None)[1] + + +# ── the cumulative log ─────────────────────────────────────────── + +def test_only_the_final_attempt_is_classified(): + """nightcrawler1's log holds a disk failure from one attempt and a download + failure from a later one. Matching the whole log would let the older line + veto a retry the newer failure has earned.""" + assert "No space left on device" in CUMULATIVE + assert deploy_retry.classify(CUMULATIVE)[0] + + +def test_a_newer_disk_failure_still_vetoes_an_older_download_failure(): + log = ("started.\nerror: Giving up on resuming the download\n" + "info: Deployment with ID x started.\nerror: No space left on device\n") + assert not deploy_retry.classify(log)[0] + + +def test_installing_artifact_is_not_treated_as_reaching_the_install_phase(): + """It is printed about a second after the deployment starts, before the + download. Wilderness A's disk log shows it one second in; nightcrawler1's + download gave up five hours after the same line.""" + assert "Installing artifact..." in CUMULATIVE + assert deploy_retry.classify(CUMULATIVE)[0] + + +def test_a_log_with_no_attempt_marker_is_still_read(): + assert deploy_retry.last_attempt("error: Giving up on resuming the download").strip() + + +# ── the artifact_name trap ─────────────────────────────────────── + +def test_a_newer_unrelated_artifact_does_not_count_as_landed(): + """nightcrawler2 installed retina-node-v0.4.5.0 minutes before failing the OS + update, so its most recent successful deployment is for a different artifact. + Treating any later success as recovery would abandon the node on v0.15.0.""" + history = [entry("retina-node-v0.4.5.0", "success", FAILED_AT + timedelta(hours=1))] + assert not deploy_retry.has_landed(history, ARTIFACT, FAILED_AT) + + +def test_a_success_for_the_same_artifact_after_the_failure_counts(): + history = [entry(ARTIFACT, "success", FAILED_AT + timedelta(hours=1))] + assert deploy_retry.has_landed(history, ARTIFACT, FAILED_AT) + + +def test_already_installed_counts_as_landed(): + """Mender reports already-installed when the device turns out to have it.""" + history = [entry(ARTIFACT, "already-installed", FAILED_AT + timedelta(hours=1))] + assert deploy_retry.has_landed(history, ARTIFACT, FAILED_AT) + + +def test_a_success_from_before_the_failure_does_not_count(): + history = [entry(ARTIFACT, "success", FAILED_AT - timedelta(days=14))] + assert not deploy_retry.has_landed(history, ARTIFACT, FAILED_AT) + + +# ── do not stack deployments on a working node ─────────────────── + +@pytest.mark.parametrize("status", ["pending", "downloading", "installing", "rebooting"]) +def test_a_device_mid_update_is_busy(status): + assert deploy_retry.is_busy([entry(ARTIFACT, status, FAILED_AT)]) + + +def test_a_device_with_only_finished_deployments_is_not_busy(): + assert not deploy_retry.is_busy([ + entry(ARTIFACT, "failure", FAILED_AT), + entry("retina-node-v0.4.5.0", "success", FAILED_AT), + ]) + + +# ── state, which is what bounds the whole thing ────────────────── + +@pytest.mark.skipif(os.geteuid() == 0, reason="root ignores the mode bits this test relies on") +def test_unwritable_state_stops_the_pass_before_anything_is_created(tmp_path, monkeypatch): + """Under the packaged unit ProtectSystem=strict leaves the checkout + read-only. Creating deployments we then cannot count is how a retry becomes + a storm, so an unwritable state file must abort before any API write.""" + readonly = tmp_path / "ro" + readonly.mkdir() + readonly.chmod(0o500) + monkeypatch.setattr(deploy_retry, "STATE_FILE", str(readonly / "state.json")) + try: + assert not deploy_retry.check_state_writable() + finally: + readonly.chmod(0o700) + + +def test_writable_state_passes_the_preflight(tmp_path, monkeypatch): + monkeypatch.setattr(deploy_retry, "STATE_FILE", str(tmp_path / "sub" / "state.json")) + assert deploy_retry.check_state_writable() + + +def test_prune_drops_pairs_with_no_live_failure(): + """An exhausted count must not outlive the failure that earned it, or the + node is refused a retry the next time it genuinely needs one.""" + state = {"dev1|art": {"attempts": 2}, "dev2|art": {"attempts": 1}} + assert deploy_retry.prune_state(state, {"dev1|art"}) == {"dev1|art": {"attempts": 2}} + + +def test_corrupt_state_reads_as_empty_rather_than_crashing(tmp_path, monkeypatch): + bad = tmp_path / "state.json" + bad.write_text("{not json") + monkeypatch.setattr(deploy_retry, "STATE_FILE", str(bad)) + assert deploy_retry.load_state() == {} + + +def test_parse_ts_handles_menders_format(): + assert deploy_retry.parse_ts("2026-09-03T21:40:57.313Z") == datetime( + 2026, 9, 3, 21, 40, 57, 313000, tzinfo=timezone.utc) + + +def test_parse_ts_survives_a_missing_or_broken_timestamp(): + assert deploy_retry.parse_ts(None) is None + assert deploy_retry.parse_ts("not a date") is None + + +# ── the accepted check, which 404s the whole fleet if it reads the wrong API ── + +class _Resp: + def __init__(self, status_code, payload=None): + self.status_code = status_code + self._payload = payload or {} + + def json(self): + return self._payload + + def raise_for_status(self): + if self.status_code >= 400: + raise deploy_retry.requests.HTTPError(f"{self.status_code}") + + +def test_accepted_check_uses_the_v2_devauth_api(monkeypatch): + """devauth is v2 while deployments are v1. Asking v1 returns 404, which + reads as a decommissioned device and silently skips every retry.""" + seen = {} + + def fake_get(url, **kwargs): + seen["url"] = url + return _Resp(200, {"status": "accepted"}) + + monkeypatch.setattr(deploy_retry.requests, "get", fake_get) + assert deploy_retry.is_accepted("dev1") + assert "/api/management/v2/devauth/devices/dev1" in seen["url"] + + +def test_a_missing_device_is_not_accepted(monkeypatch): + monkeypatch.setattr(deploy_retry.requests, "get", lambda url, **kw: _Resp(404)) + assert not deploy_retry.is_accepted("gone") + + +def test_a_network_error_does_not_condemn_the_device(monkeypatch): + """Assume accepted and ask again next pass, matching auto_accept.""" + def boom(url, **kwargs): + raise deploy_retry.requests.ConnectionError("unreachable") + + monkeypatch.setattr(deploy_retry.requests, "get", boom) + assert deploy_retry.is_accepted("dev1") + + +def test_device_log_returns_none_when_the_api_fails(monkeypatch): + def boom(url, **kwargs): + raise deploy_retry.requests.ConnectionError("unreachable") + + monkeypatch.setattr(deploy_retry.requests, "get", boom) + assert deploy_retry.device_log("dep", "dev") is None