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 #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.
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
See the guideline for information on the review process.
| Type | Reviewers |
|---|---|
| ACK | hodlinator, brunoerg |
| Stale ACK | rkrux |
If your review is incorrectly listed, please copy-paste <!–meta-tag:bot-skip–> into the comment that the bot should ignore.
Reviewers, this pull request conflicts with the following ones:
If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.
ACK fabaf466b938f0b2da6e25af2eb24f4731fcd358
Agree it’s more robust to default to 0 timeout and push code blocks towards being sufficient to print the log messages.
Double-checked that the timeout value is multiplied by timeout_factor internally.
Ran this 3 times without any skipped tests or failures:
0./build/test/functional/test_runner.py --loglevel=debug feature_anchors.py feature_config_args.py p2p_compactblocks.py p2p_dns_seeds.py p2p_headers_sync_with_minchainwork.py p2p_initial_headers_sync.py p2p_mutated_blocks.py p2p_sendtxrcncl.py p2p_timeouts.py p2p_v2_transport.py rpc_net.py wallet_resendwallettransactions.py
591@@ -592,7 +592,7 @@ def test_multiple_blocktxn_response(self, test_node):
592 # Send the same blocktxn and assert the sender gets disconnected.
593 with node.assert_debug_log(['previous compact block reconstruction attempt failed']):
594 test_node.send_without_ping(msg)
595- test_node.wait_for_disconnect()
596+ test_node.wait_for_disconnect()
Are the changes of this file intentional? Don’t we expect these debug logs to be added by the send_without_ping call only?
Why not the following diff?
0diff--- a/test/functional/p2p_compactblocks.py
1+++ b/test/functional/p2p_compactblocks.py
2@@ -590,9 +590,9 @@ class CompactBlocksTest(BitcoinTestFramework):
3 test_node.last_message["getdata"].inv[0].type == MSG_BLOCK | MSG_WITNESS_FLAG
4
5 # Send the same blocktxn and assert the sender gets disconnected.
6- with node.assert_debug_log(['previous compact block reconstruction attempt failed']):
7+ with node.assert_debug_log(['previous compact block reconstruction attempt failed'], timeout=2):
8 test_node.send_without_ping(msg)
9- test_node.wait_for_disconnect()
10+ test_node.wait_for_disconnect()
11
12 def test_getblocktxn_handler(self, test_node):
13 node = self.nodes[0]
Why not the following diff?
0diff--- a/test/functional/p2p_compactblocks.py 1+++ b/test/functional/p2p_compactblocks.py 2@@ -590,9 +590,9 @@ class CompactBlocksTest(BitcoinTestFramework): 3 test_node.last_message["getdata"].inv[0].type == MSG_BLOCK | MSG_WITNESS_FLAG 4 5 # Send the same blocktxn and assert the sender gets disconnected. 6- with node.assert_debug_log(['previous compact block reconstruction attempt failed']): 7+ with node.assert_debug_log(['previous compact block reconstruction attempt failed'], timeout=2): 8 test_node.send_without_ping(msg) 9- test_node.wait_for_disconnect() 10+ test_node.wait_for_disconnect() 11 12 def test_getblocktxn_handler(self, test_node): 13 node = self.nodes[0]
Setting a timeout and polling the debug log in a loop just seems brittle, confusing, and racy. I don’t see the benefit. The goal of this pull is to get rid of those loops where possible.
The goal of this pull is to get rid of those loops where possible.
Calling unrelated RPC (wait_for_disconnect) just to get rid of those loops adds some confusion for the reader by making them wonder which RPC / code of the whole with block is responsible for adding such logs - doesn’t help in making the code self documenting imo.
The goal of this pull is to get rid of those loops where possible.
Calling unrelated RPC (
wait_for_disconnect) just to get rid of those loops adds some confusion for the reader by making them wonder which RPC / code of the wholewithblock is responsible for adding such logs - doesn’t help in making the code self documenting imo.
The last line of code in the context should generally be responsible. This is also the case here:
The debug log is searched for the reason for disconnection, so I think it is clearer to write:
0with node.assert_debug_log(['reason for disconnect']):
1 p2p.send_a_msg()
2 p2p.wait_for_disconnect()
Than:
0with node.assert_debug_log(['reason for disconnect'], timeout=2):
1 p2p.send_a_msg()
2 # wait 2 seconds for a disconnect to happen by looping over the debug log tail
3# Once the disconnect happened, check that it happened again:
4p2p.wait_for_disconnect()
I guess it’s fine when I look at it from this^ perspective.
The last line of code in the context should generally be responsible.
Yes, I agree with this statement. The PR author / reviewer should ensure that unrelated code is not stuffed in such with blocks.
417@@ -418,8 +418,10 @@ def test_sendmsgtopeer(self):
418
419 self.log.info("Test sendmsgtopeer")
420 self.log.debug("Send a valid message")
421+ msg_bytes_before = self.nodes[1].getpeerinfo()[-1]["bytesrecv_per_msg"].get("addr", 0)
422 with self.nodes[1].assert_debug_log(expected_msgs=["received: addr"]):
423 node.sendmsgtopeer(peer_id=0, msg_type="addr", msg="FFFFFF")
424+ self.wait_until(lambda: self.nodes[1].getpeerinfo()[-1]["bytesrecv_per_msg"].get("addr", 0) > msg_bytes_before)
Nit: Using -1 as the index gives the impression that there are multiple entries and the last one is used for some reason that the reader doesn’t know about. The 0 index doesn’t carry that assumption usually.
0--- a/test/functional/rpc_net.py
1+++ b/test/functional/rpc_net.py
2@@ -418,10 +418,11 @@ class NetTest(BitcoinTestFramework):
3
4 self.log.info("Test sendmsgtopeer")
5 self.log.debug("Send a valid message")
6- msg_bytes_before = self.nodes[1].getpeerinfo()[-1]["bytesrecv_per_msg"].get("addr", 0)
7+ msg_bytes_before = self.nodes[1].getpeerinfo()[0]["bytesrecv_per_msg"].get("addr", 0)
8 with self.nodes[1].assert_debug_log(expected_msgs=["received: addr"]):
9 node.sendmsgtopeer(peer_id=0, msg_type="addr", msg="FFFFFF")
10- self.wait_until(lambda: self.nodes[1].getpeerinfo()[-1]["bytesrecv_per_msg"].get("addr", 0) > msg_bytes_before)
11+ self.wait_until(lambda: self.nodes[1].getpeerinfo()[0]["bytesrecv_per_msg"].get("addr", 0) > msg_bytes_before)
Good point. Though, I was just checking my container that was running this patch in a loop. I think this is still racy, because getpeerinfo is updated before the debug log. So my patch will intermittently fail:
0 test 2026-02-14T09:37:34.797636Z TestFramework (INFO): Test sendmsgtopeer
1 test 2026-02-14T09:37:34.797727Z TestFramework (DEBUG): Send a valid message
2 node1 2026-02-14T09:37:34.797858Z [http] [httpserver.cpp:233] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33442
3 node1 2026-02-14T09:37:34.797891Z [http_pool_1] [rpc/request.cpp:243] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
4 node0 2026-02-14T09:37:34.798363Z [http] [httpserver.cpp:233] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:52144
5 node0 2026-02-14T09:37:34.798411Z [http_pool_1] [rpc/request.cpp:243] [parse] [rpc] ThreadRPCServer method=sendmsgtopeer user=__cookie__
6 node0 2026-02-14T09:37:34.798449Z [http_pool_1] [net.cpp:4074] [PushMessage] [net] sending addr (3 bytes) peer=0
7 node1 2026-02-14T09:37:34.798737Z [http] [httpserver.cpp:233] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33442
8 node1 2026-02-14T09:37:34.798793Z [http_pool_0] [rpc/request.cpp:243] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
9 test 2026-02-14T09:37:34.799214Z TestFramework (ERROR): Unexpected exception
10 Traceback (most recent call last):
11 File "/b-c/test/functional/test_framework/test_framework.py", line 142, in main
12 self.run_test()
13 ~~~~~~~~~~~~~^^
14 File "/b-c/bld-cmake/test/functional/rpc_net.py", line 93, in run_test
15 self.test_sendmsgtopeer()
16 ~~~~~~~~~~~~~~~~~~~~~~~^^
17 File "/b-c/bld-cmake/test/functional/rpc_net.py", line 422, in test_sendmsgtopeer
18 with self.nodes[1].assert_debug_log(expected_msgs=["received: addr"]):
19 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
20 File "/usr/lib/python3.13/contextlib.py", line 148, in __exit__
21 next(self.gen)
22 ~~~~^^^^^^^^^^
23 File "/b-c/test/functional/test_framework/test_node.py", line 584, in assert_debug_log
24 self._raise_assertion_error(f'Expected message(s) {remaining_expected!s} '
25 ~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
26 f'not found in log:\n\n{join_log(log)}\n\n')
27 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
28 File "/b-c/test/functional/test_framework/test_node.py", line 229, in _raise_assertion_error
29 raise AssertionError(self._node_msg(msg))
30 AssertionError: [node 1] Expected message(s) ['received: addr'] not found in log:
31 - 2026-02-14T09:37:34.798737Z [http] [httpserver.cpp:233] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33442
32 - 2026-02-14T09:37:34.798793Z [http_pool_0] [rpc/request.cpp:243] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
33 node1 2026-02-14T09:37:34.799316Z [msghand] [net_processing.cpp:3555] [ProcessMessage] [net] received: addr (3 bytes) peer=0
34 node1 2026-02-14T09:37:34.799433Z [msghand] [net_processing.cpp:5257] [ProcessMessages] [net] ProcessMessages(addr, 3 bytes): Exception 'DataStream::read(): end of data: iostream error' (NSt8ios_base7failureB5cxx11E) caught
35 test 2026-02-14T09:37:34.803544Z TestFramework (DEBUG): Closing down network thread
36 test 2026-02-14T09:37:34.853858Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
37 test 2026-02-14T09:37:34.854000Z TestFramework (WARNING): Not cleaning up dir /tmp/test_runner_₿_🏃_20260214_092501/rpc_net_152
38 test 2026-02-14T09:37:34.854061Z TestFramework (ERROR): Test failed. Test logging available at /tmp/test_runner_₿_🏃_20260214_092501/rpc_net_152/test_framework.log
39 test 2026-02-14T09:37:34.854196Z TestFramework (ERROR):
40 test 2026-02-14T09:37:34.854294Z TestFramework (ERROR): Hint: Call /b-c/test/functional/combine_logs.py '/tmp/test_runner_₿_🏃_20260214_092501/rpc_net_152' to consolidate all logs
41 test 2026-02-14T09:37:34.854339Z TestFramework (ERROR):
42 test 2026-02-14T09:37:34.854379Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
43 test 2026-02-14T09:37:34.854449Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
44 test 2026-02-14T09:37:34.854491Z TestFramework (ERROR):
I think the only reliable way here would be a sync-with-ping, like in all other python p2p connections.
re-ACK fa4cb96bdec21319cc54c6dd96a14acf1719e3c6
Change since previous review (https://github.com/bitcoin/bitcoin/pull/34581#pullrequestreview-3807295159): Since peerinfo is updated before the debug log (https://github.com/bitcoin/bitcoin/pull/34581#discussion_r2817331019) we now ping after sending the addr-message to our peer and then wait until we’ve received a pong back (instead of waiting for addr data), by the time we get the pong, it should increase the likelihood that our peer has logged that they received the addr. N.B. I do not know the guarantees around flushing of the log & observing it on the Python side vs getpeerinfo, but the change makes sense directionally.
ACK fa4cb96bdec21319cc54c6dd96a14acf1719e3c6
Lgtm, removing the default timeout makes it better to read and understand. Tests should adjust it accordingly. Also, this PR moves some wait_for_disconnect to the block which makes sense since it’s part of the expected execution and makes the assert_debug_log “safer”.
feature_config_args.py fails now on FreeBSD: