Merge bitcoin#32677: test: headers sync timeout

61e800e test: headers sync timeout (stringintech)

Pull request description:

  When reviewing PR bitcoin#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:

  1. **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.

  2. **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.

ACKs for top commit:
  maflcko:
    re-ACK 61e800e 🗝
  stratospher:
    reACK 61e800e.

Tree-SHA512: b8a867e7986b6f0aa00d81a84b205f2bf8fb2e6047a2e37272e0244229d1f43020e9031467827dabbfe7849a91429f2685e00a25356e2ed477fa1a035fa0b1fd

Author: fanquake

test/functional/p2p_initial_headers_sync.py

@@ -1,12 +1,15 @@
 #!/usr/bin/env python3
-# Copyright (c) 2022 The Bitcoin Core developers
+# Copyright (c) 2022-present The Bitcoin Core developers
 # Distributed under the MIT software license, see the accompanying
 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
-"""Test initial headers download
+"""Test initial headers download and timeout behavior
 
 Test that we only try to initially sync headers from one peer (until our chain
 is close to caught up), and that each block announcement results in only one
 additional peer receiving a getheaders message.
+
+Also test peer timeout during initial headers sync, including normal peer
+disconnection vs noban peer behavior.
 """
 
 from test_framework.test_framework import BitcoinTestFramework
@@ -23,7 +26,24 @@
 from test_framework.util import (
     assert_equal,
 )
+import math
 import random
+import time
+
+# Constants from net_processing
+HEADERS_DOWNLOAD_TIMEOUT_BASE_SEC = 15 * 60
+HEADERS_DOWNLOAD_TIMEOUT_PER_HEADER_MS = 1
+POW_TARGET_SPACING_SEC = 10 * 60
+
+
+def calculate_headers_timeout(best_header_time, current_time):
+    seconds_since_best_header = current_time - best_header_time
+    # Using ceil ensures the calculated timeout is >= actual timeout and not lower
+    # because of precision loss from conversion to seconds
+    variable_timeout_sec = math.ceil(HEADERS_DOWNLOAD_TIMEOUT_PER_HEADER_MS / 1_000 *
+                                     seconds_since_best_header / POW_TARGET_SPACING_SEC)
+    return int(current_time + HEADERS_DOWNLOAD_TIMEOUT_BASE_SEC + variable_timeout_sec)
+
 
 class HeadersSyncTest(BitcoinTestFramework):
     def set_test_params(self):
@@ -35,7 +55,20 @@ def announce_random_block(self, peers):
         for p in peers:
             p.send_and_ping(new_block_announcement)
 
-    def run_test(self):
+    def assert_single_getheaders_recipient(self, peers):
+        count = 0
+        receiving_peer = None
+        for p in peers:
+            with p2p_lock:
+                if "getheaders" in p.last_message:
+                    count += 1
+                    receiving_peer = p
+        assert_equal(count, 1)
+        return receiving_peer
+
+    def test_initial_headers_sync(self):
+        self.log.info("Test initial headers sync")
+
         self.log.info("Adding a peer to node0")
         peer1 = self.nodes[0].add_p2p_connection(P2PInterface())
         best_block_hash = int(self.nodes[0].getbestblockhash(), 16)
@@ -69,16 +102,8 @@ def run_test(self):
         peer1.send_without_ping(msg_headers()) # Send empty response, see above
 
         self.log.info("Check that exactly 1 of {peer2, peer3} received a getheaders in response")
-        count = 0
-        peer_receiving_getheaders = None
-        for p in [peer2, peer3]:
-            with p2p_lock:
-                if "getheaders" in p.last_message:
-                    count += 1
-                    peer_receiving_getheaders = p
-                    p.send_without_ping(msg_headers()) # Send empty response, see above
-
-        assert_equal(count, 1)
+        peer_receiving_getheaders = self.assert_single_getheaders_recipient([peer2, peer3])
+        peer_receiving_getheaders.send_without_ping(msg_headers()) # Send empty response, see above
 
         self.log.info("Announce another new block, from all peers")
         self.announce_random_block(all_peers)
@@ -93,8 +118,69 @@ def run_test(self):
 
         expected_peer.wait_for_getheaders(block_hash=best_block_hash)
 
-        self.log.info("Success!")
+    def setup_timeout_test_peers(self):
+        self.log.info("Add peer1 and check it receives an initial getheaders request")
+        node = self.nodes[0]
+        with node.assert_debug_log(expected_msgs=["initial getheaders (0) to peer=0"]):
+            peer1 = node.add_p2p_connection(P2PInterface())
+            peer1.wait_for_getheaders(block_hash=int(node.getbestblockhash(), 16))
+
+        self.log.info("Add outbound peer2")
+        # This peer has to be outbound otherwise the stalling peer is
+        # protected from disconnection
+        peer2 = node.add_outbound_p2p_connection(P2PInterface(), p2p_idx=1, connection_type="outbound-full-relay")
+
+        assert_equal(node.num_test_p2p_connections(), 2)
+        return peer1, peer2
+
+    def trigger_headers_timeout(self):
+        self.log.info("Trigger the headers download timeout by advancing mock time")
+        # The node has not received any headers from peers yet
+        # So the best header time is the genesis block time
+        best_header_time = self.nodes[0].getblockchaininfo()["time"]
+        current_time = self.nodes[0].mocktime
+        timeout = calculate_headers_timeout(best_header_time, current_time)
+        # The calculated timeout above is always >= actual timeout, but we still need
+        # +1 to trigger the timeout when both values are equal
+        self.nodes[0].setmocktime(timeout + 1)
+
+    def test_normal_peer_timeout(self):
+        self.log.info("Test peer disconnection on header timeout")
+        self.restart_node(0)
+        self.nodes[0].setmocktime(int(time.time()))
+        peer1, peer2 = self.setup_timeout_test_peers()
+
+        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 peer2 receives a getheaders request")
+        peer2.wait_for_getheaders(block_hash=int(self.nodes[0].getbestblockhash(), 16))
+
+    def test_noban_peer_timeout(self):
+        self.log.info("Test noban peer on header timeout")
+        self.restart_node(0, extra_args=['[email protected]'])
+        self.nodes[0].setmocktime(int(time.time()))
+        peer1, peer2 = self.setup_timeout_test_peers()
+
+        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 exactly 1 of {peer1, peer2} receives a getheaders")
+        self.assert_single_getheaders_recipient([peer1, peer2])
+
+    def run_test(self):
+        self.test_initial_headers_sync()
+        self.test_normal_peer_timeout()
+        self.test_noban_peer_timeout()
+
 
 if __name__ == '__main__':
     HeadersSyncTest(__file__).main()
-