From 620c884133f1cac13efebaf381855462a123927c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nicki=20K=C5=99=C3=AD=C5=BEek?= Date: Fri, 6 Jun 2025 15:11:44 +0200 Subject: [PATCH 1/3] 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. --- bin/tests/system/isctest/kasp.py | 6 ++++-- bin/tests/system/isctest/run.py | 16 +++++++++++++--- 2 files changed, 17 insertions(+), 5 deletions(-) diff --git a/bin/tests/system/isctest/kasp.py b/bin/tests/system/isctest/kasp.py index 86e05ebac9..26ab63c740 100644 --- a/bin/tests/system/isctest/kasp.py +++ b/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 diff --git a/bin/tests/system/isctest/run.py b/bin/tests/system/isctest/run.py index c3b37ac059..b26190e4a3 100644 --- a/bin/tests/system/isctest/run.py +++ b/bin/tests/system/isctest/run.py @@ -127,12 +127,22 @@ def perl(script: str, args: Optional[List[str]] = None) -> None: def retry_with_timeout(func, timeout, delay=1, msg=None): start_time = time.time() + exc_msg = None while time.time() < start_time + timeout: - if func(): - return + 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 From 481b46ffccbdb6e0fbdb13a8bc437d50e44a4ca9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nicki=20K=C5=99=C3=AD=C5=BEek?= Date: Fri, 6 Jun 2025 10:46:42 +0200 Subject: [PATCH 2/3] Move param to isctest.util --- bin/tests/system/isctest/util.py | 7 +++++++ bin/tests/system/kasp/tests_kasp.py | 7 +------ 2 files changed, 8 insertions(+), 6 deletions(-) diff --git a/bin/tests/system/isctest/util.py b/bin/tests/system/isctest/util.py index 904e088ff6..eec03ae724 100644 --- a/bin/tests/system/isctest/util.py +++ b/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) diff --git a/bin/tests/system/kasp/tests_kasp.py b/bin/tests/system/kasp/tests_kasp.py index e6bc020554..2440914995 100644 --- a/bin/tests/system/kasp/tests_kasp.py +++ b/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", From 069e4ef0f72bfe045123db817908460144ff70f7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nicki=20K=C5=99=C3=AD=C5=BEek?= Date: Thu, 19 Jun 2025 14:09:57 +0200 Subject: [PATCH 3/3] Use time.monotonic() for time measumeremts in pytest For duration measurements, i.e. deadlines and timeouts, it's more suitable to use monotonic time as it's guaranteed to only go forward, unlike time.time() which can be affected by local clock settings. --- bin/tests/system/doth/tests_gnutls.py | 4 ++-- bin/tests/system/isctest/log/watchlog.py | 4 ++-- bin/tests/system/isctest/run.py | 4 ++-- bin/tests/system/pipelined/ans5/ans.py | 12 ++++++------ bin/tests/system/tcp/ans6/ans.py | 4 ++-- 5 files changed, 14 insertions(+), 14 deletions(-) diff --git a/bin/tests/system/doth/tests_gnutls.py b/bin/tests/system/doth/tests_gnutls.py index 8770206fa8..f49b4401c5 100644 --- a/bin/tests/system/doth/tests_gnutls.py +++ b/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: diff --git a/bin/tests/system/isctest/log/watchlog.py b/bin/tests/system/isctest/log/watchlog.py index b17cd0597f..ffa75e156d 100644 --- a/bin/tests/system/isctest/log/watchlog.py +++ b/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 diff --git a/bin/tests/system/isctest/run.py b/bin/tests/system/isctest/run.py index b26190e4a3..5c994ce377 100644 --- a/bin/tests/system/isctest/run.py +++ b/bin/tests/system/isctest/run.py @@ -126,9 +126,9 @@ def perl(script: str, args: Optional[List[str]] = None) -> None: def retry_with_timeout(func, timeout, delay=1, msg=None): - start_time = time.time() + start_time = time.monotonic() exc_msg = None - while time.time() < start_time + timeout: + while time.monotonic() < start_time + timeout: exc_msg = None try: if func(): diff --git a/bin/tests/system/pipelined/ans5/ans.py b/bin/tests/system/pipelined/ans5/ans.py index bac5ed35d8..b58ad84bef 100644 --- a/bin/tests/system/pipelined/ans5/ans.py +++ b/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)) diff --git a/bin/tests/system/tcp/ans6/ans.py b/bin/tests/system/tcp/ans6/ans.py index 4595ddcd07..b94697e2cd 100644 --- a/bin/tests/system/tcp/ans6/ans.py +++ b/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