From 428ac70095253225f64462ee15c595644747f376 Mon Sep 17 00:00:00 2001 From: Jeffrey Czyz Date: Wed, 21 Aug 2019 16:19:51 -0700 Subject: Add VALIDATION to BCLog::LogFlags This flag is for logging from within CValidationInterface (see #12994). A separate flag is desirable as the logging can be noisy and thus may need to be disabled without affecting other logging. --- src/logging.cpp | 1 + src/logging.h | 1 + 2 files changed, 2 insertions(+) diff --git a/src/logging.cpp b/src/logging.cpp index 9f6b5ede12..e7cadead81 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -162,6 +162,7 @@ const CLogCategoryDesc LogCategories[] = {BCLog::COINDB, "coindb"}, {BCLog::QT, "qt"}, {BCLog::LEVELDB, "leveldb"}, + {BCLog::VALIDATION, "validation"}, {BCLog::ALL, "1"}, {BCLog::ALL, "all"}, }; diff --git a/src/logging.h b/src/logging.h index a2caef51a8..9004093e4e 100644 --- a/src/logging.h +++ b/src/logging.h @@ -54,6 +54,7 @@ namespace BCLog { COINDB = (1 << 18), QT = (1 << 19), LEVELDB = (1 << 20), + VALIDATION = (1 << 21), ALL = ~(uint32_t)0, }; -- cgit v1.2.3 From 72f3227c83810936e7a334304e5fd7c6dab8e91b Mon Sep 17 00:00:00 2001 From: Jeffrey Czyz Date: Fri, 3 Jan 2020 11:32:22 -0800 Subject: Format CValidationState properly in all cases FormatStateMessage does not properly handle the case where CValidationState::IsValid() returns true. Use "Valid" for the state in this case. --- src/util/validation.cpp | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/util/validation.cpp b/src/util/validation.cpp index bd52f57751..603db51d45 100644 --- a/src/util/validation.cpp +++ b/src/util/validation.cpp @@ -11,6 +11,10 @@ /** Convert ValidationState to a human-readable message for logging */ std::string FormatStateMessage(const ValidationState &state) { + if (state.IsValid()) { + return "Valid"; + } + return strprintf("%s%s", state.GetRejectReason(), state.GetDebugMessage().empty() ? "" : ", "+state.GetDebugMessage()); -- cgit v1.2.3 From 6edebacb2191373e76d79a4972d6192300976096 Mon Sep 17 00:00:00 2001 From: Jeffrey Czyz Date: Fri, 3 Jan 2020 11:38:44 -0800 Subject: Refactor FormatStateMessage for clarity All cases of CValidationState were condensed into one strprintf call. This is no longer suitable as more cases are added (e.g., IsValid). --- src/util/validation.cpp | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/src/util/validation.cpp b/src/util/validation.cpp index 603db51d45..ed9c108bb0 100644 --- a/src/util/validation.cpp +++ b/src/util/validation.cpp @@ -8,16 +8,18 @@ #include #include -/** Convert ValidationState to a human-readable message for logging */ std::string FormatStateMessage(const ValidationState &state) { if (state.IsValid()) { return "Valid"; } - return strprintf("%s%s", - state.GetRejectReason(), - 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(); } const std::string strMessageMagic = "Bitcoin Signed Message:\n"; -- cgit v1.2.3 From f9abf4ab6d3d3e4d4b7e90723020b5422a141a6f Mon Sep 17 00:00:00 2001 From: Jeffrey Czyz Date: Wed, 21 Aug 2019 17:48:52 -0700 Subject: Add logging for CValidationInterface events This could help debug issues where there may be race conditions at play, such as #12978. Fixes #12994. --- src/validationinterface.cpp | 66 ++++++++++++++++++++++++++++++++-------- test/lint/lint-format-strings.py | 1 + 2 files changed, 55 insertions(+), 12 deletions(-) diff --git a/src/validationinterface.cpp b/src/validationinterface.cpp index 6c0f4d5edd..fee2fabb86 100644 --- a/src/validationinterface.cpp +++ b/src/validationinterface.cpp @@ -5,8 +5,13 @@ #include +#include +#include +#include #include +#include #include +#include #include #include @@ -110,52 +115,89 @@ 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 wtxid=%s", __func__, + ptx->GetHash().ToString(), + ptx->GetWitnessHash().ToString()); } void CMainSignals::TransactionRemovedFromMempool(const CTransactionRef &ptx) { - m_internals->m_schedulerClient.AddToProcessQueue([ptx, this] { + auto event = [ptx, this] { m_internals->TransactionRemovedFromMempool(ptx); - }); + }; + ENQUEUE_AND_LOG_EVENT(event, "%s: txid=%s wtxid=%s", __func__, + ptx->GetHash().ToString(), + ptx->GetWitnessHash().ToString()); } void CMainSignals::BlockConnected(const std::shared_ptr &pblock, const CBlockIndex *pindex, const std::shared_ptr>& pvtxConflicted) { - m_internals->m_schedulerClient.AddToProcessQueue([pblock, pindex, pvtxConflicted, this] { + auto event = [pblock, pindex, pvtxConflicted, this] { m_internals->BlockConnected(pblock, pindex, *pvtxConflicted); - }); + }; + 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& 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 &block) { + LOG_EVENT("%s: block hash=%s", __func__, block->GetHash().ToString()); m_internals->NewPoWValidBlock(pindex, block); } diff --git a/test/lint/lint-format-strings.py b/test/lint/lint-format-strings.py index 99127e01f8..cc24a0b609 100755 --- a/test/lint/lint-format-strings.py +++ b/test/lint/lint-format-strings.py @@ -17,6 +17,7 @@ FALSE_POSITIVES = [ ("src/index/base.cpp", "FatalError(const char* fmt, const Args&... args)"), ("src/netbase.cpp", "LogConnectFailure(bool manual_connection, const char* fmt, const Args&... args)"), ("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/logging.h", "LogPrintf(const char* fmt, const Args&... args)"), -- cgit v1.2.3