diff --git a/tests/MenderAPI/deployments.py b/tests/MenderAPI/deployments.py index f099bc8b1..e1c339bf4 100644 --- a/tests/MenderAPI/deployments.py +++ b/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): diff --git a/tests/tests/test_fault_tolerance.py b/tests/tests/test_fault_tolerance.py index 0b5c1034e..62e79ae91 100644 --- a/tests/tests/test_fault_tolerance.py +++ b/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 diff --git a/tests/tests/test_state_scripts.py b/tests/tests/test_state_scripts.py index ebcfd0121..784d57888 100644 --- a/tests/tests/test_state_scripts.py +++ b/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