← Watch feed
test: Set assert_debug_log timeout to 0
Public commit record
67/100 · Adequate
What the developer wrote
Authored by MarcoFalke
test: Set assert_debug_log timeout to 0
✓ Descriptive subject✓ Names a concrete action or component✓ Uses a recognizable type or scope✓ Mentions testing or verification! No meaningful explanatory body
What changed, and why it matters
This commit only changes Bitcoin Core's internal functional test code. It makes the default timeout for a debug-log assertion helper stricter (0 seconds instead of 2 seconds) and updates existing tests to explicitly pass a 2-second timeout where needed. There is no change to the actual Bitcoin node software that users run, so it cannot affect live networks, wallets, or consensus.
Recommended action
No security action required. Treat as a normal test-framework maintenance commit. Reviewers may optionally verify that CI functional tests still pass with the stricter default timeout.
Security signals we found
No strong security signals were identified.
Evidence from the diff
The patch modifies test_framework/test_node.py so that assert_debug_log defaults to timeout=0 (a keyword-only argument). It then updates 12 functional tests to pass timeout=2 explicitly wherever the test relies on waiting for asynchronous log messages. A few tests also had disconnect checks moved inside the assert_debug_log context manager so they execute while the log assertion is still active. These are test-harness robustness improvements only; no production C++/Python node code is touched.
Changed components
test/functional/test_framework/test_node.pytest/functional/feature_anchors.pytest/functional/feature_config_args.pytest/functional/p2p_compactblocks.pytest/functional/p2p_dns_seeds.pytest/functional/p2p_headers_sync_with_minchainwork.pytest/functional/p2p_initial_headers_sync.pytest/functional/p2p_mutated_blocks.pytest/functional/p2p_sendtxrcncl.pytest/functional/p2p_timeouts.pytest/functional/p2p_v2_transport.pytest/functional/rpc_net.pytest/functional/wallet_resendwallettransactions.pyInspect captured patch +46 / −35
diff --git a/test/functional/feature_anchors.py b/test/functional/feature_anchors.py
index e82f28f4..07f06bd5 100755
--- a/test/functional/feature_anchors.py
+++ b/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]}"])
diff --git a/test/functional/feature_config_args.py b/test/functional/feature_config_args.py
index cbd68971..2e515842 100755
--- a/test/functional/feature_config_args.py
+++ b/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)
diff --git a/test/functional/p2p_compactblocks.py b/test/functional/p2p_compactblocks.py
index 81ab3f74..48776e7d 100755
--- a/test/functional/p2p_compactblocks.py
+++ b/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
diff --git a/test/functional/p2p_dns_seeds.py b/test/functional/p2p_dns_seeds.py
index 06db3349..e2530c5e 100755
--- a/test/functional/p2p_dns_seeds.py
+++ b/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)
diff --git a/test/functional/p2p_headers_sync_with_minchainwork.py b/test/functional/p2p_headers_sync_with_minchainwork.py
index 3cb9ff21..e90dccd4 100755
--- a/test/functional/p2p_headers_sync_with_minchainwork.py
+++ b/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)
diff --git a/test/functional/p2p_initial_headers_sync.py b/test/functional/p2p_initial_headers_sync.py
index 24824f5a..55be9849 100755
--- a/test/functional/p2p_initial_headers_sync.py
+++ b/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])
diff --git a/test/functional/p2p_mutated_blocks.py b/test/functional/p2p_mutated_blocks.py
index b9ce50bf..609c4449 100755
--- a/test/functional/p2p_mutated_blocks.py
+++ b/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__':
diff --git a/test/functional/p2p_sendtxrcncl.py b/test/functional/p2p_sendtxrcncl.py
index 2addc330..f1ed30af 100755
--- a/test/functional/p2p_sendtxrcncl.py
+++ b/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*.
diff --git a/test/functional/p2p_timeouts.py b/test/functional/p2p_timeouts.py
index b165b122..a65fcba3 100755
--- a/test/functional/p2p_timeouts.py
+++ b/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)
diff --git a/test/functional/p2p_v2_transport.py b/test/functional/p2p_v2_transport.py
index 731df998..4c98d2d3 100755
--- a/test/functional/p2p_v2_transport.py
+++ b/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)
diff --git a/test/functional/rpc_net.py b/test/functional/rpc_net.py
index 6438cabe..30e0d536 100755
--- a/test/functional/rpc_net.py
+++ b/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")
diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py
index b56cf64c..15686dcd 100755
--- a/test/functional/test_framework/test_node.py
+++ b/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)
diff --git a/test/functional/wallet_resendwallettransactions.py b/test/functional/wallet_resendwallettransactions.py
index 0b749f69..83ae6f5a 100755
--- a/test/functional/wallet_resendwallettransactions.py
+++ b/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)
Risk score
Our methodology →Why this scored 15/100
Human-validated context
Community notes
Notes can correct, qualify, or add evidence to the AI analysis. Every note shown here has been validated by a human moderator.
No validated notes yet.
The AI analysis stands alone for now. Submit a note if you can add evidence or important context.