backport: merge bitcoin#23235, #23104, #24770, #24830, #24464, #24757, #25202, #25217, #25292, #25614, partial bitcoin#22766 (logging backports)

ci/test/00_setup_env_native_tsan.sh

@@ -13,5 +13,5 @@ export TEST_RUNNER_EXTRA="--extended --exclude feature_pruning,feature_dbcrash,w
 export TEST_RUNNER_EXTRA="${TEST_RUNNER_EXTRA} --timeout-factor=4"  # Increase timeout because sanitizers slow down
 export GOAL="install"
 export BITCOIN_CONFIG="--enable-zmq --with-gui=no --with-sanitizers=thread CC=clang-16 CXX=clang++-16 CXXFLAGS='-g' --with-boost-process"
-export CPPFLAGS="-DDEBUG_LOCKORDER -DARENA_DEBUG"
+export CPPFLAGS="-DARENA_DEBUG -DDEBUG_LOCKORDER -DDEBUG_LOCKCONTENTION"
 export PYZMQ=true

configure.ac

@@ -389,6 +389,7 @@ if test "x$enable_debug" = xyes; then
 
   AX_CHECK_PREPROC_FLAG([-DDEBUG_CORE],[[DEBUG_CPPFLAGS="$DEBUG_CPPFLAGS -DDEBUG_CORE"]],,[[$CXXFLAG_WERROR]])
   AX_CHECK_PREPROC_FLAG([-DDEBUG_LOCKORDER],[[DEBUG_CPPFLAGS="$DEBUG_CPPFLAGS -DDEBUG_LOCKORDER"]],,[[$CXXFLAG_WERROR]])
+  AX_CHECK_PREPROC_FLAG([-DDEBUG_LOCKCONTENTION], [DEBUG_CPPFLAGS="$DEBUG_CPPFLAGS -DDEBUG_LOCKCONTENTION"], [], [$CXXFLAG_WERROR])
   AX_CHECK_PREPROC_FLAG([-DABORT_ON_FAILED_ASSUME],[[DEBUG_CPPFLAGS="$DEBUG_CPPFLAGS -DABORT_ON_FAILED_ASSUME"]],,[[$CXXFLAG_WERROR]])
   AX_CHECK_COMPILE_FLAG([-ftrapv],[DEBUG_CXXFLAGS="$DEBUG_CXXFLAGS -ftrapv"],,[[$CXXFLAG_WERROR]])
 else

doc/developer-notes.md

@@ -17,6 +17,7 @@ Developer Notes
         - [`debug.log`](#debuglog)
         - [Testnet and Regtest modes](#testnet-and-regtest-modes)
         - [DEBUG_LOCKORDER](#debug_lockorder)
+        - [DEBUG_LOCKCONTENTION](#debug_lockcontention)
         - [Valgrind suppressions file](#valgrind-suppressions-file)
         - [Compiling for test coverage](#compiling-for-test-coverage)
         - [Performance profiling with perf](#performance-profiling-with-perf)
@@ -389,8 +390,10 @@ Run configure with the `--enable-gprof` option, then make.
 If the code is behaving strangely, take a look in the `debug.log` file in the data directory;
 error and debugging messages are written there.
 
-The `-debug=...` command-line option controls debugging; running with just `-debug` or `-debug=1` will turn
-on all categories (and give you a very large `debug.log` file).
+Debug logging can be enabled on startup with the `-debug` and `-loglevel`
+configuration options and toggled while dashd is running with the `logging`
+RPC.  For instance, launching dashd with `-debug` or `-debug=1` will turn on
+all log categories and `-loglevel=trace` will turn on all log severity levels.
 
 The Qt code routes `qDebug()` output to `debug.log` under category "qt": run with `-debug=qt`
 to see it.
@@ -412,6 +415,21 @@ configure option adds `-DDEBUG_LOCKORDER` to the compiler flags. This inserts
 run-time checks to keep track of which locks are held and adds warnings to the
 `debug.log` file if inconsistencies are detected.
 
+### DEBUG_LOCKCONTENTION
+
+Defining `DEBUG_LOCKCONTENTION` adds a "lock" logging category to the logging
+RPC that, when enabled, logs the location and duration of each lock contention
+to the `debug.log` file.
+
+The `--enable-debug` configure option adds `-DDEBUG_LOCKCONTENTION` to the
+compiler flags. You may also enable it manually for a non-debug build by running
+configure with `-DDEBUG_LOCKCONTENTION` added to your CPPFLAGS,
+i.e. `CPPFLAGS="-DDEBUG_LOCKCONTENTION"`, then build and run dashd.
+
+You can then use the `-debug=lock` configuration option at dashd startup or
+`dash-cli logging '["lock"]'` at runtime to turn on lock contention logging.
+It can be toggled off again with `dash-cli logging [] '["lock"]'`.
+
 ### Assertions and Checks
 
 The util file `src/util/check.h` offers helpers to protect against coding and
@@ -846,11 +864,6 @@ int GetInt(Tabs tab)
 Strings and formatting
 ------------------------
 
-- Be careful of `LogPrint` versus `LogPrintf`. `LogPrint` takes a `category` argument, `LogPrintf` does not.
-
-  - *Rationale*: Confusion of these can result in runtime exceptions due to
-    formatting mismatch, and it is easy to get wrong because of subtly similar naming.
-
 - Use `std::string`, avoid C string manipulation functions.
 
   - *Rationale*: C++ string handling is marginally safer, less scope for

src/batchedlogger.cpp

@@ -4,11 +4,14 @@
 
 #include <batchedlogger.h>
 
-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)
+CBatchedLogger::CBatchedLogger(BCLog::LogFlags category, BCLog::Level level, const std::string& logging_function,
+                               const std::string& source_file, int source_line) :
+    m_accept{LogAcceptCategory(category, level)},
+    m_category{category},
+    m_level{level},
+    m_logging_function{logging_function},
+    m_source_file{source_file},
+    m_source_line{source_line}
 {
 }
 
@@ -19,9 +22,9 @@ CBatchedLogger::~CBatchedLogger()
 
 void CBatchedLogger::Flush()
 {
-    if (!accept || msg.empty()) {
+    if (!m_accept || m_msg.empty()) {
         return;
     }
-    LogInstance().LogPrintStr(msg, m_logging_function, m_source_file, m_source_line);
-    msg.clear();
+    LogInstance().LogPrintStr(m_msg, m_logging_function, m_source_file, m_source_line, m_category, m_level);
+    m_msg.clear();
 }

src/batchedlogger.h

@@ -10,22 +10,26 @@
 class CBatchedLogger
 {
 private:
-    bool accept;
-    std::string m_logging_function;;
+    bool m_accept;
+    BCLog::LogFlags m_category;
+    BCLog::Level m_level;
+    std::string m_logging_function;
     std::string m_source_file;
     const int m_source_line;
-    std::string msg;
+    std::string m_msg;
+
 public:
-    CBatchedLogger(BCLog::LogFlags _category, const std::string& logging_function, const std::string& m_source_file, int m_source_line);
+    CBatchedLogger(BCLog::LogFlags category, BCLog::Level level, const std::string& logging_function,
+                   const std::string& m_source_file, int m_source_line);
     virtual ~CBatchedLogger();
 
     template<typename... Args>
     void Batch(const std::string& fmt, const Args&... args)
     {
-        if (!accept) {
+        if (!m_accept) {
             return;
         }
-        msg += "    " + strprintf(fmt, args...) + "\n";
+        m_msg += "    " + strprintf(fmt, args...) + "\n";
     }
 
     void Flush();

src/dbwrapper.cpp

@@ -20,7 +20,7 @@ class CBitcoinLevelDBLogger : public leveldb::Logger {
     // This code is adapted from posix_logger.h, which is why it is using vsprintf.
     // Please do not do this in normal code
     void Logv(const char * format, va_list ap) override {
-            if (!LogAcceptCategory(BCLog::LEVELDB)) {
+            if (!LogAcceptCategory(BCLog::LEVELDB, BCLog::Level::Debug)) {
                 return;
             }
             char buffer[500];
@@ -64,7 +64,7 @@ class CBitcoinLevelDBLogger : public leveldb::Logger {
 
                 assert(p <= limit);
                 base[std::min(bufsize - 1, (int)(p - base))] = '\0';
-                LogPrintf("leveldb: %s", base);  /* Continued */
+                LogPrintLevel(BCLog::LEVELDB, BCLog::Level::Debug, "%s", base);  /* Continued */
                 if (base != buffer) {
                     delete[] base;
                 }
@@ -187,7 +187,7 @@ CDBWrapper::~CDBWrapper()
 
 bool CDBWrapper::WriteBatch(CDBBatch& batch, bool fSync)
 {
-    const bool log_memory = LogAcceptCategory(BCLog::LEVELDB);
+    const bool log_memory = LogAcceptCategory(BCLog::LEVELDB, BCLog::Level::Debug);
     double mem_before = 0;
     if (log_memory) {
         mem_before = DynamicMemoryUsage() / 1024.0 / 1024;

src/evo/creditpool.h

@@ -10,6 +10,7 @@
 #include <serialize.h>
 #include <sync.h>
 #include <threadsafety.h>
+#include <tinyformat.h>
 #include <unordered_lru_cache.h>
 #include <util/ranges_set.h>
 

src/httpserver.cpp

@@ -375,11 +375,22 @@ static void HTTPWorkQueueRun(WorkQueue<HTTPClosure>* queue, int worker_num)
 /** libevent event log callback */
 static void libevent_log_cb(int severity, const char *msg)
 {
-    if (severity >= EVENT_LOG_WARN) // Log warn messages and higher without debug category
-        LogPrintf("libevent: %s\n", msg);
-    // The below code causes log spam on Travis and the output of these logs has never been of any use so far
-    //else
-    //    LogPrint(BCLog::LIBEVENT, "libevent: %s\n", msg);
+    BCLog::Level level;
+    switch (severity) {
+    case EVENT_LOG_DEBUG:
+        level = BCLog::Level::Debug;
+        break;
+    case EVENT_LOG_MSG:
+        level = BCLog::Level::Info;
+        break;
+    case EVENT_LOG_WARN:
+        level = BCLog::Level::Warning;
+        break;
+    default: // EVENT_LOG_ERR and others are mapped to error
+        level = BCLog::Level::Error;
+        break;
+    }
+    LogPrintLevel(BCLog::LIBEVENT, level, "%s\n", msg);
 }
 
 bool InitHTTPServer()

src/init.cpp

@@ -583,7 +583,7 @@ void SetupServerArgs(ArgsManager& argsman)
     argsman.AddArg("-peertimeout=<n>", strprintf("Specify a p2p connection timeout delay in seconds. After connecting to a peer, wait this amount of time before considering disconnection based on inactivity (minimum: 1, default: %d)", DEFAULT_PEER_CONNECT_TIMEOUT), ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION);
     argsman.AddArg("-permitbaremultisig", strprintf("Relay non-P2SH multisig (default: %u)", DEFAULT_PERMIT_BAREMULTISIG), ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION);
     argsman.AddArg("-port=<port>", strprintf("Listen for connections on <port>. Nodes not using the default ports (default: %u, testnet: %u, regtest: %u) are unlikely to get incoming connections. Not relevant for I2P (see doc/i2p.md).", defaultChainParams->GetDefaultPort(), testnetChainParams->GetDefaultPort(), regtestChainParams->GetDefaultPort()), ArgsManager::ALLOW_ANY | ArgsManager::NETWORK_ONLY, OptionsCategory::CONNECTION);
-    argsman.AddArg("-proxy=<ip:port>", "Connect through SOCKS5 proxy, set -noproxy to disable (default: disabled)", ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION);
+    argsman.AddArg("-proxy=<ip:port>", "Connect through SOCKS5 proxy, set -noproxy to disable (default: disabled)", ArgsManager::ALLOW_ANY | ArgsManager::DISALLOW_ELISION, OptionsCategory::CONNECTION);
     argsman.AddArg("-proxyrandomize", strprintf("Randomize credentials for every proxy connection. This enables Tor stream isolation (default: %u)", DEFAULT_PROXYRANDOMIZE), ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION);
     argsman.AddArg("-seednode=<ip>", "Connect to a node to retrieve peer addresses, and disconnect. This option can be specified multiple times to connect to multiple nodes.", ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION);
     argsman.AddArg("-socketevents=<mode>", "Socket events mode, which must be one of 'select', 'poll', 'epoll' or 'kqueue', depending on your system (default: Linux - 'epoll', FreeBSD/Apple - 'kqueue', Windows - 'select')", ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION);
@@ -1212,6 +1212,7 @@ bool AppInitParameterInteraction(const ArgsManager& args)
 
     // ********************************************************* Step 3: parameter-to-internal-flags
     init::SetLoggingCategories(args);
+    init::SetLoggingLevel(args);
 
     fCheckBlockIndex = args.GetBoolArg("-checkblockindex", chainparams.DefaultConsistencyChecks());
     fCheckpointsEnabled = args.GetBoolArg("-checkpoints", DEFAULT_CHECKPOINTS_ENABLED);
@@ -1337,10 +1338,6 @@ bool AppInitParameterInteraction(const ArgsManager& args)
 
     nMaxTipAge = args.GetArg("-maxtipage", DEFAULT_MAX_TIP_AGE);
 
-    if (args.IsArgSet("-proxy") && args.GetArg("-proxy", "").empty()) {
-        return InitError(_("No proxy server specified. Use -proxy=<ip> or -proxy=<ip:port>."));
-    }
-
     if (args.GetBoolArg("-reindex-chainstate", false)) {
         // indexes that must be deactivated to prevent index corruption, see #24630
         if (args.GetBoolArg("-coinstatsindex", DEFAULT_COINSTATSINDEX)) {

src/init/common.cpp

@@ -13,6 +13,7 @@
 #include <logging.h>
 #include <node/ui_interface.h>
 #include <random.h>
+#include <util/string.h>
 #include <util/system.h>
 #include <util/time.h>
 #include <util/translation.h>
@@ -57,11 +58,12 @@ bool SanityChecks()
 void AddLoggingArgs(ArgsManager& argsman)
 {
     argsman.AddArg("-debuglogfile=<file>", strprintf("Specify location of debug log file. Relative paths will be prefixed by a net-specific datadir location. (-nodebuglogfile to disable; default: %s)", DEFAULT_DEBUGLOGFILE), ArgsManager::ALLOW_ANY, OptionsCategory::OPTIONS);
-    argsman.AddArg("-debug=<category>", "Output debugging information (default: -nodebug, supplying <category> is optional). "
-        "If <category> is not supplied or if <category> = 1, output all debugging information. <category> can be: " + LogInstance().LogCategoriesString() + ". This option can be specified multiple times to output multiple categories.",
+    argsman.AddArg("-debug=<category>", "Output debug and trace logging (default: -nodebug, supplying <category> is optional). "
+        "If <category> is not supplied or if <category> = 1, output all debug and trace logging. <category> can be: " + LogInstance().LogCategoriesString() + ". This option can be specified multiple times to output multiple categories.",
         ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
-    argsman.AddArg("-debugexclude=<category>", "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("-debugexclude=<category>", "Exclude debug and trace logging for a category. Can be used in conjunction with -debug=1 to output debug and trace logging 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("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
+    argsman.AddArg("-loglevel=<level>|<category>:<level>", strprintf("Set the global or per-category severity level for logging categories enabled with the -debug configuration option or the logging RPC: %s (default=%s); warning and error levels are always logged. If <category>:<level> is supplied, the setting will override the global one and may be specified multiple times to set multiple category-specific levels. <category> can be: %s.", LogInstance().LogLevelsString(), LogInstance().LogLevelToStr(BCLog::DEFAULT_LOG_LEVEL), LogInstance().LogCategoriesString()), ArgsManager::DISALLOW_NEGATION | ArgsManager::DISALLOW_ELISION | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
     argsman.AddArg("-logtimestamps", strprintf("Prepend debug output with timestamp (default: %u)", DEFAULT_LOGTIMESTAMPS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 #ifdef HAVE_THREAD_LOCAL
     argsman.AddArg("-logthreadnames", strprintf("Prepend debug output with name of the originating thread (only available on platforms supporting thread_local) (default: %u)", DEFAULT_LOGTHREADNAMES), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
@@ -89,6 +91,26 @@ void SetLoggingOptions(const ArgsManager& args)
     fLogIPs = args.GetBoolArg("-logips", DEFAULT_LOGIPS);
 }
 
+void SetLoggingLevel(const ArgsManager& args)
+{
+    if (args.IsArgSet("-loglevel")) {
+        for (const std::string& level_str : args.GetArgs("-loglevel")) {
+            if (level_str.find_first_of(':', 3) == std::string::npos) {
+                // user passed a global log level, i.e. -loglevel=<level>
+                if (!LogInstance().SetLogLevel(level_str)) {
+                    InitWarning(strprintf(_("Unsupported global logging level -loglevel=%s. Valid values: %s."), level_str, LogInstance().LogLevelsString()));
+                }
+            } else {
+                // user passed a category-specific log level, i.e. -loglevel=<category>:<level>
+                const auto& toks = SplitString(level_str, ':');
+                if (!(toks.size() == 2 && LogInstance().SetCategoryLogLevel(toks[0], toks[1]))) {
+                    InitWarning(strprintf(_("Unsupported category-specific logging level -loglevel=%s. Expected -loglevel=<category>:<loglevel>. Valid categories: %s. Valid loglevels: %s."), level_str, LogInstance().LogCategoriesString(), LogInstance().LogLevelsString()));
+                }
+            }
+        }
+    }
+}
+
 void SetLoggingCategories(const ArgsManager& args)
 {
     if (args.IsArgSet("-debug")) {

src/init/common.h

@@ -21,6 +21,7 @@ bool SanityChecks();
 void AddLoggingArgs(ArgsManager& args);
 void SetLoggingOptions(const ArgsManager& args);
 void SetLoggingCategories(const ArgsManager& args);
+void SetLoggingLevel(const ArgsManager& args);
 bool StartLogging(const ArgsManager& args);
 void LogPackageVersion();
 } // namespace init

src/llmq/commitment.cpp

@@ -82,7 +82,7 @@ bool CFinalCommitment::Verify(CDeterministicMNManager& dmnman, gsl::not_null<con
         return false;
     }
     auto members = utils::GetAllQuorumMembers(llmqType, dmnman, pQuorumBaseBlockIndex);
-    if (LogAcceptCategory(BCLog::LLMQ)) {
+    if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
         std::stringstream ss;
         std::stringstream ss2;
         for (const auto i: irange::range(llmq_params.size)) {
@@ -106,7 +106,7 @@ bool CFinalCommitment::Verify(CDeterministicMNManager& dmnman, gsl::not_null<con
     // sigs are only checked when the block is processed
     if (checkSigs) {
         uint256 commitmentHash = BuildCommitmentHash(llmq_params.type, quorumHash, validMembers, quorumPublicKey, quorumVvecHash);
-        if (LogAcceptCategory(BCLog::LLMQ)) {
+        if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
             std::stringstream ss3;
             for (const auto &mn: members) {
                 ss3 << mn->proTxHash.ToString().substr(0, 4) << " | ";
@@ -181,7 +181,7 @@ bool CheckLLMQCommitment(CDeterministicMNManager& dmnman, const ChainstateManage
         return state.Invalid(TxValidationResult::TX_CONSENSUS, "bad-qc-commitment-type");
     }
 
-    if (LogAcceptCategory(BCLog::LLMQ)) {
+    if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
         std::stringstream ss;
         for (const auto i: irange::range(llmq_params_opt->size)) {
             ss << "v[" << i << "]=" << qcTx.commitment.validMembers[i];

src/llmq/dkgsession.cpp

@@ -33,7 +33,7 @@ namespace llmq
 {
 
 CDKGLogger::CDKGLogger(const CDKGSession& _quorumDkg, std::string_view _func, int source_line) :
-    CBatchedLogger(BCLog::LLMQ_DKG,
+    CBatchedLogger(BCLog::LLMQ_DKG, BCLog::Level::Debug,
                    strprintf("QuorumDKG(type=%s, qIndex=%d, h=%d, member=%d)", _quorumDkg.params.name, _quorumDkg.quorumIndex,
                              _quorumDkg.m_quorum_base_block_index->nHeight, _quorumDkg.AreWeMember()),
                    __FILE__, source_line)
@@ -120,7 +120,7 @@ bool CDKGSession::Init(const uint256& _myProTxHash, int _quorumIndex)
 
     CDKGLogger logger(*this, __func__, __LINE__);
 
-    if (LogAcceptCategory(BCLog::LLMQ) && IsQuorumRotationEnabled(params, m_quorum_base_block_index)) {
+    if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug) && IsQuorumRotationEnabled(params, m_quorum_base_block_index)) {
         int cycleQuorumBaseHeight = m_quorum_base_block_index->nHeight - quorumIndex;
         const CBlockIndex* pCycleQuorumBaseBlockIndex = m_quorum_base_block_index->GetAncestor(cycleQuorumBaseHeight);
         std::stringstream ss;
@@ -138,7 +138,7 @@ bool CDKGSession::Init(const uint256& _myProTxHash, int _quorumIndex)
     if (!myProTxHash.IsNull()) {
         dkgDebugManager.InitLocalSessionStatus(params, quorumIndex, m_quorum_base_block_index->GetBlockHash(), m_quorum_base_block_index->nHeight);
         relayMembers = utils::GetQuorumRelayMembers(params, m_dmnman, m_quorum_base_block_index, myProTxHash, true);
-        if (LogAcceptCategory(BCLog::LLMQ)) {
+        if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) {
             std::stringstream ss;
             for (const auto& r : relayMembers) {
                 ss << r.ToString().substr(0, 4) << " | ";