Skip to content

Commit f9abf4a

Browse files
jkczyzjkczyz
committed
Add logging for CValidationInterface events
This could help debug issues where there may be race conditions at play, such as #12978. Fixes #12994.
1 parent 6edebac commit f9abf4a

File tree

2 files changed

+55
-12
lines changed

2 files changed

+55
-12
lines changed

‎src/validationinterface.cpp‎

Lines changed: 54 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -5,8 +5,13 @@
55

66
#include <validationinterface.h>
77

8+
#include <chain.h>
9+
#include <consensus/validation.h>
10+
#include <logging.h>
811
#include <primitives/block.h>
12+
#include <primitives/transaction.h>
913
#include <scheduler.h>
14+
#include <util/validation.h>
1015

1116
#include <future>
1217
#include <unordered_map>
@@ -110,52 +115,89 @@ void SyncWithValidationInterfaceQueue() {
110115
promise.get_future().wait();
111116
}
112117

118+
// Use a macro instead of a function for conditional logging to prevent
119+
// evaluating arguments when logging is not enabled.
120+
//
121+
// NOTE: The lambda captures all local variables by value.
122+
#define ENQUEUE_AND_LOG_EVENT(event, fmt, name, ...) \
123+
do { \
124+
auto local_name = (name); \
125+
LOG_EVENT("Enqueuing " fmt, local_name, __VA_ARGS__); \
126+
m_internals->m_schedulerClient.AddToProcessQueue([=] { \
127+
LOG_EVENT(fmt, local_name, __VA_ARGS__); \
128+
event(); \
129+
}); \
130+
} while (0)
131+
132+
#define LOG_EVENT(fmt, ...) \
133+
LogPrint(BCLog::VALIDATION, fmt "\n", __VA_ARGS__)
113134

114135
void CMainSignals::UpdatedBlockTip(const CBlockIndex *pindexNew, const CBlockIndex *pindexFork, bool fInitialDownload) {
115136
// Dependencies exist that require UpdatedBlockTip events to be delivered in the order in which
116137
// the chain actually updates. One way to ensure this is for the caller to invoke this signal
117138
// in the same critical section where the chain is updated
118139

119-
m_internals->m_schedulerClient.AddToProcessQueue([pindexNew, pindexFork, fInitialDownload, this] {
140+
auto event = [pindexNew, pindexFork, fInitialDownload, this] {
120141
m_internals->UpdatedBlockTip(pindexNew, pindexFork, fInitialDownload);
121-
});
142+
};
143+
ENQUEUE_AND_LOG_EVENT(event, "%s: new block hash=%s fork block hash=%s (in IBD=%s)", __func__,
144+
pindexNew->GetBlockHash().ToString(),
145+
pindexFork ? pindexFork->GetBlockHash().ToString() : "null",
146+
fInitialDownload);
122147
}
123148

124149
void CMainSignals::TransactionAddedToMempool(const CTransactionRef &ptx) {
125-
m_internals->m_schedulerClient.AddToProcessQueue([ptx, this] {
150+
auto event = [ptx, this] {
126151
m_internals->TransactionAddedToMempool(ptx);
127-
});
152+
};
153+
ENQUEUE_AND_LOG_EVENT(event, "%s: txid=%s wtxid=%s", __func__,
154+
ptx->GetHash().ToString(),
155+
ptx->GetWitnessHash().ToString());
128156
}
129157

130158
void CMainSignals::TransactionRemovedFromMempool(const CTransactionRef &ptx) {
131-
m_internals->m_schedulerClient.AddToProcessQueue([ptx, this] {
159+
auto event = [ptx, this] {
132160
m_internals->TransactionRemovedFromMempool(ptx);
133-
});
161+
};
162+
ENQUEUE_AND_LOG_EVENT(event, "%s: txid=%s wtxid=%s", __func__,
163+
ptx->GetHash().ToString(),
164+
ptx->GetWitnessHash().ToString());
134165
}
135166

136167
void CMainSignals::BlockConnected(const std::shared_ptr<const CBlock> &pblock, const CBlockIndex *pindex, const std::shared_ptr<const std::vector<CTransactionRef>>& pvtxConflicted) {
137-
m_internals->m_schedulerClient.AddToProcessQueue([pblock, pindex, pvtxConflicted, this] {
168+
auto event = [pblock, pindex, pvtxConflicted, this] {
138169
m_internals->BlockConnected(pblock, pindex, *pvtxConflicted);
139-
});
170+
};
171+
ENQUEUE_AND_LOG_EVENT(event, "%s: block hash=%s block height=%d", __func__,
172+
pblock->GetHash().ToString(),
173+
pindex->nHeight);
140174
}
141175

142176
void CMainSignals::BlockDisconnected(const std::shared_ptr<const CBlock>& pblock, const CBlockIndex* pindex)
143177
{
144-
m_internals->m_schedulerClient.AddToProcessQueue([pblock, pindex, this] {
178+
auto event = [pblock, pindex, this] {
145179
m_internals->BlockDisconnected(pblock, pindex);
146-
});
180+
};
181+
ENQUEUE_AND_LOG_EVENT(event, "%s: block hash=%s block height=%d", __func__,
182+
pblock->GetHash().ToString(),
183+
pindex->nHeight);
147184
}
148185

149186
void CMainSignals::ChainStateFlushed(const CBlockLocator &locator) {
150-
m_internals->m_schedulerClient.AddToProcessQueue([locator, this] {
187+
auto event = [locator, this] {
151188
m_internals->ChainStateFlushed(locator);
152-
});
189+
};
190+
ENQUEUE_AND_LOG_EVENT(event, "%s: block hash=%s", __func__,
191+
locator.IsNull() ? "null" : locator.vHave.front().ToString());
153192
}
154193

155194
void CMainSignals::BlockChecked(const CBlock& block, const BlockValidationState& state) {
195+
LOG_EVENT("%s: block hash=%s state=%s", __func__,
196+
block.GetHash().ToString(), FormatStateMessage(state));
156197
m_internals->BlockChecked(block, state);
157198
}
158199

159200
void CMainSignals::NewPoWValidBlock(const CBlockIndex *pindex, const std::shared_ptr<const CBlock> &block) {
201+
LOG_EVENT("%s: block hash=%s", __func__, block->GetHash().ToString());
160202
m_internals->NewPoWValidBlock(pindex, block);
161203
}

‎test/lint/lint-format-strings.py‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@
1717
("src/index/base.cpp", "FatalError(const char* fmt, const Args&... args)"),
1818
("src/netbase.cpp", "LogConnectFailure(bool manual_connection, const char* fmt, const Args&... args)"),
1919
("src/util/system.cpp", "strprintf(_(COPYRIGHT_HOLDERS).translated, COPYRIGHT_HOLDERS_SUBSTITUTION)"),
20+
("src/validationinterface.cpp", "LogPrint(BCLog::VALIDATION, fmt \"\\n\", __VA_ARGS__)"),
2021
("src/wallet/wallet.h", "WalletLogPrintf(std::string fmt, Params... parameters)"),
2122
("src/wallet/wallet.h", "LogPrintf((\"%s \" + fmt).c_str(), GetDisplayName(), parameters...)"),
2223
("src/logging.h", "LogPrintf(const char* fmt, const Args&... args)"),

0 commit comments

Comments
 (0)