Merge #16656: test: fix rpc_setban.py race

6011c9d72d1df5c2cd09de6f85c21eb4f7eb1ba8 QA: fix rpc_setban.py race (Jonas Schnelli)

Pull request description:

  The new `rpc_setban.py` test failes regularly on CIs due to a race between injecting the ban and testing the log "on the other side".

  The problem is, that the test immediately after the `addnode` command on node0 checks for the `dropped (banned)` entry on node1 (without giving some time).

  Adding a 2 seconds sleep seems to solve the race (I guess there is no better event-driven delay).

  Example of a failed test: https://bitcoinbuilds.org/index.php?ansilog=bf743910-103f-4b54-9a97-960c471061bd.log#l2906

Top commit has no ACKs.

Tree-SHA512: 680f8ea3e5ddb07e93f824f1aeff4a459e25e6c14715a39fc7670e50506d7cf25925348672c5c2d8ba3e1243ccf5effbc2456bcd094fb96868349f8d26e008f1

2 files changed, 18 insertions, 9 deletions

diff --git a/test/functional/rpc_setban.py b/test/functional/rpc_setban.py
index a1a8196557..423741fd27 100755
--- a/test/functional/rpc_setban.py
+++ b/test/functional/rpc_setban.py
@@ -26,7 +26,7 @@ class SetBanTests(BitcoinTestFramework):
         self.nodes[1].setban("127.0.0.1", "add")
 
         # Node 0 should not be able to reconnect
-        with self.nodes[1].assert_debug_log(expected_msgs=['dropped (banned)\n']):
+        with self.nodes[1].assert_debug_log(expected_msgs=['dropped (banned)\n'],timeout=5):
             self.restart_node(1, [])
             self.nodes[0].addnode("127.0.0.1:" + str(p2p_port(1)), "onetry")
 
diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py
index df027397d2..9667cf4ea4 100755
--- a/test/functional/test_framework/test_node.py
+++ b/test/functional/test_framework/test_node.py
@@ -307,7 +307,8 @@ class TestNode():
         wait_until(self.is_node_stopped, timeout=timeout)
 
     @contextlib.contextmanager
-    def assert_debug_log(self, expected_msgs):
+    def assert_debug_log(self, expected_msgs, timeout=2):
+        time_end = time.time() + timeout
         debug_log = os.path.join(self.datadir, self.chain, 'debug.log')
         with open(debug_log, encoding='utf-8') as dl:
             dl.seek(0, 2)
@@ -315,13 +316,21 @@ class TestNode():
         try:
             yield
         finally:
-            with open(debug_log, encoding='utf-8') as dl:
-                dl.seek(prev_size)
-                log = dl.read()
-            print_log = " - " + "\n - ".join(log.splitlines())
-            for expected_msg in expected_msgs:
-                if re.search(re.escape(expected_msg), log, flags=re.MULTILINE) is None:
-                    self._raise_assertion_error('Expected message "{}" does not partially match log:\n\n{}\n\n'.format(expected_msg, print_log))
+            while True:
+                found = True
+                with open(debug_log, encoding='utf-8') as dl:
+                    dl.seek(prev_size)
+                    log = dl.read()
+                print_log = " - " + "\n - ".join(log.splitlines())
+                for expected_msg in expected_msgs:
+                    if re.search(re.escape(expected_msg), log, flags=re.MULTILINE) is None:
+                        found = False
+                if found:
+                    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))
 
     @contextlib.contextmanager
     def assert_memory_usage_stable(self, *, increase_allowed=0.03):