chg: test: Improve logging from isctest.run.retry_with_timeout

Allow use of exception (and by extension, assert statements) in the
called function in order to extract essential debug information about
the type of failure that was encountered.

In case the called function fails to succeed on the last retry and
raised an exception, log it as error and set it as the assert message to
propagate it through the pytest framework.

Closes #5324

Merge branch '5324-pytest-isctest-run-logging' into 'main'

See merge request isc-projects/bind9!10580

bin/tests/system/doth/tests_gnutls.py

@@ -72,11 +72,11 @@ def test_gnutls_cli_query(gnutls_cli_executable, named_tlsport):
         # upon receiving a DNS response.
         selector = selectors.DefaultSelector()
         selector.register(gnutls_cli.stdout, selectors.EVENT_READ)
-        deadline = time.time() + 10
+        deadline = time.monotonic() + 10
         gnutls_cli_output = b""
         response = b""
         while not response and not gnutls_cli.poll():
-            if not selector.select(timeout=deadline - time.time()):
+            if not selector.select(timeout=deadline - time.monotonic()):
                 break
             gnutls_cli_output += gnutls_cli.stdout.read(512)
             try:

bin/tests/system/isctest/kasp.py

@@ -651,7 +651,9 @@ def check_keys(zone, keys, expected):
     def _verify_keys():
         # check number of keys matches expected.
         if len(keys) != len(expected):
-            return False
+            assert (
+                False
+            ), f"check_keys(): mismatched number of keys, expected {len(expected)}, got {len(keys)}"
 
         if len(keys) == 0:
             return True
@@ -670,7 +672,7 @@ def check_keys(zone, keys, expected):
                         expected[i].key = key
                 i += 1
             if not found:
-                return False
+                assert False, f"check_keys(): key {key} not found"
 
         return True
 

bin/tests/system/isctest/log/watchlog.py

@@ -229,8 +229,8 @@ class WatchLog(abc.ABC):
             raise WatchLogException("No file to watch")
         leftover = ""
         assert timeout, "Do not use this class unless you want to WAIT for something."
-        deadline = time.time() + timeout
-        while time.time() < deadline:
+        deadline = time.monotonic() + timeout
+        while time.monotonic() < deadline:
             for line in self._fd.readlines():
                 if line[-1] != "\n":
                     # Line is not completely written yet, buffer and keep on waiting

bin/tests/system/isctest/run.py

@@ -126,13 +126,23 @@ def perl(script: str, args: Optional[List[str]] = None) -> None:
 
 
 def retry_with_timeout(func, timeout, delay=1, msg=None):
-    start_time = time.time()
-    while time.time() < start_time + timeout:
-        if func():
-            return
+    start_time = time.monotonic()
+    exc_msg = None
+    while time.monotonic() < start_time + timeout:
+        exc_msg = None
+        try:
+            if func():
+                return
+        except AssertionError as exc:
+            exc_msg = str(exc)
         time.sleep(delay)
+    if exc_msg is not None:
+        isctest.log.error(exc_msg)
     if msg is None:
-        msg = f"{func.__module__}.{func.__qualname__} timed out after {timeout} s"
+        if exc_msg is not None:
+            msg = exc_msg
+        else:
+            msg = f"{func.__module__}.{func.__qualname__} timed out after {timeout} s"
     assert False, msg
 
 

bin/tests/system/isctest/util.py

@@ -10,6 +10,7 @@
 # information regarding copyright ownership.
 
 import dns.zone
+import pytest
 
 
 def zone_contains(
@@ -40,3 +41,9 @@ def file_contents_contain(file, substr):
             if f"{substr}" in line:
                 return True
     return False
+
+
+def param(*args, **kwargs):
+    if "id" not in kwargs:
+        kwargs["id"] = args[0]  # use first argument  as test ID
+    return pytest.param(*args, **kwargs)

bin/tests/system/kasp/tests_kasp.py

@@ -26,6 +26,7 @@ from isctest.kasp import (
     KeyProperties,
     KeyTimingMetadata,
 )
+from isctest.util import param
 from isctest.vars.algorithms import ECDSAP256SHA256, ECDSAP384SHA384
 
 pytestmark = pytest.mark.extra_artifacts(
@@ -129,12 +130,6 @@ KASP_INHERIT_TSIG_SECRET = {
 }
 
 
-def param(*args, **kwargs):
-    if "id" not in kwargs:
-        kwargs["id"] = args[0]  # use first argument  as test ID
-    return pytest.param(*args, **kwargs)
-
-
 def autosign_properties(alg, size):
     return [
         f"ksk {lifetime['P2Y']} {alg} {size} goal:omnipresent dnskey:omnipresent krrsig:omnipresent ds:omnipresent",

bin/tests/system/pipelined/ans5/ans.py

@@ -84,7 +84,7 @@ class TCPDelayer(threading.Thread):
         while self.running:
             curr_timeout = 0.5
             try:
-                curr_timeout = self.queue[0][0] - time.time()
+                curr_timeout = self.queue[0][0] - time.monotonic()
             except StopIteration:
                 pass
             if curr_timeout > 0:
@@ -97,14 +97,14 @@ class TCPDelayer(threading.Thread):
                     data = self.conn.recv(65535)
                     if not data:
                         return
-                    self.queue.append((time.time() + DELAY, data))
+                    self.queue.append((time.monotonic() + DELAY, data))
                 if self.cconn in rfds:
                     data = self.cconn.recv(65535)
                     if not data == 0:
                         return
                     self.conn.send(data)
             try:
-                while self.queue[0][0] - time.time() < 0:
+                while self.queue[0][0] - time.monotonic() < 0:
                     _, data = self.queue.pop(0)
                     self.cconn.send(data)
             except StopIteration:
@@ -133,7 +133,7 @@ class UDPDelayer(threading.Thread):
         while self.running:
             curr_timeout = 0.5
             if self.queue:
-                curr_timeout = self.queue[0][0] - time.time()
+                curr_timeout = self.queue[0][0] - time.monotonic()
             if curr_timeout >= 0:
                 if curr_timeout == 0:
                     curr_timeout = 0.5
@@ -144,7 +144,7 @@ class UDPDelayer(threading.Thread):
                     data, addr = self.sock.recvfrom(65535)
                     if not data:
                         return
-                    self.queue.append((time.time() + DELAY, data))
+                    self.queue.append((time.monotonic() + DELAY, data))
                     qid = struct.unpack(">H", data[:2])[0]
                     log("Received a query from %s, queryid %d" % (str(addr), qid))
                     self.qid_mapping[qid] = addr
@@ -160,7 +160,7 @@ class UDPDelayer(threading.Thread):
                             "Received a response from %s, queryid %d, sending to %s"
                             % (str(addr), qid, str(dst))
                         )
-            while self.queue and self.queue[0][0] - time.time() < 0:
+            while self.queue and self.queue[0][0] - time.monotonic() < 0:
                 _, data = self.queue.pop(0)
                 qid = struct.unpack(">H", data[:2])[0]
                 log("Sending a query to %s, queryid %d" % (str(self.dst), qid))

bin/tests/system/tcp/ans6/ans.py

@@ -71,9 +71,9 @@ def open_connections(active_conns, count, host, port):
         else:
             queued.append(sock)
 
-    start = time.time()
+    start = time.monotonic()
     while queued:
-        now = time.time()
+        now = time.monotonic()
         time_left = OPEN_TIMEOUT - (now - start)
         if time_left <= 0:
             break