test: headers sync timeout #32677

stringintech commented at 6:50 PM on June 3, 2025: contributor

When reviewing PR #32051 and considering which functional tests might need to be adapted/extended accordingly, I noticed there appears to be limited functional test coverage for header sync timeouts and thought it might be helpful to add one.

This test attempts to cover two scenarios:

Normal peer timeout behavior: When a peer fails to respond to initial getheaders requests within the timeout period, it should be disconnected and the node should attempt to sync headers from the next available peer.
Noban peer behavior: When a peer with noban privileges times out, it should remain connected while the node still attempts to sync headers from other peers.

DrahtBot commented at 6:50 PM on June 3, 2025: contributor

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Code Coverage & Benchmarks

For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/32677.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	stratospher, maflcko
Concept ACK	yuvicc, Prabhat1308
Stale ACK	mzumsande

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

DrahtBot added the label Tests on Jun 3, 2025

stringintech force-pushed on Jun 3, 2025

DrahtBot added the label CI failed on Jun 3, 2025

DrahtBot removed the label CI failed on Jun 3, 2025

yuvicc commented at 4:53 AM on June 6, 2025: contributor

Concept ACK

Great observation and thanks for adding. I was thinking if we could add this timeout test in p2p_initial_headers_sync.py instead of creating another one.

stringintech commented at 7:28 PM on June 7, 2025: contributor

I was thinking if we could add this timeout test in p2p_initial_headers_sync.py instead of creating another one. @yuvicc Actually, I did not consider that. However, now that I am thinking about it, the two sub-tests in the new test file share some context that is not used by the test file you mentioned. So, I think it is cleaner to keep them separate, especially if it will be extended to test the addnode peers as well (like here). But I will be thinking more about it while waiting for other feedback.

in test/functional/p2p_initial_headers_sync_timeout.py:83 in 16a62fa881 outdated

  78 | +                expected_msgs=["initial getheaders (0) to peer=0"]):
  79 | +            self.peer1 = self.node.add_p2p_connection(P2PInterface())
  80 | +        self.peer1.wait_for_getheaders()
  81 | +
  82 | +        self.log.info("Add outbound peer2")
  83 | +        with self.node.wait_for_new_peer():

mzumsande commented at 1:43 AM on June 9, 2025:

this seems unnecessary, add_outbound_p2p_connection already has a built-in wait for the verack.

in test/functional/p2p_initial_headers_sync_timeout.py:94 in 16a62fa881 outdated

  89 | +        assert_equal(self.node.num_test_p2p_connections(), 2)
  90 | +
  91 | +    def trigger_timeout(self):
  92 | +        self.log.info("Trigger the headers download timeout by advancing "
  93 | +                      "mock time")
  94 | +        best_header_time = self.node.getblockchaininfo()['time']

mzumsande commented at 1:51 AM on June 9, 2025:

This doesn't return the timestamp of the best header, but the time of the tip (which is still at genesis, after all headers up to minchainwork have been downloaded but no blocks connected). As far as I know (didn't check) we don't expose m_chainman.m_best_header->Time() via RPC, so to test the dynamic part in a functional test we would have to check the actual timestamps of the headers we sent the node, instead of using getblockchaininfo.

stringintech commented at 9:39 PM on June 11, 2025:

I used getblockchaininfo()['time'] because we hadn't sent the node any headers yet, so I relied on the assumption that the best header should still be at genesis with the genesis block time (which I should have commented better). But I agree with your suggestion as it is more direct and I have applied it - I appreciate your further feedback on it.

stringintech commented at 10:44 PM on June 17, 2025:

@mzumsande I just reviewed the code again and found an issue with how I implemented your suggestion. The problem is that self.send_new_block(peer1) gets called after the headers sync timeout for peer1 has already been calculated. During peer setup, the timeout calculation uses the genesis block time as the best header time, not the new block's header time that gets set later. So I need to make additional changes to fix this timing issue.

mzumsande commented at 3:19 PM on June 18, 2025:

I looked at this again, and I think the original approach is fine - I think I was confused by something in my original comment, sorry! Just adding a comment that the genesis block time is the best header time in this case (because we didn't receive any headers from peers) should be sufficient - no need to send a block.

It could be good though to run the timeout tests at the beginning of p2p_initial_headers_sync, before the test_initial_headers_sync subtest (which does send headers).

stringintech commented at 4:58 AM on June 21, 2025:

Thanks for looking into this further. I fixed the timing issue I mentioned earlier (fixed version here), but while reviewing it, I started to question how much value sending a new header/block actually adds to the test. I’ll revert it to use the genesis block time as the best header time and add the comment.

But does changing the order of the subtests actually matter, given that the test_initial_headers_sync subtest sends no actual headers?

stringintech commented at 5:30 PM on June 23, 2025:

(Just pushed a new version; I'll update the subtest order once this conversation wraps up. Thanks!)

mzumsande commented at 5:37 PM on June 24, 2025:

right, it just sends an empty headers message - kind of surprising that a test called test_initial_headers_sync doesn't send a single header. I think it's fine to leave the order as is.

mzumsande commented at 2:07 AM on June 9, 2025: contributor

Concept ACK. Didn't read the above, but I also thought it might be better to add the additional tests to p2p_initial_headers_sync.py - after all, this is not a particularly long test.

stringintech force-pushed on Jun 11, 2025

stringintech commented at 9:45 PM on June 11, 2025: contributor

16a62fa to bff80f5 - Addressed feedback by @mzumsande and @yuvicc; Thanks!

in test/functional/p2p_initial_headers_sync.py:2 in bff80f59bd outdated

   0 | @@ -1,18 +1,27 @@
   1 |  #!/usr/bin/env python3
   2 | -# Copyright (c) 2022 The Bitcoin Core developers
   3 | +# Copyright (c) 2022-2025 The Bitcoin Core developers

Prabhat1308 commented at 11:22 AM on June 17, 2025:

Would be better to do 2022-Present

stringintech commented at 5:26 PM on June 23, 2025:

Applied. Thanks!

Prabhat1308 commented at 2:37 PM on June 17, 2025: contributor

Concept ACK . left a nit

in test/functional/p2p_initial_headers_sync.py:98 in bff80f59bd outdated

 105 | -                    p.send_without_ping(msg_headers()) # Send empty response, see above
 106 | +        # Send empty response, see above
 107 | +        peer1.send_without_ping(msg_headers())
 108 |  
 109 | -        assert_equal(count, 1)
 110 | +        self.log.info(

mzumsande commented at 10:30 PM on June 17, 2025:

I think it would be good to drop the formatting changes to code you don't change for easier review. Some linters such as flake8 will suggest a 80 character limit, but that is not usually followed here - there will be longer lines in almost every functional test (it's fine to respect in the added code if you want).

stringintech commented at 5:25 PM on June 23, 2025:

Done. Good to know the line length limit isn't strictly enforced everywhere since respecting it actually hurts readability in some places.

stratospher commented at 7:43 AM on July 14, 2025:

(just more style nits):

looks like there's a few more instances - ex: announce_random_block cuts off in the middle.

also announce_random_block wasn't touched in the PR but seeing a diff for it. I think the general pattern in the codebase is to keep the helper functions before the respective test_ function (see for example: feature_fee_estimation.py). so it's ok to keep announce_random_block on top.

When subclassing the BitcoinTestFramework, place overrides for the set_test_params(), add_options() and setup_xxxx() methods at the top of the subclass, then locally-defined helper methods, then the run_test() method.

stringintech commented at 2:24 PM on July 14, 2025:

While I personally prefer a top-down approach where the main test methods are visible at the top without much scrolling, I am seeing the pattern you described is mostly respected across the tests, so I applied it.

stringintech marked this as a draft on Jun 18, 2025

stringintech commented at 9:48 AM on June 18, 2025: contributor

Drafted to address the issue explained here and the new comments.

stringintech force-pushed on Jun 23, 2025

stringintech marked this as ready for review on Jun 23, 2025

stringintech commented at 5:44 PM on June 23, 2025: contributor

bff80f5 to 8d257ed - Addressed formatting comments and reverted to original approach of using the genesis block time as best header time for timeout calculation (as discussed in this conversation).

mzumsande commented at 5:38 PM on June 24, 2025: contributor

Code Review ACK 8d257ed5937a47e1a60b7fe085f2e984eb60a956

DrahtBot requested review from Prabhat1308 on Jun 24, 2025

in test/functional/p2p_initial_headers_sync.py:116 in 8d257ed593 outdated

 112 | +
 113 | +        self.log.info("Check that stalling peer1 is disconnected")
 114 | +        peer1.wait_for_disconnect()
 115 | +        assert_equal(self.nodes[0].num_test_p2p_connections(), 1)
 116 | +
 117 | +        self.log.info("Check that peer2 receives a getheader request")

maflcko commented at 9:59 AM on June 25, 2025:

getheader -> getheaders [matches the method and plural usage elsewhere]

in test/functional/p2p_initial_headers_sync.py:45 in 8d257ed593 outdated

  38 | +def calculate_headers_timeout(best_header_time, current_time):
  39 | +    seconds_since_best_header = current_time - best_header_time
  40 | +    variable_timeout_us = (HEADERS_DOWNLOAD_TIMEOUT_PER_HEADER_US *
  41 | +                           seconds_since_best_header / POW_TARGET_SPACING_SEC)
  42 | +    variable_timeout_sec = variable_timeout_us / 1_000_000
  43 | +    return int(current_time + HEADERS_DOWNLOAD_TIMEOUT_BASE_SEC + variable_timeout_sec)

maflcko commented at 10:33 AM on June 25, 2025:

    variable_timeout_sec = math.ceil(HEADERS_DOWNLOAD_TIMEOUT_PER_HEADER_MS /1_000 *
                           seconds_since_best_header / POW_TARGET_SPACING_SEC)   # ceil, to make this function usable with mocktime, which only has second precision.

    return (current_time + HEADERS_DOWNLOAD_TIMEOUT_BASE_SEC + variable_timeout_sec)

seems a bit odd to be rounding down in this function and then apply a random +1 offset below. So it is actually rounding up. It would be better to just round up directly. Also, documenting why rounding is needed at all can't hurt. Finally, 1000/1000000 can be written as 1/1000.

stringintech commented at 5:27 PM on June 25, 2025:

I think the +1 offset would still be needed in a corner case when the input of the ceil function is already an integer. In this case, if +1 is removed, the timeout will not be triggered because the check current_time > peer->m_headers_sync_timeout (here) would evaluate to timeout > timeout (false) instead of timeout + 1 > timeout (true).

stringintech commented at 5:37 PM on June 25, 2025:

Aside from the +1 offset though, maybe it is good to apply your suggestion and use the ceil function so that calculate_headers_timeout returns a time that is >= the real timeout calculated by core, ensuring it doesn't return a lower value due to precision loss.

in test/functional/p2p_initial_headers_sync.py:149 in 8d257ed593 outdated

  99 | @@ -93,8 +100,86 @@ def run_test(self):
 100 |  
 101 |          expected_peer.wait_for_getheaders(block_hash=best_block_hash)
 102 |  
 103 | -        self.log.info("Success!")
 104 | +    def test_normal_peer_timeout(self):
 105 | +        self.log.info("Test peer disconnection on header timeout")
 106 | +        self.restart_node(0)

maflcko commented at 10:41 AM on June 25, 2025:

nit: it is probably a bit faster to self.nodes[0].disconnect_p2ps() when the goal is to disconnect all peers (and throw away their peer state)

stringintech commented at 7:40 PM on June 25, 2025:

I tried this and it seems that doing this instead of restarting the node does not reset the peer indexes, and I can no longer count on the peer indexes in the debug logs. For example, for the test_normal_peer_timeout subset:

Timeout downloading headers, disconnecting peer=0

becomes

Timeout downloading headers, disconnecting peer=3

Although still having peer=0 for the test_noban_peer_timeout subtest since we need a restart for that.

But it shouldn't matter if you think I should get rid of the debug log assertions altogether.

maflcko commented at 5:23 PM on June 26, 2025:

no strong opinion. Generally, nits are left for the author to decide on (take or leave)

in test/functional/p2p_initial_headers_sync.py:158 in 8d257ed593 outdated

 154 | +    def setup_timeout_test_peers(self):
 155 | +        self.log.info("Add peer1 and check it receives an initial getheaders request")
 156 | +        node = self.nodes[0]
 157 | +        with node.assert_debug_log(expected_msgs=["initial getheaders (0) to peer=0"]):
 158 | +            peer1 = node.add_p2p_connection(P2PInterface())
 159 | +        peer1.wait_for_getheaders()

maflcko commented at 10:44 AM on June 25, 2025:

        with node.assert_debug_log(expected_msgs=["initial getheaders (0) to peer=0"]):
            peer1 = node.add_p2p_connection(P2PInterface())
            peer1.wait_for_getheaders()

nit: it is a bit better to check the state (and wait for it directly) than to indirectly read the debug log in a loop until a specific log line is hit.

maflcko commented at 10:51 AM on June 25, 2025:

also, could check the getheaders block_hash=int(node.getbestblockhash(), 16)

maflcko commented at 10:56 AM on June 25, 2025: member

lgtm. Nice test for both branches

review ACK 8d257ed5937a47e1a60b7fe085f2e984eb60a956 👋

<details><summary>Show signature</summary>

Signature:

untrusted comment: signature from minisign secret key on empty file; verify via: minisign -Vm "${path_to_any_empty_file}" -P RWTRmVTMeKV5noAMqVlsMugDDCyyTSbA3Re5AkUrhvLVln0tSaFWglOw -x "${path_to_this_whole_four_line_signature_blob}"
RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
trusted comment: review ACK 8d257ed5937a47e1a60b7fe085f2e984eb60a956 👋
Dx0uDH6sK4oEHrtvkvxApjRYlTLYj+EHHZzNAl++iaYjo/3lz0ow5P9Hx+JBjxTIAPOCUijhrwtWNKESdnxHDQ==

</details>

stringintech force-pushed on Jun 27, 2025

in test/functional/p2p_initial_headers_sync.py:34 in ac33f52e29 outdated

  25 | @@ -23,19 +26,33 @@
  26 |  from test_framework.util import (
  27 |      assert_equal,
  28 |  )
  29 | +import math
  30 |  import random
  31 | +import time
  32 | +
  33 | +# Constants from net_processing
  34 | +HEADERS_DOWNLOAD_TIMEOUT_BASE_SEC = 900  # 15 minutes

l0rinc commented at 2:56 PM on June 27, 2025:

you could store it as a multiplication instead of the comment:

HEADERS_DOWNLOAD_TIMEOUT_BASE_SEC = 15 * 60

stringintech force-pushed on Jun 27, 2025

stringintech commented at 3:11 PM on June 27, 2025: contributor

8d257ed to 1154618 (compare) - Addresses review comments from @maflcko and @l0rinc. Thanks!

stratospher commented at 7:42 AM on July 14, 2025: contributor

ACK 11546183c70def6c0aa539642fd1c9ada3d46840. nice test! left some more style nits here - #32677 (review)

DrahtBot requested review from maflcko on Jul 14, 2025

DrahtBot requested review from mzumsande on Jul 14, 2025

maflcko commented at 10:16 AM on July 14, 2025: member

re-ACK 11546183c70def6c0aa539642fd1c9ada3d46840 🗻

<details><summary>Show signature</summary>

Signature:

untrusted comment: signature from minisign secret key on empty file; verify via: minisign -Vm "${path_to_any_empty_file}" -P RWTRmVTMeKV5noAMqVlsMugDDCyyTSbA3Re5AkUrhvLVln0tSaFWglOw -x "${path_to_this_whole_four_line_signature_blob}"
RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
trusted comment: re-ACK 11546183c70def6c0aa539642fd1c9ada3d46840 🗻
mqU5RZJ+SCn2jP2WG28PjthiMcefRUfGQhbyBaqFzcGSJGzjbCeWMsdkfKxExydD2QhCuNnvvHPlzBI4hcfHCA==

</details>

test: headers sync timeout 61e800e75c

stringintech force-pushed on Jul 14, 2025

stringintech commented at 2:23 PM on July 14, 2025: contributor

1154618 to 61e800e - Applied suggestion by @stratospher to move helper methods before their respective subtest. Thanks!

stratospher approved

stratospher commented at 3:41 AM on July 15, 2025: contributor

reACK 61e800e7.

maflcko commented at 7:54 AM on July 15, 2025: member

re-ACK 61e800e75cffa256ccdbc2ffc7a1739c00880ce0 🗝

<details><summary>Show signature</summary>

Signature:

untrusted comment: signature from minisign secret key on empty file; verify via: minisign -Vm "${path_to_any_empty_file}" -P RWTRmVTMeKV5noAMqVlsMugDDCyyTSbA3Re5AkUrhvLVln0tSaFWglOw -x "${path_to_this_whole_four_line_signature_blob}"
RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
trusted comment: re-ACK 61e800e75cffa256ccdbc2ffc7a1739c00880ce0 🗝
XhUGX4l4l2w6MYNlOvNRVgYeftSBi08ZqM3A4eRybDzwtcBh2wPhgBSfIAMcPCLAmOwRbbJywtNLWPRazKx6CA==

</details>

fanquake merged this on Jul 15, 2025

fanquake closed this on Jul 15, 2025

TheCharlatan referenced this in commit 02ded863ba on Jul 28, 2025

TheCharlatan referenced this in commit 52d7f32bd6 on Jul 28, 2025

jonatack commented at 9:45 PM on August 4, 2025: member

Post-merge ACK, thanks @stringintech!