Merge bitcoin#19809: log: Prefix log messages with function name and 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

Author: laanwj

src/batchedlogger.cpp

@@ -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)
 {
 }
 
@@ -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();
 }

src/batchedlogger.h

@@ -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>

src/init.cpp

@@ -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);
@@ -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();

src/llmq/commitment.cpp

@@ -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;
     }
 
@@ -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);
@@ -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;
         }
     }
@@ -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;
@@ -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;
 }
@@ -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;
     }
 
@@ -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;
@@ -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");
     }
 
@@ -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");
     }
 
@@ -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;
 }