From 9d3e39c29c31775fd82af319d1d4dfbbd3e21bfa Mon Sep 17 00:00:00 2001 From: Sjors Provoost Date: Fri, 21 Feb 2025 15:35:43 +0100 Subject: [PATCH 1/4] Log block header in net_processing Previously ChainstateManager::AcceptBlockHeader would log when it saw a new header. This commit moves logging to the call site(s) in net_processing. The next commits will then log which peer sent it and whether it was part of a compact block. This commit changes behavior: - when multiple headers are received in a single message, only the last one is logged - if any of the headers are invalid, the valid ones are not logged This happens because net_processing calls ProcessNewBlockHeaders with multiple headers, which then calls AcceptBlockHeader one header at a time. Additionally: - when the header is received via a compact block, there's no more duplicate log (a later commit also unifies logging code paths) --- src/net_processing.cpp | 34 +++++++++++++++++++++++++++++++++- src/validation.cpp | 17 ----------------- src/validation.h | 1 + 3 files changed, 34 insertions(+), 18 deletions(-) diff --git a/src/net_processing.cpp b/src/net_processing.cpp index 0b25396dd21..d7061fdec87 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -1071,6 +1071,8 @@ private: void AddAddressKnown(Peer& peer, const CAddress& addr) EXCLUSIVE_LOCKS_REQUIRED(g_msgproc_mutex); void PushAddress(Peer& peer, const CAddress& addr) EXCLUSIVE_LOCKS_REQUIRED(g_msgproc_mutex); + + void LogBlockHeader(const CBlockIndex& index); }; const CNodeState* PeerManagerImpl::State(NodeId pnode) const @@ -2970,7 +2972,10 @@ void PeerManagerImpl::ProcessHeadersMessage(CNode& pfrom, Peer& peer, // Now process all the headers. BlockValidationState state; - if (!m_chainman.ProcessNewBlockHeaders(headers, /*min_pow_checked=*/true, state, &pindexLast)) { + const bool processed{m_chainman.ProcessNewBlockHeaders(headers, + /*min_pow_checked=*/true, + state, &pindexLast)}; + if (!processed) { if (state.IsInvalid()) { MaybePunishNodeForBlock(pfrom.GetId(), state, via_compact_block, "invalid header received"); return; @@ -2978,6 +2983,10 @@ void PeerManagerImpl::ProcessHeadersMessage(CNode& pfrom, Peer& peer, } assert(pindexLast); + if (processed && received_new_header) { + LogBlockHeader(*pindexLast); + } + // Consider fetching more headers if we are not using our headers-sync mechanism. if (nCount == m_opts.max_headers_result && !have_headers_sync) { // Headers message had its maximum size; the peer may have more headers. @@ -3405,6 +3414,29 @@ void PeerManagerImpl::ProcessCompactBlockTxns(CNode& pfrom, Peer& peer, const Bl return; } +void PeerManagerImpl::LogBlockHeader(const CBlockIndex& index) { + // To prevent log spam, this function should only be called after it was determined that a + // header is both new and valid. + // + // These messages are valuable for detecting potential selfish mining behavior; + // if multiple displacing headers are seen near simultaneously across many + // nodes in the network, this might be an indication of selfish mining. + // In addition it can be used to identify peers which send us a header, but + // don't followup with a complete and valid (compact) block. + // Having this log by default when not in IBD ensures broad availability of + // this data in case investigation is merited. + const auto msg = strprintf( + "Saw new header hash=%s height=%d", + index.GetBlockHash().ToString(), + index.nHeight + ); + if (m_chainman.IsInitialBlockDownload()) { + LogDebug(BCLog::VALIDATION, "%s", msg); + } else { + LogInfo("%s", msg); + } +} + void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, DataStream& vRecv, const std::chrono::microseconds time_received, const std::atomic& interruptMsgProc) diff --git a/src/validation.cpp b/src/validation.cpp index aa1effb736f..01650ba1f57 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -4403,23 +4403,6 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida if (ppindex) *ppindex = pindex; - // Since this is the earliest point at which we have determined that a - // header is both new and valid, log here. - // - // These messages are valuable for detecting potential selfish mining behavior; - // if multiple displacing headers are seen near simultaneously across many - // nodes in the network, this might be an indication of selfish mining. Having - // this log by default when not in IBD ensures broad availability of this data - // in case investigation is merited. - const auto msg = strprintf( - "Saw new header hash=%s height=%d", hash.ToString(), pindex->nHeight); - - if (IsInitialBlockDownload()) { - LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Debug, "%s\n", msg); - } else { - LogPrintf("%s\n", msg); - } - return true; } diff --git a/src/validation.h b/src/validation.h index e361c7af101..cdea2a98936 100644 --- a/src/validation.h +++ b/src/validation.h @@ -1218,6 +1218,7 @@ public: * @param[in] min_pow_checked True if proof-of-work anti-DoS checks have been done by caller for headers chain * @param[out] state This may be set to an Error state if any error occurred processing them * @param[out] ppindex If set, the pointer will be set to point to the last new block index object for the given headers + * @returns false if AcceptBlockHeader fails on any of the headers, true otherwise (including if headers were already known) */ bool ProcessNewBlockHeaders(std::span headers, bool min_pow_checked, BlockValidationState& state, const CBlockIndex** ppindex = nullptr) LOCKS_EXCLUDED(cs_main); From bad7c914793134abe2f64d96c367d5e9b07e60fd Mon Sep 17 00:00:00 2001 From: Sjors Provoost Date: Fri, 21 Feb 2025 15:31:26 +0100 Subject: [PATCH 2/4] Log which peer sent us a header This also supports -logips. --- src/net_processing.cpp | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/src/net_processing.cpp b/src/net_processing.cpp index d7061fdec87..d5ee780063b 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -1072,7 +1072,7 @@ private: void AddAddressKnown(Peer& peer, const CAddress& addr) EXCLUSIVE_LOCKS_REQUIRED(g_msgproc_mutex); void PushAddress(Peer& peer, const CAddress& addr) EXCLUSIVE_LOCKS_REQUIRED(g_msgproc_mutex); - void LogBlockHeader(const CBlockIndex& index); + void LogBlockHeader(const CBlockIndex& index, const CNode& peer); }; const CNodeState* PeerManagerImpl::State(NodeId pnode) const @@ -2984,7 +2984,7 @@ void PeerManagerImpl::ProcessHeadersMessage(CNode& pfrom, Peer& peer, assert(pindexLast); if (processed && received_new_header) { - LogBlockHeader(*pindexLast); + LogBlockHeader(*pindexLast, pfrom); } // Consider fetching more headers if we are not using our headers-sync mechanism. @@ -3414,7 +3414,7 @@ void PeerManagerImpl::ProcessCompactBlockTxns(CNode& pfrom, Peer& peer, const Bl return; } -void PeerManagerImpl::LogBlockHeader(const CBlockIndex& index) { +void PeerManagerImpl::LogBlockHeader(const CBlockIndex& index, const CNode& peer) { // To prevent log spam, this function should only be called after it was determined that a // header is both new and valid. // @@ -3426,9 +3426,11 @@ void PeerManagerImpl::LogBlockHeader(const CBlockIndex& index) { // Having this log by default when not in IBD ensures broad availability of // this data in case investigation is merited. const auto msg = strprintf( - "Saw new header hash=%s height=%d", + "Saw new header hash=%s height=%d peer=%d%s", index.GetBlockHash().ToString(), - index.nHeight + index.nHeight, + peer.GetId(), + peer.LogIP(fLogIPs) ); if (m_chainman.IsInitialBlockDownload()) { LogDebug(BCLog::VALIDATION, "%s", msg); From f9fa28788e63e2bd059a21ec0e76ae6903b2a6be Mon Sep 17 00:00:00 2001 From: Sjors Provoost Date: Fri, 21 Feb 2025 15:34:29 +0100 Subject: [PATCH 3/4] Use LogBlockHeader for compact blocks The only behavior change is that the block height is now added to the log message. --- src/net_processing.cpp | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/src/net_processing.cpp b/src/net_processing.cpp index d5ee780063b..78e97b66840 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -1072,7 +1072,7 @@ private: void AddAddressKnown(Peer& peer, const CAddress& addr) EXCLUSIVE_LOCKS_REQUIRED(g_msgproc_mutex); void PushAddress(Peer& peer, const CAddress& addr) EXCLUSIVE_LOCKS_REQUIRED(g_msgproc_mutex); - void LogBlockHeader(const CBlockIndex& index, const CNode& peer); + void LogBlockHeader(const CBlockIndex& index, const CNode& peer, bool via_compact_block); }; const CNodeState* PeerManagerImpl::State(NodeId pnode) const @@ -2984,7 +2984,7 @@ void PeerManagerImpl::ProcessHeadersMessage(CNode& pfrom, Peer& peer, assert(pindexLast); if (processed && received_new_header) { - LogBlockHeader(*pindexLast, pfrom); + LogBlockHeader(*pindexLast, pfrom, /*via_compact_block=*/false); } // Consider fetching more headers if we are not using our headers-sync mechanism. @@ -3414,7 +3414,7 @@ void PeerManagerImpl::ProcessCompactBlockTxns(CNode& pfrom, Peer& peer, const Bl return; } -void PeerManagerImpl::LogBlockHeader(const CBlockIndex& index, const CNode& peer) { +void PeerManagerImpl::LogBlockHeader(const CBlockIndex& index, const CNode& peer, bool via_compact_block) { // To prevent log spam, this function should only be called after it was determined that a // header is both new and valid. // @@ -3426,7 +3426,8 @@ void PeerManagerImpl::LogBlockHeader(const CBlockIndex& index, const CNode& peer // Having this log by default when not in IBD ensures broad availability of // this data in case investigation is merited. const auto msg = strprintf( - "Saw new header hash=%s height=%d peer=%d%s", + "Saw new %sheader hash=%s height=%d peer=%d%s", + via_compact_block ? "cmpctblock " : "", index.GetBlockHash().ToString(), index.nHeight, peer.GetId(), @@ -4387,9 +4388,10 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, } } + // If AcceptBlockHeader returned true, it set pindex + Assert(pindex); if (received_new_header) { - LogInfo("Saw new cmpctblock header hash=%s peer=%d\n", - blockhash.ToString(), pfrom.GetId()); + LogBlockHeader(*pindex, pfrom, /*via_compact_block=*/true); } bool fProcessBLOCKTXN = false; @@ -4405,8 +4407,6 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, { LOCK(cs_main); - // If AcceptBlockHeader returned true, it set pindex - assert(pindex); UpdateBlockAvailability(pfrom.GetId(), pindex->GetBlockHash()); CNodeState *nodestate = State(pfrom.GetId()); From abe43dfadd6325f80975a76aea57a549c3162191 Mon Sep 17 00:00:00 2001 From: Sjors Provoost Date: Tue, 15 Apr 2025 07:48:48 -0400 Subject: [PATCH 4/4] doc: release note for #27826 --- doc/release-notes-27826.md | 4 ++++ 1 file changed, 4 insertions(+) create mode 100644 doc/release-notes-27826.md diff --git a/doc/release-notes-27826.md b/doc/release-notes-27826.md new file mode 100644 index 00000000000..7f8a9ee4ded --- /dev/null +++ b/doc/release-notes-27826.md @@ -0,0 +1,4 @@ +- Logs now include which peer sent us a header. Additionaly there are fewer + redundant header log messages. A side-effect of this change is that for + some untypical cases new headers aren't logged anymore, e.g. a direct + `BLOCK` message with a previously unknown header and `submitheader` RPC. (#27826)