Merge bitcoin/bitcoin#33423: qa: Improvements to debug_assert_log + busy_wait_for_debug_log

a1f7623020 qa: Only complain about expected messages that were not found (Hodlinator)
1e54125e2e refactor(qa): Avoid unnecessary string operations (Hodlinator)
a9021101dc qa: Replace always-escaped regexps with "X in Y" (Hodlinator)
5c16e4631c doc: Remove no longer correct comment (Hodlinator)

Pull request description:

  * Remove incorrect docstring in `busy_wait_for_debug_log()`.
  * Replace nerfed regex searches with `X in Y` expressions.
  * Only compute the log string to be printed on failure *when we actually fail* instead of every 0.05s.
  * As we find each needle (expected message) in the haystack (log output), stop searching for it. **If we fail and time out, we will only complain about the needles (expected messages) we didn't find. On master we also include found needles, which is less helpful.**

  Found while developing a new test case in https://github.com/bitcoin/bitcoin/pull/33336#discussion_r2351892330

ACKs for top commit:
  l0rinc:
    Code review ACK a1f7623020
  maflcko:
    review ACK a1f7623020 💨

Tree-SHA512: 191ea7647b0ea8b4220e37c62d176861c2fd0e3737aee3641b262915d9118f48953cf1204767c93a93a8fc78a44c2c29206fb390b44c59d99fc2aa7d12bf4889

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):
+                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}" '
-            for expected_msg in expected_msgs:
+                                                f'found in log:\n\n{join_log(log)}\n\n')
-                if re.search(re.escape(expected_msg), log, flags=re.MULTILINE) is None:
+            while remaining_expected and remaining_expected[-1] in log:
-                    found = False
+                remaining_expected.pop()
-            if found:
+            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:
+            while remaining_expected and remaining_expected[-1] in log:
-                if expected_msg not in log:
+                remaining_expected.pop()
-                    found = False
+            if not remaining_expected:
-
-            if found:
                 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(
+        remaining_expected = [e for e in remaining_expected if e not in log]
-            'Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(
+        self._raise_assertion_error(f'Expected message(s) {remaining_expected!s} '
-                str(expected_msgs), print_log))
+                                    f'not found in log:\n\n{print_log}\n\n')
 
     @contextlib.contextmanager
     def wait_for_new_peer(self, timeout=5):