diff --git a/ci/test/00_setup_env_native_tsan.sh b/ci/test/00_setup_env_native_tsan.sh index 633304580f..add809a28c 100755 --- a/ci/test/00_setup_env_native_tsan.sh +++ b/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 diff --git a/configure.ac b/configure.ac index 4c92f2e237..922af556f3 100644 --- a/configure.ac +++ b/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 diff --git a/doc/developer-notes.md b/doc/developer-notes.md index 5d81f32d21..1f3aef04a6 100644 --- a/doc/developer-notes.md +++ b/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 diff --git a/src/batchedlogger.cpp b/src/batchedlogger.cpp index a4204e86f4..0006ac51da 100644 --- a/src/batchedlogger.cpp +++ b/src/batchedlogger.cpp @@ -4,11 +4,14 @@ #include -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(); } diff --git a/src/batchedlogger.h b/src/batchedlogger.h index c24ca84fe5..6f2b13bf9b 100644 --- a/src/batchedlogger.h +++ b/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 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(); diff --git a/src/dbwrapper.cpp b/src/dbwrapper.cpp index 1c6efe7595..193f5f9258 100644 --- a/src/dbwrapper.cpp +++ b/src/dbwrapper.cpp @@ -20,7 +20,7 @@ public: // 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 @@ public: 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; diff --git a/src/evo/creditpool.h b/src/evo/creditpool.h index 5da980df65..4d4169974d 100644 --- a/src/evo/creditpool.h +++ b/src/evo/creditpool.h @@ -10,6 +10,7 @@ #include #include #include +#include #include #include diff --git a/src/httpserver.cpp b/src/httpserver.cpp index 951e99f999..504f3cf642 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -375,11 +375,22 @@ static void HTTPWorkQueueRun(WorkQueue* 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() diff --git a/src/init.cpp b/src/init.cpp index 618cf3a478..8967159b7b 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -583,7 +583,7 @@ void SetupServerArgs(ArgsManager& argsman) argsman.AddArg("-peertimeout=", 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=", strprintf("Listen for connections on . 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=", "Connect through SOCKS5 proxy, set -noproxy to disable (default: disabled)", ArgsManager::ALLOW_ANY, OptionsCategory::CONNECTION); + argsman.AddArg("-proxy=", "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=", "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=", "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= or -proxy=.")); - } - if (args.GetBoolArg("-reindex-chainstate", false)) { // indexes that must be deactivated to prevent index corruption, see #24630 if (args.GetBoolArg("-coinstatsindex", DEFAULT_COINSTATSINDEX)) { diff --git a/src/init/common.cpp b/src/init/common.cpp index 366f1f9118..2a83ae16b7 100644 --- a/src/init/common.cpp +++ b/src/init/common.cpp @@ -13,6 +13,7 @@ #include #include #include +#include #include #include #include @@ -57,11 +58,12 @@ bool SanityChecks() void AddLoggingArgs(ArgsManager& argsman) { argsman.AddArg("-debuglogfile=", 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=", "Output debugging information (default: -nodebug, supplying is optional). " - "If is not supplied or if = 1, output all debugging information. can be: " + LogInstance().LogCategoriesString() + ". This option can be specified multiple times to output multiple categories.", + argsman.AddArg("-debug=", "Output debug and trace logging (default: -nodebug, supplying is optional). " + "If is not supplied or if = 1, output all debug and trace logging. can be: " + LogInstance().LogCategoriesString() + ". This option can be specified multiple times to output multiple categories.", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); - argsman.AddArg("-debugexclude=", "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=", "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=|:", 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 : is supplied, the setting will override the global one and may be specified multiple times to set multiple category-specific levels. 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= + 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=: + 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=:. Valid categories: %s. Valid loglevels: %s."), level_str, LogInstance().LogCategoriesString(), LogInstance().LogLevelsString())); + } + } + } + } +} + void SetLoggingCategories(const ArgsManager& args) { if (args.IsArgSet("-debug")) { diff --git a/src/init/common.h b/src/init/common.h index fc4bc1b280..bcd46f41d3 100644 --- a/src/init/common.h +++ b/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 diff --git a/src/llmq/commitment.cpp b/src/llmq/commitment.cpp index ea131b113c..05607c34a6 100644 --- a/src/llmq/commitment.cpp +++ b/src/llmq/commitment.cpp @@ -82,7 +82,7 @@ bool CFinalCommitment::Verify(CDeterministicMNManager& dmnman, gsl::not_nullproTxHash.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]; diff --git a/src/llmq/dkgsession.cpp b/src/llmq/dkgsession.cpp index d59e7defee..1c95881efe 100644 --- a/src/llmq/dkgsession.cpp +++ b/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) << " | "; diff --git a/src/llmq/instantsend.cpp b/src/llmq/instantsend.cpp index c50fa939e0..e175009bb8 100644 --- a/src/llmq/instantsend.cpp +++ b/src/llmq/instantsend.cpp @@ -639,7 +639,7 @@ void CInstantSendManager::HandleNewInputLockRecoveredSig(const CRecoveredSig& re return; } - if (LogAcceptCategory(BCLog::INSTANTSEND)) { + if (LogAcceptCategory(BCLog::INSTANTSEND, BCLog::Level::Debug)) { for (const auto& in : tx->vin) { auto id = ::SerializeHash(std::make_pair(INPUTLOCK_REQUESTID_PREFIX, in.prevout)); if (id == recoveredSig.getId()) { @@ -1509,7 +1509,7 @@ void CInstantSendManager::ProcessPendingRetryLockTxs() // CheckCanLock is already called by ProcessTx, so we should avoid calling it twice. But we also shouldn't spam // the logs when retrying TXs that are not ready yet. - if (LogAcceptCategory(BCLog::INSTANTSEND)) { + if (LogAcceptCategory(BCLog::INSTANTSEND, BCLog::Level::Debug)) { if (!CheckCanLock(*tx, false, Params().GetConsensus())) { continue; } diff --git a/src/llmq/quorums.h b/src/llmq/quorums.h index 4700bd6fc1..892c0ecd27 100644 --- a/src/llmq/quorums.h +++ b/src/llmq/quorums.h @@ -15,6 +15,7 @@ #include #include #include +#include #include #include diff --git a/src/llmq/signing_shares.cpp b/src/llmq/signing_shares.cpp index 5f53acce39..3f522a121b 100644 --- a/src/llmq/signing_shares.cpp +++ b/src/llmq/signing_shares.cpp @@ -1334,7 +1334,7 @@ void CSigSharesManager::Cleanup() const auto& oneSigShare = m->begin()->second; std::string strMissingMembers; - if (LogAcceptCategory(BCLog::LLMQ_SIGS)) { + if (LogAcceptCategory(BCLog::LLMQ_SIGS, BCLog::Level::Debug)) { if (const auto quorumIt = quorums.find(std::make_pair(oneSigShare.getLlmqType(), oneSigShare.getQuorumHash())); quorumIt != quorums.end()) { const auto& quorum = quorumIt->second; for (const auto i : irange::range(quorum->members.size())) { @@ -1346,11 +1346,15 @@ void CSigSharesManager::Cleanup() } } - LogPrint(BCLog::LLMQ_SIGS, "CSigSharesManager::%s -- signing session timed out. signHash=%s, id=%s, msgHash=%s, sigShareCount=%d, missingMembers=%s\n", __func__, - signHash.ToString(), oneSigShare.getId().ToString(), oneSigShare.getMsgHash().ToString(), count, strMissingMembers); + LogPrintLevel(BCLog::LLMQ_SIGS, BCLog::Level::Info, /* Continued */ + "CSigSharesManager::%s -- signing session timed out. signHash=%s, id=%s, msgHash=%s, " + "sigShareCount=%d, missingMembers=%s\n", + __func__, signHash.ToString(), oneSigShare.getId().ToString(), + oneSigShare.getMsgHash().ToString(), count, strMissingMembers); } else { - LogPrint(BCLog::LLMQ_SIGS, "CSigSharesManager::%s -- signing session timed out. signHash=%s, sigShareCount=%d\n", __func__, - signHash.ToString(), count); + LogPrintLevel(BCLog::LLMQ_SIGS, BCLog::Level::Info, /* Continued */ + "CSigSharesManager::%s -- signing session timed out. signHash=%s, sigShareCount=%d\n", + __func__, signHash.ToString(), count); } RemoveSigSharesForSession(signHash); } diff --git a/src/llmq/utils.cpp b/src/llmq/utils.cpp index e3cc8ac240..59147750ee 100644 --- a/src/llmq/utils.cpp +++ b/src/llmq/utils.cpp @@ -216,7 +216,7 @@ std::vector> ComputeQuorumMembersByQuarterRota //TODO Check if it is triggered from outside (P2P, block validation). Throwing an exception is probably a wiser choice //assert (!newQuarterMembers.empty()); - if (LogAcceptCategory(BCLog::LLMQ)) { + if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) { for (const size_t i : irange::range(nQuorums)) { std::stringstream ss; @@ -249,7 +249,7 @@ std::vector> ComputeQuorumMembersByQuarterRota std::move(previousQuarters.quarterHMinusC[i].begin(), previousQuarters.quarterHMinusC[i].end(), std::back_inserter(quorumMembers[i])); std::move(newQuarterMembers[i].begin(), newQuarterMembers[i].end(), std::back_inserter(quorumMembers[i])); - if (LogAcceptCategory(BCLog::LLMQ)) { + if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) { std::stringstream ss; ss << " ["; for (const auto &m: quorumMembers[i]) { @@ -397,7 +397,7 @@ std::vector> BuildNewQuorumQuarterMembers(cons sortedCombinedMnsList.push_back(std::move(m)); } - if (LogAcceptCategory(BCLog::LLMQ)) { + if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) { std::stringstream ss; ss << " ["; for (const auto &m: sortedCombinedMnsList) { @@ -517,7 +517,7 @@ std::vector> GetQuorumQuarterMembersBySnapshot std::move(sortedMnsUsedAtH.begin(), sortedMnsUsedAtH.end(), std::back_inserter(sortedCombinedMns)); } - if (LogAcceptCategory(BCLog::LLMQ)) { + if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) { std::stringstream ss; ss << " ["; for (const auto &m: sortedCombinedMns) { @@ -788,7 +788,8 @@ bool EnsureQuorumConnections(const Consensus::LLMQParams& llmqParams, CConnman& relayMembers = connections; } if (!connections.empty()) { - if (!connman.HasMasternodeQuorumNodes(llmqParams.type, pQuorumBaseBlockIndex->GetBlockHash()) && LogAcceptCategory(BCLog::LLMQ)) { + if (!connman.HasMasternodeQuorumNodes(llmqParams.type, pQuorumBaseBlockIndex->GetBlockHash()) && + LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) { std::string debugMsg = strprintf("%s -- adding masternodes quorum connections for quorum %s:\n", __func__, pQuorumBaseBlockIndex->GetBlockHash().ToString()); for (const auto& c : connections) { auto dmn = tip_mn_list.GetValidMN(c); @@ -835,7 +836,7 @@ void AddQuorumProbeConnections(const Consensus::LLMQParams& llmqParams, CConnman } if (!probeConnections.empty()) { - if (LogAcceptCategory(BCLog::LLMQ)) { + if (LogAcceptCategory(BCLog::LLMQ, BCLog::Level::Debug)) { std::string debugMsg = strprintf("%s -- adding masternodes probes for quorum %s:\n", __func__, pQuorumBaseBlockIndex->GetBlockHash().ToString()); for (const auto& c : probeConnections) { auto dmn = tip_mn_list.GetValidMN(c); diff --git a/src/logging.cpp b/src/logging.cpp index dbbff8b92f..ab59bd5599 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -5,15 +5,17 @@ #include #include +#include #include #include -#include #include #include #include +#include const char * const DEFAULT_DEBUGLOGFILE = "debug.log"; +constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL{BCLog::Level::Info}; BCLog::Logger& LogInstance() { @@ -122,6 +124,19 @@ bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const return (m_categories.load(std::memory_order_relaxed) & category) != 0; } +bool BCLog::Logger::WillLogCategoryLevel(BCLog::LogFlags category, BCLog::Level level) const +{ + // Log messages at Warning and Error level unconditionally, so that + // important troubleshooting information doesn't get lost. + if (level >= BCLog::Level::Warning) return true; + + if (!WillLogCategory(category)) return false; + + StdLockGuard scoped_lock(m_cs); + const auto it{m_category_log_levels.find(category)}; + return level >= (it == m_category_log_levels.end() ? LogLevel() : it->second); +} + bool BCLog::Logger::DefaultShrinkDebugFile() const { return m_categories == BCLog::NONE; @@ -135,7 +150,7 @@ struct CLogCategoryDesc { const CLogCategoryDesc LogCategories[] = { {BCLog::NONE, "0"}, - {BCLog::NONE, "none"}, + {BCLog::NONE, ""}, {BCLog::NET, "net"}, {BCLog::TOR, "tor"}, {BCLog::MEMPOOL, "mempool"}, @@ -160,7 +175,10 @@ const CLogCategoryDesc LogCategories[] = {BCLog::VALIDATION, "validation"}, {BCLog::I2P, "i2p"}, {BCLog::IPC, "ipc"}, +#ifdef DEBUG_LOCKCONTENTION {BCLog::LOCK, "lock"}, +#endif + {BCLog::BLOCKSTORE, "blockstorage"}, {BCLog::TXRECONCILIATION, "txreconciliation"}, {BCLog::ALL, "1"}, {BCLog::ALL, "all"}, @@ -185,7 +203,7 @@ const CLogCategoryDesc LogCategories[] = bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) { - if (str == "") { + if (str.empty()) { flag = BCLog::ALL; return true; } @@ -198,6 +216,144 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) return false; } +std::string BCLog::Logger::LogLevelToStr(BCLog::Level level) const +{ + switch (level) { + case BCLog::Level::Trace: + return "trace"; + case BCLog::Level::Debug: + return "debug"; + case BCLog::Level::Info: + return "info"; + case BCLog::Level::Warning: + return "warning"; + case BCLog::Level::Error: + return "error"; + case BCLog::Level::None: + return ""; + } + assert(false); +} + +std::string LogCategoryToStr(BCLog::LogFlags category) +{ + // Each log category string representation should sync with LogCategories + switch (category) { + case BCLog::LogFlags::NONE: + return ""; + case BCLog::LogFlags::NET: + return "net"; + case BCLog::LogFlags::TOR: + return "tor"; + case BCLog::LogFlags::MEMPOOL: + return "mempool"; + case BCLog::LogFlags::HTTP: + return "http"; + case BCLog::LogFlags::BENCHMARK: + return "bench"; + case BCLog::LogFlags::ZMQ: + return "zmq"; + case BCLog::LogFlags::WALLETDB: + return "walletdb"; + case BCLog::LogFlags::RPC: + return "rpc"; + case BCLog::LogFlags::ESTIMATEFEE: + return "estimatefee"; + case BCLog::LogFlags::ADDRMAN: + return "addrman"; + case BCLog::LogFlags::SELECTCOINS: + return "selectcoins"; + case BCLog::LogFlags::REINDEX: + return "reindex"; + case BCLog::LogFlags::CMPCTBLOCK: + return "cmpctblock"; + case BCLog::LogFlags::RANDOM: + return "rand"; + case BCLog::LogFlags::PRUNE: + return "prune"; + case BCLog::LogFlags::PROXY: + return "proxy"; + case BCLog::LogFlags::MEMPOOLREJ: + return "mempoolrej"; + case BCLog::LogFlags::LIBEVENT: + return "libevent"; + case BCLog::LogFlags::COINDB: + return "coindb"; + case BCLog::LogFlags::QT: + return "qt"; + case BCLog::LogFlags::LEVELDB: + return "leveldb"; + case BCLog::LogFlags::VALIDATION: + return "validation"; + case BCLog::LogFlags::I2P: + return "i2p"; + case BCLog::LogFlags::IPC: + return "ipc"; +#ifdef DEBUG_LOCKCONTENTION + case BCLog::LogFlags::LOCK: + return "lock"; +#endif + case BCLog::LogFlags::BLOCKSTORE: + return "blockstorage"; + case BCLog::LogFlags::TXRECONCILIATION: + return "txreconciliation"; + /* Start Dash */ + case BCLog::LogFlags::CHAINLOCKS: + return "chainlocks"; + case BCLog::LogFlags::GOBJECT: + return "gobject"; + case BCLog::LogFlags::INSTANTSEND: + return "instantsend"; + case BCLog::LogFlags::LLMQ: + return "llmq"; + case BCLog::LogFlags::LLMQ_DKG: + return "llmq-dkg"; + case BCLog::LogFlags::LLMQ_SIGS: + return "llmq-sigs"; + case BCLog::LogFlags::MNPAYMENTS: + return "mnpayments"; + case BCLog::LogFlags::MNSYNC: + return "mnsync"; + case BCLog::LogFlags::COINJOIN: + return "coinjoin"; + case BCLog::LogFlags::SPORK: + return "spork"; + case BCLog::LogFlags::NETCONN: + return "netconn"; + case BCLog::LogFlags::CREDITPOOL: + return "creditpool"; + case BCLog::LogFlags::EHF: + return "ehf"; + case BCLog::LogFlags::DASH: + return "dash"; + case BCLog::LogFlags::NET_NETCONN: + return "net|netconn"; + /* End Dash */ + case BCLog::LogFlags::ALL: + return "all"; + } + assert(false); +} + +static std::optional GetLogLevel(const std::string& level_str) +{ + if (level_str == "trace") { + return BCLog::Level::Trace; + } else if (level_str == "debug") { + return BCLog::Level::Debug; + } else if (level_str == "info") { + return BCLog::Level::Info; + } else if (level_str == "warning") { + return BCLog::Level::Warning; + } else if (level_str == "error") { + return BCLog::Level::Error; + } else if (level_str == "none") { + return BCLog::Level::None; + } else { + return std::nullopt; + } +} + std::vector BCLog::Logger::LogCategoriesList(bool enabled_only) const { // Sort log categories by alphabetical order. @@ -218,6 +374,18 @@ std::vector BCLog::Logger::LogCategoriesList(bool enabled_only) con return ret; } +/** Log severity levels that can be selected by the user. */ +static constexpr std::array LogLevelsList() +{ + return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace}; +} + +std::string BCLog::Logger::LogLevelsString() const +{ + const auto& levels = LogLevelsList(); + return Join(std::vector{levels.begin(), levels.end()}, ", ", [this](BCLog::Level level) { return LogLevelToStr(level); }); +} + std::string BCLog::Logger::LogTimestampStr(const std::string& str) { std::string strStamped; @@ -265,11 +433,31 @@ namespace BCLog { } } // namespace BCLog -void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line) +void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level) { StdLockGuard scoped_lock(m_cs); std::string str_prefixed = LogEscapeMessage(str); + if ((category != LogFlags::NONE || level != Level::None) && m_started_new_line) { + std::string s{"["}; + + if (category != LogFlags::NONE) { + s += LogCategoryToStr(category); + } + + if (category != LogFlags::NONE && level != Level::None) { + // Only add separator if both flag and level are not NONE + s += ":"; + } + + if (level != Level::None) { + s += LogLevelToStr(level); + } + + s += "] "; + str_prefixed.insert(0, s); + } + if (m_log_sourcelocations && m_started_new_line) { str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] "); } @@ -354,3 +542,24 @@ void BCLog::Logger::ShrinkDebugFile() else if (file != nullptr) fclose(file); } + +bool BCLog::Logger::SetLogLevel(const std::string& level_str) +{ + const auto level = GetLogLevel(level_str); + if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false; + m_log_level = level.value(); + return true; +} + +bool BCLog::Logger::SetCategoryLogLevel(const std::string& category_str, const std::string& level_str) +{ + BCLog::LogFlags flag; + if (!GetLogCategory(flag, category_str)) return false; + + const auto level = GetLogLevel(level_str); + if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false; + + StdLockGuard scoped_lock(m_cs); + m_category_log_levels[flag] = level.value(); + return true; +} diff --git a/src/logging.h b/src/logging.h index a534512049..a8d5453047 100644 --- a/src/logging.h +++ b/src/logging.h @@ -7,8 +7,8 @@ #define BITCOIN_LOGGING_H #include -#include #include +#include #include #include @@ -17,6 +17,7 @@ #include #include #include +#include #include static const bool DEFAULT_LOGTIMEMICROS = false; @@ -61,7 +62,10 @@ namespace BCLog { VALIDATION = (1 << 21), I2P = (1 << 22), IPC = (1 << 23), +#ifdef DEBUG_LOCKCONTENTION LOCK = (1 << 24), +#endif + BLOCKSTORE = (1 << 26), TXRECONCILIATION = (1 << 27), //Start Dash @@ -88,6 +92,15 @@ namespace BCLog { ALL = ~(uint64_t)0, }; + enum class Level { + Trace = 0, // High-volume or detailed logging for development/debugging + Debug, // Reasonably noisy logging, but still usable in production + Info, // Default + Warning, + Error, + None, // Internal use only + }; + constexpr auto DEFAULT_LOG_LEVEL{Level::Debug}; class Logger { @@ -105,6 +118,13 @@ namespace BCLog { */ std::atomic_bool m_started_new_line{true}; + //! Category-specific log level. Overrides `m_log_level`. + std::unordered_map m_category_log_levels GUARDED_BY(m_cs); + + //! If there is no category-specific log level, all logs with a severity + //! level lower than `m_log_level` will be ignored. + std::atomic m_log_level{DEFAULT_LOG_LEVEL}; + /** Log categories bitfield. */ std::atomic m_categories{0}; @@ -127,7 +147,7 @@ namespace BCLog { std::atomic m_reopen_file{false}; /** Send a string to the log output */ - void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line); + void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level); /** Returns whether logs will be written to any output */ bool Enabled() const @@ -158,6 +178,22 @@ namespace BCLog { void ShrinkDebugFile(); + std::unordered_map CategoryLevels() const + { + StdLockGuard scoped_lock(m_cs); + return m_category_log_levels; + } + void SetCategoryLogLevel(const std::unordered_map& levels) + { + StdLockGuard scoped_lock(m_cs); + m_category_log_levels = levels; + } + bool SetCategoryLogLevel(const std::string& category_str, const std::string& level_str); + + Level LogLevel() const { return m_log_level.load(); } + void SetLogLevel(Level level) { m_log_level = level; } + bool SetLogLevel(const std::string& level); + uint64_t GetCategoryMask() const { return m_categories.load(); } void EnableCategory(LogFlags flag); @@ -166,6 +202,8 @@ namespace BCLog { bool DisableCategory(const std::string& str); bool WillLogCategory(LogFlags category) const; + bool WillLogCategoryLevel(LogFlags category, Level level) const; + /** Returns a vector of the log categories in alphabetical order. */ std::vector LogCategoriesList(bool enabled_only = false) const; /** Returns a string with the log categories in alphabetical order. */ @@ -174,6 +212,12 @@ namespace BCLog { return Join(LogCategoriesList(enabled_only), ", ", [&](const LogCategory& i) { return i.category; }); }; + //! Returns a string with all user-selectable log levels. + std::string LogLevelsString() const; + + //! Returns the string representation of a log level. + std::string LogLevelToStr(BCLog::Level level) const; + bool DefaultShrinkDebugFile() const; }; @@ -181,10 +225,10 @@ namespace BCLog { BCLog::Logger& LogInstance(); -/** Return true if log accepts specified category */ -static inline bool LogAcceptCategory(BCLog::LogFlags category) +/** Return true if log accepts specified category, at the specified level. */ +static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level level) { - return LogInstance().WillLogCategory(category); + return LogInstance().WillLogCategoryLevel(category, level); } /** Return true if str parses as a log category and set the flag */ @@ -208,7 +252,7 @@ std::string SafeStringFormat(const std::string& fmt, const Args&... args) // peer can fill up a user's disk with debug.log entries. template -static inline void LogPrintf_(const std::string& logging_function, const std::string& source_file, const int source_line, 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 BCLog::LogFlags flag, const BCLog::Level level, const char* fmt, const Args&... args) { if (LogInstance().Enabled()) { std::string log_msg; @@ -218,19 +262,29 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st /* 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, logging_function, source_file, source_line); + LogInstance().LogPrintStr(log_msg, logging_function, source_file, source_line, flag, level); } } -#define LogPrintf(...) LogPrintf_(__func__, __FILE__, __LINE__, __VA_ARGS__) + +#define LogPrintLevel_(category, level, ...) LogPrintf_(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) + +#define LogPrintf(...) LogPrintLevel_(BCLog::LogFlags::NONE, BCLog::Level::None, __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, ...) \ - do { \ - if (LogAcceptCategory((category))) { \ - LogPrintf(__VA_ARGS__); \ - } \ +#define LogPrint(category, ...) \ + do { \ + if (LogAcceptCategory((category), BCLog::Level::Debug)) { \ + LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__); \ + } \ + } while (0) + +#define LogPrintLevel(category, level, ...) \ + do { \ + if (LogAcceptCategory((category), (level))) { \ + LogPrintLevel_(category, level, __VA_ARGS__); \ + } \ } while (0) #endif // BITCOIN_LOGGING_H diff --git a/src/net.cpp b/src/net.cpp index 3b54c7422c..ce10298659 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -481,7 +481,7 @@ static CAddress GetBindAddress(const Sock& sock) if (!sock.GetSockName((struct sockaddr*)&sockaddr_bind, &sockaddr_bind_len)) { addr_bind.SetSockAddr((const struct sockaddr*)&sockaddr_bind); } else { - LogPrint(BCLog::NET, "Warning: getsockname failed\n"); + LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "getsockname failed\n"); } } return addr_bind; @@ -509,14 +509,14 @@ CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCo /// debug print if (fLogIPs) { - LogPrint(BCLog::NET, "trying %s connection %s lastseen=%.1fhrs\n", - use_v2transport ? "v2" : "v1", - pszDest ? pszDest : addrConnect.ToStringAddrPort(), - pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0); + LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "trying %s connection %s lastseen=%.1fhrs\n", + use_v2transport ? "v2" : "v1", + pszDest ? pszDest : addrConnect.ToStringAddrPort(), + pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0); } else { - LogPrint(BCLog::NET, "trying %s connection lastseen=%.1fhrs\n", - use_v2transport ? "v2" : "v1", - pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0); + LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "trying %s connection lastseen=%.1fhrs\n", + use_v2transport ? "v2" : "v1", + pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0); } // Resolve @@ -1963,7 +1963,7 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket, CMasternodeSy } if (!addr.SetSockAddr((const struct sockaddr*)&sockaddr)) { - LogPrintf("Warning: Unknown socket family\n"); + LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "Unknown socket family\n"); } else { addr = CAddress{MaybeFlipIPv6toCJDNS(addr), NODE_NONE}; } @@ -4068,14 +4068,14 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError, if (!addrBind.GetSockAddr((struct sockaddr*)&sockaddr, &len)) { strError = strprintf(Untranslated("Error: Bind address family for %s not supported"), addrBind.ToStringAddrPort()); - LogPrintf("%s\n", strError.original); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original); return false; } std::unique_ptr sock = CreateSock(addrBind); if (!sock) { - strError = strprintf(Untranslated("Error: Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError())); - LogPrintf("%s\n", strError.original); + strError = strprintf(Untranslated("Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError())); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original); return false; } @@ -4110,7 +4110,7 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError, strError = strprintf(_("Unable to bind to %s on this computer. %s is probably already running."), addrBind.ToStringAddrPort(), PACKAGE_NAME); else strError = strprintf(_("Unable to bind to %s on this computer (bind returned error %s)"), addrBind.ToStringAddrPort(), NetworkErrorString(nErr)); - LogPrintf("%s\n", strError.original); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original); return false; } LogPrintf("Bound to %s\n", addrBind.ToStringAddrPort()); @@ -4118,8 +4118,8 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError, // Listen for incoming connections if (sock->Listen(SOMAXCONN) == SOCKET_ERROR) { - strError = strprintf(_("Error: Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError())); - LogPrintf("%s\n", strError.original); + strError = strprintf(_("Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError())); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original); return false; } diff --git a/src/net.h b/src/net.h index 22fcc827b0..c0a2b82cde 100644 --- a/src/net.h +++ b/src/net.h @@ -16,6 +16,7 @@ #include #include #include +#include #include #include #include @@ -42,6 +43,7 @@ #include #include #include +#include #include #include #include diff --git a/src/net_processing.cpp b/src/net_processing.cpp index d6ebc6bed7..f6085ffd7c 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -3716,7 +3716,7 @@ void PeerManagerImpl::ProcessMessage( // Log succesful connections unconditionally for outbound, but not for inbound as those // can be triggered by an attacker at high rate. - if (!pfrom.IsInboundConn() || LogAcceptCategory(BCLog::NET)) { + if (!pfrom.IsInboundConn() || LogAcceptCategory(BCLog::NET, BCLog::Level::Debug)) { LogPrintf("New %s %s peer connected: version: %d, blocks=%d, peer=%d%s\n", pfrom.ConnectionTypeAsString(), TransportTypeAsString(pfrom.m_transport->GetInfo().transport_type), @@ -3817,19 +3817,19 @@ void PeerManagerImpl::ProcessMessage( // from switching announcement protocols after the connection is up. if (msg_type == NetMsgType::SENDTXRCNCL) { if (!m_txreconciliation) { - LogPrint(BCLog::NET, "sendtxrcncl from peer=%d ignored, as our node does not have txreconciliation enabled\n", pfrom.GetId()); + LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "sendtxrcncl from peer=%d ignored, as our node does not have txreconciliation enabled\n", pfrom.GetId()); return; } if (pfrom.fSuccessfullyConnected) { - LogPrint(BCLog::NET, "sendtxrcncl received after verack from peer=%d; disconnecting\n", pfrom.GetId()); + LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "sendtxrcncl received after verack from peer=%d; disconnecting\n", pfrom.GetId()); pfrom.fDisconnect = true; return; } // Peer must not offer us reconciliations if we specified no tx relay support in VERSION. if (RejectIncomingTxs(pfrom)) { - LogPrint(BCLog::NET, "sendtxrcncl received from peer=%d to which we indicated no tx relay; disconnecting\n", pfrom.GetId()); + LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "sendtxrcncl received from peer=%d to which we indicated no tx relay; disconnecting\n", pfrom.GetId()); pfrom.fDisconnect = true; return; } @@ -3838,7 +3838,7 @@ void PeerManagerImpl::ProcessMessage( // This flag might also be false in other cases, but the RejectIncomingTxs check above // eliminates them, so that this flag fully represents what we are looking for. if (!pfrom.m_relays_txs) { - LogPrint(BCLog::NET, "sendtxrcncl received from peer=%d which indicated no tx relay to us; disconnecting\n", pfrom.GetId()); + LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "sendtxrcncl received from peer=%d which indicated no tx relay to us; disconnecting\n", pfrom.GetId()); pfrom.fDisconnect = true; return; } @@ -3851,16 +3851,16 @@ void PeerManagerImpl::ProcessMessage( peer_txreconcl_version, remote_salt); switch (result) { case ReconciliationRegisterResult::NOT_FOUND: - LogPrint(BCLog::NET, "Ignore unexpected txreconciliation signal from peer=%d\n", pfrom.GetId()); + LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "Ignore unexpected txreconciliation signal from peer=%d\n", pfrom.GetId()); break; case ReconciliationRegisterResult::SUCCESS: break; case ReconciliationRegisterResult::ALREADY_REGISTERED: - LogPrint(BCLog::NET, "txreconciliation protocol violation from peer=%d (sendtxrcncl received from already registered peer); disconnecting\n", pfrom.GetId()); + LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "txreconciliation protocol violation from peer=%d (sendtxrcncl received from already registered peer); disconnecting\n", pfrom.GetId()); pfrom.fDisconnect = true; return; case ReconciliationRegisterResult::PROTOCOL_VIOLATION: - LogPrint(BCLog::NET, "txreconciliation protocol violation from peer=%d; disconnecting\n", pfrom.GetId()); + LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "txreconciliation protocol violation from peer=%d; disconnecting\n", pfrom.GetId()); pfrom.fDisconnect = true; return; } diff --git a/src/node/blockstorage.cpp b/src/node/blockstorage.cpp index 3c13592e8a..ed1e8005e8 100644 --- a/src/node/blockstorage.cpp +++ b/src/node/blockstorage.cpp @@ -585,7 +585,7 @@ void UnlinkPrunedFiles(const std::set& setFilesToPrune) FlatFilePos pos(*it, 0); fs::remove(BlockFileSeq().FileName(pos)); fs::remove(UndoFileSeq().FileName(pos)); - LogPrintf("Prune: %s deleted blk/rev (%05u)\n", __func__, *it); + LogPrint(BCLog::BLOCKSTORE, "Prune: %s deleted blk/rev (%05u)\n", __func__, *it); } } @@ -642,7 +642,7 @@ bool BlockManager::FindBlockPos(FlatFilePos& pos, unsigned int nAddSize, unsigne if ((int)nFile != m_last_blockfile) { if (!fKnown) { - LogPrint(BCLog::VALIDATION, "Leaving block file %i: %s\n", m_last_blockfile, m_blockfile_info[m_last_blockfile].ToString()); + LogPrint(BCLog::BLOCKSTORE, "Leaving block file %i: %s\n", m_last_blockfile, m_blockfile_info[m_last_blockfile].ToString()); } FlushBlockFile(!fKnown, finalize_undo); m_last_blockfile = nFile; diff --git a/src/node/txreconciliation.cpp b/src/node/txreconciliation.cpp index 8d23c85a9a..03d4258a84 100644 --- a/src/node/txreconciliation.cpp +++ b/src/node/txreconciliation.cpp @@ -83,7 +83,7 @@ public: AssertLockNotHeld(m_txreconciliation_mutex); LOCK(m_txreconciliation_mutex); - LogPrint(BCLog::TXRECONCILIATION, "Pre-register peer=%d\n", peer_id); + LogPrintLevel(BCLog::TXRECONCILIATION, BCLog::Level::Debug, "Pre-register peer=%d\n", peer_id); const uint64_t local_salt{GetRand(UINT64_MAX)}; // We do this exactly once per peer (which are unique by NodeId, see GetNewNodeId) so it's @@ -116,7 +116,8 @@ public: // v1 is the lowest version, so suggesting something below must be a protocol violation. if (recon_version < 1) return ReconciliationRegisterResult::PROTOCOL_VIOLATION; - LogPrint(BCLog::TXRECONCILIATION, "Register peer=%d (inbound=%i)\n", peer_id, is_peer_inbound); + LogPrintLevel(BCLog::TXRECONCILIATION, BCLog::Level::Debug, "Register peer=%d (inbound=%i)\n", + peer_id, is_peer_inbound); const uint256 full_salt{ComputeSalt(local_salt, remote_salt)}; recon_state->second = TxReconciliationState(!is_peer_inbound, full_salt.GetUint64(0), full_salt.GetUint64(1)); @@ -128,7 +129,7 @@ public: AssertLockNotHeld(m_txreconciliation_mutex); LOCK(m_txreconciliation_mutex); if (m_states.erase(peer_id)) { - LogPrint(BCLog::TXRECONCILIATION, "Forget txreconciliation state of peer=%d\n", peer_id); + LogPrintLevel(BCLog::TXRECONCILIATION, BCLog::Level::Debug, "Forget txreconciliation state of peer=%d\n", peer_id); } } diff --git a/src/qt/coincontroldialog.cpp b/src/qt/coincontroldialog.cpp index 4ada490a7a..4c89d8314e 100644 --- a/src/qt/coincontroldialog.cpp +++ b/src/qt/coincontroldialog.cpp @@ -770,7 +770,7 @@ void CoinControlDialog::updateView() // CoinJoin rounds int nRounds = model->getRealOutpointCoinJoinRounds(output); - if (nRounds >= 0 || LogAcceptCategory(BCLog::COINJOIN)) { + if (nRounds >= 0 || LogAcceptCategory(BCLog::COINJOIN, BCLog::Level::Debug)) { itemOutput->setText(COLUMN_COINJOIN_ROUNDS, QString::number(nRounds)); } else { itemOutput->setText(COLUMN_COINJOIN_ROUNDS, tr("n/a")); diff --git a/src/stats/rawsender.cpp b/src/stats/rawsender.cpp index eb423e37d5..8b56875f2f 100644 --- a/src/stats/rawsender.cpp +++ b/src/stats/rawsender.cpp @@ -5,6 +5,7 @@ #include +#include #include #include #include diff --git a/src/sync.cpp b/src/sync.cpp index 7540819262..c0a3314765 100644 --- a/src/sync.cpp +++ b/src/sync.cpp @@ -94,34 +94,36 @@ LockData& GetLockData() { static void potential_deadlock_detected(const LockPair& mismatch, const LockStack& s1, const LockStack& s2) { - std::string strOutput = ""; - strOutput += "POTENTIAL DEADLOCK DETECTED\n"; - strOutput += "Previous lock order was:\n"; + std::string log_message{}; + log_message += "POTENTIAL DEADLOCK DETECTED\n"; + log_message += "Previous lock order was:\n"; for (const LockStackItem& i : s1) { + std::string prefix{}; if (i.first == mismatch.first) { - strOutput += " (1)"; + prefix = " (1)"; } if (i.first == mismatch.second) { - strOutput += " (2)"; + prefix = " (2)"; } - strOutput += strprintf(" %s\n", i.second.ToString()); + log_message += strprintf("%s %s\n", prefix, i.second.ToString()); } std::string mutex_a, mutex_b; - strOutput += "Current lock order is:\n"; + log_message += "Current lock order is:\n"; for (const LockStackItem& i : s2) { + std::string prefix{}; if (i.first == mismatch.first) { - strOutput += " (1)"; + prefix = " (1)"; mutex_a = i.second.Name(); } if (i.first == mismatch.second) { - strOutput += " (2)"; + prefix = " (2)"; mutex_b = i.second.Name(); } - strOutput += strprintf(" %s\n", i.second.ToString()); + log_message += strprintf("%s %s\n", prefix, i.second.ToString()); } - LogPrintf("%s\n", strOutput); + LogPrintf("%s\n", log_message); if (g_debug_lockorder_abort) { tfm::format(std::cerr, "Assertion failed: detected inconsistent lock order for %s, details in debug log.\n", s2.back().second.ToString()); diff --git a/src/sync.h b/src/sync.h index 7206ac387a..6f4ffcc680 100644 --- a/src/sync.h +++ b/src/sync.h @@ -6,8 +6,11 @@ #ifndef BITCOIN_SYNC_H #define BITCOIN_SYNC_H +#ifdef DEBUG_LOCKCONTENTION #include #include +#endif + #include #include @@ -161,8 +164,10 @@ private: void Enter(const char* pszName, const char* pszFile, int nLine) { EnterCritical(pszName, pszFile, nLine, Base::mutex()); +#ifdef DEBUG_LOCKCONTENTION if (Base::try_lock()) return; LOG_TIME_MICROS_WITH_CATEGORY(strprintf("lock contention %s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK); +#endif Base::lock(); } @@ -251,13 +256,10 @@ private: { EnterCritical(pszName, pszFile, nLine, Base::mutex()); #ifdef DEBUG_LOCKCONTENTION - if (!Base::try_lock()) { - PrintLockContention(pszName, pszFile, nLine); -#endif - Base::lock(); -#ifdef DEBUG_LOCKCONTENTION - } + if (Base::try_lock()) return; + LOG_TIME_MICROS_WITH_CATEGORY(strprintf("lock contention %s, %s:%d", pszName, pszFile, nLine), BCLog::LOCK); #endif + Base::lock(); } bool TrySharedEnter(const char* pszName, const char* pszFile, int nLine) diff --git a/src/test/checkqueue_tests.cpp b/src/test/checkqueue_tests.cpp index d0e5404057..b7ccc71cdc 100644 --- a/src/test/checkqueue_tests.cpp +++ b/src/test/checkqueue_tests.cpp @@ -18,13 +18,17 @@ #include /** - * Identical to TestingSetup but excludes lock contention logging, as some of - * these tests are designed to be heavily contested to trigger race conditions - * or other issues. + * Identical to TestingSetup but excludes lock contention logging if + * `DEBUG_LOCKCONTENTION` is defined, as some of these tests are designed to be + * heavily contested to trigger race conditions or other issues. */ struct NoLockLoggingTestingSetup : public TestingSetup { NoLockLoggingTestingSetup() +#ifdef DEBUG_LOCKCONTENTION : TestingSetup{CBaseChainParams::MAIN, /*extra_args=*/{"-debugexclude=lock"}} {} +#else + : TestingSetup{CBaseChainParams::MAIN} {} +#endif }; BOOST_FIXTURE_TEST_SUITE(checkqueue_tests, NoLockLoggingTestingSetup) diff --git a/src/test/i2p_tests.cpp b/src/test/i2p_tests.cpp index 79b34931d3..95a0fb6a04 100644 --- a/src/test/i2p_tests.cpp +++ b/src/test/i2p_tests.cpp @@ -3,6 +3,7 @@ // file COPYING or http://www.opensource.org/licenses/mit-license.php. #include +#include #include #include #include @@ -20,6 +21,8 @@ BOOST_FIXTURE_TEST_SUITE(i2p_tests, BasicTestingSetup) BOOST_AUTO_TEST_CASE(unlimited_recv) { + const auto prev_log_level{LogInstance().LogLevel()}; + LogInstance().SetLogLevel(BCLog::Level::Trace); auto CreateSockOrig = CreateSock; // Mock CreateSock() to create MockSock. @@ -40,6 +43,7 @@ BOOST_AUTO_TEST_CASE(unlimited_recv) } CreateSock = CreateSockOrig; + LogInstance().SetLogLevel(prev_log_level); } BOOST_AUTO_TEST_SUITE_END() diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 84ddbc50c6..69257af721 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -2,16 +2,77 @@ // Distributed under the MIT software license, see the accompanying // file COPYING or http://www.opensource.org/licenses/mit-license.php. +#include #include #include #include +#include #include +#include +#include +#include +#include +#include #include BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup) +static void ResetLogger() +{ + LogInstance().SetLogLevel(BCLog::DEFAULT_LOG_LEVEL); + LogInstance().SetCategoryLogLevel({}); +} + +struct LogSetup : public BasicTestingSetup { + fs::path prev_log_path; + fs::path tmp_log_path; + bool prev_reopen_file; + bool prev_print_to_file; + bool prev_log_timestamps; + bool prev_log_threadnames; + bool prev_log_sourcelocations; + std::unordered_map prev_category_levels; + BCLog::Level prev_log_level; + + LogSetup() : prev_log_path{LogInstance().m_file_path}, + tmp_log_path{m_args.GetDataDirBase() / "tmp_debug.log"}, + prev_reopen_file{LogInstance().m_reopen_file}, + prev_print_to_file{LogInstance().m_print_to_file}, + prev_log_timestamps{LogInstance().m_log_timestamps}, + prev_log_threadnames{LogInstance().m_log_threadnames}, + prev_log_sourcelocations{LogInstance().m_log_sourcelocations}, + prev_category_levels{LogInstance().CategoryLevels()}, + prev_log_level{LogInstance().LogLevel()} + { + LogInstance().m_file_path = tmp_log_path; + LogInstance().m_reopen_file = true; + LogInstance().m_print_to_file = true; + LogInstance().m_log_timestamps = false; + LogInstance().m_log_threadnames = false; + + // Prevent tests from failing when the line number of the logs changes. + LogInstance().m_log_sourcelocations = false; + + LogInstance().SetLogLevel(BCLog::Level::Debug); + LogInstance().SetCategoryLogLevel({}); + } + + ~LogSetup() + { + LogInstance().m_file_path = prev_log_path; + LogPrintf("Sentinel log to reopen log file\n"); + LogInstance().m_print_to_file = prev_print_to_file; + LogInstance().m_reopen_file = prev_reopen_file; + LogInstance().m_log_timestamps = prev_log_timestamps; + LogInstance().m_log_threadnames = prev_log_threadnames; + LogInstance().m_log_sourcelocations = prev_log_sourcelocations; + LogInstance().SetLogLevel(prev_log_level); + LogInstance().SetCategoryLogLevel(prev_category_levels); + } +}; + BOOST_AUTO_TEST_CASE(logging_timer) { SetMockTime(1); @@ -30,4 +91,166 @@ BOOST_AUTO_TEST_CASE(logging_timer) BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), "tests: test secs (1.00s)"); } +BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) +{ + LogInstance().m_log_sourcelocations = true; + LogPrintf_("fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug, "foo1: %s", "bar1\n"); + LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::None, "foo2: %s", "bar2\n"); + LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo3: %s", "bar3\n"); + LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::NONE, BCLog::Level::None, "foo4: %s", "bar4\n"); + std::ifstream file{tmp_log_path}; + std::vector log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + std::vector expected = { + "[src1:1] [fn1] [net:debug] foo1: bar1", + "[src2:2] [fn2] [net] foo2: bar2", + "[src3:3] [fn3] [debug] foo3: bar3", + "[src4:4] [fn4] foo4: bar4", + }; + BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); +} + +BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) +{ + LogPrintf("foo5: %s\n", "bar5"); + LogPrint(BCLog::NET, "foo6: %s\n", "bar6"); + LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo7: %s\n", "bar7"); + LogPrintLevel(BCLog::NET, BCLog::Level::Info, "foo8: %s\n", "bar8"); + LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo9: %s\n", "bar9"); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo10: %s\n", "bar10"); + std::ifstream file{tmp_log_path}; + std::vector log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + std::vector expected = { + "foo5: bar5", + "[net] foo6: bar6", + "[net:debug] foo7: bar7", + "[net:info] foo8: bar8", + "[net:warning] foo9: bar9", + "[net:error] foo10: bar10"}; + BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); +} + +BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup) +{ + LogInstance().EnableCategory(BCLog::LogFlags::ALL); + const auto concatenated_category_names = LogInstance().LogCategoriesString(); + std::vector> expected_category_names; + const auto category_names = SplitString(concatenated_category_names, ','); + for (const auto& category_name : category_names) { + BCLog::LogFlags category; + const auto trimmed_category_name = TrimString(category_name); + BOOST_REQUIRE(GetLogCategory(category, trimmed_category_name)); + expected_category_names.emplace_back(category, trimmed_category_name); + } + + std::vector expected; + for (const auto& [category, name] : expected_category_names) { + LogPrint(category, "foo: %s\n", "bar"); + std::string expected_log = "["; + expected_log += name; + expected_log += "] foo: bar"; + expected.push_back(expected_log); + } + + std::ifstream file{tmp_log_path}; + std::vector log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); +} + +BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup) +{ + LogInstance().EnableCategory(BCLog::LogFlags::ALL); + + LogInstance().SetLogLevel(BCLog::Level::Debug); + LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info"); + + // Global log level + LogPrintLevel(BCLog::HTTP, BCLog::Level::Info, "foo1: %s\n", "bar1"); + LogPrintLevel(BCLog::MEMPOOL, BCLog::Level::Trace, "foo2: %s. This log level is lower than the global one.\n", "bar2"); + LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Warning, "foo3: %s\n", "bar3"); + LogPrintLevel(BCLog::RPC, BCLog::Level::Error, "foo4: %s\n", "bar4"); + + // Category-specific log level + LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo5: %s\n", "bar5"); + LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo6: %s. This log level is the same as the global one but lower than the category-specific one, which takes precedence. \n", "bar6"); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo7: %s\n", "bar7"); + + std::vector expected = { + "[http:info] foo1: bar1", + "[validation:warning] foo3: bar3", + "[rpc:error] foo4: bar4", + "[net:warning] foo5: bar5", + "[net:error] foo7: bar7", + }; + std::ifstream file{tmp_log_path}; + std::vector log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); +} + +BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup) +{ + // Set global log level + { + ResetLogger(); + ArgsManager args; + args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); + const char* argv_test[] = {"dashd", "-loglevel=debug"}; + std::string err; + BOOST_REQUIRE(args.ParseParameters(2, argv_test, err)); + init::SetLoggingLevel(args); + BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug); + } + + // Set category-specific log level + { + ResetLogger(); + ArgsManager args; + args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); + const char* argv_test[] = {"dashd", "-loglevel=net:trace"}; + std::string err; + BOOST_REQUIRE(args.ParseParameters(2, argv_test, err)); + init::SetLoggingLevel(args); + BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::DEFAULT_LOG_LEVEL); + + const auto& category_levels{LogInstance().CategoryLevels()}; + const auto net_it{category_levels.find(BCLog::LogFlags::NET)}; + BOOST_REQUIRE(net_it != category_levels.end()); + BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace); + } + + // Set both global log level and category-specific log level + { + ResetLogger(); + ArgsManager args; + args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); + const char* argv_test[] = {"dashd", "-loglevel=debug", "-loglevel=net:trace", "-loglevel=http:info"}; + std::string err; + BOOST_REQUIRE(args.ParseParameters(4, argv_test, err)); + init::SetLoggingLevel(args); + BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug); + + const auto& category_levels{LogInstance().CategoryLevels()}; + BOOST_CHECK_EQUAL(category_levels.size(), 2); + + const auto net_it{category_levels.find(BCLog::LogFlags::NET)}; + BOOST_CHECK(net_it != category_levels.end()); + BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace); + + const auto http_it{category_levels.find(BCLog::LogFlags::HTTP)}; + BOOST_CHECK(http_it != category_levels.end()); + BOOST_CHECK_EQUAL(http_it->second, BCLog::Level::Info); + } +} + BOOST_AUTO_TEST_SUITE_END() diff --git a/src/test/util/setup_common.cpp b/src/test/util/setup_common.cpp index 487bb1bb56..25b355ef71 100644 --- a/src/test/util/setup_common.cpp +++ b/src/test/util/setup_common.cpp @@ -149,6 +149,7 @@ BasicTestingSetup::BasicTestingSetup(const std::string& chainName, const std::ve "-logsourcelocations", "-logtimemicros", "-logthreadnames", + "-loglevel=trace", "-debug", "-debugexclude=libevent", "-debugexclude=leveldb", diff --git a/src/timedata.cpp b/src/timedata.cpp index bf0427cb95..a0b8c33e7a 100644 --- a/src/timedata.cpp +++ b/src/timedata.cpp @@ -99,7 +99,7 @@ void AddTimeData(const CNetAddr& ip, int64_t nOffsetSample) } } - if (LogAcceptCategory(BCLog::NET)) { + if (LogAcceptCategory(BCLog::NET, BCLog::Level::Debug)) { std::string log_message{"time data samples: "}; for (const int64_t n : vSorted) { log_message += strprintf("%+d ", n); diff --git a/src/util/system.cpp b/src/util/system.cpp index a0261103c4..84d633db09 100644 --- a/src/util/system.cpp +++ b/src/util/system.cpp @@ -79,6 +79,7 @@ #include #include #include +#include #include #include #include @@ -205,60 +206,69 @@ static std::string SettingName(const std::string& arg) return arg.size() > 0 && arg[0] == '-' ? arg.substr(1) : arg; } +struct KeyInfo { + std::string name; + std::string section; + bool negated{false}; +}; + /** - * Interpret -nofoo as if the user supplied -foo=0. + * Parse "name", "section.name", "noname", "section.noname" settings keys. * - * This method also tracks when the -no form was supplied, and if so, - * checks whether there was a double-negative (-nofoo=0 -> -foo=1). - * - * If there was not a double negative, it removes the "no" from the key - * and returns false. - * - * If there was a double negative, it removes "no" from the key, and - * returns true. - * - * If there was no "no", it returns the string value untouched. - * - * Where an option was negated can be later checked using the + * @note Where an option was negated can be later checked using the * IsArgNegated() method. One use case for this is to have a way to disable * options that are not normally boolean (e.g. using -nodebuglogfile to request * that debug log output is not sent to any file at all). */ - -static util::SettingsValue InterpretOption(std::string& section, std::string& key, const std::string& value) +KeyInfo InterpretKey(std::string key) { + KeyInfo result; // Split section name from key name for keys like "testnet.foo" or "regtest.bar" size_t option_index = key.find('.'); if (option_index != std::string::npos) { - section = key.substr(0, option_index); + result.section = key.substr(0, option_index); key.erase(0, option_index + 1); } if (key.substr(0, 2) == "no") { key.erase(0, 2); + result.negated = true; + } + result.name = key; + return result; +} + +/** + * Interpret settings value based on registered flags. + * + * @param[in] key key information to know if key was negated + * @param[in] value string value of setting to be parsed + * @param[in] flags ArgsManager registered argument flags + * @param[out] error Error description if settings value is not valid + * + * @return parsed settings value if it is valid, otherwise nullopt accompanied + * by a descriptive error string + */ +static std::optional InterpretValue(const KeyInfo& key, const std::string* value, + unsigned int flags, std::string& error) +{ + // Return negated settings as false values. + if (key.negated) { + if (flags & ArgsManager::DISALLOW_NEGATION) { + error = strprintf("Negating of -%s is meaningless and therefore forbidden", key.name); + return std::nullopt; + } // Double negatives like -nofoo=0 are supported (but discouraged) - if (!InterpretBool(value)) { - LogPrintf("Warning: parsed potentially confusing double-negative -%s=%s\n", key, value); + if (value && !InterpretBool(*value)) { + LogPrintf("Warning: parsed potentially confusing double-negative -%s=%s\n", key.name, *value); return true; } return false; } - return value; -} - -/** - * Check settings value validity according to flags. - * - * TODO: Add more meaningful error checks here in the future - * See "here's how the flags are meant to behave" in - * https://github.com/bitcoin/bitcoin/pull/16097#issuecomment-514627823 - */ -static bool CheckValid(const std::string& key, const util::SettingsValue& val, unsigned int flags, std::string& error) -{ - if (val.isBool() && !(flags & ArgsManager::ALLOW_BOOL)) { - error = strprintf("Negating of -%s is meaningless and therefore forbidden", key); - return false; + if (!value && (flags & ArgsManager::DISALLOW_ELISION)) { + error = strprintf("Can not set -%s with no value. Please specify value with -%s=value.", key.name, key.name); + return std::nullopt; } - return true; + return value ? *value : ""; } // Define default constructor and destructor that are not inline, so code instantiating this class doesn't need to @@ -331,7 +341,7 @@ bool ArgsManager::ParseParameters(int argc, const char* const argv[], std::strin if (key.substr(0, 5) == "-psn_") continue; #endif - std::string val; + std::optional val; size_t is_index = key.find('='); if (is_index != std::string::npos) { val = key.substr(is_index + 1); @@ -366,21 +376,21 @@ bool ArgsManager::ParseParameters(int argc, const char* const argv[], std::strin // Transform -foo to foo key.erase(0, 1); - std::string section; - util::SettingsValue value = InterpretOption(section, key, val); - std::optional flags = GetArgFlags('-' + key); + KeyInfo keyinfo = InterpretKey(key); + std::optional flags = GetArgFlags('-' + keyinfo.name); // Unknown command line options and command line options with dot - // characters (which are returned from InterpretOption with nonempty + // characters (which are returned from InterpretKey with nonempty // section strings) are not valid. - if (!flags || !section.empty()) { + if (!flags || !keyinfo.section.empty()) { error = strprintf("Invalid parameter %s", argv[i]); return false; } - if (!CheckValid(key, value, *flags, error)) return false; + std::optional value = InterpretValue(keyinfo, val ? &*val : nullptr, *flags, error); + if (!value) return false; - m_settings.command_line_options[key].push_back(value); + m_settings.command_line_options[keyinfo.name].push_back(*value); } // we do not allow -includeconf from command line, only -noincludeconf @@ -583,10 +593,8 @@ bool ArgsManager::ReadSettingsFile(std::vector* errors) return false; } for (const auto& setting : m_settings.rw_settings) { - std::string section; - std::string key = setting.first; - (void)InterpretOption(section, key, /* value */ {}); // Split setting key into section and argname - if (!GetArgFlags('-' + key)) { + KeyInfo key = InterpretKey(setting.first); // Split setting key into section and argname + if (!GetArgFlags('-' + key.name)) { LogPrintf("Ignoring unknown rw_settings value %s\n", setting.first); } } @@ -683,6 +691,7 @@ void ArgsManager::AddArg(const std::string& name, const std::string& help, unsig LOCK(cs_args); std::map& arg_map = m_available_args[cat]; + if ((flags & (ALLOW_ANY | ALLOW_BOOL)) == 0) flags |= DISALLOW_NEGATION; // Temporary, removed in next scripted-diff auto ret = arg_map.emplace(arg_name, Arg{name.substr(eq_index, name.size() - eq_index), help, flags}); assert(ret.second); // Make sure an insertion actually happened @@ -929,15 +938,14 @@ bool ArgsManager::ReadConfigStream(std::istream& stream, const std::string& file return false; } for (const std::pair& option : options) { - std::string section; - std::string key = option.first; - util::SettingsValue value = InterpretOption(section, key, option.second); - std::optional flags = GetArgFlags('-' + key); + KeyInfo key = InterpretKey(option.first); + std::optional flags = GetArgFlags('-' + key.name); if (flags) { - if (!CheckValid(key, value, *flags, error)) { + std::optional value = InterpretValue(key, &option.second, *flags, error); + if (!value) { return false; } - m_settings.ro_config[section][key].push_back(value); + m_settings.ro_config[key.section][key.name].push_back(*value); } else { if (ignore_invalid_keys) { LogPrintf("Ignoring unknown configuration value %s\n", option.first); diff --git a/src/util/system.h b/src/util/system.h index 6243069894..5779beb065 100644 --- a/src/util/system.h +++ b/src/util/system.h @@ -178,12 +178,19 @@ struct SectionInfo class ArgsManager { public: + /** + * Flags controlling how config and command line arguments are validated and + * interpreted. + */ enum Flags : uint32_t { - // Boolean options can accept negation syntax -noOPTION or -noOPTION=1 - ALLOW_BOOL = 0x01, - ALLOW_INT = 0x02, - ALLOW_STRING = 0x04, - ALLOW_ANY = ALLOW_BOOL | ALLOW_INT | ALLOW_STRING, + ALLOW_ANY = 0x01, //!< disable validation + ALLOW_BOOL = 0x02, //!< unimplemented, draft implementation in #16545 + ALLOW_INT = 0x04, //!< unimplemented, draft implementation in #16545 + ALLOW_STRING = 0x08, //!< unimplemented, draft implementation in #16545 + ALLOW_LIST = 0x10, //!< unimplemented, draft implementation in #16545 + DISALLOW_NEGATION = 0x20, //!< disallow -nofoo syntax + DISALLOW_ELISION = 0x40, //!< disallow -foo syntax that doesn't assign any value + DEBUG_ONLY = 0x100, /* Some options would cause cross-contamination if values for * mainnet were used while running on regtest/testnet (or vice-versa). diff --git a/src/validation.cpp b/src/validation.cpp index fda0a2b1f7..1074bb065f 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2463,8 +2463,8 @@ bool CChainState::FlushStateToDisk( // Flush best chain related state. This can only be done if the blocks / block index write was also done. if (fDoFullFlush && !CoinsTip().GetBestBlock().IsNull()) { { - LOG_TIME_SECONDS(strprintf("write coins cache to disk (%d coins, %.2fkB)", - coins_count, coins_mem_usage / 1000)); + LOG_TIME_MILLIS_WITH_CATEGORY(strprintf("write coins cache to disk (%d coins, %.2fkB)", + coins_count, coins_mem_usage / 1000), BCLog::BENCHMARK); // Typical Coin structures on disk are around 48 bytes in size. // Pushing a new one to the database can cause it to be written @@ -3756,7 +3756,7 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida if (ppindex) *ppindex = pindex; if (pindex->nStatus & BLOCK_FAILED_MASK) { - LogPrintf("ERROR: %s: block %s is marked invalid\n", __func__, hash.ToString()); + LogPrint(BCLog::VALIDATION, "%s: block %s is marked invalid\n", __func__, hash.ToString()); return state.Invalid(BlockValidationResult::BLOCK_CACHED_INVALID, "duplicate"); } if (pindex->nStatus & BLOCK_CONFLICT_CHAINLOCK) { @@ -3775,25 +3775,26 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida CBlockIndex* pindexPrev = nullptr; BlockMap::iterator mi{m_blockman.m_block_index.find(block.hashPrevBlock)}; if (mi == m_blockman.m_block_index.end()) { - LogPrintf("ERROR: %s: prev block not found\n", __func__); + LogPrint(BCLog::VALIDATION, "%s: %s prev block not found\n", __func__, hash.ToString()); return state.Invalid(BlockValidationResult::BLOCK_MISSING_PREV, "prev-blk-not-found"); } pindexPrev = &((*mi).second); assert(pindexPrev); if (pindexPrev->nStatus & BLOCK_FAILED_MASK) { - LogPrintf("ERROR: %s: prev block invalid\n", __func__); + LogPrint(BCLog::VALIDATION, "%s: %s prev block invalid\n", __func__, hash.ToString()); return state.Invalid(BlockValidationResult::BLOCK_INVALID_PREV, "bad-prevblk"); } if (pindexPrev->nStatus & BLOCK_CONFLICT_CHAINLOCK) { // it's ok-ish, the other node is probably missing the latest chainlock - LogPrintf("ERROR: %s: prev block %s conflicts with chainlock\n", __func__, block.hashPrevBlock.ToString()); + LogPrint(BCLog::VALIDATION, "%s: prev block %s conflicts with chainlock\n", __func__, block.hashPrevBlock.ToString()); return state.Invalid(BlockValidationResult::BLOCK_CHAINLOCK, "bad-prevblk-chainlock"); } if (!ContextualCheckBlockHeader(block, state, m_blockman, chainparams, pindexPrev, GetAdjustedTime())) { - return error("%s: Consensus::ContextualCheckBlockHeader: %s, %s", __func__, hash.ToString(), state.ToString()); + LogPrint(BCLog::VALIDATION, "%s: Consensus::ContextualCheckBlockHeader: %s, %s\n", __func__, hash.ToString(), state.ToString()); + return false; } /* Determine if this block descends from any block which has been found @@ -3829,7 +3830,7 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida m_blockman.m_dirty_blockindex.insert(invalid_walk); invalid_walk = invalid_walk->pprev; } - LogPrintf("ERROR: %s: prev block invalid\n", __func__); + LogPrint(BCLog::VALIDATION, "%s: %s prev block invalid\n", __func__, hash.ToString()); return state.Invalid(BlockValidationResult::BLOCK_INVALID_PREV, "bad-prevblk"); } } diff --git a/src/wallet/coinselection.cpp b/src/wallet/coinselection.cpp index be9fdbb1c2..6bd9044da8 100644 --- a/src/wallet/coinselection.cpp +++ b/src/wallet/coinselection.cpp @@ -340,15 +340,15 @@ bool KnapsackSolver(const CAmount& nTargetValue, std::vector& group util::insert(setCoinsRet, lowest_larger->m_outputs); nValueRet += lowest_larger->m_value; } else { - std::string s = "CWallet::SelectCoinsMinConf best subset: "; + std::string log_message{"Coin selection best subset: "}; for (unsigned int i = 0; i < applicable_groups.size(); i++) { if (vfBest[i]) { util::insert(setCoinsRet, applicable_groups[i].m_outputs); nValueRet += applicable_groups[i].m_value; - s += FormatMoney(applicable_groups[i].m_value) + " "; + log_message += strprintf("%s ", FormatMoney(applicable_groups[i].m_value)); } } - LogPrint(BCLog::SELECTCOINS, "%s - total %s\n", s, FormatMoney(nBest)); + LogPrint(BCLog::SELECTCOINS, "%stotal %s\n", log_message, FormatMoney(nBest)); } // There is no change in PS, so we know the fee beforehand, diff --git a/src/wallet/wallet.cpp b/src/wallet/wallet.cpp index 3449332970..346a2ec199 100644 --- a/src/wallet/wallet.cpp +++ b/src/wallet/wallet.cpp @@ -3432,7 +3432,7 @@ std::vector CWallet::SelectCoinsGroupedByAddresses(bool fSkipD } // debug - if (LogAcceptCategory(BCLog::SELECTCOINS)) { + if (LogAcceptCategory(BCLog::SELECTCOINS, BCLog::Level::Debug)) { std::string strMessage = "SelectCoinsGroupedByAddresses - vecTallyRet:\n"; for (const auto& item : vecTallyRet) strMessage += strprintf(" %s %f\n", EncodeDestination(item.txdest), float(item.nAmount)/COIN); diff --git a/src/wallet/wallet.h b/src/wallet/wallet.h index dd0238595b..7b41966216 100644 --- a/src/wallet/wallet.h +++ b/src/wallet/wallet.h @@ -150,11 +150,11 @@ extern const std::map WALLET_FLAG_CAVEATS; // Use a macro instead of a function for conditional logging to prevent // evaluating arguments when logging for the category is not enabled. -#define WalletCJLogPrint(wallet, ...) \ - do { \ - if (LogAcceptCategory(BCLog::COINJOIN)) { \ - wallet.WalletLogPrintf(__VA_ARGS__); \ - } \ +#define WalletCJLogPrint(wallet, ...) \ + do { \ + if (LogAcceptCategory(BCLog::COINJOIN, BCLog::Level::Debug)) { \ + wallet.WalletLogPrintf(__VA_ARGS__); \ + } \ } while (0) /** A wrapper to reserve an address from a wallet diff --git a/test/functional/feature_config_args.py b/test/functional/feature_config_args.py index 666aee897e..cba1d17cb5 100755 --- a/test/functional/feature_config_args.py +++ b/test/functional/feature_config_args.py @@ -84,7 +84,7 @@ class ConfArgsTest(BitcoinTestFramework): def test_invalid_command_line_options(self): self.nodes[0].assert_start_raises_init_error( - expected_msg='Error: No proxy server specified. Use -proxy= or -proxy=.', + expected_msg='Error: Error parsing command line arguments: Can not set -proxy with no value. Please specify value with -proxy=value.', extra_args=['-proxy'], ) diff --git a/test/functional/rpc_misc.py b/test/functional/rpc_misc.py index ca3901dd6d..cd69f65ddb 100755 --- a/test/functional/rpc_misc.py +++ b/test/functional/rpc_misc.py @@ -56,9 +56,6 @@ class RpcMiscTest(BitcoinTestFramework): self.log.info("test logging rpc and help") - # Test logging RPC returns the expected number of logging categories. - assert_equal(len(node.logging()), 39) - # Test toggling a logging category on/off/on with the logging RPC. assert_equal(node.logging()['qt'], True) node.logging(exclude=['qt']) diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index 0f2bd413eb..6863e72b40 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -125,6 +125,8 @@ class TestNode(): self.args.append("-logthreadnames") if self.version_is_at_least(21000000): self.args.append("-logsourcelocations") + if self.version_is_at_least(22010000): + self.args.append("-loglevel=trace") # Default behavior from global -v2transport flag is added to args to persist it over restarts. # May be overwritten in individual tests, using extra_args. diff --git a/test/lint/lint-format-strings.sh b/test/lint/lint-format-strings.sh index ca4bc89258..21586d1cee 100755 --- a/test/lint/lint-format-strings.sh +++ b/test/lint/lint-format-strings.sh @@ -17,6 +17,7 @@ FUNCTION_NAMES_AND_NUMBER_OF_LEADING_ARGUMENTS=( "LogConnectFailure,1" "LogPrint,1" "LogPrintf,0" + "LogPrintLevel,2" "printf,0" "snprintf,2" "sprintf,1" diff --git a/test/lint/lint-logs.sh b/test/lint/lint-logs.sh index 7972aa9fe8..85f94a1cdf 100755 --- a/test/lint/lint-logs.sh +++ b/test/lint/lint-logs.sh @@ -14,7 +14,7 @@ export LC_ALL=C -UNTERMINATED_LOGS=$(git grep --extended-regexp "LogPrintf?\(" -- "*.cpp" | \ +UNTERMINATED_LOGS=$(git grep --extended-regexp "(LogPrintLevel|LogPrintf?)\(" -- "*.cpp" | \ grep -v '\\n"' | \ grep -v '\.\.\.' | \ grep -v "/\* Continued \*/" | \ @@ -22,7 +22,7 @@ UNTERMINATED_LOGS=$(git grep --extended-regexp "LogPrintf?\(" -- "*.cpp" | \ grep -v "LogPrintf()") if [[ ${UNTERMINATED_LOGS} != "" ]]; then # shellcheck disable=SC2028 - echo "All calls to LogPrintf() and LogPrint() should be terminated with \\n" + echo "All calls to LogPrintf(), LogPrint(), LogPrintLevel(), and WalletLogPrintf() should be terminated with \\n" echo echo "${UNTERMINATED_LOGS}" exit 1