test: adds outbound eviction functional tests, updates comment in Con…

…siderEviction

src/net_processing.cpp

@@ -5092,16 +5092,19 @@ void PeerManagerImpl::ConsiderEviction(CNode& pto, Peer& peer, std::chrono::seco
         // unless it's invalid, in which case we should find that out and
         // disconnect from them elsewhere).
         if (state.pindexBestKnownBlock != nullptr && state.pindexBestKnownBlock->nChainWork >= m_chainman.ActiveChain().Tip()->nChainWork) {
+            // The outbound peer has sent us a block with at least as much work as our current tip, so reset the timeout if it was set
             if (state.m_chain_sync.m_timeout != 0s) {
                 state.m_chain_sync.m_timeout = 0s;
                 state.m_chain_sync.m_work_header = nullptr;
                 state.m_chain_sync.m_sent_getheaders = false;
             }
-        } else if (state.m_chain_sync.m_timeout == 0s || (state.m_chain_sync.m_work_header != nullptr && state.pindexBestKnownBlock != nullptr && state.pindexBestKnownBlock->nChainWork >= state.m_chain_sync.m_work_header->nChainWork)) {
-            // Our best block known by this peer is behind our tip, and we're either noticing
-            // that for the first time, OR this peer was able to catch up to some earlier point
-            // where we checked against our tip.
-            // Either way, set a new timeout based on current tip.
+        } else if (state.m_chain_sync.m_timeout == 0s || (state.m_chain_sync.m_work_header != nullptr && state.pindexBestKnownBlock != nullptr && state.pindexBestKnownBlock->nChainWork >= state.m_chain_sync.m_work_header->nChainWork)) {\
+            // At this point we know that the outbound peer has either never sent us a block/header or they have, but its tip is behind ours
+            // AND
+            // we are noticing this for the first time (m_timeout is 0)
+            // OR we noticed this at some point within the last CHAIN_SYNC_TIMEOUT + HEADERS_RESPONSE_TIME seconds and set a timeout
+            // for them, they caught up to our tip at the time of setting the timer but not to our current one (we've also advanced).
+            // Either way, set a new timeout based on our current tip.
             state.m_chain_sync.m_timeout = time_in_seconds + CHAIN_SYNC_TIMEOUT;
             state.m_chain_sync.m_work_header = m_chainman.ActiveChain().Tip();
             state.m_chain_sync.m_sent_getheaders = false;

test/functional/p2p_eviction.py

@@ -21,6 +21,9 @@
 from test_framework.messages import (
     msg_pong,
     msg_tx,
+    from_hex,
+    msg_headers,
+    CBlockHeader,
 )
 from test_framework.p2p import (
     P2PDataStore,
@@ -30,6 +33,10 @@
 from test_framework.util import assert_equal
 from test_framework.wallet import MiniWallet
 
+# Timeouts (in minutes)
+CHAIN_SYNC_TIMEOUT = 20 * 60
+HEADERS_RESPONSE_TIME = 2 * 60
+
 
 class SlowP2PDataStore(P2PDataStore):
     def on_ping(self, message):
@@ -51,7 +58,7 @@ def set_test_params(self):
         # 4 by netgroup, 4 that sent us blocks, 4 that sent us transactions and 8 via lowest ping time
         self.extra_args = [['-maxconnections=32']]
 
-    def run_test(self):
+    def test_inbound_eviction(self):
         protected_peers = set()  # peers that we expect to be protected from eviction
         current_peer = -1
         node = self.nodes[0]
@@ -106,7 +113,7 @@ def run_test(self):
         self.log.info("Create peer that triggers the eviction mechanism")
         node.add_p2p_connection(SlowP2PInterface())
 
-        # One of the non-protected peers must be evicted. We can't be sure which one because
+        # One of the unprotected peers must be evicted. We can't be sure which one because
         # 4 peers are protected via netgroup, which is identical for all peers,
         # and the eviction mechanism doesn't preserve the order of identical elements.
         evicted_peers = []
@@ -122,6 +129,178 @@ def run_test(self):
         self.log.debug("{} protected peers: {}".format(len(protected_peers), protected_peers))
         assert evicted_peers[0] not in protected_peers
 
+        node.disconnect_p2ps()
+
+    def test_outbound_eviction_unprotected(self):
+        # This tests the eviction logic for **unprotected** outbound peers (that is, PeerManagerImpl::ConsiderEviction)
+        node = self.nodes[0]
+        cur_mock_time = node.mocktime if node.mocktime else int(time.time())
+
+        self.log.info("Create an outbound connection and don't send any headers")
+        # Test disconnect due to no block being announced in 22+ minutes (headers are not even exchanged)
+        test_node = node.add_outbound_p2p_connection(P2PInterface(), p2p_idx=0, connection_type="outbound-full-relay")
+        # Wait for over 20 min to trigger the first eviction timeout. This sets the last call past 2 min in the future.
+        test_node.sync_with_ping()
+        cur_mock_time += (CHAIN_SYNC_TIMEOUT + 1)
+        node.setmocktime(cur_mock_time)
+        test_node.sync_with_ping()
+        # Wait for over 2 more min to trigger the disconnection
+        cur_mock_time += (HEADERS_RESPONSE_TIME + 1)
+        node.setmocktime(cur_mock_time)
+        self.log.info("Test that the peers gets evicted")
+        test_node.wait_for_disconnect()
+
+        self.log.info("Create an outbound connection and send header but never catch up")
+        # Mimic a node that just falls behind for long enough
+        # This should also apply for a node doing IBD that does not catch up in time
+        # Get our tip header and its parent
+        tip_header = from_hex(CBlockHeader(), node.getblockheader(node.getbestblockhash(), False))
+        prev_header = from_hex(CBlockHeader(), node.getblockheader(f"{tip_header.hashPrevBlock:064x}", False))
+
+        # Connect a peer and make it send us headers ending in our tip's parent
+        test_node = node.add_outbound_p2p_connection(P2PInterface(), p2p_idx=0, connection_type="outbound-full-relay")
+        headers_message = msg_headers()
+        headers_message.headers = [prev_header]
+        test_node.send_and_ping(headers_message)
+
+        # Trigger the timeouts
+        cur_mock_time += (CHAIN_SYNC_TIMEOUT + 1)
+        node.setmocktime(cur_mock_time)
+        test_node.sync_with_ping()
+        cur_mock_time += (HEADERS_RESPONSE_TIME + 1)
+        node.setmocktime(cur_mock_time)
+        self.log.info("Test that the peers gets evicted")
+        test_node.wait_for_disconnect()
+
+        self.log.info("Create an outbound connection and keep lagging behind, but not too much")
+        # Test that if the peer never catches up with our current tip, but it does with the
+        # expected work that we set when setting the timer (that is, our tip at the time)
+        # we do not disconnect the peer
+        test_node = node.add_outbound_p2p_connection(P2PInterface(), p2p_idx=0, connection_type="outbound-full-relay")
+        self.log.info("Mine a block so our peer starts lagging")
+        best_block_hash = self.generateblock(self.nodes[0], output="raw(42)", transactions=[])["hash"]
+        tip_header = from_hex(CBlockHeader(), node.getblockheader(best_block_hash, False))
+        test_node.sync_with_ping()
+        self.log.info("Keep catching up with the old tip and check that we are not evicted")
+        for _ in range(10):
+            # Advance time but not enough to evict the peer
+            best_block_hash = self.generateblock(self.nodes[0], output="raw(42)", transactions=[])["hash"]
+            cur_mock_time += (CHAIN_SYNC_TIMEOUT + 1)
+            node.setmocktime(cur_mock_time)
+
+            # Send a header with the old tip
+            headers_message = msg_headers()
+            headers_message.headers = [tip_header]
+            test_node.send_and_ping(headers_message)
+            tip_header = from_hex(CBlockHeader(), node.getblockheader(best_block_hash, False))
+
+            # Check that we are not evicted
+            cur_mock_time += (HEADERS_RESPONSE_TIME + 1)
+            node.setmocktime(cur_mock_time)
+            test_node.sync_with_ping()
+
+        self.log.info("Create an outbound connection and take some time to catch up, but do it in time")
+        # Check that if the peer manages to catch up within time, the timeouts are removed (and the peer is not disconnected)
+        # We are reusing the peer from the previous case which already sent us a valid (but old) block and whose timer is ticking
+
+        # Send an updated headers message matching our tip
+        headers_message = msg_headers()
+        headers_message.headers = [from_hex(CBlockHeader(), node.getblockheader(node.getbestblockhash(), False))]
+        test_node.send_and_ping(headers_message)
+
+        # Wait for long enough for the timeouts to have triggered and check that we are still connected
+        cur_mock_time += (CHAIN_SYNC_TIMEOUT + 1)
+        node.setmocktime(cur_mock_time)
+        test_node.sync_with_ping()
+        cur_mock_time += (HEADERS_RESPONSE_TIME + 1)
+        node.setmocktime(cur_mock_time)
+        self.log.info("Test that the peers does not get evicted")
+        test_node.sync_with_ping()
+
+        node.disconnect_p2ps()
+
+    def test_outbound_eviction_protected(self):
+        # This tests the eviction logic for **protected** outbound peers (that is, PeerManagerImpl::ConsiderEviction)
+        # Outbound connections are flagged as protected as long as they have sent us a connecting block with at least as
+        # much work as our current tip and we have enough empty protected_peers slots.
+        node = self.nodes[0]
+        cur_mock_time = node.mocktime if node.mocktime else int(time.time())
+        tip_header = from_hex(CBlockHeader(), node.getblockheader(node.getbestblockhash(), False))
+
+        self.log.info("Create an outbound connection to a peer that shares our tip so it gets granted protection")
+        test_node = node.add_outbound_p2p_connection(P2PInterface(), p2p_idx=0, connection_type="outbound-full-relay")
+        headers_message = msg_headers()
+        headers_message.headers = [tip_header]
+        test_node.send_and_ping(headers_message)
+
+        self.log.info("Mine a new block and sync with our peer")
+        self.generateblock(self.nodes[0], output="raw(42)", transactions=[])
+        test_node.sync_with_ping()
+
+        self.log.info("Let enough time pass for the timeouts to go off")
+        # Trigger the timeouts and check how we are still connected
+        cur_mock_time += (CHAIN_SYNC_TIMEOUT + 1)
+        node.setmocktime(cur_mock_time)
+        test_node.sync_with_ping()
+        cur_mock_time += (HEADERS_RESPONSE_TIME + 1)
+        node.setmocktime(cur_mock_time)
+        self.log.info("Test that the node does not get evicted")
+        test_node.sync_with_ping()
+
+        node.disconnect_p2ps()
+
+    def test_outbound_eviction_protected_mixed(self):
+        node = self.nodes[0]
+        cur_mock_time = node.mocktime if node.mocktime else int(time.time())
+
+        self.log.info("Create a mix of protected and unprotected outbound connections to check against eviction")
+
+        # Lets try this logic having multiple peers, some protected and some unprotected
+        # We protect up to 4 peers as long as they have provided a block with the same amount of work as our tip
+        self.log.info("The first 4 peers are protected by sending us a valid block with enough work")
+        tip_header = from_hex(CBlockHeader(), node.getblockheader(node.getbestblockhash(), False))
+        headers_message = msg_headers()
+        headers_message.headers = [tip_header]
+        protected_peers = []
+        for i in range(4):
+            peer = node.add_outbound_p2p_connection(P2PInterface(), p2p_idx=i, connection_type="outbound-full-relay")
+            peer.send_and_ping(headers_message)
+            protected_peers.append(peer)
+
+        # We can create 4 additional outbound connections to peers that are unprotected. Let's mix between not sending
+        # headers and sending old ones
+        self.log.info("The remaining 4 are split between peers sending us no headers and old header")
+        prev_header = from_hex(CBlockHeader(), node.getblockheader(f"{tip_header.hashPrevBlock:064x}", False))
+        headers_message = msg_headers()
+        headers_message.headers = [prev_header]
+        unprotected_peers = []
+        for i in range(4):
+            peer = node.add_outbound_p2p_connection(P2PInterface(), p2p_idx=4+i, connection_type="outbound-full-relay")
+            if i%2==0:
+                peer.send_and_ping(headers_message)
+            unprotected_peers.append(peer)
+
+        # Mine a block so all peers become outdated
+        self.generateblock(self.nodes[0], output="raw(42)", transactions=[])
+
+        # Let the timeouts hit and check back
+        cur_mock_time += (CHAIN_SYNC_TIMEOUT + 1)
+        node.setmocktime(cur_mock_time)
+        for peer in protected_peers + unprotected_peers:
+            peer.sync_with_ping()
+        cur_mock_time += (HEADERS_RESPONSE_TIME + 1)
+        node.setmocktime(cur_mock_time)
+        self.log.info("Check how none of the protected peers was evicted but all the unprotected were")
+        for peer in protected_peers:
+            peer.sync_with_ping()
+        for peer in unprotected_peers:
+            peer.wait_for_disconnect()
+
+    def run_test(self):
+        self.test_inbound_eviction()
+        self.test_outbound_eviction_unprotected()
+        self.test_outbound_eviction_protected()
+        self.test_outbound_eviction_protected_mixed()
 
 if __name__ == '__main__':
     P2PEvict().main()