Merge #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/init.cpp

@@ -533,6 +533,7 @@ void SetupServerArgs(NodeContext& node)
 #else
     hidden_args.emplace_back("-logthreadnames");
 #endif
+    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);
     argsman.AddArg("-mocktime=<n>", "Replace actual time with " + UNIX_EPOCH_TIME + " (default: 0)", ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
     argsman.AddArg("-maxsigcachesize=<n>", strprintf("Limit sum of signature cache and script execution cache sizes to <n> MiB (default: %u)", DEFAULT_MAX_SIG_CACHE_SIZE), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
@@ -883,6 +884,7 @@ 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);
 

src/logging.cpp

@@ -5,6 +5,7 @@
 
 #include <logging.h>
 #include <util/threadnames.h>
+#include <util/string.h>
 #include <util/time.h>
 
 #include <mutex>
@@ -236,11 +237,15 @@ namespace BCLog {
     }
 }
 
-void BCLog::Logger::LogPrintStr(const std::string& str)
+void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line)
 {
     StdLockGuard scoped_lock(m_cs);
     std::string str_prefixed = LogEscapeMessage(str);
 
+    if (m_log_sourcelocations && m_started_new_line) {
+        str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
+    }
+
     if (m_log_threadnames && m_started_new_line) {
         str_prefixed.insert(0, "[" + util::ThreadGetInternalName() + "] ");
     }

src/logging.h

@@ -22,6 +22,7 @@ static const bool DEFAULT_LOGTIMEMICROS = false;
 static const bool DEFAULT_LOGIPS        = false;
 static const bool DEFAULT_LOGTIMESTAMPS = true;
 static const bool DEFAULT_LOGTHREADNAMES = false;
+static const bool DEFAULT_LOGSOURCELOCATIONS = false;
 extern const char * const DEFAULT_DEBUGLOGFILE;
 
 extern bool fLogIPs;
@@ -90,12 +91,13 @@ namespace BCLog {
         bool m_log_timestamps = DEFAULT_LOGTIMESTAMPS;
         bool m_log_time_micros = DEFAULT_LOGTIMEMICROS;
         bool m_log_threadnames = DEFAULT_LOGTHREADNAMES;
+        bool m_log_sourcelocations = DEFAULT_LOGSOURCELOCATIONS;
 
         fs::path m_file_path;
         std::atomic<bool> m_reopen_file{false};
 
         /** Send a string to the log output */
-        void LogPrintStr(const std::string& str);
+        void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line);
 
         /** Returns whether logs will be written to any output */
         bool Enabled() const
@@ -163,7 +165,7 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str);
 // peer can fill up a user's disk with debug.log entries.
 
 template <typename... Args>
-static inline void LogPrintf(const char* fmt, const Args&... args)
+static inline void LogPrintf_(const std::string& logging_function, const std::string& source_file, const int source_line, const char* fmt, const Args&... args)
 {
     if (LogInstance().Enabled()) {
         std::string log_msg;
@@ -173,10 +175,12 @@ static inline void LogPrintf(const char* fmt, const Args&... args)
             /* Original format string will have newline so don't add one here */
             log_msg = "Error \"" + std::string(fmterr.what()) + "\" while formatting log message: " + fmt;
         }
-        LogInstance().LogPrintStr(log_msg);
+        LogInstance().LogPrintStr(log_msg, logging_function, source_file, source_line);
     }
 }
 
+#define LogPrintf(...) LogPrintf_(__func__, __FILE__, __LINE__, __VA_ARGS__)
+
 // Use a macro instead of a function for conditional logging to prevent
 // evaluating arguments when logging for the category is not enabled.
 #define LogPrint(category, ...)              \

src/test/fuzz/string.cpp

@@ -67,6 +67,7 @@ FUZZ_TARGET(string)
     }
     OutputType output_type;
     (void)ParseOutputType(random_string_1, output_type);
+    (void)RemovePrefix(random_string_1, random_string_2);
     (void)ResolveErrMsg(random_string_1, random_string_2);
     try {
         (void)RPCConvertNamedValues(random_string_1, random_string_vector);

src/test/util/setup_common.cpp

@@ -77,6 +77,7 @@ BasicTestingSetup::BasicTestingSetup(const std::string& chainName, const std::ve
         {
             "dummy",
             "-printtoconsole=0",
+            "-logsourcelocations",
             "-logtimemicros",
             "-logthreadnames",
             "-debug",

src/test/util_tests.cpp

@@ -2201,4 +2201,17 @@ BOOST_AUTO_TEST_CASE(message_hash)
     BOOST_CHECK_NE(message_hash1, signature_hash);
 }
 
+BOOST_AUTO_TEST_CASE(remove_prefix)
+{
+    BOOST_CHECK_EQUAL(RemovePrefix("./util/system.h", "./"), "util/system.h");
+    BOOST_CHECK_EQUAL(RemovePrefix("foo", "foo"), "");
+    BOOST_CHECK_EQUAL(RemovePrefix("foo", "fo"), "o");
+    BOOST_CHECK_EQUAL(RemovePrefix("foo", "f"), "oo");
+    BOOST_CHECK_EQUAL(RemovePrefix("foo", ""), "foo");
+    BOOST_CHECK_EQUAL(RemovePrefix("fo", "foo"), "fo");
+    BOOST_CHECK_EQUAL(RemovePrefix("f", "foo"), "f");
+    BOOST_CHECK_EQUAL(RemovePrefix("", "foo"), "");
+    BOOST_CHECK_EQUAL(RemovePrefix("", ""), "");
+}
+
 BOOST_AUTO_TEST_SUITE_END()

src/util/string.h

@@ -25,6 +25,14 @@
     return str.substr(front, end - front + 1);
 }
 
+[[nodiscard]] inline std::string RemovePrefix(const std::string& str, const std::string& prefix)
+{
+    if (str.substr(0, prefix.size()) == prefix) {
+        return str.substr(prefix.size());
+    }
+    return str;
+}
+
 /**
  * Join a list of items
  *

test/functional/test_framework/test_node.py

@@ -115,6 +115,8 @@ def __init__(self, i, datadir, *, chain, rpchost, timewait, timeout_factor, bitc
 
         if self.version_is_at_least(190000):
             self.args.append("-logthreadnames")
+        if self.version_is_at_least(219900):
+            self.args.append("-logsourcelocations")
 
         self.cli = TestNodeCLI(bitcoin_cli, self.datadir)
         self.use_cli = use_cli