Add logging for CValidationInterface events

>>> backports bitcoin/bitcoin@f9abf4a This could help debug issues where there may be race conditions at play, such as btc#12978.
PIVX-Project · Sep 10, 2021 · 22dc168 · 22dc168
1 parent 97d9633
commit 22dc168
Show file tree

Hide file tree

Showing 2 changed files with 58 additions and 15 deletions.
diff --git a/src/primitives/block.h b/src/primitives/block.h
@@ -174,7 +174,7 @@ struct CBlockLocator
         vHave.clear();
     }
 
-    bool IsNull()
+    bool IsNull() const
     {
         return vHave.empty();
     }

diff --git a/src/validationinterface.cpp b/src/validationinterface.cpp
@@ -5,8 +5,14 @@
 // file COPYING or http://www.opensource.org/licenses/mit-license.php.
 
 #include "validationinterface.h"
+
+#include "chain.h"
+#include "consensus/validation.h"
+#include "evo/deterministicmns.h"
+#include "logging.h"
 #include "scheduler.h"
-#include "validation.h"
+#include "util/validation.h"
+#include "validation.h" // cs_main
 
 #include <future>
 #include <list>
@@ -132,44 +138,73 @@ void SyncWithValidationInterfaceQueue() {
     promise.get_future().wait();
 }
 
+// Use a macro instead of a function for conditional logging to prevent
+// evaluating arguments when logging is not enabled.
+//
+// NOTE: The lambda captures all local variables by value.
+#define ENQUEUE_AND_LOG_EVENT(event, fmt, name, ...)           \
+    do {                                                       \
+        auto local_name = (name);                              \
+        LOG_EVENT("Enqueuing " fmt, local_name, __VA_ARGS__);  \
+        m_internals->m_schedulerClient.AddToProcessQueue([=] { \
+            LOG_EVENT(fmt, local_name, __VA_ARGS__);           \
+            event();                                           \
+        });                                                    \
+    } while (0)
+
+#define LOG_EVENT(fmt, ...) \
+    LogPrint(BCLog::VALIDATION, fmt "\n", __VA_ARGS__)
+
 void CMainSignals::UpdatedBlockTip(const CBlockIndex* pindexNew, const CBlockIndex* pindexFork, bool fInitialDownload) {
     // Dependencies exist that require UpdatedBlockTip events to be delivered in the order in which
     // the chain actually updates. One way to ensure this is for the caller to invoke this signal
     // in the same critical section where the chain is updated
 
-    m_internals->m_schedulerClient.AddToProcessQueue([pindexNew, pindexFork, fInitialDownload, this] {
+    auto event = [pindexNew, pindexFork, fInitialDownload, this] {
         m_internals->UpdatedBlockTip(pindexNew, pindexFork, fInitialDownload);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: new block hash=%s, fork block hash=%s (in IBD=%s)", __func__,
+                          pindexNew->GetBlockHash().ToString(),
+                          pindexFork ? pindexFork->GetBlockHash().ToString() : "null",
+                          fInitialDownload);
 }
 
 void CMainSignals::TransactionAddedToMempool(const CTransactionRef &ptx) {
-    m_internals->m_schedulerClient.AddToProcessQueue([ptx, this] {
+    auto event = [ptx, this] {
         m_internals->TransactionAddedToMempool(ptx);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: txid=%s", __func__, ptx->GetHash().ToString());
 }
 
 void CMainSignals::TransactionRemovedFromMempool(const CTransactionRef& ptx, MemPoolRemovalReason reason) {
-    m_internals->m_schedulerClient.AddToProcessQueue([ptx, reason, this] {
+    auto event = [ptx, reason, this] {
         m_internals->TransactionRemovedFromMempool(ptx, reason);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: txid=%s", __func__, ptx->GetHash().ToString());
 }
 
 void CMainSignals::BlockConnected(const std::shared_ptr<const CBlock> &pblock, const CBlockIndex *pindex) {
-    m_internals->m_schedulerClient.AddToProcessQueue([pblock, pindex, this] {
+    auto event = [pblock, pindex, this] {
         m_internals->BlockConnected(pblock, pindex);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: block hash=%s, block height=%d", __func__,
+                          pblock->GetHash().ToString(), pindex->nHeight);
 }
 
 void CMainSignals::BlockDisconnected(const std::shared_ptr<const CBlock> &pblock, const uint256& blockHash, int nBlockHeight, int64_t blockTime) {
-    m_internals->m_schedulerClient.AddToProcessQueue([pblock, blockHash, nBlockHeight, blockTime, this] {
+    auto event = [pblock, blockHash, nBlockHeight, blockTime, this] {
         m_internals->BlockDisconnected(pblock, blockHash, nBlockHeight, blockTime);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: block hash=%s, block height=%d, block time=%d", __func__,
+                          blockHash.ToString(), nBlockHeight, blockTime);
 }
 
-void CMainSignals::SetBestChain(const CBlockLocator &locator) {
-    m_internals->m_schedulerClient.AddToProcessQueue([locator, this] {
+void CMainSignals::SetBestChain(const CBlockLocator& locator) {
+    auto event = [locator, this] {
         m_internals->SetBestChain(locator);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: block hash=%s", __func__,
+                          locator.IsNull() ? "null" : locator.vHave.front().ToString());
 }
 
 void CMainSignals::Broadcast(CConnman* connman) {
@@ -178,8 +213,16 @@ void CMainSignals::Broadcast(CConnman* connman) {
 
 void CMainSignals::BlockChecked(const CBlock& block, const CValidationState& state) {
     m_internals->BlockChecked(block, state);
+    LOG_EVENT("%s: block hash=%s (state=%s)", __func__,
+              block.GetHash().ToString(), FormatStateMessage(state));
 }
 
 void CMainSignals::NotifyMasternodeListChanged(bool undo, const CDeterministicMNList& oldMNList, const CDeterministicMNListDiff& diff) {
     m_internals->NotifyMasternodeListChanged(undo, oldMNList, diff);
+    LOG_EVENT("%s: (undo=%d) old list for=%s, added=%d, updated=%d, removed=%d", __func__,
+              undo,
+              oldMNList.GetBlockHash().ToString(),
+              diff.addedMNs.size(),
+              diff.updatedMNs.size(),
+              diff.removedMns.size());
 }