diff --git a/doc/release-notes-27052.md b/doc/release-notes-27052.md new file mode 100644 index 0000000000000..40460f005b20d --- /dev/null +++ b/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. diff --git a/src/net_processing.cpp b/src/net_processing.cpp index c8da927763443..6d5d2651f1f9c 100644 --- a/src/net_processing.cpp +++ b/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& 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(); } // 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(); } 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::max(); + std::optional 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(*oldest_block_announcement)); pnode->fDisconnect = true; return true; } else { diff --git a/src/net_processing.h b/src/net_processing.h index f8d7a8f5115e1..8d5d850c23344 100644 --- a/src/net_processing.h +++ b/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& 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. diff --git a/src/rpc/net.cpp b/src/rpc/net.cpp index 5e6f42b596517..7cfd923677e70 100644 --- a/src/rpc/net.cpp +++ b/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(statestats.m_last_block_announcement)); obj.pushKV("bytessent", stats.nSendBytes); obj.pushKV("bytesrecv", stats.nRecvBytes); obj.pushKV("conntime", count_seconds(stats.m_connected)); diff --git a/src/test/denialofservice_tests.cpp b/src/test/denialofservice_tests.cpp index 0fef8c59069e1..8d81eaf0c34fe 100644 --- a/src/test/denialofservice_tests.cpp +++ b/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()); peerLogic->CheckForStaleTipAndEvictPeers(); for (int i = 0; i < max_outbound_full_relay - 1; ++i) { diff --git a/test/functional/p2p_block_times.py b/test/functional/p2p_block_times.py new file mode 100755 index 0000000000000..af0b77029c46b --- /dev/null +++ b/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() diff --git a/test/functional/rpc_net.py b/test/functional/rpc_net.py index afb75ab208fe4..d3e433cf3337d 100755 --- a/test/functional/rpc_net.py +++ b/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, diff --git a/test/functional/test_runner.py b/test/functional/test_runner.py index e438a60edc8d6..4a0f92bffa0d7 100755 --- a/test/functional/test_runner.py +++ b/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',