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.
<!--e57a25ab6845829454e8d69fc972939a-->
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
<!--021abf342d371248e50ceaed478a90ca-->
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 <code><!--meta-tag:bot-skip--></code> into the comment that the bot should ignore.
<!--174a7506f384e20aa4161008e828411d-->
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.
<!--5faf32d7da4f0f540f40219e4f7537a3-->
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:
./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?
diff--- a/test/functional/p2p_compactblocks.py
+++ b/test/functional/p2p_compactblocks.py
@@ -590,9 +590,9 @@ class CompactBlocksTest(BitcoinTestFramework):
test_node.last_message["getdata"].inv[0].type == MSG_BLOCK | MSG_WITNESS_FLAG
# Send the same blocktxn and assert the sender gets disconnected.
- with node.assert_debug_log(['previous compact block reconstruction attempt failed']):
+ with node.assert_debug_log(['previous compact block reconstruction attempt failed'], timeout=2):
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]
Why not the following diff?
diff--- a/test/functional/p2p_compactblocks.py +++ b/test/functional/p2p_compactblocks.py @@ -590,9 +590,9 @@ class CompactBlocksTest(BitcoinTestFramework): test_node.last_message["getdata"].inv[0].type == MSG_BLOCK | MSG_WITNESS_FLAG # Send the same blocktxn and assert the sender gets disconnected. - with node.assert_debug_log(['previous compact block reconstruction attempt failed']): + with node.assert_debug_log(['previous compact block reconstruction attempt failed'], timeout=2): 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]
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:
with node.assert_debug_log(['reason for disconnect']):
p2p.send_a_msg()
p2p.wait_for_disconnect()
Than:
with node.assert_debug_log(['reason for disconnect'], timeout=2):
p2p.send_a_msg()
# wait 2 seconds for a disconnect to happen by looping over the debug log tail
# Once the disconnect happened, check that it happened again:
p2p.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.
--- a/test/functional/rpc_net.py
+++ b/test/functional/rpc_net.py
@@ -418,10 +418,11 @@ class NetTest(BitcoinTestFramework):
self.log.info("Test sendmsgtopeer")
self.log.debug("Send a valid message")
- msg_bytes_before = self.nodes[1].getpeerinfo()[-1]["bytesrecv_per_msg"].get("addr", 0)
+ msg_bytes_before = self.nodes[1].getpeerinfo()[0]["bytesrecv_per_msg"].get("addr", 0)
with self.nodes[1].assert_debug_log(expected_msgs=["received: addr"]):
node.sendmsgtopeer(peer_id=0, msg_type="addr", msg="FFFFFF")
- self.wait_until(lambda: self.nodes[1].getpeerinfo()[-1]["bytesrecv_per_msg"].get("addr", 0) > msg_bytes_before)
+ 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:
test 2026-02-14T09:37:34.797636Z TestFramework (INFO): Test sendmsgtopeer
test 2026-02-14T09:37:34.797727Z TestFramework (DEBUG): Send a valid message
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
node1 2026-02-14T09:37:34.797891Z [http_pool_1] [rpc/request.cpp:243] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
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
node0 2026-02-14T09:37:34.798411Z [http_pool_1] [rpc/request.cpp:243] [parse] [rpc] ThreadRPCServer method=sendmsgtopeer user=__cookie__
node0 2026-02-14T09:37:34.798449Z [http_pool_1] [net.cpp:4074] [PushMessage] [net] sending addr (3 bytes) peer=0
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
node1 2026-02-14T09:37:34.798793Z [http_pool_0] [rpc/request.cpp:243] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
test 2026-02-14T09:37:34.799214Z TestFramework (ERROR): Unexpected exception
Traceback (most recent call last):
File "/b-c/test/functional/test_framework/test_framework.py", line 142, in main
self.run_test()
~~~~~~~~~~~~~^^
File "/b-c/bld-cmake/test/functional/rpc_net.py", line 93, in run_test
self.test_sendmsgtopeer()
~~~~~~~~~~~~~~~~~~~~~~~^^
File "/b-c/bld-cmake/test/functional/rpc_net.py", line 422, in test_sendmsgtopeer
with self.nodes[1].assert_debug_log(expected_msgs=["received: addr"]):
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3.13/contextlib.py", line 148, in __exit__
next(self.gen)
~~~~^^^^^^^^^^
File "/b-c/test/functional/test_framework/test_node.py", line 584, in assert_debug_log
self._raise_assertion_error(f'Expected message(s) {remaining_expected!s} '
~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
f'not found in log:\n\n{join_log(log)}\n\n')
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/b-c/test/functional/test_framework/test_node.py", line 229, in _raise_assertion_error
raise AssertionError(self._node_msg(msg))
AssertionError: [node 1] Expected message(s) ['received: addr'] not found in log:
- 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
- 2026-02-14T09:37:34.798793Z [http_pool_0] [rpc/request.cpp:243] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
node1 2026-02-14T09:37:34.799316Z [msghand] [net_processing.cpp:3555] [ProcessMessage] [net] received: addr (3 bytes) peer=0
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
test 2026-02-14T09:37:34.803544Z TestFramework (DEBUG): Closing down network thread
test 2026-02-14T09:37:34.853858Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
test 2026-02-14T09:37:34.854000Z TestFramework (WARNING): Not cleaning up dir /tmp/test_runner_₿_🏃_20260214_092501/rpc_net_152
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
test 2026-02-14T09:37:34.854196Z TestFramework (ERROR):
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
test 2026-02-14T09:37:34.854339Z TestFramework (ERROR):
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.
test 2026-02-14T09:37:34.854449Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
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.
ACK fabaf466b938f0b2da6e25af2eb24f4731fcd358
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:
329 | @@ -330,7 +330,7 @@ def test_seed_peers(self): 330 | "Loaded 0 addresses from peers.dat", 331 | "DNS seeding disabled", 332 | "Adding fixed seeds as -dnsseed=0 (or IPv4/IPv6 connections are disabled via -onlynet) and neither -addnode nor -seednode are provided\n", 333 | - ]): 334 | + ], timeout=2):
Possible this timeout might be too short?
I saw a CI failure here on an unrelated change https://github.com/bitcoin/bitcoin/actions/runs/29296496538/job/86971066595 and claude suggested raising this to 10 seconds:
The "Adding fixed seeds as -dnsseed=0 ..." message is generated inside
ThreadOpenConnections after a 500ms sleep_for(). When node startup takes
~1.7s on a loaded CI runner the message arrives at ~2.2s, past the
previous 2s timeout. Increase to 10s, matching the timeout used for the
earlier start_node call in this same test function.
In general I think having these individual hardcoded timeouts is not good and it would be better to define a generic failure timeout that is something more like 30 or 60 seconds for operations that are expected to complete quickly but will cause the test to fail if they do not.
Sure, makes sense. However, let's recall that this pull request did not change the timeout value here.
According to the diff, the prior value was 2:
def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2):
And it is 2 after this pull request.
Feel free to ask claude to submit a pull request, but I don't think the failure is related to the changes here.
it would be better to define a generic failure timeout that is something more like 30 or 60 seconds for operations that are expected to complete quickly
I wouldn't call 30 or 60 seconds quickly. Think about someone writing a test, where each failure takes 60 seconds. So 10 failed iterations will take 10 minutes of useless waiting while writing the test. I think there are two meaningful knobs:
Again, happy to review a pull request, but I don't think this is triggered by the changes here.