From 287930406b092a79aea27f5c4e6f4c2c8bbe369d Mon Sep 17 00:00:00 2001 From: Josh Poole Date: Fri, 4 Sep 2026 11:37:52 +0100 Subject: [PATCH 1/2] 20260904 - Retry deployments that failed before the artifact arrived nightcrawler2 lost owl-os-pi5-v0.16.1 on 2026-09-03 to a broken download: two truncated streams, then a resumed range request that R2 answered 400, and the deployment was over three minutes after it started with eight of its ten client retries unused. Recovering it meant creating a deployment by hand, which does not scale with the fleet. Hosted Mender's own Retries field is a paid-plan feature. On this tenant's `os` plan, creating a deployment with one is rejected outright with 403 "Feature not available in your Plan.", so the retry lives here instead. Only one failure is treated as 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 the log cannot explain. The costs are asymmetric. A missed retry costs one hand deployment; a wrong one reboots a live node on a timer for a reason that will not change. Two properties of Mender's device log make the obvious implementation wrong, and both were found against real fleet logs rather than reasoned about: * "Installing artifact..." is printed about a second after the deployment starts, before the download, so it does not mark the install phase. A phase test built on it would have refused every genuine download failure. Wilderness A shows the line one second in; nightcrawler1 shows it five hours before its download gave up. * The log is cumulative across attempts. nightcrawler1's carries three attempts at one deployment plus lines dated four months earlier from a clock skew, so matching over the whole log would let an old disk-full line veto a retry forever and an old transport error authorise one. Only the final attempt is classified. Blast radius is bounded deliberately: it can only re-send an artifact a human-created deployment had already targeted at that device, two attempts per pair, five per pass, and it aborts before creating anything if the attempt counts cannot be persisted. Deployments it cannot count are how a retry becomes a storm, and ProtectSystem=strict leaves the checkout read-only under the packaged unit. Co-Authored-By: Claude Opus 5 (1M context) --- .gitignore | 1 + README.md | 75 +++ mender-auto-accept/.env.example | 26 + mender-auto-accept/deploy_retry.py | 466 ++++++++++++++++++ .../systemd/retina-deploy-retry.service | 27 + .../systemd/retina-deploy-retry.timer | 15 + mender-auto-accept/test_deploy_retry.py | 297 +++++++++++ 7 files changed, 907 insertions(+) create mode 100644 mender-auto-accept/deploy_retry.py create mode 100644 mender-auto-accept/systemd/retina-deploy-retry.service create mode 100644 mender-auto-accept/systemd/retina-deploy-retry.timer create mode 100644 mender-auto-accept/test_deploy_retry.py 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..bdbea19 100644 --- a/README.md +++ b/README.md @@ -60,3 +60,78 @@ 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 +``` + +### Check what it would do + +Without `--apply` it reports and changes nothing. Run this first: + +```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..8f22e24 --- /dev/null +++ b/mender-auto-accept/systemd/retina-deploy-retry.service @@ -0,0 +1,27 @@ +[Unit] +Description=Re-issue Mender deployments that failed for transient reasons +After=network-online.target +Wants=network-online.target + +[Service] +Type=oneshot +# --apply, not a report-only run. Without it the pass prints what it would do +# and changes nothing, which is the right default when running it by hand but +# would make this timer a no-op. +ExecStart=/root/retina/node-infra/mender-auto-accept/.venv/bin/python /root/retina/node-infra/mender-auto-accept/deploy_retry.py --apply +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 From 15a62bc9fbd6371aa7cd317921febc2d520eac5e Mon Sep 17 00:00:00 2001 From: Josh Poole Date: Fri, 4 Sep 2026 12:39:12 +0100 Subject: [PATCH 2/2] 20260904 - Ship the deployment retry observing only, without --apply The classifier is validated against every failure log currently in the fleet, but the path that creates a deployment has never run against real hardware, and the classification depends on log wording that only Mender controls. So the packaged unit reports its verdict on each failure and creates nothing. The journal is the evidence for whether to trust it. Once its calls match the ones a person would have made, --apply is a one-line change and a daemon-reload. Until then a failure it would have retried still needs a deployment by hand, which is what the README now says. Co-Authored-By: Claude Opus 5 (1M context) --- README.md | 15 +++++++++++++-- .../systemd/retina-deploy-retry.service | 9 +++++---- 2 files changed, 18 insertions(+), 6 deletions(-) diff --git a/README.md b/README.md index bdbea19..8392290 100644 --- a/README.md +++ b/README.md @@ -127,9 +127,20 @@ sudo systemctl daemon-reload sudo systemctl enable --now retina-deploy-retry.timer ``` -### Check what it would do +**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. -Without `--apply` it reports and changes nothing. Run this 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 diff --git a/mender-auto-accept/systemd/retina-deploy-retry.service b/mender-auto-accept/systemd/retina-deploy-retry.service index 8f22e24..9963174 100644 --- a/mender-auto-accept/systemd/retina-deploy-retry.service +++ b/mender-auto-accept/systemd/retina-deploy-retry.service @@ -5,10 +5,11 @@ Wants=network-online.target [Service] Type=oneshot -# --apply, not a report-only run. Without it the pass prints what it would do -# and changes nothing, which is the right default when running it by hand but -# would make this timer a no-op. -ExecStart=/root/retina/node-infra/mender-auto-accept/.venv/bin/python /root/retina/node-infra/mender-auto-accept/deploy_retry.py --apply +# 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