From 5c16e4631c009056d571d83fe17062c107f71798 Mon Sep 17 00:00:00 2001 From: Hodlinator <172445034+hodlinator@users.noreply.github.com> Date: Fri, 26 Sep 2025 22:26:12 +0200 Subject: [PATCH 1/4] doc: Remove no longer correct comment MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Left over since fa7b07571f24b6def6effdd4cc1b96c7507bf959. Co-authored-by: Lőrinc --- test/functional/test_framework/test_node.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index 1ec2fe8a657..0540ca34694 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -575,8 +575,6 @@ class TestNode(): def busy_wait_for_debug_log(self, expected_msgs, timeout=60): """ Block until we see a particular debug log message fragment or until we exceed the timeout. - Return: - the number of log lines we encountered when matching """ time_end = time.time() + timeout * self.timeout_factor prev_size = self.debug_log_size(mode="rb") # Must use same mode that is used to read() below From a9021101dc63ee7fb1e1f342387ab7d3f0e3cefc Mon Sep 17 00:00:00 2001 From: Hodlinator <172445034+hodlinator@users.noreply.github.com> Date: Sat, 20 Sep 2025 19:59:08 +0200 Subject: [PATCH 2/4] qa: Replace always-escaped regexps with "X in Y" MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Always escaping the search string makes the use of regular expressions unnecessary. Co-authored-by: Lőrinc --- test/functional/test_framework/test_node.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index 0540ca34694..3a13a923404 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -559,10 +559,10 @@ class TestNode(): log = dl.read() print_log = " - " + "\n - ".join(log.splitlines()) for unexpected_msg in unexpected_msgs: - if re.search(re.escape(unexpected_msg), log, flags=re.MULTILINE): + if unexpected_msg in log: self._raise_assertion_error('Unexpected message "{}" partially matches log:\n\n{}\n\n'.format(unexpected_msg, print_log)) for expected_msg in expected_msgs: - if re.search(re.escape(expected_msg), log, flags=re.MULTILINE) is None: + if expected_msg not in log: found = False if found: return From 1e54125e2e0063e4586265b957912896c056ba0a Mon Sep 17 00:00:00 2001 From: Hodlinator <172445034+hodlinator@users.noreply.github.com> Date: Fri, 19 Sep 2025 15:05:50 +0200 Subject: [PATCH 3/4] refactor(qa): Avoid unnecessary string operations print_log was recalculated every 0.05s in assert_debug_log(), even during successful circumstances - changed to only be computed upon failure. Simplified terminology from "(does not) partially match(es)" to "(not) found in" since it seems to reference the first function having used regular expression matching, while it always escaped the search strings (see parent commit). (Simplified grammar also avoids issues with singular/plural "was/were not found"). --- test/functional/test_framework/test_node.py | 15 +++++++++------ 1 file changed, 9 insertions(+), 6 deletions(-) diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index 3a13a923404..cf92f926bca 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -550,6 +550,9 @@ class TestNode(): time_end = time.time() + timeout * self.timeout_factor prev_size = self.debug_log_size(encoding="utf-8") # Must use same encoding that is used to read() below + def join_log(log): + return " - " + "\n - ".join(log.splitlines()) + yield while True: @@ -557,10 +560,10 @@ class TestNode(): with open(self.debug_log_path, encoding="utf-8", errors="replace") as dl: dl.seek(prev_size) log = dl.read() - print_log = " - " + "\n - ".join(log.splitlines()) for unexpected_msg in unexpected_msgs: if unexpected_msg in log: - self._raise_assertion_error('Unexpected message "{}" partially matches log:\n\n{}\n\n'.format(unexpected_msg, print_log)) + self._raise_assertion_error(f'Unexpected message "{unexpected_msg}" ' + f'found in log:\n\n{join_log(log)}\n\n') for expected_msg in expected_msgs: if expected_msg not in log: found = False @@ -569,7 +572,8 @@ class TestNode(): if time.time() >= time_end: break time.sleep(0.05) - self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log)) + self._raise_assertion_error(f'Expected message(s) {expected_msgs!s} ' + f'not found in log:\n\n{join_log(log)}\n\n') @contextlib.contextmanager def busy_wait_for_debug_log(self, expected_msgs, timeout=60): @@ -601,9 +605,8 @@ class TestNode(): # No sleep here because we want to detect the message fragment as fast as # possible. - self._raise_assertion_error( - 'Expected messages "{}" does not partially match log:\n\n{}\n\n'.format( - str(expected_msgs), print_log)) + self._raise_assertion_error(f'Expected message(s) {expected_msgs!s} ' + f'not found in log:\n\n{print_log}\n\n') @contextlib.contextmanager def wait_for_new_peer(self, timeout=5): From a1f76230209629c5141984aaac1cc4ba7b4f761a Mon Sep 17 00:00:00 2001 From: Hodlinator <172445034+hodlinator@users.noreply.github.com> Date: Thu, 25 Sep 2025 23:12:01 +0200 Subject: [PATCH 4/4] qa: Only complain about expected messages that were not found MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Only leaves messages we never found in the final assert message of the functions, which is more helpful (remaining_expected). Avoids repeatedly searching for messages we have already found (pop()). Stops searching for other expected messages if we already failed finding one. Still need to clean remaining_expected at the end, but *only if we fail*. Co-authored-by: Lőrinc --- test/functional/test_framework/test_node.py | 25 ++++++++++----------- 1 file changed, 12 insertions(+), 13 deletions(-) diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index cf92f926bca..653d58d0b53 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -546,6 +546,7 @@ class TestNode(): unexpected_msgs = [] assert_equal(type(expected_msgs), list) assert_equal(type(unexpected_msgs), list) + remaining_expected = list(expected_msgs) time_end = time.time() + timeout * self.timeout_factor prev_size = self.debug_log_size(encoding="utf-8") # Must use same encoding that is used to read() below @@ -556,7 +557,6 @@ class TestNode(): yield while True: - found = True with open(self.debug_log_path, encoding="utf-8", errors="replace") as dl: dl.seek(prev_size) log = dl.read() @@ -564,15 +564,15 @@ class TestNode(): if unexpected_msg in log: self._raise_assertion_error(f'Unexpected message "{unexpected_msg}" ' f'found in log:\n\n{join_log(log)}\n\n') - for expected_msg in expected_msgs: - if expected_msg not in log: - found = False - if found: + while remaining_expected and remaining_expected[-1] in log: + remaining_expected.pop() + if not remaining_expected: return if time.time() >= time_end: break time.sleep(0.05) - self._raise_assertion_error(f'Expected message(s) {expected_msgs!s} ' + remaining_expected = [e for e in remaining_expected if e not in log] + self._raise_assertion_error(f'Expected message(s) {remaining_expected!s} ' f'not found in log:\n\n{join_log(log)}\n\n') @contextlib.contextmanager @@ -582,20 +582,18 @@ class TestNode(): """ time_end = time.time() + timeout * self.timeout_factor prev_size = self.debug_log_size(mode="rb") # Must use same mode that is used to read() below + remaining_expected = list(expected_msgs) yield while True: - found = True with open(self.debug_log_path, "rb") as dl: dl.seek(prev_size) log = dl.read() - for expected_msg in expected_msgs: - if expected_msg not in log: - found = False - - if found: + while remaining_expected and remaining_expected[-1] in log: + remaining_expected.pop() + if not remaining_expected: return if time.time() >= time_end: @@ -605,7 +603,8 @@ class TestNode(): # No sleep here because we want to detect the message fragment as fast as # possible. - self._raise_assertion_error(f'Expected message(s) {expected_msgs!s} ' + remaining_expected = [e for e in remaining_expected if e not in log] + self._raise_assertion_error(f'Expected message(s) {remaining_expected!s} ' f'not found in log:\n\n{print_log}\n\n') @contextlib.contextmanager