From 479ae82ecc1b2714de81c2d28e86515f7c9fab04 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Mon, 18 Nov 2024 10:45:27 +0000 Subject: [PATCH 01/14] merge bitcoin#23235: Reduce unnecessary default logging --- src/logging.cpp | 1 + src/logging.h | 1 + src/node/blockstorage.cpp | 4 ++-- src/validation.cpp | 17 +++++++++-------- test/functional/rpc_misc.py | 2 +- 5 files changed, 14 insertions(+), 11 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index dbbff8b92f..ddb6c57fbd 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -161,6 +161,7 @@ const CLogCategoryDesc LogCategories[] = {BCLog::I2P, "i2p"}, {BCLog::IPC, "ipc"}, {BCLog::LOCK, "lock"}, + {BCLog::BLOCKSTORE, "blockstorage"}, {BCLog::TXRECONCILIATION, "txreconciliation"}, {BCLog::ALL, "1"}, {BCLog::ALL, "all"}, diff --git a/src/logging.h b/src/logging.h index a534512049..b12a22cb63 100644 --- a/src/logging.h +++ b/src/logging.h @@ -62,6 +62,7 @@ namespace BCLog { I2P = (1 << 22), IPC = (1 << 23), LOCK = (1 << 24), + BLOCKSTORE = (1 << 26), TXRECONCILIATION = (1 << 27), //Start Dash 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/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/test/functional/rpc_misc.py b/test/functional/rpc_misc.py index ca3901dd6d..1d141d8e1c 100755 --- a/test/functional/rpc_misc.py +++ b/test/functional/rpc_misc.py @@ -57,7 +57,7 @@ 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) + assert_equal(len(node.logging()), 40) # Test toggling a logging category on/off/on with the logging RPC. assert_equal(node.logging()['qt'], True) From d9cc2ea17824a9b0667f2091819b51a90eca8093 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Wed, 20 Nov 2024 17:26:32 +0000 Subject: [PATCH 02/14] merge bitcoin#23104: Avoid breaking single log lines over multiple lines in the log file --- src/sync.cpp | 24 +++++++++++++----------- src/wallet/coinselection.cpp | 6 +++--- 2 files changed, 16 insertions(+), 14 deletions(-) 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/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, From f331cbe8c84c69f0be023b7d13eceb4728b0d02a Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Mon, 18 Nov 2024 10:47:10 +0000 Subject: [PATCH 03/14] merge bitcoin#24770: Put lock logging behind DEBUG_LOCKCONTENTION preprocessor directive --- doc/developer-notes.md | 14 ++++++++++++++ src/evo/creditpool.h | 1 + src/llmq/quorums.h | 1 + src/logging.cpp | 2 ++ src/logging.h | 2 ++ src/net.h | 2 ++ src/stats/rawsender.cpp | 1 + src/sync.h | 5 +++++ src/test/checkqueue_tests.cpp | 10 +++++++--- test/functional/rpc_misc.py | 3 --- 10 files changed, 35 insertions(+), 6 deletions(-) diff --git a/doc/developer-notes.md b/doc/developer-notes.md index 5d81f32d21..f4a7095392 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) @@ -412,6 +413,19 @@ 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. + +To enable it, run configure with `-DDEBUG_LOCKCONTENTION` added to your +CPPFLAGS, e.g. `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 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/llmq/quorums.h b/src/llmq/quorums.h index fac31afb02..415b4c60fd 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/logging.cpp b/src/logging.cpp index ddb6c57fbd..5ac21e344b 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -160,7 +160,9 @@ 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"}, diff --git a/src/logging.h b/src/logging.h index b12a22cb63..c88bae4957 100644 --- a/src/logging.h +++ b/src/logging.h @@ -61,7 +61,9 @@ namespace BCLog { VALIDATION = (1 << 21), I2P = (1 << 22), IPC = (1 << 23), +#ifdef DEBUG_LOCKCONTENTION LOCK = (1 << 24), +#endif BLOCKSTORE = (1 << 26), TXRECONCILIATION = (1 << 27), diff --git a/src/net.h b/src/net.h index 89ea78a4b9..3ac5523e21 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/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.h b/src/sync.h index 7206ac387a..dfe5846d7c 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(); } 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/test/functional/rpc_misc.py b/test/functional/rpc_misc.py index 1d141d8e1c..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()), 40) - # Test toggling a logging category on/off/on with the logging RPC. assert_equal(node.logging()['qt'], True) node.logging(exclude=['qt']) From a9cfbd1048f79796d4835cb88412ebcdc19d8a5c Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Sun, 17 Nov 2024 16:04:28 +0000 Subject: [PATCH 04/14] fix: don't use non-existent `PrintLockContention` in `SharedEnter` `PrintLockContention` hasn't existed since dash#6046 --- src/sync.h | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/src/sync.h b/src/sync.h index dfe5846d7c..6f4ffcc680 100644 --- a/src/sync.h +++ b/src/sync.h @@ -256,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) From 0e01d5b5f38104f1db3c9a1e2aca87c209c35a85 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Sun, 17 Nov 2024 15:11:52 +0000 Subject: [PATCH 05/14] partial bitcoin#22766: Clarify and disable unused ArgsManager flags excludes: - c5d7e34bd9a4ad752c5ec88032420e2e90ab17ab --- src/util/system.cpp | 104 +++++++++++++++++++++++--------------------- src/util/system.h | 16 ++++--- 2 files changed, 65 insertions(+), 55 deletions(-) diff --git a/src/util/system.cpp b/src/util/system.cpp index 6834189aa6..112dbb9e09 100644 --- a/src/util/system.cpp +++ b/src/util/system.cpp @@ -79,6 +79,7 @@ #include #include #include +#include #include #include #include @@ -205,39 +206,60 @@ 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); + LogPrintf("Warning: parsed potentially confusing double-negative -%s=%s\n", key.name, value); return true; } return false; @@ -245,22 +267,6 @@ static util::SettingsValue InterpretOption(std::string& section, std::string& ke 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; - } - return true; -} - // Define default constructor and destructor that are not inline, so code instantiating this class doesn't need to // #include class definitions for all members. // For example, m_settings has an internal dependency on univalue. @@ -366,21 +372,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, *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 @@ -580,10 +586,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); } } @@ -680,6 +684,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 @@ -926,15 +931,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 b99a5f9a1e..376b6ca90b 100644 --- a/src/util/system.h +++ b/src/util/system.h @@ -178,12 +178,18 @@ 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 + DEBUG_ONLY = 0x100, /* Some options would cause cross-contamination if values for * mainnet were used while running on regtest/testnet (or vice-versa). From d3e837ad22db389da3f57da1f63e7df74a5f1184 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Tue, 12 Apr 2022 03:00:28 -0400 Subject: [PATCH 06/14] merge bitcoin#24830: Allow -proxy="" setting values --- src/init.cpp | 6 +----- src/util/system.cpp | 18 +++++++++++------- src/util/system.h | 1 + test/functional/feature_config_args.py | 2 +- 4 files changed, 14 insertions(+), 13 deletions(-) diff --git a/src/init.cpp b/src/init.cpp index efb29eae5d..f82252d439 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); @@ -1337,10 +1337,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/util/system.cpp b/src/util/system.cpp index 112dbb9e09..3277d52b41 100644 --- a/src/util/system.cpp +++ b/src/util/system.cpp @@ -248,7 +248,7 @@ KeyInfo InterpretKey(std::string key) * @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, +static std::optional InterpretValue(const KeyInfo& key, const std::string* value, unsigned int flags, std::string& error) { // Return negated settings as false values. @@ -258,13 +258,17 @@ static std::optional InterpretValue(const KeyInfo& key, con 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.name, value); + if (value && !InterpretBool(*value)) { + LogPrintf("Warning: parsed potentially confusing double-negative -%s=%s\n", key.name, *value); return true; } return false; } - return value; + 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 value ? *value : ""; } // Define default constructor and destructor that are not inline, so code instantiating this class doesn't need to @@ -337,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); @@ -383,7 +387,7 @@ bool ArgsManager::ParseParameters(int argc, const char* const argv[], std::strin return false; } - std::optional value = InterpretValue(keyinfo, val, *flags, error); + std::optional value = InterpretValue(keyinfo, val ? &*val : nullptr, *flags, error); if (!value) return false; m_settings.command_line_options[keyinfo.name].push_back(*value); @@ -934,7 +938,7 @@ bool ArgsManager::ReadConfigStream(std::istream& stream, const std::string& file KeyInfo key = InterpretKey(option.first); std::optional flags = GetArgFlags('-' + key.name); if (flags) { - std::optional value = InterpretValue(key, option.second, *flags, error); + std::optional value = InterpretValue(key, &option.second, *flags, error); if (!value) { return false; } diff --git a/src/util/system.h b/src/util/system.h index 376b6ca90b..f4e17d9195 100644 --- a/src/util/system.h +++ b/src/util/system.h @@ -189,6 +189,7 @@ public: 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 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'], ) From 88592f30a30658908b954f0a182dbbd1bb5c7cf3 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Sun, 17 Nov 2024 17:14:18 +0000 Subject: [PATCH 07/14] merge bitcoin#24464: Add severity level to logs --- src/logging.cpp | 141 ++++++++++++++++++++++++++++++++++++- src/logging.h | 35 ++++++--- src/net.cpp | 30 ++++---- src/test/logging_tests.cpp | 120 +++++++++++++++++++++++++++++++ 4 files changed, 300 insertions(+), 26 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index 5ac21e344b..68516b20f9 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -188,7 +188,7 @@ const CLogCategoryDesc LogCategories[] = bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) { - if (str == "") { + if (str.empty()) { flag = BCLog::ALL; return true; } @@ -201,6 +201,123 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) return false; } +std::string LogLevelToStr(BCLog::Level level) +{ + switch (level) { + case BCLog::Level::None: + return "none"; + case BCLog::Level::Debug: + return "debug"; + case BCLog::Level::Info: + return "info"; + case BCLog::Level::Warning: + return "warning"; + case BCLog::Level::Error: + return "error"; + } + assert(false); +} + +std::string LogCategoryToStr(BCLog::LogFlags category) +{ + // Each log category string representation should sync with LogCategories + switch (category) { + case BCLog::LogFlags::NONE: + return "none"; + 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); +} + std::vector BCLog::Logger::LogCategoriesList(bool enabled_only) const { // Sort log categories by alphabetical order. @@ -268,11 +385,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, const int source_line, const BCLog::LogFlags category, const 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 + "] "); } diff --git a/src/logging.h b/src/logging.h index c88bae4957..3e085db5fb 100644 --- a/src/logging.h +++ b/src/logging.h @@ -91,6 +91,13 @@ namespace BCLog { ALL = ~(uint64_t)0, }; + enum class Level { + Debug = 0, + None = 1, + Info = 2, + Warning = 3, + Error = 4, + }; class Logger { @@ -130,7 +137,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, const int source_line, const BCLog::LogFlags category, const BCLog::Level level); /** Returns whether logs will be written to any output */ bool Enabled() const @@ -211,7 +218,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; @@ -221,19 +228,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))) { \ + LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__); \ + } \ + } while (0) + +#define LogPrintLevel(level, category, ...) \ + do { \ + if (LogAcceptCategory((category))) { \ + LogPrintLevel_(category, level, __VA_ARGS__); \ + } \ } while (0) #endif // BITCOIN_LOGGING_H diff --git a/src/net.cpp b/src/net.cpp index 3b54c7422c..49fa69941d 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::Level::Warning, BCLog::NET, "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::Level::Debug, 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); } 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::Level::Debug, BCLog::NET, "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::Level::Warning, BCLog::NET, "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::Level::Error, BCLog::NET, "%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::Level::Error, BCLog::NET, "%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::Level::Error, BCLog::NET, "%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::Level::Error, BCLog::NET, "%s\n", strError.original); return false; } diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 84ddbc50c6..2ce9060074 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -5,13 +5,55 @@ #include #include #include +#include #include +#include +#include +#include +#include #include BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup) +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; + + 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} + { + 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; + LogInstance().m_log_sourcelocations = true; + } + + ~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; + } +}; + BOOST_AUTO_TEST_CASE(logging_timer) { SetMockTime(1); @@ -30,4 +72,82 @@ 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) +{ + 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) +{ + // Prevent tests from failing when the line number of the following log calls changes. + LogInstance().m_log_sourcelocations = false; + + LogPrintf("foo5: %s\n", "bar5"); + LogPrint(BCLog::NET, "foo6: %s\n", "bar6"); + LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "foo7: %s\n", "bar7"); + LogPrintLevel(BCLog::Level::Info, BCLog::NET, "foo8: %s\n", "bar8"); + LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "foo9: %s\n", "bar9"); + LogPrintLevel(BCLog::Level::Error, BCLog::NET, "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) +{ + // Prevent tests from failing when the line number of the following log calls changes. + LogInstance().m_log_sourcelocations = false; + LogInstance().EnableCategory(BCLog::LogFlags::ALL); + const auto concated_categery_names = LogInstance().LogCategoriesString(); + std::vector> expected_category_names; + const auto category_names = SplitString(concated_categery_names, ','); + for (const auto& category_name : category_names) { + BCLog::LogFlags category = BCLog::NONE; + const auto trimmed_category_name = TrimString(category_name); + BOOST_TEST(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_AUTO_TEST_SUITE_END() From ff6304f5f3a439de12d3c0d25cc10de63286e05f Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Mon, 4 Apr 2022 13:10:10 +0200 Subject: [PATCH 08/14] merge bitcoin#24757: add `DEBUG_LOCKCONTENTION` to `--enable-debug` and CI --- ci/test/00_setup_env_native_tsan.sh | 2 +- configure.ac | 1 + doc/developer-notes.md | 6 ++++-- 3 files changed, 6 insertions(+), 3 deletions(-) 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 55fae0a021..816dc964e9 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 f4a7095392..7226447c51 100644 --- a/doc/developer-notes.md +++ b/doc/developer-notes.md @@ -419,8 +419,10 @@ 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. -To enable it, run configure with `-DDEBUG_LOCKCONTENTION` added to your -CPPFLAGS, e.g. `CPPFLAGS="-DDEBUG_LOCKCONTENTION"`, then build and run dashd. +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. From 7697b73257c4a8f4e92e224538347fd32f565834 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Mon, 11 Nov 2024 19:22:46 +0000 Subject: [PATCH 09/14] revert dash#2794: Disable logging of libevent debug messages reverts: - a1e4ac21fd3a97332c5d270a01babd4e278fc300 --- src/httpserver.cpp | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/src/httpserver.cpp b/src/httpserver.cpp index 951e99f999..081c6898e4 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -377,9 +377,8 @@ 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); + else + LogPrint(BCLog::LIBEVENT, "libevent: %s\n", msg); } bool InitHTTPServer() From b046e091c91c8b90f7f1370203d4f1d2f85c4537 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Wed, 20 Nov 2024 16:31:08 +0000 Subject: [PATCH 10/14] merge bitcoin#25202: Use severity-based logging for leveldb/libevent messages, reverse LogPrintLevel order Co-authored-by: UdjinM6 --- src/batchedlogger.cpp | 19 +++++++++++-------- src/batchedlogger.h | 16 ++++++++++------ src/dbwrapper.cpp | 6 +++--- src/httpserver.cpp | 20 ++++++++++++++++---- src/llmq/commitment.cpp | 6 +++--- src/llmq/dkgsession.cpp | 6 +++--- src/llmq/instantsend.cpp | 4 ++-- src/llmq/signing_shares.cpp | 14 +++++++++----- src/llmq/utils.cpp | 13 +++++++------ src/logging.h | 15 ++++++++++----- src/net.cpp | 16 ++++++++-------- src/net_processing.cpp | 2 +- src/qt/coincontroldialog.cpp | 2 +- src/test/logging_tests.cpp | 8 ++++---- src/timedata.cpp | 2 +- src/wallet/wallet.cpp | 2 +- src/wallet/wallet.h | 10 +++++----- 17 files changed, 95 insertions(+), 66 deletions(-) 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/httpserver.cpp b/src/httpserver.cpp index 081c6898e4..504f3cf642 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -375,10 +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); - 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/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/signing_shares.cpp b/src/llmq/signing_shares.cpp index baa31593d2..f3e53442e3 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.h b/src/logging.h index 3e085db5fb..69d07b5e09 100644 --- a/src/logging.h +++ b/src/logging.h @@ -191,9 +191,14 @@ 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) { + // Log messages at Warning and Error level unconditionally, so that + // important troubleshooting information doesn't get lost. + if (level >= BCLog::Level::Warning) { + return true; + } return LogInstance().WillLogCategory(category); } @@ -241,14 +246,14 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st // evaluating arguments when logging for the category is not enabled. #define LogPrint(category, ...) \ do { \ - if (LogAcceptCategory((category))) { \ + if (LogAcceptCategory((category), BCLog::Level::Debug)) { \ LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__); \ } \ } while (0) -#define LogPrintLevel(level, category, ...) \ +#define LogPrintLevel(category, level, ...) \ do { \ - if (LogAcceptCategory((category))) { \ + if (LogAcceptCategory((category), (level))) { \ LogPrintLevel_(category, level, __VA_ARGS__); \ } \ } while (0) diff --git a/src/net.cpp b/src/net.cpp index 49fa69941d..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 { - LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "getsockname failed\n"); + LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "getsockname failed\n"); } } return addr_bind; @@ -509,12 +509,12 @@ CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCo /// debug print if (fLogIPs) { - LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "trying %s connection %s lastseen=%.1fhrs\n", + 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 { - LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "trying %s connection lastseen=%.1fhrs\n", + 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); } @@ -1963,7 +1963,7 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket, CMasternodeSy } if (!addr.SetSockAddr((const struct sockaddr*)&sockaddr)) { - LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "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()); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%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("Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError())); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); + 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)); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original); return false; } LogPrintf("Bound to %s\n", addrBind.ToStringAddrPort()); @@ -4119,7 +4119,7 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError, if (sock->Listen(SOMAXCONN) == SOCKET_ERROR) { strError = strprintf(_("Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError())); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original); return false; } diff --git a/src/net_processing.cpp b/src/net_processing.cpp index 8676ad3371..e66e7e11ee 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -3662,7 +3662,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), 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/test/logging_tests.cpp b/src/test/logging_tests.cpp index 2ce9060074..1f86cc33fd 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -99,10 +99,10 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) LogPrintf("foo5: %s\n", "bar5"); LogPrint(BCLog::NET, "foo6: %s\n", "bar6"); - LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "foo7: %s\n", "bar7"); - LogPrintLevel(BCLog::Level::Info, BCLog::NET, "foo8: %s\n", "bar8"); - LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "foo9: %s\n", "bar9"); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "foo10: %s\n", "bar10"); + 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);) { 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/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 From 026409e4ffcc82b16f0c7f6d96ebf8b7ef1f5ab9 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Sun, 17 Nov 2024 12:39:12 +0000 Subject: [PATCH 11/14] merge bitcoin#25217: update lint-logs.py to detect LogPrintLevel, mention WalletLogPrintf --- test/lint/lint-logs.sh | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) 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 From 21470fdeb383ba4ce1691049417ae49be1f2b66b Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Tue, 7 Jun 2022 15:39:29 +0200 Subject: [PATCH 12/14] merge bitcoin#25292: Add LogPrintLevel to lint-format-strings, drop LogPrint-vs-LogPrintf section in dev notes --- doc/developer-notes.md | 5 ----- test/lint/lint-format-strings.sh | 1 + 2 files changed, 1 insertion(+), 5 deletions(-) diff --git a/doc/developer-notes.md b/doc/developer-notes.md index 7226447c51..8fe61e0f31 100644 --- a/doc/developer-notes.md +++ b/doc/developer-notes.md @@ -862,11 +862,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/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" From 52a12639892de407ee8895d8c2c017dd4ebc3d77 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Wed, 20 Nov 2024 16:28:40 +0000 Subject: [PATCH 13/14] merge bitcoin#25614: Severity-based logging, step 2 --- doc/developer-notes.md | 6 +- src/init.cpp | 1 + src/init/common.cpp | 28 ++++- src/init/common.h | 1 + src/logging.cpp | 83 +++++++++++-- src/logging.h | 55 +++++++-- src/test/i2p_tests.cpp | 4 + src/test/logging_tests.cpp | 125 ++++++++++++++++++-- src/test/util/setup_common.cpp | 1 + test/functional/test_framework/test_node.py | 2 + 10 files changed, 270 insertions(+), 36 deletions(-) diff --git a/doc/developer-notes.md b/doc/developer-notes.md index 8fe61e0f31..1f3aef04a6 100644 --- a/doc/developer-notes.md +++ b/doc/developer-notes.md @@ -390,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. diff --git a/src/init.cpp b/src/init.cpp index f82252d439..002818135b 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -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); diff --git a/src/init/common.cpp b/src/init/common.cpp index 8be70f7caf..ecf1095b90 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/logging.cpp b/src/logging.cpp index 68516b20f9..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"}, @@ -201,11 +216,11 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) return false; } -std::string LogLevelToStr(BCLog::Level level) +std::string BCLog::Logger::LogLevelToStr(BCLog::Level level) const { switch (level) { - case BCLog::Level::None: - return "none"; + case BCLog::Level::Trace: + return "trace"; case BCLog::Level::Debug: return "debug"; case BCLog::Level::Info: @@ -214,6 +229,8 @@ std::string LogLevelToStr(BCLog::Level level) return "warning"; case BCLog::Level::Error: return "error"; + case BCLog::Level::None: + return ""; } assert(false); } @@ -223,7 +240,7 @@ std::string LogCategoryToStr(BCLog::LogFlags category) // Each log category string representation should sync with LogCategories switch (category) { case BCLog::LogFlags::NONE: - return "none"; + return ""; case BCLog::LogFlags::NET: return "net"; case BCLog::LogFlags::TOR: @@ -318,6 +335,25 @@ std::string LogCategoryToStr(BCLog::LogFlags category) 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. @@ -338,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; @@ -385,7 +433,7 @@ 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, const BCLog::LogFlags category, const BCLog::Level level) +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); @@ -494,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 69d07b5e09..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; @@ -92,12 +93,14 @@ namespace BCLog { ALL = ~(uint64_t)0, }; enum class Level { - Debug = 0, - None = 1, - Info = 2, - Warning = 3, - Error = 4, + 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 { @@ -115,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}; @@ -137,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, const BCLog::LogFlags category, const BCLog::Level level); + 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 @@ -168,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); @@ -176,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. */ @@ -184,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; }; @@ -194,12 +228,7 @@ BCLog::Logger& LogInstance(); /** Return true if log accepts specified category, at the specified level. */ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level level) { - // Log messages at Warning and Error level unconditionally, so that - // important troubleshooting information doesn't get lost. - if (level >= BCLog::Level::Warning) { - return true; - } - return LogInstance().WillLogCategory(category); + return LogInstance().WillLogCategoryLevel(category, level); } /** Return true if str parses as a log category and set the flag */ 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 1f86cc33fd..69257af721 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -2,6 +2,7 @@ // Distributed under the MIT software license, see the accompanying // file COPYING or http://www.opensource.org/licenses/mit-license.php. +#include #include #include #include @@ -10,6 +11,7 @@ #include #include #include +#include #include #include @@ -17,6 +19,12 @@ 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; @@ -25,6 +33,8 @@ struct LogSetup : public BasicTestingSetup { 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"}, @@ -32,14 +42,21 @@ struct LogSetup : public BasicTestingSetup { 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_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; - LogInstance().m_log_sourcelocations = true; + + // 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() @@ -51,6 +68,8 @@ struct LogSetup : public BasicTestingSetup { 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); } }; @@ -74,6 +93,7 @@ BOOST_AUTO_TEST_CASE(logging_timer) 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"); @@ -94,9 +114,6 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) { - // Prevent tests from failing when the line number of the following log calls changes. - LogInstance().m_log_sourcelocations = false; - LogPrintf("foo5: %s\n", "bar5"); LogPrint(BCLog::NET, "foo6: %s\n", "bar6"); LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo7: %s\n", "bar7"); @@ -120,16 +137,14 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup) { - // Prevent tests from failing when the line number of the following log calls changes. - LogInstance().m_log_sourcelocations = false; LogInstance().EnableCategory(BCLog::LogFlags::ALL); - const auto concated_categery_names = LogInstance().LogCategoriesString(); + const auto concatenated_category_names = LogInstance().LogCategoriesString(); std::vector> expected_category_names; - const auto category_names = SplitString(concated_categery_names, ','); + const auto category_names = SplitString(concatenated_category_names, ','); for (const auto& category_name : category_names) { - BCLog::LogFlags category = BCLog::NONE; + BCLog::LogFlags category; const auto trimmed_category_name = TrimString(category_name); - BOOST_TEST(GetLogCategory(category, trimmed_category_name)); + BOOST_REQUIRE(GetLogCategory(category, trimmed_category_name)); expected_category_names.emplace_back(category, trimmed_category_name); } @@ -150,4 +165,92 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup) 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/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. From 1621696a6f6b59fb584e9203e6806e935f507b80 Mon Sep 17 00:00:00 2001 From: Kittywhiskers Van Gogh <63189531+kwvg@users.noreply.github.com> Date: Sun, 17 Nov 2024 13:26:16 +0000 Subject: [PATCH 14/14] log: restore `LogPrintLevel` messages from prior backports --- src/net_processing.cpp | 14 +++++++------- src/node/txreconciliation.cpp | 7 ++++--- 2 files changed, 11 insertions(+), 10 deletions(-) diff --git a/src/net_processing.cpp b/src/net_processing.cpp index e66e7e11ee..187d70c79c 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -3763,19 +3763,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; } @@ -3784,7 +3784,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; } @@ -3797,16 +3797,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/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); } }