Merge bitcoin/bitcoin#27278: Log new headers

2c3a90f663a61ee147d785167a2902494d81d34d log: on new valid header (James O'Beirne)
e5ce8576349d404c466b2f4cab1ca7bf920904b2 log: net: new header over cmpctblock (James O'Beirne)

Pull request description:

  Alternate to #27276.

  Devs were [suprised to realize](https://twitter.com/jamesob/status/1637237917201383425) last night that we don't have definitive logging for when a given header was first received.

  This logs to the main stream when new headers are received outside of IBD, as well as when headers come in over cmpctblocks. The rationale of not hiding these under log categories is that they may be useful to have widely available when debugging strange network activity, and the marginal volume is modest.

ACKs for top commit:
  dergoegge:
    Code review ACK 2c3a90f663a61ee147d785167a2902494d81d34d
  achow101:
    ACK 2c3a90f663a61ee147d785167a2902494d81d34d
  Sjors:
    tACK 2c3a90f663a61ee147d785167a2902494d81d34d
  josibake:
    ACK https://github.com/bitcoin/bitcoin/pull/27278/commits/2c3a90f663a61ee147d785167a2902494d81d34d

Tree-SHA512: 49fdcbe07799c8adc24143d7e5054a0c93fef120d2e9d5fddbd3b119550d895e2985be6ac10dd1825ea23a6fa5479c1b76d5518c136fbd983fa76c0d39dc354f

2 files changed, 28 insertions, 5 deletions

diff --git a/src/net_processing.cpp b/src/net_processing.cpp
index 25c65c7090..5dd00d58a0 100644
--- a/src/net_processing.cpp
+++ b/src/net_processing.cpp
@@ -4190,6 +4190,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
         vRecv >> cmpctblock;
 
         bool received_new_header = false;
+        const auto blockhash = cmpctblock.header.GetHash();
 
         {
         LOCK(cs_main);
@@ -4207,7 +4208,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
             return;
         }
 
-        if (!m_chainman.m_blockman.LookupBlockIndex(cmpctblock.header.GetHash())) {
+        if (!m_chainman.m_blockman.LookupBlockIndex(blockhash)) {
             received_new_header = true;
         }
         }
@@ -4221,6 +4222,11 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
             }
         }
 
+        if (received_new_header) {
+            LogPrintfCategory(BCLog::NET, "Saw new cmpctblock header hash=%s peer=%d\n",
+                blockhash.ToString(), pfrom.GetId());
+        }
+
         // When we succeed in decoding a block's txids from a cmpctblock
         // message we typically jump to the BLOCKTXN handling code, with a
         // dummy (empty) BLOCKTXN message, to re-use the logic there in
@@ -4263,7 +4269,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
                 // We requested this block for some reason, but our mempool will probably be useless
                 // so we just grab the block via normal getdata
                 std::vector<CInv> vInv(1);
-                vInv[0] = CInv(MSG_BLOCK | GetFetchFlags(*peer), cmpctblock.header.GetHash());
+                vInv[0] = CInv(MSG_BLOCK | GetFetchFlags(*peer), blockhash);
                 m_connman.PushMessage(&pfrom, msgMaker.Make(NetMsgType::GETDATA, vInv));
             }
             return;
@@ -4299,7 +4305,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
                 } else if (status == READ_STATUS_FAILED) {
                     // Duplicate txindexes, the block is now in-flight, so just request it
                     std::vector<CInv> vInv(1);
-                    vInv[0] = CInv(MSG_BLOCK | GetFetchFlags(*peer), cmpctblock.header.GetHash());
+                    vInv[0] = CInv(MSG_BLOCK | GetFetchFlags(*peer), blockhash);
                     m_connman.PushMessage(&pfrom, msgMaker.Make(NetMsgType::GETDATA, vInv));
                     return;
                 }
@@ -4312,7 +4318,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
                 if (req.indexes.empty()) {
                     // Dirty hack to jump to BLOCKTXN code (TODO: move message handling into their own functions)
                     BlockTransactions txn;
-                    txn.blockhash = cmpctblock.header.GetHash();
+                    txn.blockhash = blockhash;
                     blockTxnMsg << txn;
                     fProcessBLOCKTXN = true;
                 } else {
@@ -4342,7 +4348,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
                 // We requested this block, but its far into the future, so our
                 // mempool will probably be useless - request the block normally
                 std::vector<CInv> vInv(1);
-                vInv[0] = CInv(MSG_BLOCK | GetFetchFlags(*peer), cmpctblock.header.GetHash());
+                vInv[0] = CInv(MSG_BLOCK | GetFetchFlags(*peer), blockhash);
                 m_connman.PushMessage(&pfrom, msgMaker.Make(NetMsgType::GETDATA, vInv));
                 return;
             } else {
diff --git a/src/validation.cpp b/src/validation.cpp
index d1b941f081..2af7e2cc8d 100644
--- a/src/validation.cpp
+++ b/src/validation.cpp
@@ -3845,6 +3845,23 @@ 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 (ActiveChainstate().IsInitialBlockDownload()) {
+        LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Debug, "%s\n", msg);
+    } else {
+        LogPrintf("%s\n", msg);
+    }
+
     return true;
 }