Merge #16688: log: Add validation interface logging

f9abf4ab6d3d3e4d4b7e90723020b5422a141a6f Add logging for CValidationInterface events (Jeffrey Czyz)
6edebacb2191373e76d79a4972d6192300976096 Refactor FormatStateMessage for clarity (Jeffrey Czyz)
72f3227c83810936e7a334304e5fd7c6dab8e91b Format CValidationState properly in all cases (Jeffrey Czyz)
428ac70095253225f64462ee15c595644747f376 Add VALIDATION to BCLog::LogFlags (Jeffrey Czyz)

Pull request description:

  Add logging of `CValidationInterface` callbacks using a new `VALIDATIONINTERFACE` log flag (see #12994). A separate flag is desirable as the logging can be noisy and thus may need to be disabled without affecting other logging.

  This could help debug issues where there may be race conditions at play, such as #12978.

ACKs for top commit:
  jnewbery:
    ACK f9abf4ab6d3d3e4d4b7e90723020b5422a141a6f
  hebasto:
    ACK f9abf4ab6d3d3e4d4b7e90723020b5422a141a6f
  ariard:
    ACK f9abf4a, only changes since 0cadb12 are replacing log indication `VALIDATIONINTERFACE` by `VALIDATION` and avoiding a forward declaration with a new include
  ryanofsky:
    Code review ACK f9abf4ab6d3d3e4d4b7e90723020b5422a141a6f. Just suggested changes since last review (thanks!)

Tree-SHA512: 3e0f6e2c8951cf46fbad3ff440971d95d526df2a52a2e4d6452a82785c63d53accfdabae66b0b30e2fe0b00737f8d5cb717edbad1460b63acb11a72c8f5d4236

src/logging.cpp

@@ -161,6 +161,7 @@ const CLogCategoryDesc LogCategories[] =
     {BCLog::COINDB, "coindb"},
     {BCLog::QT, "qt"},
     {BCLog::LEVELDB, "leveldb"},
+    {BCLog::VALIDATION, "validation"},
     {BCLog::ALL, "1"},
     {BCLog::ALL, "all"},
 

src/logging.h

@@ -56,6 +56,7 @@ namespace BCLog {
         COINDB      = (1 << 18),
         QT          = (1 << 19),
         LEVELDB     = (1 << 20),
+        VALIDATION  = (1 << 21),
 
         //Start Dash
         CHAINLOCKS  = ((uint64_t)1 << 32),

src/util/validation.cpp

@@ -8,10 +8,16 @@
 #include <consensus/validation.h>
 #include <tinyformat.h>
 
-/** Convert ValidationState to a human-readable message for logging */
 std::string FormatStateMessage(const ValidationState &state)
 {
-    return strprintf("%s%s",
+    if (state.IsValid()) {
-        state.GetRejectReason(),
+        return "Valid";
-        state.GetDebugMessage().empty() ? "" : ", "+state.GetDebugMessage());
+    }
+
+    const std::string debug_message = state.GetDebugMessage();
+    if (!debug_message.empty()) {
+        return strprintf("%s, %s", state.GetRejectReason(), debug_message);
+    }
+
+    return state.GetRejectReason();
 }

src/validationinterface.cpp

@@ -5,8 +5,18 @@
 
 #include <validationinterface.h>
 
+#include <chain.h>
+#include <consensus/validation.h>
+#include <logging.h>
 #include <primitives/block.h>
+#include <primitives/transaction.h>
 #include <scheduler.h>
+#include <util/validation.h>
+
+#include <governance/object.h>
+#include <governance/vote.h>
+#include <llmq/clsig.h>
+#include <llmq/signing.h>
 
 #include <future>
 #include <unordered_map>
@@ -154,14 +164,35 @@ 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::SynchronousUpdatedBlockTip(const CBlockIndex *pindexNew, const CBlockIndex *pindexFork, bool fInitialDownload) {
@@ -169,87 +200,117 @@ void CMainSignals::SynchronousUpdatedBlockTip(const CBlockIndex *pindexNew, cons
 }
 
 void CMainSignals::TransactionAddedToMempool(const CTransactionRef &ptx, int64_t nAcceptTime) {
-    m_internals->m_schedulerClient.AddToProcessQueue([ptx, nAcceptTime, this] {
+    auto event = [ptx, nAcceptTime, this] {
         m_internals->TransactionAddedToMempool(ptx, nAcceptTime);
-    });
+    };
+    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 CBlockIndex* pindex) {
-    m_internals->m_schedulerClient.AddToProcessQueue([pblock, pindex, this] {
+    auto event = [pblock, pindex, this] {
         m_internals->BlockDisconnected(pblock, pindex);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: block hash=%s block height=%d", __func__,
+                          pblock->GetHash().ToString(),
+                          pindex->nHeight);
 }
 
 void CMainSignals::ChainStateFlushed(const CBlockLocator &locator) {
-    m_internals->m_schedulerClient.AddToProcessQueue([locator, this] {
+    auto event = [locator, this] {
         m_internals->ChainStateFlushed(locator);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: block hash=%s", __func__,
+                          locator.IsNull() ? "null" : locator.vHave.front().ToString());
 }
 
 void CMainSignals::BlockChecked(const CBlock& block, const BlockValidationState& state) {
+    LOG_EVENT("%s: block hash=%s state=%s", __func__,
+              block.GetHash().ToString(), FormatStateMessage(state));
     m_internals->BlockChecked(block, state);
 }
 
 void CMainSignals::NewPoWValidBlock(const CBlockIndex *pindex, const std::shared_ptr<const CBlock> &block) {
+    LOG_EVENT("%s: block hash=%s", __func__, block->GetHash().ToString());
     m_internals->NewPoWValidBlock(pindex, block);
 }
 
 void CMainSignals::AcceptedBlockHeader(const CBlockIndex *pindexNew) {
+    LOG_EVENT("%s: accepted block header hash=%s", __func__, pindexNew->GetBlockHash().ToString());
     m_internals->AcceptedBlockHeader(pindexNew);
 }
 
 void CMainSignals::NotifyHeaderTip(const CBlockIndex *pindexNew, bool fInitialDownload) {
+    LOG_EVENT("%s: accepted block header hash=%s initial=%d", __func__, pindexNew->GetBlockHash().ToString(), fInitialDownload);
     m_internals->NotifyHeaderTip(pindexNew, fInitialDownload);
 }
 
 void CMainSignals::NotifyTransactionLock(const CTransactionRef &tx, const std::shared_ptr<const llmq::CInstantSendLock>& islock) {
-    m_internals->m_schedulerClient.AddToProcessQueue([tx, islock, this] {
+    auto event = [tx, islock, this] {
         m_internals->NotifyTransactionLock(tx, islock);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: transaction lock txid=%s", __func__,
+                          tx->GetHash().ToString());
 }
 
 void CMainSignals::NotifyChainLock(const CBlockIndex* pindex, const std::shared_ptr<const llmq::CChainLockSig>& clsig) {
-    m_internals->m_schedulerClient.AddToProcessQueue([pindex, clsig, this] {
+    auto event = [pindex, clsig, this] {
         m_internals->NotifyChainLock(pindex, clsig);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: notify chainlock at block=%s cl=%s", __func__,
+            pindex->GetBlockHash().ToString(),
+            clsig->ToString());
 }
 
 void CMainSignals::NotifyGovernanceVote(const std::shared_ptr<const CGovernanceVote>& vote) {
-    m_internals->m_schedulerClient.AddToProcessQueue([vote, this] {
+    auto event = [vote, this] {
         m_internals->NotifyGovernanceVote(vote);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: notify governance vote: %s", __func__, vote->GetHash().ToString());
 }
 
 void CMainSignals::NotifyGovernanceObject(const std::shared_ptr<const CGovernanceObject>& object) {
-    m_internals->m_schedulerClient.AddToProcessQueue([object, this] {
+    auto event = [object, this] {
         m_internals->NotifyGovernanceObject(object);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: notify governance object: %s", __func__, object->GetHash().ToString());
 }
 
 void CMainSignals::NotifyInstantSendDoubleSpendAttempt(const CTransactionRef& currentTx, const CTransactionRef& previousTx) {
-    m_internals->m_schedulerClient.AddToProcessQueue([currentTx, previousTx, this] {
+    auto event = [currentTx, previousTx, this] {
         m_internals->NotifyInstantSendDoubleSpendAttempt(currentTx, previousTx);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: notify instant doublespendattempt currenttxid=%s previoustxid=%s", __func__,
+            currentTx->GetHash().ToString(),
+            previousTx->GetHash().ToString());
 }
 
 void CMainSignals::NotifyRecoveredSig(const std::shared_ptr<const llmq::CRecoveredSig>& sig) {
-    m_internals->m_schedulerClient.AddToProcessQueue([sig, this] {
+    auto event = [sig, this] {
         m_internals->NotifyRecoveredSig(sig);
-    });
+    };
+    ENQUEUE_AND_LOG_EVENT(event, "%s: notify recoveredsig=%s", __func__,
+            sig->GetHash().ToString());
 }
 
 void CMainSignals::NotifyMasternodeListChanged(bool undo, const CDeterministicMNList& oldMNList, const CDeterministicMNListDiff& diff, CConnman& connman) {
+    LOG_EVENT("%s: notify mn list changed undo=%d", __func__, undo);
     m_internals->NotifyMasternodeListChanged(undo, oldMNList, diff, connman);
 }

test/lint/lint-circular-dependencies.sh

@@ -82,6 +82,10 @@ EXPECTED_CIRCULAR_DEPENDENCIES=(
     "llmq/snapshot -> llmq/utils -> llmq/snapshot"
     "spork -> validation -> spork"
     "governance/governance -> validation -> governance/governance"
+    "evo/deterministicmns -> validationinterface -> governance/vote -> evo/deterministicmns"
+    "governance/object -> validationinterface -> governance/object"
+    "governance/vote -> validation -> validationinterface -> governance/vote"
+    "llmq/signing -> masternode/node -> validationinterface -> llmq/signing"
     "llmq/debug -> llmq/dkgsessionhandler -> llmq/debug"
     "llmq/debug -> llmq/dkgsessionhandler -> llmq/dkgsession -> llmq/debug"
 )

test/lint/lint-format-strings.py

@@ -27,6 +27,7 @@ FALSE_POSITIVES = [
     ("src/statsd_client.cpp", "snprintf(d->errmsg, sizeof(d->errmsg), \"could not create socket, err=%m\")"),
     ("src/statsd_client.cpp", "snprintf(d->errmsg, sizeof(d->errmsg), \"sendto server fail, host=%s:%d, err=%m\", d->host.c_str(), d->port)"),
     ("src/util/system.cpp", "strprintf(_(COPYRIGHT_HOLDERS).translated, COPYRIGHT_HOLDERS_SUBSTITUTION)"),
+    ("src/validationinterface.cpp", "LogPrint(BCLog::VALIDATION, fmt \"\\n\", __VA_ARGS__)"),
     ("src/wallet/wallet.h",  "WalletLogPrintf(std::string fmt, Params... parameters)"),
     ("src/wallet/wallet.h", "LogPrintf((\"%s \" + fmt).c_str(), GetDisplayName(), parameters...)"),
     ("src/wallet/scriptpubkeyman.h",  "WalletLogPrintf(std::string fmt, Params... parameters)"),