From 50ed54854a0c8796b2d77ffc9d1f3a1a10684616 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 170352f7299..e4880b82d68 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -461,7 +461,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}; }; class PeerManagerImpl final : public PeerManager @@ -513,7 +513,7 @@ public: 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_most_recent_block_mutex, !m_headers_presync_mutex, g_msgproc_mutex, !m_tx_download_mutex); - void UpdateLastBlockAnnounceTime(NodeId node, int64_t time_in_seconds) override; + void UpdateLastBlockAnnounceTime(NodeId node, NodeSeconds time_in_seconds) override; ServiceFlags GetDesirableServiceFlags(ServiceFlags services) const override; private: @@ -1513,7 +1513,7 @@ void PeerManagerImpl::PushNodeVersion(CNode& pnode, const Peer& peer) } } -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); @@ -2770,7 +2770,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 @@ -4346,7 +4346,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 @@ -5121,7 +5121,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); @@ -5136,7 +5136,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; } @@ -5152,7 +5155,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()) { - LogDebug(BCLog::NET, "disconnecting extra outbound peer=%d (last block announcement received at time %d)\n", pnode->GetId(), oldest_block_announcement); + LogDebug(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 0d2dc59c5ae..d1ebb7fdae5 100644 --- a/src/net_processing.h +++ b/src/net_processing.h @@ -128,7 +128,7 @@ public: 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 9ee7e9c9fe2..a113831f300 100644 --- a/src/test/denialofservice_tests.cpp +++ b/src/test/denialofservice_tests.cpp @@ -197,7 +197,7 @@ BOOST_FIXTURE_TEST_CASE(stale_tip_peer_management, OutboundTest) // 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 7e860886856a005283aa4e06dba11cae20f79834 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 e4880b82d68..e487a97410c 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -1679,6 +1679,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); @@ -5156,7 +5157,7 @@ void PeerManagerImpl::EvictExtraOutboundPeers(std::chrono::seconds now) CNodeState &state = *State(pnode->GetId()); if (now - pnode->m_connected > MINIMUM_CONNECT_TIME && state.vBlocksInFlight.empty()) { LogDebug(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 d1ebb7fdae5..5db13454180 100644 --- a/src/net_processing.h +++ b/src/net_processing.h @@ -50,6 +50,7 @@ struct CNodeStateStats { ServiceFlags their_services; int64_t presync_height{-1}; std::chrono::seconds time_offset{0}; + NodeSeconds m_last_block_announcement; }; struct PeerManagerInfo { From 1e806590106ef4bd46f39e4338d89ef79d80ace9 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 5398685074d..97899594318 100644 --- a/src/rpc/net.cpp +++ b/src/rpc/net.cpp @@ -141,6 +141,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"}, @@ -237,6 +238,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 b63059b1eec..46636737c5c 100755 --- a/test/functional/rpc_net.py +++ b/test/functional/rpc_net.py @@ -101,7 +101,8 @@ class NetTest(BitcoinTestFramework): 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) @@ -155,6 +156,7 @@ class NetTest(BitcoinTestFramework): "inbound": True, "inflight": [], "last_block": 0, + "last_block_announcement": 0, "last_transaction": 0, "lastrecv": 0 if not self.options.v2transport else no_version_peer_conntime, "lastsend": 0 if not self.options.v2transport else no_version_peer_conntime, From 99396b231680575e3688567931fc14b9f592ddc5 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 00000000000..5452a1124de --- /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(__file__).main() diff --git a/test/functional/test_runner.py b/test/functional/test_runner.py index dc9053491cc..002fe799760 100755 --- a/test/functional/test_runner.py +++ b/test/functional/test_runner.py @@ -206,6 +206,7 @@ BASE_SCRIPTS = [ 'mempool_reorg.py', 'p2p_block_sync.py --v1transport', 'p2p_block_sync.py --v2transport', + 'p2p_block_times.py', 'wallet_createwallet.py --legacy-wallet', 'wallet_createwallet.py --usecli', 'wallet_createwallet.py --descriptors', From 21ad9f83750350589898332458485a7c95bb875e 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 | 8 ++++++++ 1 file changed, 8 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 00000000000..37393c6fc91 --- /dev/null +++ b/doc/release-notes-27052.md @@ -0,0 +1,8 @@ +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 stale-tip +eviction logic.