Merge bitcoin/bitcoin#27826: validation: log which peer sent us a header

abe43df doc: release note for #27826 (Sjors Provoost)
f9fa287 Use LogBlockHeader for compact blocks (Sjors Provoost)
bad7c91 Log which peer sent us a header (Sjors Provoost)
9d3e39c Log block header in net_processing (Sjors Provoost)

Pull request description:

  Fixes #27744

  Since #27278 we log received headers. For compact blocks we also log which peer sent it (e5ce857), but not for regular headers. That required an additional refactor, which this PR provides.

  Move the logging from validation to net_processing.

  This also reduces the number of log entries (under default configuration) per compact block header from 3 to 2: one for the header and one for the connected tip.

  The PR introduces a new helper method `LogBlockHeader`.

  When receiving a _compact block_ we call `LogBlockHeader` from the exact same place as where we previously logged. So that log message doesn't change. What does change is that we no longer _also_ log from `AcceptBlockHeader`.

  When receiving a regular header(s) message, _we only log the last one_. This is a change in behaviour because it was simpler to implement, but it's probably better anyway. It does mean that if a peer sends of a bunch of headers of which _any_ is invalid, we won't log it (here).

  Lastly I expanded the code comment explaining why we log this. It initially only covered selfish mining, but we also care about peers sending us headers but not following up (see e.g. #27626).

  Example log:

  ```
  2023-06-05T13:12:21Z Saw new header hash=000000000000000000045910263ef84b575ae3af151865238f1e5c619e69c330 height=792964 peer=0
  2023-06-05T13:12:23Z UpdateTip: new best=000000000000000000045910263ef84b575ae3af151865238f1e5c619e69c330 height=792964 version=0x20000000 log2_work=94.223098 tx=848176824 date='2023-06-05T13:11:49Z' progress=1.000000 cache=6.4MiB(54615txo)
  2023-06-05T13:14:05Z Saw new cmpctblock header hash=00000000000000000003c6fd4ef2e1246a3f9e1fffab7247344f94cadb9de979 height=792965 peer=0
  2023-06-05T13:14:05Z UpdateTip: new best=00000000000000000003c6fd4ef2e1246a3f9e1fffab7247344f94cadb9de979 height=792965 version=0x20000000 log2_work=94.223112 tx=848179461 date='2023-06-05T13:13:58Z' progress=1.000000 cache=7.2MiB(61275txo)
  2023-06-05T13:14:41Z Saw new header hash=000000000000000000048e6d69c8399992782d08cb57f5d6cbc81a9f996c3f43 height=792966 peer=8
  2023-06-05T13:14:42Z UpdateTip: new best=000000000000000000048e6d69c8399992782d08cb57f5d6cbc81a9f996c3f43 height=792966 version=0x2db3c000 log2_work=94.223126 tx=848182944 date='2023-06-05T13:14:35Z' progress=1.000000 cache=8.0MiB(69837txo)
  ```

ACKs for top commit:
  danielabrozzoni:
    tACK abe43df
  achow101:
    ACK abe43df
  vasild:
    ACK abe43df

Tree-SHA512: 081e0de62cbd8a0b35cf54daaa09e3e6991d0cc9f706ef3eb50908752fe7815de69b367f7313381c90cd8d5de0ae5f532d1cd54948c5c1133b1832f266d9c232

Author: achow101

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)

src/net_processing.cpp

@@ -1071,6 +1071,8 @@ class PeerManagerImpl final : public PeerManager
 
     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, bool via_compact_block);
 };
 
 const CNodeState* PeerManagerImpl::State(NodeId pnode) const
@@ -2970,14 +2972,21 @@ 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;
         }
     }
     assert(pindexLast);
 
+    if (processed && received_new_header) {
+        LogBlockHeader(*pindexLast, pfrom, /*via_compact_block=*/false);
+    }
+
     // 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,32 @@ void PeerManagerImpl::ProcessCompactBlockTxns(CNode& pfrom, Peer& peer, const Bl
     return;
 }
 
+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.
+    //
+    // 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 %sheader hash=%s height=%d peer=%d%s",
+        via_compact_block ? "cmpctblock " : "",
+        index.GetBlockHash().ToString(),
+        index.nHeight,
+        peer.GetId(),
+        peer.LogIP(fLogIPs)
+    );
+    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<bool>& interruptMsgProc)
@@ -4353,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;
@@ -4371,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());

src/validation.cpp

@@ -4376,23 +4376,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;
 }
 

src/validation.h

@@ -1216,6 +1216,7 @@ class ChainstateManager
      * @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<const CBlockHeader> headers, bool min_pow_checked, BlockValidationState& state, const CBlockIndex** ppindex = nullptr) LOCKS_EXCLUDED(cs_main);