diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index 060a932d1c8..b3f3d2d304c 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -550,54 +550,54 @@ 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 + def join_log(log): + return " - " + "\n - ".join(log.splitlines()) + 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() - print_log = " - " + "\n - ".join(log.splitlines()) for unexpected_msg in unexpected_msgs: - if re.search(re.escape(unexpected_msg), log, flags=re.MULTILINE): - 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: - found = False - if found: + 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') + 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('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log)) + 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 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 + 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: @@ -607,9 +607,9 @@ 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)) + 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 def wait_for_new_peer(self, timeout=5):