[Tests] Eliminate intermittent failures in sendheaders.py

- Add race-condition debugging tool to mininode
- Eliminate race condition in sendheaders.py test

Clear the last block announcement before mining new blocks.

Github-Pull: #7308
Rebased-From: 82a0ce09b45ab9c09ce4f516be5b9b413dcec470 168915e6dec88b31793d4ee4b60b94d4149de36c

2 files changed, 24 insertions, 9 deletions

diff --git a/qa/rpc-tests/sendheaders.py b/qa/rpc-tests/sendheaders.py
index e6e26dbce3..7572bc2776 100755
--- a/qa/rpc-tests/sendheaders.py
+++ b/qa/rpc-tests/sendheaders.py
@@ -220,18 +220,20 @@ class SendHeadersTest(BitcoinTestFramework):
 
     # mine count blocks and return the new tip
     def mine_blocks(self, count):
+        # Clear out last block announcement from each p2p listener
+        [ x.clear_last_announcement() for x in self.p2p_connections ]
         self.nodes[0].generate(count)
         return int(self.nodes[0].getbestblockhash(), 16)
 
     # mine a reorg that invalidates length blocks (replacing them with
     # length+1 blocks).
-    # peers is the p2p nodes we're using; we clear their state after the
+    # Note: we clear the state of our p2p connections after the
     # to-be-reorged-out blocks are mined, so that we don't break later tests.
     # return the list of block hashes newly mined
-    def mine_reorg(self, length, peers):
+    def mine_reorg(self, length):
         self.nodes[0].generate(length) # make sure all invalidated blocks are node0's
         sync_blocks(self.nodes, wait=0.1)
-        [x.clear_last_announcement() for x in peers]
+        [x.clear_last_announcement() for x in self.p2p_connections]
 
         tip_height = self.nodes[1].getblockcount()
         hash_to_invalidate = self.nodes[1].getblockhash(tip_height-(length-1))
@@ -245,6 +247,8 @@ class SendHeadersTest(BitcoinTestFramework):
         inv_node = InvNode()
         test_node = TestNode()
 
+        self.p2p_connections = [inv_node, test_node]
+
         connections = []
         connections.append(NodeConn('127.0.0.1', p2p_port(0), self.nodes[0], inv_node))
         # Set nServices to 0 for test_node, so no block download will occur outside of
@@ -303,7 +307,6 @@ class SendHeadersTest(BitcoinTestFramework):
         prev_tip = int(self.nodes[0].getbestblockhash(), 16)
         test_node.get_headers(locator=[prev_tip], hashstop=0L)
         test_node.sync_with_ping()
-        test_node.clear_last_announcement() # Clear out empty headers response
 
         # Now that we've synced headers, headers announcements should work
         tip = self.mine_blocks(1)
@@ -352,8 +355,6 @@ class SendHeadersTest(BitcoinTestFramework):
                 # broadcast it)
                 assert_equal(inv_node.last_inv, None)
                 assert_equal(inv_node.last_headers, None)
-                inv_node.clear_last_announcement()
-                test_node.clear_last_announcement()
                 tip = self.mine_blocks(1)
                 assert_equal(inv_node.check_last_announcement(inv=[tip]), True)
                 assert_equal(test_node.check_last_announcement(headers=[tip]), True)
@@ -368,7 +369,7 @@ class SendHeadersTest(BitcoinTestFramework):
         # getheaders or inv from peer.
         for j in xrange(2):
             # First try mining a reorg that can propagate with header announcement
-            new_block_hashes = self.mine_reorg(length=7, peers=[test_node, inv_node])
+            new_block_hashes = self.mine_reorg(length=7)
             tip = new_block_hashes[-1]
             assert_equal(inv_node.check_last_announcement(inv=[tip]), True)
             assert_equal(test_node.check_last_announcement(headers=new_block_hashes), True)
@@ -376,7 +377,7 @@ class SendHeadersTest(BitcoinTestFramework):
             block_time += 8 
 
             # Mine a too-large reorg, which should be announced with a single inv
-            new_block_hashes = self.mine_reorg(length=8, peers=[test_node, inv_node])
+            new_block_hashes = self.mine_reorg(length=8)
             tip = new_block_hashes[-1]
             assert_equal(inv_node.check_last_announcement(inv=[tip]), True)
             assert_equal(test_node.check_last_announcement(inv=[tip]), True)
@@ -407,7 +408,6 @@ class SendHeadersTest(BitcoinTestFramework):
                     test_node.get_headers(locator=[fork_point], hashstop=new_block_hashes[1])
                     test_node.get_data([tip])
                     test_node.wait_for_block(tip)
-                    test_node.clear_last_announcement()
                 elif i == 2:
                     test_node.get_data([tip])
                     test_node.wait_for_block(tip)
diff --git a/qa/rpc-tests/test_framework/mininode.py b/qa/rpc-tests/test_framework/mininode.py
index 8e49b56565..ca65fb6e79 100755
--- a/qa/rpc-tests/test_framework/mininode.py
+++ b/qa/rpc-tests/test_framework/mininode.py
@@ -1004,6 +1004,18 @@ class msg_reject(object):
 class NodeConnCB(object):
     def __init__(self):
         self.verack_received = False
+        # deliver_sleep_time is helpful for debugging race conditions in p2p
+        # tests; it causes message delivery to sleep for the specified time
+        # before acquiring the global lock and delivering the next message.
+        self.deliver_sleep_time = None
+
+    def set_deliver_sleep_time(self, value):
+        with mininode_lock:
+            self.deliver_sleep_time = value
+
+    def get_deliver_sleep_time(self):
+        with mininode_lock:
+            return self.deliver_sleep_time
 
     # Spin until verack message is received from the node.
     # Tests may want to use this as a signal that the test can begin.
@@ -1017,6 +1029,9 @@ class NodeConnCB(object):
             time.sleep(0.05)
 
     def deliver(self, conn, message):
+        deliver_sleep = self.get_deliver_sleep_time()
+        if deliver_sleep is not None:
+            time.sleep(deliver_sleep)
         with mininode_lock:
             try:
                 getattr(self, 'on_' + message.command)(conn, message)