diff --git a/mender-auto-accept/deploy_retry.py b/mender-auto-accept/deploy_retry.py index 117ff8f..538edf6 100644 --- a/mender-auto-accept/deploy_retry.py +++ b/mender-auto-accept/deploy_retry.py @@ -99,12 +99,31 @@ 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. +# all 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), + # nightcrawler2, owl-os v0.16.1, 2026-09-04: three hours of resumed reads on + # Wi-Fi, then the client killed its own download. + re.compile(r"Update Module Download process timed out", re.I), + # Jonathan 1, owl-os v0.8.20, 2026-06-18: the client lost its streaming + # pipe to the module mid-download. + re.compile(r"Cannot open \S*/stream-next", re.I), ] +# A power cut mid-deployment, recognised by the node going dark: the client +# daemon starts again after a silence longer than INTERRUPT_GAP. ret9573ecda and +# retc47d6f72 were dark for four and eight hours on 2026-09-24. A broken OS image +# reboots within about a minute and then fails ArtifactVerifyReboot, so the gap +# keeps it out. Retrying these is stage 3 of the rollout agreed on 2026-09-24 and +# waits for the retina-node preflight and the forked Update Module to reach the +# fleet, so it is off unless DEPLOY_RETRY_INTERRUPTED=1. Until then the verdict +# is still reported. +RETRY_INTERRUPTED = os.environ.get("DEPLOY_RETRY_INTERRUPTED") == "1" +INTERRUPT_GAP = timedelta(minutes=int(os.environ.get("DEPLOY_RETRY_INTERRUPT_GAP_MINUTES", "10"))) +DAEMON_START = re.compile(r"Running mender-update \d") +LOG_TS = re.compile(r"^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2})") + # The node's own condition caused the failure and still holds, so an identical # deployment fails identically. Overrides everything. DEVICE_STATE = [ @@ -168,6 +187,26 @@ def last_attempt(log: str) -> str: return log[matches[-1].start():] if matches else log +def dark_for(tail: str) -> timedelta | None: + """How long the node went dark mid-attempt, if it did for INTERRUPT_GAP or more. + + Only a restart before any update step has failed counts: a failure that came + first is the cause, and the power cut after it is not. + """ + previous = None + for line in tail.splitlines(): + if PROCESS_FAILED.search(line): + return None + stamp = LOG_TS.match(line) + if not stamp: + continue + ts = datetime.strptime(stamp.group(1), "%Y-%m-%d %H:%M:%S") + if DAEMON_START.search(line) and previous is not None and ts - previous >= INTERRUPT_GAP: + return ts - previous + previous = ts + return None + + def classify(log: str | None) -> tuple[bool, str]: """Decide whether a new deployment can fix this failure. @@ -184,10 +223,21 @@ def classify(log: str | None) -> tuple[bool, str]: 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): + process_failed = PROCESS_FAILED.search(tail) + # A download that gave up is the failure even when the node went dark after + # it (nightcrawler1, v0.4.4.0: gave up, then off for 44 hours), and nothing + # on the node was touched, so it is checked before the power cut. + if not process_failed and any(pattern.search(tail) for pattern in FETCH_FAILED): return True, "the artifact never finished downloading" + gap = dark_for(tail) + if gap is not None: + hours = gap.total_seconds() / 3600 + if RETRY_INTERRUPTED: + return True, f"power lost mid-deployment (node dark {hours:.1f} h)" + return False, (f"power lost mid-deployment (node dark {hours:.1f} h); " + "retrying these is not enabled (DEPLOY_RETRY_INTERRUPTED)") + if process_failed: + return False, "an update step ran and failed on the node" return False, "failed for an unrecognised reason" diff --git a/mender-auto-accept/test_deploy_retry.py b/mender-auto-accept/test_deploy_retry.py index d75f3dc..8482e44 100644 --- a/mender-auto-accept/test_deploy_retry.py +++ b/mender-auto-accept/test_deploy_retry.py @@ -295,3 +295,137 @@ def boom(url, **kwargs): monkeypatch.setattr(deploy_retry.requests, "get", boom) assert deploy_retry.device_log("dep", "dev") is None + + +# --- Failures the first version missed (2026-09-24 replay over all 45 logs) --- + +# nightcrawler2, deployment dde1802e: three hours of resumed reads on Wi-Fi, +# then the client killed its own download. +NIGHTCRAWLER2_TIMEOUT = """\ +2026-09-04 10:07:03.44 +0000 UTC info: Deployment with ID dde1802e started. +2026-09-04 10:07:04.274 +0000 UTC info: Installing artifact... +2026-09-04 11:10:03.08 +0000 UTC info: Resuming download after 60 seconds. Retry 1/10 +2026-09-04 14:07:04.337 +0000 UTC info: Sending SIGTERM to PID 2631957 +2026-09-04 14:07:04.355 +0000 UTC info: PID 2631957 exited with status 15 +2026-09-04 14:07:04.355 +0000 UTC error: Connection timed out: Update Module Download process timed out +2026-09-04 14:07:04.356 +0000 UTC error: Operation canceled: GET https://r2.cloudflarestorage.com/mender-artifacts-us/a4102b9c +""" + +# Jonathan 1, deployment f20eee61: the client lost its pipe to the module. +JONATHAN1_STREAM = """\ +2026-06-18 17:58:17.342 +0000 UTC info: Deployment with ID f20eee61 started. +2026-06-18 17:58:23.828 +0000 UTC info: Installing artifact... +2026-06-18 18:01:41.358 +0000 UTC error: Cancel::open() returned error: No such file or directory +2026-06-18 18:01:41.38 +0000 UTC error: No such file or directory: Cannot open /var/lib/mender/modules/v3/payloads/0000/tree/stream-next +2026-06-18 18:01:41.454 +0000 UTC error: Operation canceled: GET https://r2.cloudflarestorage.com/mender-artifacts-us/86cea7f7 +""" + +# retc47d6f72, owl-os v0.17.0, deployment d175ca0d: the site lost power at the +# reboot into the new partition and the node was dark for eight hours. It came +# back on the old partition, so ArtifactVerifyReboot failed: the A/B fallback +# working, not a broken image. +RETC47_POWER_CUT_AT_REBOOT = """\ +2026-09-24 02:13:47.371 +0000 UTC info: Deployment with ID d175ca0d started. +2026-09-24 02:15:00.945 +0000 UTC info: Sending status update to server +2026-09-24 02:15:01.235 +0000 UTC info: Calling `reboot` command and waiting for system to restart. +2026-09-24 02:15:01.366 +0000 UTC info: Termination signal received, shutting down gracefully +2026-09-24 10:02:12.702 +0000 UTC info: Running mender-update 5.1.0 +2026-09-24 10:02:12.922 +0000 UTC info: The update client daemon is now ready to handle incoming deployments +2026-09-24 10:02:13.228 +0000 UTC error: Process returned non-zero exit status: ArtifactVerifyReboot: Process exited with status 1 +2026-09-24 10:02:52.793 +0000 UTC info: Running mender-update 5.1.0 +2026-09-24 10:02:53.367 +0000 UTC info: Running State Script: /var/lib/mender/scripts/ArtifactFailure_Enter_00_retina_state +""" + +# ret9573ecda, owl-os v0.17.0, deployment d175ca0d: dark for four hours while +# installing. +RET9573_POWER_CUT_MID_INSTALL = """\ +2026-09-23 22:21:41.897 +0000 UTC info: Deployment with ID d175ca0d started. +2026-09-23 22:21:42.147 +0000 UTC info: Running State Script: /etc/mender/scripts/Download_Enter_00_retina_state +2026-09-23 22:21:42.451 +0000 UTC info: Installing artifact... +2026-09-24 02:13:35.612 +0000 UTC info: Running mender-update 5.1.0 +2026-09-24 02:13:35.763 +0000 UTC info: The update client daemon is now ready to handle incoming deployments +2026-09-24 02:13:35.805 +0000 UTC info: Sending status update to server +""" + +# Josh Test Node 2, deployment 71fe1a9b: a deliberate sysrq power cut, back in +# 51 s. Too short to tell apart from a quick reboot, so it is not counted. +SHORT_POWER_CUT = """\ +2026-09-24 10:33:01.292 +0000 UTC info: Deployment with ID 71fe1a9b started. +2026-09-24 10:35:55.588 +0000 UTC info: Update Module output (stdout): extracting images +2026-09-24 10:36:46.448 +0000 UTC info: Running mender-update 5.1.0 +2026-09-24 10:36:50.041 +0000 UTC info: Update Module output (stdout): Rolling back docker-compose artifact retina-node-v0.4.6.0 +""" + +# What a broken OS image looks like: it reboots, comes back within a minute on +# the old partition, and fails verification. Retrying it would reboot a live +# node again for nothing. +BROKEN_OS_IMAGE = """\ +2026-09-24 12:00:00.000 +0000 UTC info: Deployment with ID bad0s000 started. +2026-09-24 12:03:00.000 +0000 UTC info: Calling `reboot` command and waiting for system to restart. +2026-09-24 12:03:41.000 +0000 UTC info: Running mender-update 5.1.0 +2026-09-24 12:03:41.500 +0000 UTC error: Process returned non-zero exit status: ArtifactVerifyReboot: Process exited with status 1 +""" + +# A failed install step, then a power cut. The failure came first and is the +# cause; the power cut does not make it retryable. +FAILED_THEN_POWER_CUT = """\ +2026-09-24 12:00:00.000 +0000 UTC info: Deployment with ID fail0000 started. +2026-09-24 12:04:00.000 +0000 UTC error: Process returned non-zero exit status: ArtifactInstall: Process exited with status 1 +2026-09-24 16:00:00.000 +0000 UTC info: Running mender-update 5.1.0 +""" + + +def test_a_download_that_timed_out_is_retried(): + assert deploy_retry.classify(NIGHTCRAWLER2_TIMEOUT) == (True, "the artifact never finished downloading") + + +def test_a_lost_stream_to_the_module_is_retried(): + assert deploy_retry.classify(JONATHAN1_STREAM) == (True, "the artifact never finished downloading") + + +@pytest.mark.parametrize("log,hours", [(RETC47_POWER_CUT_AT_REBOOT, "7.8"), (RET9573_POWER_CUT_MID_INSTALL, "3.9")]) +def test_a_long_power_cut_is_reported_but_not_retried_by_default(log, hours, monkeypatch): + monkeypatch.setattr(deploy_retry, "RETRY_INTERRUPTED", False) + retry, reason = deploy_retry.classify(log) + assert retry is False + assert f"power lost mid-deployment (node dark {hours} h)" in reason + assert "not enabled" in reason + + +@pytest.mark.parametrize("log", [RETC47_POWER_CUT_AT_REBOOT, RET9573_POWER_CUT_MID_INSTALL]) +def test_a_long_power_cut_is_retried_once_enabled(log, monkeypatch): + monkeypatch.setattr(deploy_retry, "RETRY_INTERRUPTED", True) + retry, reason = deploy_retry.classify(log) + assert retry is True + assert reason.startswith("power lost mid-deployment") + + +@pytest.mark.parametrize("log", [SHORT_POWER_CUT, BROKEN_OS_IMAGE, FAILED_THEN_POWER_CUT]) +def test_a_short_gap_or_an_earlier_failure_is_never_read_as_a_power_cut(log, monkeypatch): + monkeypatch.setattr(deploy_retry, "RETRY_INTERRUPTED", True) + retry, reason = deploy_retry.classify(log) + assert retry is False + assert "power lost" not in reason + + +def test_disk_full_still_vetoes_a_power_cut(monkeypatch): + monkeypatch.setattr(deploy_retry, "RETRY_INTERRUPTED", True) + log = RET9573_POWER_CUT_MID_INSTALL + "2026-09-24 02:14:00.000 +0000 UTC error: No space left on device\n" + assert deploy_retry.classify(log) == (False, "no disk space on the node") + + +# nightcrawler1, deployment d0c9144c: the download gave up, and the node was +# then off for 44 hours. The failure is the download, not the power cut. +NIGHTCRAWLER1_GAVE_UP_THEN_DARK = """\ +2026-08-23 12:52:58.618 +0000 UTC info: Deployment with ID d0c9144c started. +2026-08-23 12:53:08.624 +0000 UTC info: Installing artifact... +2026-08-23 16:50:37.434 +0000 UTC info: Resuming download after 60 seconds. Retry 10/10 +2026-08-23 17:29:04.684 +0000 UTC error: Resume download error: Giving up on resuming the download: Tried maximum number of times: Exponential backoff +2026-08-25 13:41:04.317 +0000 UTC info: Running mender-update 5.1.0 +""" + + +@pytest.mark.parametrize("enabled", [False, True]) +def test_a_download_that_gave_up_before_a_power_cut_is_still_a_download_failure(enabled, monkeypatch): + monkeypatch.setattr(deploy_retry, "RETRY_INTERRUPTED", enabled) + assert deploy_retry.classify(NIGHTCRAWLER1_GAVE_UP_THEN_DARK) == (True, "the artifact never finished downloading")