Reboot crossing watchdog timeout

tests/MenderAPI/deployments.py

@@ -24,6 +24,26 @@
 from .requests_helpers import requests_retry
 
 
+# The mender-update client's automatic system-reboot watchdog: if the `reboot`
+# command does not kill the client, mender-update waits this long before giving
+# up and reporting a terminal deployment status. Hardcoded in the client as
+# chrono::minutes(10):
+#   mender/src/mender-update/update_module/v3/platform/c++17/update_module_call.cpp
+#       -> UpdateModule::AsyncSystemReboot
+# A deployment that crosses a reboot can therefore take up to this long to reach
+# a terminal status on the server. SINGLE SOURCE OF TRUTH -- if the client value
+# changes, change it here and everything derived below follows.
+CLIENT_AUTOMATIC_REBOOT_WATCHDOG = 10 * 60
+
+# Give-up deadline for a deployment that crosses a reboot. DERIVED from the
+# client watchdog with a *multiplicative* margin, deliberately NOT an independent
+# literal: a +/-1s drift on either side can never create a dead heat (the
+# 600-vs-601 / 900-vs-901 trap). Polling returns the instant the terminal status
+# is observed, so a larger value never slows a passing test -- it only bounds a
+# genuinely-stuck deployment.
+REBOOT_CROSSING_DEPLOYMENT_TIMEOUT = CLIENT_AUTOMATIC_REBOOT_WATCHDOG * 2
+
+
 class Deployments:
     # track the last statistic for a deployment id
     last_statistic = {}
@@ -258,9 +278,45 @@ def check_expected_statistics(
                 return
             time.sleep(polling_frequency)
 
+        # Self-diagnosing timeout. Dump the per-device deployment log so the real
+        # cause (a hung reboot, "Version file error", the state the client got
+        # stuck in) is visible directly in the test output -- no need to pull
+        # artifacts. Also flag the dead-heat case explicitly.
+        racing = max_wait <= CLIENT_AUTOMATIC_REBOOT_WATCHDOG
+        device_logs = ""
+        try:
+            for device in self.devauth.get_devices():
+                try:
+                    device_logs += "----- device %s -----\n%s\n\n" % (
+                        device["id"],
+                        self.get_logs(device["id"], deployment_id),
+                    )
+                except Exception:
+                    pass
+        except Exception:
+            pass
         pytest.fail(
-            "Never found: %s:%s, only seen: %s after %d seconds"
-            % (expected_status, expected_count, str(seen), max_wait)
+            "Never found %s:%s within %ds for deployment %s.\n"
+            "Statuses seen (in order of appearance): %s\n"
+            "%s"
+            "Device deployment log(s):\n%s"
+            % (
+                expected_status,
+                expected_count,
+                max_wait,
+                deployment_id,
+                str(seen),
+                (
+                    "WARNING: max_wait (%ds) <= client automatic-reboot watchdog "
+                    "(%ds). This poll is racing the watchdog, not testing the "
+                    "client. Pass max_wait=REBOOT_CROSSING_DEPLOYMENT_TIMEOUT for "
+                    "any deployment that crosses a reboot.\n"
+                    % (max_wait, CLIENT_AUTOMATIC_REBOOT_WATCHDOG)
+                    if racing
+                    else ""
+                ),
+                device_logs or "(could not fetch device logs)",
+            )
         )
 
     def get_deployment_overview(self, deployment_id):

tests/tests/test_fault_tolerance.py

@@ -25,6 +25,7 @@
 )
 from .common_update import common_update_procedure, update_image_failed
 from ..MenderAPI import DeviceAuthV2, Deployments, logger
+from ..MenderAPI.deployments import REBOOT_CROSSING_DEPLOYMENT_TIMEOUT
 from .mendertesting import MenderTesting
 
 
@@ -156,8 +157,10 @@ def do_test_update_image_breaks_networking(
             deployment_id, _ = common_update_procedure(
                 broken_network_image, devauth=devauth, deploy=deploy
             )
-            reboot.verify_reboot_performed()  # since the network is broken, two reboots will be performed, and the last one will be detected
-            deploy.check_expected_statistics(deployment_id, "failure", 1)
+            reboot.verify_reboot_performed(max_wait=REBOOT_CROSSING_DEPLOYMENT_TIMEOUT)  # since the network is broken, two reboots will be performed, and the last one will be detected
+            deploy.check_expected_statistics(
+                deployment_id, "failure", 1, max_wait=REBOOT_CROSSING_DEPLOYMENT_TIMEOUT
+            )
 
     def do_test_deployed_during_network_outage(
         self,
@@ -194,8 +197,10 @@ def do_test_deployed_during_network_outage(
             self.manipulate_network_connectivity(mender_device, True)
 
             logger.info("Network stabilized")
-            reboot.verify_reboot_performed()
-            deploy.check_expected_statistics(deployment_id, "success", 1)
+            reboot.verify_reboot_performed(max_wait=REBOOT_CROSSING_DEPLOYMENT_TIMEOUT)
+            deploy.check_expected_statistics(
+                deployment_id, "success", 1, max_wait=REBOOT_CROSSING_DEPLOYMENT_TIMEOUT
+            )
 
         assert mender_device.yocto_id_installed_on_machine() == expected_yocto_id
 
@@ -270,7 +275,7 @@ def do_test_image_download_retry_timeout(
                 mender_device, True, hosts=[blocked_service]
             )
 
-            reboot.verify_reboot_performed()
+            reboot.verify_reboot_performed(max_wait=REBOOT_CROSSING_DEPLOYMENT_TIMEOUT)
             deploy.check_expected_status("finished", deployment_id)
 
             assert mender_device.get_active_partition() == inactive_part
@@ -388,7 +393,7 @@ def do_test_image_download_retry_download_count(
             )
 
             if success:
-                reboot.verify_reboot_performed()
+                reboot.verify_reboot_performed(max_wait=REBOOT_CROSSING_DEPLOYMENT_TIMEOUT)
                 deploy.check_expected_status("finished", deployment_id)
 
                 assert mender_device.get_active_partition() == inactive_part
@@ -435,7 +440,7 @@ def do_test_image_download_retry_hosts_broken(
             )
             mender_device.run("sed -i.bak '/1.1.1.1/d' /etc/hosts")
 
-            reboot.verify_reboot_performed()
+            reboot.verify_reboot_performed(max_wait=REBOOT_CROSSING_DEPLOYMENT_TIMEOUT)
             deploy.check_expected_status("finished", deployment_id)
 
             assert mender_device.get_active_partition() == inactive_part

tests/tests/test_state_scripts.py

@@ -28,6 +28,7 @@
 from .common_update import common_update_procedure
 from ..helpers import Helpers
 from ..MenderAPI import DeviceAuthV2, Deployments, logger, image
+from ..MenderAPI.deployments import REBOOT_CROSSING_DEPLOYMENT_TIMEOUT
 from .mendertesting import MenderTesting
 from testutils.infra.device import MenderDeviceGroup
 
@@ -838,8 +839,16 @@ def fetch_info(cmd_list):
                         'Waited too long for "Error" to appear in log:\n%s' % info
                     )
             else:
+                # Reboot-crossing failure cases (ArtifactReboot / ArtifactCommit
+                # failures and the Corrupted_script_version sets) only reach
+                # 'failure' after the client's automatic-reboot watchdog. Use the
+                # derived deadline so we never race it -- it is a function of the
+                # client watchdog, not an independent magic number.
                 deploy.check_expected_statistics(
-                    deployment_id, test_set["ExpectedStatus"], 1
+                    deployment_id,
+                    test_set["ExpectedStatus"],
+                    1,
+                    max_wait=REBOOT_CROSSING_DEPLOYMENT_TIMEOUT,
                 )
 
             # Always give the client a little bit of time to settle in the base