Skip to content

Commit

Permalink
Merge bitcoin#19809: log: Prefix log messages with function name and …
Browse files Browse the repository at this point in the history 
…source code location if -logsourcelocations is set

b4511e2 log: Prefix log messages with function name if -logsourcelocations is set (practicalswift)

Pull request description:

  Prefix log messages with function name if `-logfunctionnames` is set.

  Yes, exactly like `-logthreadnames` but for function names instead of thread names :)

  This is a small developer ergonomics improvement: I've found this to be a cheap/simple way to correlate log output and originating function.

  For me it beats the ordinary cycle of 1.) try to figure out a regexp matching the static part of the dynamic log message, 2.) `git grep -E 'Using .* MiB out of .* requested for signature cache'`, 3.) `mcedit filename.cpp` (`openemacs filename.cpp` works too!) and 4.) search for log message and scroll up to find the function name :)

  Without any logging parameters:

  ```
  $ src/bitcoind -regtest
  2020-08-25T03:29:04Z Using RdRand as an additional entropy source
  2020-08-25T03:29:04Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
  2020-08-25T03:29:04Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
  2020-08-25T03:29:04Z Loaded best chain: hashBestChain=0fff88f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e22ff height=0 date=2011-02-02T23:16:42Z progress=1.000000
  2020-08-25T03:29:04Z block tree size = 1
  2020-08-25T03:29:04Z nBestHeight = 0
  2020-08-25T03:29:04Z Imported mempool transactions from disk: 0 succeeded, 0 failed, 0 expired, 0 already there, 0 waiting for initial broadcast
  2020-08-25T03:29:04Z 0 addresses found from DNS seeds
  ```

  With `-logthreadnames` and `-logfunctionnames`:

  ```
  $ src/bitcoind -regtest -logthreadnames -logfunctionnames
  2020-08-25T03:29:04Z [init] [ReportHardwareRand] Using RdRand as an additional entropy source
  2020-08-25T03:29:04Z [init] [InitSignatureCache] Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
  2020-08-25T03:29:04Z [init] [InitScriptExecutionCache] Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
  2020-08-25T03:29:04Z [init] [LoadChainTip] Loaded best chain: hashBestChain=0fff88f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e22ff height=0 date=2011-02-02T23:16:42Z progress=1.000000
  2020-08-25T03:29:04Z [init] [AppInitMain] block tree size = 1
  2020-08-25T03:29:04Z [init] [AppInitMain] nBestHeight = 0
  2020-08-25T03:29:04Z [loadblk] [LoadMempool] Imported mempool transactions from disk: 0 succeeded, 0 failed, 0 expired, 0 already there, 0 waiting for initial broadcast
  2020-08-25T03:29:04Z [dnsseed] [ThreadDNSAddressSeed] 0 addresses found from DNS seeds
  ```

ACKs for top commit:
  laanwj:
    Code review ACK b4511e2
  MarcoFalke:
    review ACK b4511e2 🌃

Tree-SHA512: d100f5364630c323f31d275259864c597f7725e462d5f4bdedcc7033ea616d7fc0d16ef1b2af557e692f4deea73c6773ccfc681589e7bf6ba970b9ec169040c7
  • Loading branch information
@laanwj @knst
laanwj authored and knst committed Apr 10, 2024
1 parent 43a94f0 commit 4774e1e
Show file tree
Hide file tree
Showing 12 changed files with 104 additions and 69 deletions.
9 changes: 6 additions & 3 deletions src/batchedlogger.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,8 +4,11 @@

#include <batchedlogger.h>

CBatchedLogger::CBatchedLogger(BCLog::LogFlags _category, const std::string& _header) :
accept(LogAcceptCategory(_category)), header(_header)
CBatchedLogger::CBatchedLogger(BCLog::LogFlags _category, const std::string& logging_function, const std::string& source_file, int source_line) :
accept(LogAcceptCategory(_category)),
m_logging_function(logging_function),
m_source_file(source_file),
m_source_line(source_line)
{
}

Expand All @@ -19,6 +22,6 @@ void CBatchedLogger::Flush()
if (!accept || msg.empty()) {
return;
}
LogInstance().LogPrintStr(strprintf("%s:\n%s", header, msg));
LogInstance().LogPrintStr(msg, m_logging_function, m_source_file, m_source_line);
msg.clear();
}
6 changes: 4 additions & 2 deletions src/batchedlogger.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -11,10 +11,12 @@ class CBatchedLogger
{
private:
bool accept;
std::string header;
std::string m_logging_function;;
std::string m_source_file;
const int m_source_line;
std::string msg;
public:
CBatchedLogger(BCLog::LogFlags _category, const std::string& _header);
CBatchedLogger(BCLog::LogFlags _category, const std::string& logging_function, const std::string& m_source_file, int m_source_line);
virtual ~CBatchedLogger();

template<typename... Args>
Expand Down
3 changes: 3 additions & 0 deletions src/init.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -719,6 +719,7 @@ void SetupServerArgs(NodeContext& node)
argsman.AddArg("-debugexclude=<category>", strprintf("Exclude debugging information for a category. Can be used in conjunction with -debug=1 to output debug logs for all categories except the specified category. This option can be specified multiple times to exclude multiple categories."), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-disablegovernance", strprintf("Disable governance validation (0-1, default: %u)", 0), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-logsourcelocations", strprintf("Prepend debug output with name of the originating source location (source file, line number and function name) (default: %u)", DEFAULT_LOGSOURCELOCATIONS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-logtimemicros", strprintf("Add microsecond precision to debug timestamps (default: %u)", DEFAULT_LOGTIMEMICROS), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
#ifdef HAVE_THREAD_LOCAL
argsman.AddArg("-logtimestamps", strprintf("Prepend debug output with timestamp (default: %u)", DEFAULT_LOGTIMESTAMPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
Expand Down Expand Up @@ -1084,6 +1085,8 @@ void InitLogging(const ArgsManager& args)
#ifdef HAVE_THREAD_LOCAL
LogInstance().m_log_threadnames = args.GetBoolArg("-logthreadnames", DEFAULT_LOGTHREADNAMES);
#endif
LogInstance().m_log_sourcelocations = args.GetBoolArg("-logsourcelocations", DEFAULT_LOGSOURCELOCATIONS);

fLogIPs = args.GetBoolArg("-logips", DEFAULT_LOGIPS);

std::string version_string = FormatFullVersion();
Expand Down
63 changes: 28 additions & 35 deletions src/llmq/commitment.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -27,36 +27,29 @@ CFinalCommitment::CFinalCommitment(const Consensus::LLMQParams& params, const ui
{
}

template<typename... Types>
void LogPrintfFinalCommitment(Types... out) {
if (LogAcceptCategory(BCLog::LLMQ)) {
LogInstance().LogPrintStr(strprintf("CFinalCommitment::%s -- %s", __func__, tinyformat::format(out...)));
}
}

bool CFinalCommitment::Verify(CDeterministicMNManager& dmnman, gsl::not_null<const CBlockIndex*> pQuorumBaseBlockIndex, bool checkSigs) const
{
const auto& llmq_params_opt = Params().GetLLMQ(llmqType);
if (!llmq_params_opt.has_value()) {
LogPrintfFinalCommitment("q[%s] invalid llmqType=%d\n", quorumHash.ToString(), ToUnderlying(llmqType));
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid llmqType=%d\n", quorumHash.ToString(), ToUnderlying(llmqType));
return false;
}
const auto& llmq_params = llmq_params_opt.value();

const uint16_t expected_nversion{CFinalCommitment::GetVersion(IsQuorumRotationEnabled(llmq_params, pQuorumBaseBlockIndex),
DeploymentActiveAfter(pQuorumBaseBlockIndex, Params().GetConsensus(), Consensus::DEPLOYMENT_V19))};
if (nVersion == 0 || nVersion != expected_nversion) {
LogPrintfFinalCommitment("q[%s] invalid nVersion=%d expectednVersion\n", quorumHash.ToString(), nVersion, expected_nversion);
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid nVersion=%d expectednVersion\n", quorumHash.ToString(), nVersion, expected_nversion);
return false;
}

if (pQuorumBaseBlockIndex->GetBlockHash() != quorumHash) {
LogPrintfFinalCommitment("q[%s] invalid quorumHash\n", quorumHash.ToString());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid quorumHash\n", quorumHash.ToString());
return false;
}

if ((pQuorumBaseBlockIndex->nHeight % llmq_params.dkgInterval) != quorumIndex) {
LogPrintfFinalCommitment("q[%s] invalid quorumIndex=%d\n", quorumHash.ToString(), quorumIndex);
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid quorumIndex=%d\n", quorumHash.ToString(), quorumIndex);
return false;
}

Expand All @@ -65,27 +58,27 @@ bool CFinalCommitment::Verify(CDeterministicMNManager& dmnman, gsl::not_null<con
}

if (CountValidMembers() < llmq_params.minSize) {
LogPrintfFinalCommitment("q[%s] invalid validMembers count. validMembersCount=%d\n", quorumHash.ToString(), CountValidMembers());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid validMembers count. validMembersCount=%d\n", quorumHash.ToString(), CountValidMembers());
return false;
}
if (CountSigners() < llmq_params.minSize) {
LogPrintfFinalCommitment("q[%s] invalid signers count. signersCount=%d\n", quorumHash.ToString(), CountSigners());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid signers count. signersCount=%d\n", quorumHash.ToString(), CountSigners());
return false;
}
if (!quorumPublicKey.IsValid()) {
LogPrintfFinalCommitment("q[%s] invalid quorumPublicKey\n", quorumHash.ToString());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid quorumPublicKey\n", quorumHash.ToString());
return false;
}
if (quorumVvecHash.IsNull()) {
LogPrintfFinalCommitment("q[%s] invalid quorumVvecHash\n", quorumHash.ToString());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid quorumVvecHash\n", quorumHash.ToString());
return false;
}
if (!membersSig.IsValid()) {
LogPrintfFinalCommitment("q[%s] invalid membersSig\n", quorumHash.ToString());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid membersSig\n", quorumHash.ToString());
return false;
}
if (!quorumSig.IsValid()) {
LogPrintfFinalCommitment("q[%s] invalid vvecSig\n");
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid vvecSig\n");
return false;
}
auto members = utils::GetAllQuorumMembers(llmqType, dmnman, pQuorumBaseBlockIndex);
Expand All @@ -96,16 +89,16 @@ bool CFinalCommitment::Verify(CDeterministicMNManager& dmnman, gsl::not_null<con
ss << "v[" << i << "]=" << validMembers[i];
ss2 << "s[" << i << "]=" << signers[i];
}
LogPrintfFinalCommitment("CFinalCommitment::%s mns[%d] validMembers[%s] signers[%s]\n", __func__, members.size(), ss.str(), ss2.str());
LogPrint(BCLog::LLMQ, "CFinalCommitment::%s mns[%d] validMembers[%s] signers[%s]\n", __func__, members.size(), ss.str(), ss2.str());
}

for (const auto i : irange::range(members.size(), size_t(llmq_params.size))) {
if (validMembers[i]) {
LogPrintfFinalCommitment("q[%s] invalid validMembers bitset. bit %d should not be set\n", quorumHash.ToString(), i);
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid validMembers bitset. bit %d should not be set\n", quorumHash.ToString(), i);
return false;
}
if (signers[i]) {
LogPrintfFinalCommitment("q[%s] invalid signers bitset. bit %d should not be set\n", quorumHash.ToString(), i);
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid signers bitset. bit %d should not be set\n", quorumHash.ToString(), i);
return false;
}
}
Expand All @@ -118,7 +111,7 @@ bool CFinalCommitment::Verify(CDeterministicMNManager& dmnman, gsl::not_null<con
for (const auto &mn: members) {
ss3 << mn->proTxHash.ToString().substr(0, 4) << " | ";
}
LogPrintfFinalCommitment("CFinalCommitment::%s members[%s] quorumPublicKey[%s] commitmentHash[%s]\n",
LogPrint(BCLog::LLMQ, "CFinalCommitment::%s members[%s] quorumPublicKey[%s] commitmentHash[%s]\n",
__func__, ss3.str(), quorumPublicKey.ToString(), commitmentHash.ToString());
}
std::vector<CBLSPublicKey> memberPubKeys;
Expand All @@ -130,17 +123,17 @@ bool CFinalCommitment::Verify(CDeterministicMNManager& dmnman, gsl::not_null<con
}

if (!membersSig.VerifySecureAggregated(memberPubKeys, commitmentHash)) {
LogPrintfFinalCommitment("q[%s] invalid aggregated members signature\n", quorumHash.ToString());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid aggregated members signature\n", quorumHash.ToString());
return false;
}

if (!quorumSig.VerifyInsecure(quorumPublicKey, commitmentHash)) {
LogPrintfFinalCommitment("q[%s] invalid quorum signature\n", quorumHash.ToString());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid quorum signature\n", quorumHash.ToString());
return false;
}
}

LogPrintfFinalCommitment("q[%s] VALID\n", quorumHash.ToString());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] VALID QUORUM\n", quorumHash.ToString());

return true;
}
Expand All @@ -149,7 +142,7 @@ bool CFinalCommitment::VerifyNull() const
{
const auto& llmq_params_opt = Params().GetLLMQ(llmqType);
if (!llmq_params_opt.has_value()) {
LogPrintfFinalCommitment("q[%s]invalid llmqType=%d\n", quorumHash.ToString(), ToUnderlying(llmqType));
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s]invalid llmqType=%d\n", quorumHash.ToString(), ToUnderlying(llmqType));
return false;
}

Expand All @@ -163,11 +156,11 @@ bool CFinalCommitment::VerifyNull() const
bool CFinalCommitment::VerifySizes(const Consensus::LLMQParams& params) const
{
if (signers.size() != size_t(params.size)) {
LogPrintfFinalCommitment("q[%s] invalid signers.size=%d\n", quorumHash.ToString(), signers.size());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid signers.size=%d\n", quorumHash.ToString(), signers.size());
return false;
}
if (validMembers.size() != size_t(params.size)) {
LogPrintfFinalCommitment("q[%s] invalid signers.size=%d\n", quorumHash.ToString(), signers.size());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- q[%s] invalid signers.size=%d\n", quorumHash.ToString(), signers.size());
return false;
}
return true;
Expand All @@ -177,14 +170,14 @@ bool CheckLLMQCommitment(CDeterministicMNManager& dmnman, const CTransaction& tx
{
const auto opt_qcTx = GetTxPayload<CFinalCommitmentTxPayload>(tx);
if (!opt_qcTx) {
LogPrintfFinalCommitment("h[%d] GetTxPayload failed\n", pindexPrev->nHeight);
LogPrint(BCLog::LLMQ, "CFinalCommitment -- h[%d] GetTxPayload LLMQCommitment failed\n", pindexPrev->nHeight);
return state.Invalid(TxValidationResult::TX_CONSENSUS, "bad-qc-payload");
}
auto& qcTx = *opt_qcTx;

const auto& llmq_params_opt = Params().GetLLMQ(qcTx.commitment.llmqType);
if (!llmq_params_opt.has_value()) {
LogPrintfFinalCommitment("h[%d] GetLLMQ failed for llmqType[%d]\n", pindexPrev->nHeight, ToUnderlying(qcTx.commitment.llmqType));
LogPrint(BCLog::LLMQ, "CFinalCommitment -- h[%d] GetLLMQ failed for llmqType[%d]\n", pindexPrev->nHeight, ToUnderlying(qcTx.commitment.llmqType));
return state.Invalid(TxValidationResult::TX_CONSENSUS, "bad-qc-commitment-type");
}

Expand All @@ -193,17 +186,17 @@ bool CheckLLMQCommitment(CDeterministicMNManager& dmnman, const CTransaction& tx
for (const auto i: irange::range(llmq_params_opt->size)) {
ss << "v[" << i << "]=" << qcTx.commitment.validMembers[i];
}
LogPrintfFinalCommitment("%s llmqType[%d] validMembers[%s] signers[]\n", __func__,
LogPrint(BCLog::LLMQ, "CFinalCommitment -- %s llmqType[%d] validMembers[%s] signers[]\n", __func__,
int(qcTx.commitment.llmqType), ss.str());
}

if (qcTx.nVersion == 0 || qcTx.nVersion > CFinalCommitmentTxPayload::CURRENT_VERSION) {
LogPrintfFinalCommitment("h[%d] invalid qcTx.nVersion[%d]\n", pindexPrev->nHeight, qcTx.nVersion);
LogPrint(BCLog::LLMQ, "CFinalCommitment -- h[%d] invalid qcTx.nVersion[%d]\n", pindexPrev->nHeight, qcTx.nVersion);
return state.Invalid(TxValidationResult::TX_CONSENSUS, "bad-qc-version");
}

if (qcTx.nHeight != uint32_t(pindexPrev->nHeight + 1)) {
LogPrintfFinalCommitment("h[%d] invalid qcTx.nHeight[%d]\n", pindexPrev->nHeight, qcTx.nHeight);
LogPrint(BCLog::LLMQ, "CFinalCommitment -- h[%d] invalid qcTx.nHeight[%d]\n", pindexPrev->nHeight, qcTx.nHeight);
return state.Invalid(TxValidationResult::TX_CONSENSUS, "bad-qc-height");
}

Expand All @@ -220,18 +213,18 @@ bool CheckLLMQCommitment(CDeterministicMNManager& dmnman, const CTransaction& tx

if (qcTx.commitment.IsNull()) {
if (!qcTx.commitment.VerifyNull()) {
LogPrintfFinalCommitment("h[%d] invalid qcTx.commitment[%s] VerifyNull failed\n", pindexPrev->nHeight, qcTx.commitment.quorumHash.ToString());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- h[%d] invalid qcTx.commitment[%s] VerifyNull failed\n", pindexPrev->nHeight, qcTx.commitment.quorumHash.ToString());
return state.Invalid(TxValidationResult::TX_CONSENSUS, "bad-qc-invalid-null");
}
return true;
}

if (!qcTx.commitment.Verify(dmnman, pQuorumBaseBlockIndex, false)) {
LogPrintfFinalCommitment("h[%d] invalid qcTx.commitment[%s] Verify failed\n", pindexPrev->nHeight, qcTx.commitment.quorumHash.ToString());
LogPrint(BCLog::LLMQ, "CFinalCommitment -- h[%d] invalid qcTx.commitment[%s] Verify failed\n", pindexPrev->nHeight, qcTx.commitment.quorumHash.ToString());
return state.Invalid(TxValidationResult::TX_CONSENSUS, "bad-qc-invalid");
}

LogPrintfFinalCommitment("h[%d] CheckLLMQCommitment VALID\n", pindexPrev->nHeight);
LogPrint(BCLog::LLMQ, "CFinalCommitment -- h[%d] CheckLLMQCommitment VALID\n", pindexPrev->nHeight);

return true;
}
Expand Down
Loading

0 comments on commit 4774e1e

Please sign in to comment.