Merge bitcoin/bitcoin#34581: test: Set assert_debug_log timeout to 0

fa4cb96bde test: Set assert_debug_log timeout to 0 (MarcoFalke)

Pull request description:

  The `assert_debug_log` helper is meant to be a context manager. However, it has a  default timeout of 2 seconds, and can act as a silent polling/wait/sync function. This is confusing and brittle, and leads to intermittent bugs such as https://github.com/bitcoin/bitcoin/pull/34571.

  Fix all issues, by setting the default timeout to zero. Then adjust all call sites to either use this correctly like a context manager, or adjust them explicitly to specify a timeout, to document that this is a polling sync function.

ACKs for top commit:
  hodlinator:
    re-ACK fa4cb96bde
  brunoerg:
    ACK fa4cb96bde

Tree-SHA512: 111a45c84327c3afea98fd9f8de13dd7d11969b2309471b4ad21694b290a3734f6e1eda75a41b39613b0995c5b7075298085cea2ca06aa07d4385eb8d72fe95b

test/functional/feature_anchors.py

@@ -138,7 +138,7 @@ class AnchorsTest(BitcoinTestFramework):
             file_handler.write(new_data + new_data_hash)
 
         self.log.info("Restarting node attempts to reconnect to anchors")
-        with self.nodes[0].assert_debug_log([f"Trying to make an anchor connection to {ONION_ADDR}"]):
+        with self.nodes[0].assert_debug_log([f"Trying to make an anchor connection to {ONION_ADDR}"], timeout=2):
             self.start_node(0, extra_args=[f"-onion={onion_conf.addr[0]}:{onion_conf.addr[1]}"])
 
 

test/functional/feature_config_args.py

@@ -319,7 +319,7 @@ class ConfArgsTest(BitcoinTestFramework):
 
         with self.nodes[0].assert_debug_log(expected_msgs=[
                 "Adding fixed seeds as 60 seconds have passed and addrman is empty",
-        ]):
+        ], timeout=2):
             self.nodes[0].setmocktime(start + 65)
         self.stop_node(0)
 
@@ -330,7 +330,7 @@ class ConfArgsTest(BitcoinTestFramework):
                 "Loaded 0 addresses from peers.dat",
                 "DNS seeding disabled",
                 "Adding fixed seeds as -dnsseed=0 (or IPv4/IPv6 connections are disabled via -onlynet) and neither -addnode nor -seednode are provided\n",
-        ]):
+        ], timeout=2):
             self.start_node(0, extra_args=['-dnsseed=0', '-fixedseeds=1'])
         self.stop_node(0)
         self.nodes[0].assert_start_raises_init_error(['-dnsseed=1', '-onlynet=i2p', '-i2psam=127.0.0.1:7656'], "Error: Incompatible options: -dnsseed=1 was explicitly specified, but -onlynet forbids connections to IPv4/IPv6")
@@ -361,7 +361,7 @@ class ConfArgsTest(BitcoinTestFramework):
             self.start_node(0, extra_args=['-dnsseed=0', '-fixedseeds=1', '-addnode=fakenodeaddr', f'-mocktime={start}', UNREACHABLE_PROXY_ARG])
         with self.nodes[0].assert_debug_log(expected_msgs=[
                 "Adding fixed seeds as 60 seconds have passed and addrman is empty",
-        ]):
+        ], timeout=2):
             self.nodes[0].setmocktime(start + 65)
         self.stop_node(0)
 

test/functional/p2p_compactblocks.py

@@ -592,7 +592,7 @@ class CompactBlocksTest(BitcoinTestFramework):
         # Send the same blocktxn and assert the sender gets disconnected.
         with node.assert_debug_log(['previous compact block reconstruction attempt failed']):
             test_node.send_without_ping(msg)
-        test_node.wait_for_disconnect()
+            test_node.wait_for_disconnect()
 
     def test_getblocktxn_handler(self, test_node):
         node = self.nodes[0]
@@ -642,7 +642,7 @@ class CompactBlocksTest(BitcoinTestFramework):
         msg.block_txn_request = BlockTransactionsRequest(int(block_hash, 16), [len(block.vtx)])
         with node.assert_debug_log(['getblocktxn with out-of-bounds tx indices']):
             bad_peer.send_without_ping(msg)
-        bad_peer.wait_for_disconnect()
+            bad_peer.wait_for_disconnect()
 
     def test_low_work_compactblocks(self, test_node):
         # A compactblock with insufficient work won't get its header included

test/functional/p2p_dns_seeds.py

@@ -29,7 +29,7 @@ class P2PDNSSeeds(BitcoinTestFramework):
 
         self.log.info("Check that setting -connect disables -dnsseed by default")
         self.nodes[0].stop_node()
-        with self.nodes[0].assert_debug_log(expected_msgs=["DNS seeding disabled"]):
+        with self.nodes[0].assert_debug_log(expected_msgs=["DNS seeding disabled"], timeout=2):
             self.start_node(0, extra_args=[f"-connect={fakeaddr}", UNREACHABLE_PROXY_ARG])
 
         self.log.info("Check that running -connect and -dnsseed means DNS logic runs.")
@@ -103,7 +103,7 @@ class P2PDNSSeeds(BitcoinTestFramework):
             self.nodes[0].addpeeraddress(a, 8333)
 
         # The delay should be 11 seconds
-        with self.nodes[0].assert_debug_log(expected_msgs=["Waiting 11 seconds before querying DNS seeds.\n"]):
+        with self.nodes[0].assert_debug_log(expected_msgs=["Waiting 11 seconds before querying DNS seeds.\n"], timeout=2):
             self.restart_node(0)
 
         # Populate addrman with > 1000 addresses
@@ -122,7 +122,7 @@ class P2PDNSSeeds(BitcoinTestFramework):
                     break
 
         # The delay should be 5 mins
-        with self.nodes[0].assert_debug_log(expected_msgs=["Waiting 300 seconds before querying DNS seeds.\n"]):
+        with self.nodes[0].assert_debug_log(expected_msgs=["Waiting 300 seconds before querying DNS seeds.\n"], timeout=2):
             self.restart_node(0)
 
 

test/functional/p2p_headers_sync_with_minchainwork.py

@@ -56,7 +56,11 @@ class RejectLowDifficultyHeadersTest(BitcoinTestFramework):
 
     def test_chains_sync_when_long_enough(self):
         self.log.info("Generate blocks on the node with no required chainwork, and verify nodes 1 and 2 have no new headers in their headers tree")
-        with self.nodes[1].assert_debug_log(expected_msgs=["[net] Ignoring low-work chain (height=14)"]), self.nodes[2].assert_debug_log(expected_msgs=["[net] Ignoring low-work chain (height=14)"]), self.nodes[3].assert_debug_log(expected_msgs=["Synchronizing blockheaders, height: 14"]):
+        with (
+                self.nodes[1].assert_debug_log(expected_msgs=["[net] Ignoring low-work chain (height=14)"], timeout=2),
+                self.nodes[2].assert_debug_log(expected_msgs=["[net] Ignoring low-work chain (height=14)"], timeout=2),
+                self.nodes[3].assert_debug_log(expected_msgs=["Synchronizing blockheaders, height: 14"], timeout=2),
+        ):
             self.generate(self.nodes[0], NODE1_BLOCKS_REQUIRED-1, sync_fun=self.no_op)
 
         # Node3 should always allow headers due to noban permissions
@@ -85,7 +89,10 @@ class RejectLowDifficultyHeadersTest(BitcoinTestFramework):
             } in chaintips
 
         self.log.info("Generate more blocks to satisfy node1's minchainwork requirement, and verify node2 still has no new headers in headers tree")
-        with self.nodes[2].assert_debug_log(expected_msgs=["[net] Ignoring low-work chain (height=15)"]), self.nodes[3].assert_debug_log(expected_msgs=["Synchronizing blockheaders, height: 15"]):
+        with (
+                self.nodes[2].assert_debug_log(expected_msgs=["[net] Ignoring low-work chain (height=15)"], timeout=2),
+                self.nodes[3].assert_debug_log(expected_msgs=["Synchronizing blockheaders, height: 15"], timeout=2),
+        ):
             self.generate(self.nodes[0], NODE1_BLOCKS_REQUIRED - self.nodes[0].getblockcount(), sync_fun=self.no_op)
         self.sync_blocks(self.nodes[0:2]) # node3 will sync headers (noban permissions) but not blocks (due to minchainwork)
 

test/functional/p2p_initial_headers_sync.py

@@ -153,9 +153,9 @@ class HeadersSyncTest(BitcoinTestFramework):
         with self.nodes[0].assert_debug_log(["Timeout downloading headers, disconnecting peer=0"]):
             self.trigger_headers_timeout()
 
-        self.log.info("Check that stalling peer1 is disconnected")
-        peer1.wait_for_disconnect()
-        assert_equal(self.nodes[0].num_test_p2p_connections(), 1)
+            self.log.info("Check that stalling peer1 is disconnected")
+            peer1.wait_for_disconnect()
+            assert_equal(self.nodes[0].num_test_p2p_connections(), 1)
 
         self.log.info("Check that peer2 receives a getheaders request")
         peer2.wait_for_getheaders(block_hash=int(self.nodes[0].getbestblockhash(), 16))
@@ -169,9 +169,9 @@ class HeadersSyncTest(BitcoinTestFramework):
         with self.nodes[0].assert_debug_log(["Timeout downloading headers from noban peer, not disconnecting peer=0"]):
             self.trigger_headers_timeout()
 
-        self.log.info("Check that noban peer1 is not disconnected")
-        peer1.sync_with_ping()
-        assert_equal(self.nodes[0].num_test_p2p_connections(), 2)
+            self.log.info("Check that noban peer1 is not disconnected")
+            peer1.sync_with_ping()
+            assert_equal(self.nodes[0].num_test_p2p_connections(), 2)
 
         self.log.info("Check that exactly 1 of {peer1, peer2} receives a getheaders")
         self.assert_single_getheaders_recipient([peer1, peer2])

test/functional/p2p_mutated_blocks.py

@@ -81,8 +81,8 @@ class MutatedBlocksTest(BitcoinTestFramework):
         # mutated block (as the attacker).
         with self.nodes[0].assert_debug_log(expected_msgs=["Block mutated: bad-txnmrklroot, hashMerkleRoot mismatch"]):
             attacker.send_without_ping(msg_block(mutated_block))
-        # Attacker should get disconnected for sending a mutated block
-        attacker.wait_for_disconnect(timeout=5)
+            # Attacker should get disconnected for sending a mutated block
+            attacker.wait_for_disconnect(timeout=5)
 
         # Block at height 101 should *still* be the only block in-flight from
         # peer 0
@@ -108,7 +108,7 @@ class MutatedBlocksTest(BitcoinTestFramework):
         assert_equal(len(self.nodes[0].getpeerinfo()), 2)
         with self.nodes[0].assert_debug_log(expected_msgs=["AcceptBlock FAILED (prev-blk-not-found)"]):
             attacker.send_without_ping(msg_block(block_missing_prev))
-        attacker.wait_for_disconnect(timeout=5)
+            attacker.wait_for_disconnect(timeout=5)
 
 
 if __name__ == '__main__':

test/functional/p2p_sendtxrcncl.py

@@ -168,7 +168,7 @@ class SendTxRcnclTest(BitcoinTestFramework):
         self.restart_node(0, ["-txreconciliation"])
         self.log.info('valid SENDTXRCNCL received')
         peer = self.nodes[0].add_p2p_connection(PeerNoVerack(), send_version=True, wait_for_verack=False)
-        with self.nodes[0].assert_debug_log(["received: sendtxrcncl"]):
+        with self.nodes[0].assert_debug_log(["received: sendtxrcncl"], timeout=2):
             peer.send_without_ping(create_sendtxrcncl_msg())
         self.log.info('second SENDTXRCNCL triggers a disconnect')
         with self.nodes[0].assert_debug_log(["(sendtxrcncl received from already registered peer), disconnecting peer=0"]):
@@ -178,7 +178,7 @@ class SendTxRcnclTest(BitcoinTestFramework):
         self.restart_node(0, [])
         self.log.info('SENDTXRCNCL if no txreconciliation supported is ignored')
         peer = self.nodes[0].add_p2p_connection(PeerNoVerack(), send_version=True, wait_for_verack=False)
-        with self.nodes[0].assert_debug_log(['ignored, as our node does not have txreconciliation enabled']):
+        with self.nodes[0].assert_debug_log(['ignored, as our node does not have txreconciliation enabled'], timeout=2):
             peer.send_without_ping(create_sendtxrcncl_msg())
         self.nodes[0].disconnect_p2ps()
 
@@ -196,7 +196,7 @@ class SendTxRcnclTest(BitcoinTestFramework):
         sendtxrcncl_higher_version = create_sendtxrcncl_msg()
         sendtxrcncl_higher_version.version = 2
         peer = self.nodes[0].add_p2p_connection(PeerNoVerack(), send_version=True, wait_for_verack=False)
-        with self.nodes[0].assert_debug_log(['Register peer=1']):
+        with self.nodes[0].assert_debug_log(['Register peer=1'], timeout=2):
             peer.send_without_ping(sendtxrcncl_higher_version)
         self.nodes[0].disconnect_p2ps()
 
@@ -208,7 +208,7 @@ class SendTxRcnclTest(BitcoinTestFramework):
         old_version_msg.nServices = P2P_SERVICES
         old_version_msg.relay = 1
         peer.send_without_ping(old_version_msg)
-        with self.nodes[0].assert_debug_log(['Ignore unexpected txreconciliation signal']):
+        with self.nodes[0].assert_debug_log(['Ignore unexpected txreconciliation signal'], timeout=2):
             peer.send_without_ping(create_sendtxrcncl_msg())
         self.nodes[0].disconnect_p2ps()
 
@@ -222,7 +222,7 @@ class SendTxRcnclTest(BitcoinTestFramework):
         peer = self.nodes[0].add_p2p_connection(PeerNoVerack(wtxidrelay=False), send_version=True, wait_for_verack=False)
         with self.nodes[0].assert_debug_log(['Forget txreconciliation state of peer']):
             peer.send_without_ping(create_sendtxrcncl_msg())
-            peer.send_without_ping(msg_verack())
+            peer.send_and_ping(msg_verack())
         self.nodes[0].disconnect_p2ps()
 
         # Now, *receiving* from *outbound*.

test/functional/p2p_timeouts.py

@@ -49,11 +49,11 @@ class TimeoutsTest(BitcoinTestFramework):
         self.mock_forward(0)
 
         # Setup the p2p connections, making sure the connections are established before the mocktime is bumped
-        with self.nodes[0].assert_debug_log(['Added connection peer=0']):
+        with self.nodes[0].assert_debug_log(['Added connection peer=0'], timeout=2):
             no_verack_node = self.nodes[0].add_p2p_connection(TestP2PConn(), wait_for_verack=False)
-        with self.nodes[0].assert_debug_log(['Added connection peer=1']):
+        with self.nodes[0].assert_debug_log(['Added connection peer=1'], timeout=2):
             no_version_node = self.nodes[0].add_p2p_connection(TestP2PConn(), send_version=False, wait_for_verack=False)
-        with self.nodes[0].assert_debug_log(['Added connection peer=2']):
+        with self.nodes[0].assert_debug_log(['Added connection peer=2'], timeout=2):
             no_send_node = self.nodes[0].add_p2p_connection(TestP2PConn(), send_version=False, wait_for_verack=False)
 
         # Wait until we got the verack in response to the version. Though, don't wait for the other node to receive the
@@ -66,10 +66,10 @@ class TimeoutsTest(BitcoinTestFramework):
         assert no_version_node.is_connected
         assert no_send_node.is_connected
 
-        with self.nodes[0].assert_debug_log(['Unsupported message "ping" prior to verack from peer=0']):
+        with self.nodes[0].assert_debug_log(['Unsupported message "ping" prior to verack from peer=0'], timeout=2):
             no_verack_node.send_without_ping(msg_ping())
 
-        with self.nodes[0].assert_debug_log(['non-version message before version handshake. Message "ping" from peer=1']):
+        with self.nodes[0].assert_debug_log(['non-version message before version handshake. Message "ping" from peer=1'], timeout=2):
             no_version_node.send_without_ping(msg_ping())
 
         self.mock_forward(1)

test/functional/p2p_v2_transport.py

@@ -151,7 +151,7 @@ class V2TransportTest(BitcoinTestFramework):
         with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as s:
             with self.nodes[0].wait_for_new_peer():
                 s.connect(("127.0.0.1", p2p_port(0)))
-            with self.nodes[0].assert_debug_log(["V2 transport error: V1 peer with wrong MessageStart"]):
+            with self.nodes[0].assert_debug_log(["V2 transport error: V1 peer with wrong MessageStart"], timeout=2):
                 s.sendall(wrong_network_magic_prefix + b"somepayload")
 
         # Check detection of missing garbage terminator (hits after fixed amount of data if terminator never matches garbage)

test/functional/rpc_net.py

@@ -418,8 +418,12 @@ class NetTest(BitcoinTestFramework):
 
         self.log.info("Test sendmsgtopeer")
         self.log.debug("Send a valid message")
+        msg_bytes_before = node.getpeerinfo()[0]["bytesrecv_per_msg"]["pong"]
+
         with self.nodes[1].assert_debug_log(expected_msgs=["received: addr"]):
             node.sendmsgtopeer(peer_id=0, msg_type="addr", msg="FFFFFF")
+            node.ping()
+            self.wait_until(lambda: node.getpeerinfo()[0]["bytesrecv_per_msg"]["pong"] > msg_bytes_before)
 
         self.log.debug("Test error for sending to non-existing peer")
         assert_raises_rpc_error(-1, "Error: Could not send message to peer", node.sendmsgtopeer, peer_id=100, msg_type="addr", msg="FF")

test/functional/test_framework/test_node.py

@@ -550,7 +550,7 @@ class TestNode():
             return dl.tell()
 
     @contextlib.contextmanager
-    def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2):
+    def assert_debug_log(self, expected_msgs, unexpected_msgs=None, *, timeout=0):
         if unexpected_msgs is None:
             unexpected_msgs = []
         assert_equal(type(expected_msgs), list)

test/functional/wallet_resendwallettransactions.py

@@ -69,7 +69,7 @@ class ResendWalletTransactionsTest(BitcoinTestFramework):
         self.log.info("Bump time & check that transaction is rebroadcast")
         # Transaction should be rebroadcast approximately 24 hours in the future,
         # but can range from 12-36. So bump 36 hours to be sure.
-        with node.assert_debug_log(['resubmit 1 unconfirmed transactions']):
+        with node.assert_debug_log(['resubmit 1 unconfirmed transactions'], timeout=2):
             node.setmocktime(now + 36 * 60 * 60)
             # Tell scheduler to call MaybeResendWalletTxs now.
             node.mockscheduler(60)
@@ -127,7 +127,7 @@ class ResendWalletTransactionsTest(BitcoinTestFramework):
 
         evict_time = block_time + 60 * 60 * DEFAULT_MEMPOOL_EXPIRY_HOURS + 5
         # Flush out currently scheduled resubmit attempt now so that there can't be one right between eviction and check.
-        with node.assert_debug_log(['resubmit 2 unconfirmed transactions']):
+        with node.assert_debug_log(['resubmit 2 unconfirmed transactions'], timeout=2):
             node.setmocktime(evict_time)
             node.mockscheduler(60)
 
@@ -138,7 +138,7 @@ class ResendWalletTransactionsTest(BitcoinTestFramework):
         assert_raises_rpc_error(-5, "Transaction not in mempool", node.getmempoolentry, child_txid)
 
         # Rebroadcast and check that parent and child are both in the mempool
-        with node.assert_debug_log(['resubmit 2 unconfirmed transactions']):
+        with node.assert_debug_log(['resubmit 2 unconfirmed transactions'], timeout=2):
             node.setmocktime(evict_time + 36 * 60 * 60) # 36 hrs is the upper limit of the resend timer
             node.mockscheduler(60)
         node.getmempoolentry(txid)