test: rpc: add last block announcement time to getpeerinfo result

doc/release-notes-27052.md

@@ -0,0 +1,7 @@
+JSON-RPC
+--------
+
+The `getpeerinfo` RPC now returns an additional result field,
+`last_block_announcement`, which indicates the most recent time
+this peer was the first to announce a new block to the local node.
+This timestamp, previously internal only, is used by the eviction logic.

src/net_processing.cpp

@@ -471,7 +471,7 @@ struct CNodeState {
     ChainSyncTimeoutState m_chain_sync;
 
     //! Time of last new block announcement
-    int64_t m_last_block_announcement{0};
+    NodeSeconds m_last_block_announcement{0s};
 
     //! Whether this peer is an inbound connection
     const bool m_is_inbound;
@@ -525,8 +525,8 @@ class PeerManagerImpl final : public PeerManager
     void ProcessMessage(CNode& pfrom, const std::string& msg_type, DataStream& vRecv,
                         const std::chrono::microseconds time_received, const std::atomic<bool>& interruptMsgProc) override
         EXCLUSIVE_LOCKS_REQUIRED(!m_peer_mutex, !m_recent_confirmed_transactions_mutex, !m_most_recent_block_mutex, !m_headers_presync_mutex, g_msgproc_mutex);
-    void UpdateLastBlockAnnounceTime(NodeId node, int64_t time_in_seconds) override;
     ServiceFlags GetDesirableServiceFlags(ServiceFlags services) const override;
+    void UpdateLastBlockAnnounceTime(NodeId node, NodeSeconds time_in_seconds) override;
 
 private:
     /** Consider evicting an outbound peer based on the amount of time they've been behind our tip */
@@ -1556,7 +1556,7 @@ void PeerManagerImpl::AddTxAnnouncement(const CNode& node, const GenTxid& gtxid,
     m_txrequest.ReceivedInv(nodeid, gtxid, preferred, current_time + delay);
 }
 
-void PeerManagerImpl::UpdateLastBlockAnnounceTime(NodeId node, int64_t time_in_seconds)
+void PeerManagerImpl::UpdateLastBlockAnnounceTime(NodeId node, NodeSeconds time_in_seconds)
 {
     LOCK(cs_main);
     CNodeState *state = State(node);
@@ -1721,6 +1721,7 @@ bool PeerManagerImpl::GetNodeStateStats(NodeId nodeid, CNodeStateStats& stats) c
             if (queue.pindex)
                 stats.vHeightInFlight.push_back(queue.pindex->nHeight);
         }
+        stats.m_last_block_announcement = state->m_last_block_announcement;
     }
 
     PeerRef peer = GetPeerRef(nodeid);
@@ -2848,7 +2849,7 @@ void PeerManagerImpl::UpdatePeerStateForReceivedHeaders(CNode& pfrom, Peer& peer
     // are still present, however, as belt-and-suspenders.
 
     if (received_new_header && last_header.nChainWork > m_chainman.ActiveChain().Tip()->nChainWork) {
-        nodestate->m_last_block_announcement = GetTime();
+        nodestate->m_last_block_announcement = Now<NodeSeconds>();
     }
 
     // If we're in IBD, we want outbound peers that will serve us a useful
@@ -4471,7 +4472,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
         // If this was a new header with more work than our tip, update the
         // peer's last block announcement time
         if (received_new_header && pindex->nChainWork > m_chainman.ActiveChain().Tip()->nChainWork) {
-            nodestate->m_last_block_announcement = GetTime();
+            nodestate->m_last_block_announcement = Now<NodeSeconds>();
         }
 
         if (pindex->nStatus & BLOCK_HAVE_DATA) // Nothing to do here
@@ -5231,7 +5232,7 @@ void PeerManagerImpl::EvictExtraOutboundPeers(std::chrono::seconds now)
         // Protect peers from eviction if we don't have another connection
         // to their network, counting both outbound-full-relay and manual peers.
         NodeId worst_peer = -1;
-        int64_t oldest_block_announcement = std::numeric_limits<int64_t>::max();
+        std::optional<NodeSeconds> oldest_block_announcement;
 
         m_connman.ForEachNode([&](CNode* pnode) EXCLUSIVE_LOCKS_REQUIRED(::cs_main, m_connman.GetNodesMutex()) {
             AssertLockHeld(::cs_main);
@@ -5246,7 +5247,10 @@ void PeerManagerImpl::EvictExtraOutboundPeers(std::chrono::seconds now)
             // If this is the only connection on a particular network that is
             // OUTBOUND_FULL_RELAY or MANUAL, protect it.
             if (!m_connman.MultipleManualOrFullOutboundConns(pnode->addr.GetNetwork())) return;
-            if (state->m_last_block_announcement < oldest_block_announcement || (state->m_last_block_announcement == oldest_block_announcement && pnode->GetId() > worst_peer)) {
+            if (!oldest_block_announcement.has_value() ||
+                (state->m_last_block_announcement < *oldest_block_announcement) ||
+                ((state->m_last_block_announcement == *oldest_block_announcement) && pnode->GetId() > worst_peer))
+            {
                 worst_peer = pnode->GetId();
                 oldest_block_announcement = state->m_last_block_announcement;
             }
@@ -5262,7 +5266,8 @@ void PeerManagerImpl::EvictExtraOutboundPeers(std::chrono::seconds now)
                 // block from.
                 CNodeState &state = *State(pnode->GetId());
                 if (now - pnode->m_connected > MINIMUM_CONNECT_TIME && state.vBlocksInFlight.empty()) {
-                    LogPrint(BCLog::NET, "disconnecting extra outbound peer=%d (last block announcement received at time %d)\n", pnode->GetId(), oldest_block_announcement);
+                    LogPrint(BCLog::NET, "disconnecting extra outbound peer=%d (last block announcement received at time %d)\n",
+                             pnode->GetId(), TicksSinceEpoch<std::chrono::seconds>(*oldest_block_announcement));
                     pnode->fDisconnect = true;
                     return true;
                 } else {

src/net_processing.h

@@ -41,6 +41,7 @@ struct CNodeStateStats {
     bool m_addr_relay_enabled{false};
     ServiceFlags their_services;
     int64_t presync_height{-1};
+    NodeSeconds m_last_block_announcement;
 };
 
 class PeerManager : public CValidationInterface, public NetEventsInterface
@@ -109,7 +110,7 @@ class PeerManager : public CValidationInterface, public NetEventsInterface
                                 const std::chrono::microseconds time_received, const std::atomic<bool>& interruptMsgProc) EXCLUSIVE_LOCKS_REQUIRED(g_msgproc_mutex) = 0;
 
     /** This function is used for testing the stale tip eviction logic, see denialofservice_tests.cpp */
-    virtual void UpdateLastBlockAnnounceTime(NodeId node, int64_t time_in_seconds) = 0;
+    virtual void UpdateLastBlockAnnounceTime(NodeId node, NodeSeconds time_in_seconds) = 0;
 
     /**
      * Gets the set of service flags which are "desirable" for a given peer.

src/rpc/net.cpp

@@ -140,6 +140,7 @@ static RPCHelpMan getpeerinfo()
                     {RPCResult::Type::NUM_TIME, "lastrecv", "The " + UNIX_EPOCH_TIME + " of the last receive"},
                     {RPCResult::Type::NUM_TIME, "last_transaction", "The " + UNIX_EPOCH_TIME + " of the last valid transaction received from this peer"},
                     {RPCResult::Type::NUM_TIME, "last_block", "The " + UNIX_EPOCH_TIME + " of the last block received from this peer"},
+                    {RPCResult::Type::NUM_TIME, "last_block_announcement", "The " + UNIX_EPOCH_TIME + " this peer was first to announce a block"},
                     {RPCResult::Type::NUM, "bytessent", "The total bytes sent"},
                     {RPCResult::Type::NUM, "bytesrecv", "The total bytes received"},
                     {RPCResult::Type::NUM_TIME, "conntime", "The " + UNIX_EPOCH_TIME + " of the connection"},
@@ -236,6 +237,7 @@ static RPCHelpMan getpeerinfo()
         obj.pushKV("lastrecv", count_seconds(stats.m_last_recv));
         obj.pushKV("last_transaction", count_seconds(stats.m_last_tx_time));
         obj.pushKV("last_block", count_seconds(stats.m_last_block_time));
+        obj.pushKV("last_block_announcement", TicksSinceEpoch<std::chrono::seconds>(statestats.m_last_block_announcement));
         obj.pushKV("bytessent", stats.nSendBytes);
         obj.pushKV("bytesrecv", stats.nRecvBytes);
         obj.pushKV("conntime", count_seconds(stats.m_connected));

src/test/denialofservice_tests.cpp

@@ -197,7 +197,7 @@ BOOST_AUTO_TEST_CASE(stale_tip_peer_management)
 
     // Update the last announced block time for the last
     // peer, and check that the next newest node gets evicted.
-    peerLogic->UpdateLastBlockAnnounceTime(vNodes.back()->GetId(), GetTime());
+    peerLogic->UpdateLastBlockAnnounceTime(vNodes.back()->GetId(), Now<NodeSeconds>());
 
     peerLogic->CheckForStaleTipAndEvictPeers();
     for (int i = 0; i < max_outbound_full_relay - 1; ++i) {

test/functional/p2p_block_times.py

@@ -0,0 +1,83 @@
+#!/usr/bin/env python3
+# Copyright (c) 2023 The Bitcoin Core developers
+# Distributed under the MIT software license, see the accompanying
+# file COPYING or https://www.opensource.org/licenses/mit-license.php.
+
+""" Test block announcement time tracking
+
+The bitcoind client records, for each peer, the most recent time that
+this peer announced a block that the client wasn't already aware of. This
+timestamp, CNodeStateStats::m_last_block_announcement, is available in the
+`last_block_announcement` field of each peer's `getpeerinfo` result. The
+value zero means that this peer has never been the first to announce
+a block to us. Blocks are announced using either the "headers" or
+"cmpctblock" messages.
+
+This timestamp is used when the "potential stale tip" condition occurs:
+When a new block hasn't been seen for a longer-than-expected amount of
+time (currently 30 minutes, see TipMayBeStale()), the client, suspecting
+that there may be new blocks that its peers are not announcing, will
+add an extra outbound peer and disconnect (evict) the peer that has
+least recently been the first to announced a new block to us. (If there
+is a tie, it will disconnect the most recently-added of those peers.)
+
+This test verifies that this timestamp is being set correctly.
+(This tests PR 26172.)
+"""
+
+import time
+from test_framework.blocktools import (
+    create_block,
+    create_coinbase,
+)
+from test_framework.messages import (
+    CBlockHeader,
+    msg_headers,
+)
+from test_framework.p2p import P2PDataStore
+from test_framework.test_framework import BitcoinTestFramework
+
+
+class P2PBlockTimes(BitcoinTestFramework):
+    def set_test_params(self):
+        self.setup_clean_chain = True
+        self.num_nodes = 1
+        self.disable_autoconnect = False
+
+    def run_test(self):
+        node = self.nodes[0]
+        cur_time = int(time.time())
+        node.setmocktime(cur_time)
+
+        # Generate one block to exit IBD
+        self.generate(node, 1)
+
+        self.log.info("Create a full-outbound test framework peer")
+        node.add_outbound_p2p_connection(P2PDataStore(), p2p_idx=0)
+
+        self.log.info("Test framework peer generates a new block")
+        tip = int(node.getbestblockhash(), 16)
+        block = create_block(tip, create_coinbase(2))
+        block.solve()
+
+        self.log.info("Test framework peer sends node the new block)")
+        node.p2ps[0].send_blocks_and_test([block], node, success=True)
+
+        self.log.info("Verify peerinfo block timestamps")
+        peerinfo = node.getpeerinfo()[0]
+        assert peerinfo['last_block'] == cur_time
+        assert peerinfo['last_block_announcement'] == cur_time
+
+        self.log.info("Sending a block announcement with no new blocks")
+        node.setmocktime(cur_time+1)
+        headers_message = msg_headers()
+        headers_message.headers = [CBlockHeader(block)]
+        node.p2ps[0].send_message(headers_message)
+        node.p2ps[0].sync_with_ping()
+
+        self.log.info("Verify that block announcement time isn't updated")
+        peerinfo = node.getpeerinfo()[0]
+        assert peerinfo['last_block_announcement'] == cur_time
+
+if __name__ == '__main__':
+    P2PBlockTimes().main()

test/functional/rpc_net.py

@@ -84,7 +84,8 @@ def test_getpeerinfo(self):
         time_now = int(time.time())
         peer_info = [x.getpeerinfo() for x in self.nodes]
         # Verify last_block and last_transaction keys/values.
-        for node, peer, field in product(range(self.num_nodes), range(2), ['last_block', 'last_transaction']):
+        for node, peer, field in product(range(self.num_nodes), range(2),
+                                         ['last_block', 'last_block_announcement', 'last_transaction']):
             assert field in peer_info[node][peer].keys()
             if peer_info[node][peer][field] != 0:
                 assert_approx(peer_info[node][peer][field], time_now, vspan=60)
@@ -135,6 +136,7 @@ def test_getpeerinfo(self):
                 "inbound": True,
                 "inflight": [],
                 "last_block": 0,
+                "last_block_announcement": 0,
                 "last_transaction": 0,
                 "lastrecv": 0,
                 "lastsend": 0,

test/functional/test_runner.py

@@ -203,6 +203,7 @@
     'mempool_reorg.py',
     'p2p_block_sync.py',
     'p2p_block_sync.py --v2transport',
+    'p2p_block_times.py',
     'wallet_createwallet.py --legacy-wallet',
     'wallet_createwallet.py --usecli',
     'wallet_createwallet.py --descriptors',