From 4f56e397a9b9de24fac770ea514fdfea35396c2c Mon Sep 17 00:00:00 2001 From: Larry Ruane Date: Mon, 14 Aug 2023 22:52:43 -0600 Subject: [PATCH 1/5] change m_last_block_announcement type from int64_t to NodeSeconds --- src/net_processing.cpp | 20 ++++++++++++-------- src/net_processing.h | 2 +- src/test/denialofservice_tests.cpp | 2 +- 3 files changed, 14 insertions(+), 10 deletions(-) diff --git a/src/net_processing.cpp b/src/net_processing.cpp index c8da927763443..9d8ab6074bfe2 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); @@ -2848,7 +2848,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 +4471,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 +5231,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 +5246,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 +5265,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(), (*oldest_block_announcement).time_since_epoch().count()); pnode->fDisconnect = true; return true; } else { diff --git a/src/net_processing.h b/src/net_processing.h index f8d7a8f5115e1..bccf56ccab1e9 100644 --- a/src/net_processing.h +++ b/src/net_processing.h @@ -109,7 +109,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/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) { From a5bafa0bc53d1cf363560ede8a22266cbda063ca Mon Sep 17 00:00:00 2001 From: Larry Ruane Date: Mon, 14 Aug 2023 23:20:29 -0600 Subject: [PATCH 2/5] add m_last_block_announcement to CNodeStateStats Copy its value from CNodeState. Unused until the next commit. --- src/net_processing.cpp | 3 ++- src/net_processing.h | 1 + 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/src/net_processing.cpp b/src/net_processing.cpp index 9d8ab6074bfe2..6d5d2651f1f9c 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -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); @@ -5266,7 +5267,7 @@ void PeerManagerImpl::EvictExtraOutboundPeers(std::chrono::seconds now) 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).time_since_epoch().count()); + 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 bccf56ccab1e9..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 From 8a7d19fd63a63f2ba3ed983dc21aad112ee978d2 Mon Sep 17 00:00:00 2001 From: Larry Ruane Date: Mon, 14 Aug 2023 23:57:38 -0600 Subject: [PATCH 3/5] add last_block_announcement to the getpeerinfo output --- src/rpc/net.cpp | 2 ++ test/functional/rpc_net.py | 4 +++- 2 files changed, 5 insertions(+), 1 deletion(-) 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/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, From a563827eb8647ee37e785a445ebc7612c19684a5 Mon Sep 17 00:00:00 2001 From: Larry Ruane Date: Mon, 14 Aug 2023 23:59:54 -0600 Subject: [PATCH 4/5] add functional test --- test/functional/p2p_block_times.py | 83 ++++++++++++++++++++++++++++++ test/functional/test_runner.py | 1 + 2 files changed, 84 insertions(+) create mode 100755 test/functional/p2p_block_times.py 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/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', From b1c3826ec093386c2ddec1d30ca3e777f8860892 Mon Sep 17 00:00:00 2001 From: Larry Ruane Date: Tue, 15 Aug 2023 00:28:44 -0600 Subject: [PATCH 5/5] add release notes --- doc/release-notes-27052.md | 7 +++++++ 1 file changed, 7 insertions(+) create mode 100644 doc/release-notes-27052.md 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.