Merge ~adam-collard/maas-ci/+git/system-tests:debug-after-giving-up-waiting into ~maas-committers/maas-ci/+git/system-tests:master

[Adam Collard]

Get debug information after we give up waiting for machines

[Alberto Donato (ack)]

nice, +1

small nit inline

review: Approve

42fe55c... by Adam Collard on 2021-08-25

ack's feedback

[Diego Mascialino (dmascialino)]

I like this feature. Two comments inline

[Diego Mascialino (dmascialino)]

looks good.

review: Approve

diff --git a/systemtests/api.py b/systemtests/api.py
index 18c9b52..6a55cae 100644
--- a/systemtests/api.py
+++ b/systemtests/api.py
@@ -2,7 +2,7 @@ import json
 import time
 from logging import getLogger
 
-from .utils import wait_for_machines
+from .utils import filter_just_hostname, wait_for_machines
 
 LOG = getLogger("systemtests.api")
 
@@ -144,6 +144,7 @@ class AuthenticatedAPIClient:
         wait_for_machines(
             self,
             [{"hostname": machine["hostname"], "status": "ready"}],
+            filter_just_hostname,
             timeout=5 * 60,
             delay=10,
         )
@@ -185,6 +186,7 @@ class AuthenticatedAPIClient:
         wait_for_machines(
             self,
             [{"hostname": machine["hostname"], "status": "rescue_mode"}],
+            filter_just_hostname,
             timeout=20 * 60,
             delay=30,
         )
@@ -195,6 +197,7 @@ class AuthenticatedAPIClient:
         wait_for_machines(
             self,
             [{"hostname": machine["hostname"], "status": next_status}],
+            filter_just_hostname,
             timeout=20 * 60,
             delay=30,
         )
diff --git a/systemtests/tests/test_admin.py b/systemtests/tests/test_admin.py
index c70a35e..01653c8 100644
--- a/systemtests/tests/test_admin.py
+++ b/systemtests/tests/test_admin.py
@@ -1,6 +1,6 @@
 import pytest
 
-from ..utils import ssh_execute_command, wait_for_machines
+from ..utils import filter_just_mac, ssh_execute_command, wait_for_machines
 
 
 @pytest.mark.usefixtures("authenticated_admin")
@@ -89,7 +89,9 @@ class TestMachines:
             waiting_for.append(
                 {"mac_address": power_config["mac_address"], "status": "new"}
             )
-        wait_for_machines(authenticated_admin, waiting_for, timeout=20 * 60)
+        wait_for_machines(
+            authenticated_admin, waiting_for, filter_just_mac, timeout=20 * 60
+        )
 
     @pytest.mark.dependency(name="commission", depends=["enlist"])
     def test_commission(self, authenticated_admin, config):
@@ -101,7 +103,9 @@ class TestMachines:
             authenticated_admin.commission_machine(machine)
             waiting_for.append({"mac_address": mac_address, "status": "ready"})
 
-        wait_for_machines(authenticated_admin, waiting_for, timeout=20 * 60)
+        wait_for_machines(
+            authenticated_admin, waiting_for, filter_just_mac, timeout=20 * 60
+        )
 
     @pytest.mark.dependency(name="deploy", depends=["commission"])
     def test_deploy(self, authenticated_admin, config, ssh_key, testlog):
@@ -113,7 +117,9 @@ class TestMachines:
             authenticated_admin.deploy_machine(machine, osystem=osystem)
             waiting_for.append({"mac_address": mac_address, "status": "deployed"})
 
-        wait_for_machines(authenticated_admin, waiting_for, timeout=20 * 60)
+        wait_for_machines(
+            authenticated_admin, waiting_for, filter_just_mac, timeout=20 * 60
+        )
 
         leave_machine_deployed = True
         for machine_name, power_config in config["machines"]["hardware"].items():
diff --git a/systemtests/utils.py b/systemtests/utils.py
index 125b1c0..fe6bf93 100644
--- a/systemtests/utils.py
+++ b/systemtests/utils.py
@@ -6,6 +6,26 @@ import paramiko
 from retry.api import retry_call
 
 
+class UnexpectedMachineStatus(Exception):
+    """Raised when we run out of time waiting for machines to be in a given state.
+
+    Will report on the desired state, the time we waited for and debug outputs.
+    """
+
+    def __init__(self, filters, elapsed_time, debug_outputs):
+        self._filters = filters
+        self._elapsed_time = elapsed_time
+        self._debug_outputs = debug_outputs
+
+    def __str__(self):
+        return f"""\
+Machines not found for: {self._filters} after {self._elapsed_time:.01f} seconds.
+
+Debug information:
+{self._debug_outputs}
+"""
+
+
 def randomstring(length=10):
     """Return a random string."""
     return "".join(random.choice(string.ascii_lowercase) for _ in range(length))
@@ -29,8 +49,27 @@ def retries(timeout=30, delay=1):
             break
 
 
-def wait_for_machines(api_client, select_params, timeout=10 * 60, delay=30):
-    """Blocks execution until all select_params are satisfied."""
+def filter_just_mac(params):
+    return {"mac_address": params["mac_address"]}
+
+
+def filter_just_hostname(params):
+    return {"hostname": params["hostname"]}
+
+
+def wait_for_machines(
+    api_client, select_params, filter_for_debug, timeout=10 * 60, delay=30
+):
+    """Blocks execution until all select_params are satisfied.
+
+    `filter_for_debug` is called for each filter in the select_params
+    that doesn't match after `timeout` seconds with `delay` seconds
+    sleep between each attempt.
+
+    The results of the filters after calling `filter_for_debug` are
+    used to debug what's going on with the machines that didn't match
+    the given state.
+    """
     select_params = select_params.copy()  # I dont want to modify the extern values
 
     for elapsed, _ in retries(timeout, delay):
@@ -40,13 +79,17 @@ def wait_for_machines(api_client, select_params, timeout=10 * 60, delay=30):
         if not select_params:
             break
 
-    assert (
-        select_params == []
-    ), f"Machines not found for this params: {select_params} after {elapsed:.01f} seconds"
+    if select_params:
+        # We've timed out waiting for machines to match the filter
+        debug_outputs = []
+        for filters in select_params:
+            debug_filter = filter_for_debug(filters)
+            debug_outputs.append(api_client.list_machines(**debug_filter))
+        raise UnexpectedMachineStatus(select_params, elapsed, debug_outputs)
 
 
 def ssh_execute_command(machine, username, pkey, command):
-    """ Connect to machine, execute command and return stdout."""
+    """Connect to machine, execute command and return stdout."""
     client = paramiko.SSHClient()
     client.set_missing_host_key_policy(paramiko.AutoAddPolicy())