From f1379aeca9d3a8c4d3528de4d0af8298cb42fee4 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Tue, 31 May 2022 21:49:55 +0200 Subject: [PATCH 01/12] Simplify BCLog::Level enum class and LogLevelToStr() function - simplify the BCLog::Level enum class (and future changes to it) by only setting the value of the first enumerator - move the BCLog::Level:None enumerator to the end of the BCLog::Level enum class and LogLevelToStr() member function, as the None enumerator is only used internally, and by being the highest BCLog::Level value it can be used to iterate over the enumerators - replace the unused BCLog::Level:None string "none" with an empty string as the case will never be hit - add documentation --- src/logging.cpp | 8 ++++---- src/logging.h | 10 +++++----- 2 files changed, 9 insertions(+), 9 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index 1e2c1d5a77..3a25e7118d 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -135,7 +135,7 @@ struct CLogCategoryDesc { const CLogCategoryDesc LogCategories[] = { {BCLog::NONE, "0"}, - {BCLog::NONE, "none"}, + {BCLog::NONE, ""}, {BCLog::NET, "net"}, {BCLog::TOR, "tor"}, {BCLog::MEMPOOL, "mempool"}, @@ -187,8 +187,6 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) std::string LogLevelToStr(BCLog::Level level) { switch (level) { - case BCLog::Level::None: - return "none"; case BCLog::Level::Debug: return "debug"; case BCLog::Level::Info: @@ -197,6 +195,8 @@ std::string LogLevelToStr(BCLog::Level level) return "warning"; case BCLog::Level::Error: return "error"; + case BCLog::Level::None: + return ""; } assert(false); } @@ -206,7 +206,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: diff --git a/src/logging.h b/src/logging.h index 50869ad89a..f3914958cf 100644 --- a/src/logging.h +++ b/src/logging.h @@ -68,11 +68,11 @@ namespace BCLog { ALL = ~(uint32_t)0, }; enum class Level { - Debug = 0, - None = 1, - Info = 2, - Warning = 3, - Error = 4, + Debug = 0, // High-volume or detailed logging for development/debugging + Info, // Default + Warning, + Error, + None, // Internal use only }; class Logger From 2978b387bffc226fb1eaca4d30f24a0deedb2a36 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Thu, 18 Aug 2022 12:02:26 +0200 Subject: [PATCH 02/12] Add BCLog::Logger::m_log_level data member and getter/setter Co-authored-by: "klementtan " --- src/logging.h | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/src/logging.h b/src/logging.h index f3914958cf..e6cf451b55 100644 --- a/src/logging.h +++ b/src/logging.h @@ -74,6 +74,7 @@ namespace BCLog { Error, None, // Internal use only }; + constexpr auto DEFAULT_LOG_LEVEL{Level::Debug}; class Logger { @@ -91,6 +92,10 @@ namespace BCLog { */ std::atomic_bool m_started_new_line{true}; + //! 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}; @@ -143,6 +148,9 @@ namespace BCLog { void ShrinkDebugFile(); + Level LogLevel() const { return m_log_level.load(); } + void SetLogLevel(Level level) { m_log_level = level; } + uint32_t GetCategoryMask() const { return m_categories.load(); } void EnableCategory(LogFlags flag); From f6c0cc03509255ffa4dfd6e2822fce840dd0b181 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Thu, 18 Aug 2022 12:17:16 +0200 Subject: [PATCH 03/12] Add BCLog::Logger::m_category_log_levels data member and getter/setter Co-authored-by: "klementtan " --- src/logging.h | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/src/logging.h b/src/logging.h index e6cf451b55..fd806ce142 100644 --- a/src/logging.h +++ b/src/logging.h @@ -17,6 +17,7 @@ #include #include #include +#include #include static const bool DEFAULT_LOGTIMEMICROS = false; @@ -92,6 +93,9 @@ 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}; @@ -148,6 +152,17 @@ 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; + } + Level LogLevel() const { return m_log_level.load(); } void SetLogLevel(Level level) { m_log_level = level; } From c2797cfc602c5cdd899a7c11b37bb5711cebff38 Mon Sep 17 00:00:00 2001 From: klementtan Date: Thu, 18 Aug 2022 12:51:37 +0200 Subject: [PATCH 04/12] Add BCLog::Logger::SetLogLevel()/SetCategoryLogLevel() for string inputs and remove unnecessary param constness in LogPrintStr() Co-authored-by: jonatack --- src/logging.cpp | 44 ++++++++++++++++++++++++++++++++++++++++++-- src/logging.h | 6 ++++-- 2 files changed, 46 insertions(+), 4 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index 3a25e7118d..3816297820 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() { @@ -269,6 +271,23 @@ std::string LogCategoryToStr(BCLog::LogFlags category) assert(false); } +static std::optional GetLogLevel(const std::string& level_str) +{ + 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() const { // Sort log categories by alphabetical order. @@ -334,7 +353,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); @@ -443,3 +462,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 fd806ce142..f49a2db326 100644 --- a/src/logging.h +++ b/src/logging.h @@ -7,8 +7,8 @@ #define BITCOIN_LOGGING_H #include -#include #include +#include #include #include @@ -121,7 +121,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 @@ -162,9 +162,11 @@ namespace BCLog { 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); uint32_t GetCategoryMask() const { return m_categories.load(); } From 8fe3457dbb4146952b92fb9509bbe4e97dc1f05b Mon Sep 17 00:00:00 2001 From: klementtan Date: Thu, 18 Aug 2022 13:37:25 +0200 Subject: [PATCH 05/12] Update LogAcceptCategory() and unit tests with log severity levels Co-authored-by: "Jon Atack " --- src/logging.cpp | 13 +++++++++ src/logging.h | 9 +++---- src/test/i2p_tests.cpp | 4 +++ src/test/logging_tests.cpp | 30 +++++++++++++-------- test/functional/test_framework/test_node.py | 2 ++ 5 files changed, 41 insertions(+), 17 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index 3816297820..522b4dc42e 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -124,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; diff --git a/src/logging.h b/src/logging.h index f49a2db326..76bed39e91 100644 --- a/src/logging.h +++ b/src/logging.h @@ -176,6 +176,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() const; /** Returns a string with the log categories in alphabetical order. */ @@ -194,12 +196,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 bd9ba4b8f7..6fb104622d 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 @@ -19,6 +20,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::Debug); auto CreateSockOrig = CreateSock; // Mock CreateSock() to create MockSock. @@ -39,6 +42,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 5a5e3b3f1f..00c6107c5a 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -10,6 +10,7 @@ #include #include #include +#include #include #include @@ -25,6 +26,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 +35,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 +61,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 +86,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 +107,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"); @@ -123,16 +133,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); } diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index 03f6c8adea..e28d458f69 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -118,6 +118,8 @@ class TestNode(): self.args.append("-logthreadnames") if self.version_is_at_least(219900): self.args.append("-logsourcelocations") + if self.version_is_at_least(239000): + self.args.append("-loglevel=debug") self.cli = TestNodeCLI(bitcoin_cli, self.datadir) self.use_cli = use_cli From 9c7507bf76e79da99766a69df939520ea0a125d1 Mon Sep 17 00:00:00 2001 From: klementtan Date: Thu, 18 Aug 2022 13:56:36 +0200 Subject: [PATCH 06/12] Create BCLog::Logger::LogLevelsString() helper function Co-authored-by: "Jon Atack " --- src/logging.cpp | 12 ++++++++++++ src/logging.h | 3 +++ 2 files changed, 15 insertions(+) diff --git a/src/logging.cpp b/src/logging.cpp index 522b4dc42e..214f6af9a7 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -319,6 +319,18 @@ std::vector BCLog::Logger::LogCategoriesList() const return ret; } +/** Log severity levels that can be selected by the user. */ +static constexpr std::array LogLevelsList() +{ + return {BCLog::Level::Info, BCLog::Level::Debug}; +} + +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; diff --git a/src/logging.h b/src/logging.h index 76bed39e91..680eb47f4b 100644 --- a/src/logging.h +++ b/src/logging.h @@ -186,6 +186,9 @@ namespace BCLog { return Join(LogCategoriesList(), ", ", [&](const LogCategory& i) { return i.category; }); }; + //! Returns a string with all user-selectable log levels. + std::string LogLevelsString() const; + bool DefaultShrinkDebugFile() const; }; From 98a1f9c68744074f29fa5fa67514218b5ee9edc4 Mon Sep 17 00:00:00 2001 From: klementtan Date: Thu, 18 Aug 2022 11:02:54 +0200 Subject: [PATCH 07/12] Unit test coverage for log severity levels Co-authored-by: "Jon Atack " --- src/test/logging_tests.cpp | 33 +++++++++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 00c6107c5a..c827b4eec5 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -161,4 +161,37 @@ 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::Info); + 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::Debug, "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 lower than the category-specific one.\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_AUTO_TEST_SUITE_END() From eb7bee5f84d41e35cb4296e01bea2aa5ac80a856 Mon Sep 17 00:00:00 2001 From: klementtan Date: Tue, 7 Jun 2022 00:18:58 +0800 Subject: [PATCH 08/12] Create -loglevel configuration option - add a -loglevel=| config option to allow users to set a global -loglevel and category-specific log levels. LogPrintLevel messages with a higher severity level than -loglevel will not be printed in the debug log. - for now, this config option is debug-only during the migration to severity-based logging - update unit and functional tests Co-authored-by: "Jon Atack " --- src/init.cpp | 1 + src/init/common.cpp | 22 ++++++++++++++++++++++ src/init/common.h | 1 + src/logging.cpp | 2 +- src/logging.h | 3 +++ src/test/util/setup_common.cpp | 1 + 6 files changed, 29 insertions(+), 1 deletion(-) diff --git a/src/init.cpp b/src/init.cpp index 4606b77e9f..2b40e882a4 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -915,6 +915,7 @@ bool AppInitParameterInteraction(const ArgsManager& args, bool use_syscall_sandb // ********************************************************* 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 bdd7f16307..3261c18e5a 100644 --- a/src/init/common.cpp +++ b/src/init/common.cpp @@ -11,6 +11,7 @@ #include #include #include +#include #include #include #include @@ -28,6 +29,7 @@ void AddLoggingArgs(ArgsManager& argsman) 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("-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, OptionsCategory::DEBUG_TEST); @@ -55,6 +57,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 2c7f485908..53c860c297 100644 --- a/src/init/common.h +++ b/src/init/common.h @@ -14,6 +14,7 @@ namespace init { 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 214f6af9a7..0de74c4913 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -199,7 +199,7 @@ 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::Debug: diff --git a/src/logging.h b/src/logging.h index 680eb47f4b..1288efa0fe 100644 --- a/src/logging.h +++ b/src/logging.h @@ -189,6 +189,9 @@ namespace BCLog { //! 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; }; diff --git a/src/test/util/setup_common.cpp b/src/test/util/setup_common.cpp index 30d26ecf79..872310f1ca 100644 --- a/src/test/util/setup_common.cpp +++ b/src/test/util/setup_common.cpp @@ -108,6 +108,7 @@ BasicTestingSetup::BasicTestingSetup(const std::string& chainName, const std::ve "-logsourcelocations", "-logtimemicros", "-logthreadnames", + "-loglevel=debug", "-debug", "-debugexclude=libevent", "-debugexclude=leveldb", From 2a8712db4fb5d06f1a525a79bb0f793cb733aaa6 Mon Sep 17 00:00:00 2001 From: klementtan Date: Thu, 18 Aug 2022 11:03:28 +0200 Subject: [PATCH 09/12] Unit test coverage for -loglevel configuration option Co-authored-by: "Jon Atack " --- src/test/logging_tests.cpp | 62 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 62 insertions(+) diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index c827b4eec5..352b517890 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 @@ -18,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; @@ -194,4 +201,59 @@ BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup) 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[] = {"bitcoind", "-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[] = {"bitcoind", "-loglevel=net:debug"}; + 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::Debug); + } + + // 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[] = {"bitcoind", "-loglevel=debug", "-loglevel=net:debug", "-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::Debug); + + 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() From 45f92821621a60891044f57c7a7bc4ab4c7d8a01 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Wed, 1 Jun 2022 13:44:59 +0200 Subject: [PATCH 10/12] Create BCLog::Level::Trace log severity level for verbose log messages for development or debugging only, as bitcoind may run more slowly, that are more granular/frequent than the Debug log level, i.e. for very high-frequency, low-level messages to be logged distinctly from higher-level, less-frequent debug logging that could still be usable in production. An example would be to log higher-level peer events (connection, disconnection, misbehavior, eviction) as Debug, versus Trace for low-level, high-volume p2p messages in the BCLog::NET category. This will enable the user to log only the former without the latter, in order to focus on high-level peer management events. With respect to the name, "trace" is suggested as the most granular level in resources like the following: - https://sematext.com/blog/logging-levels - https://howtodoinjava.com/log4j2/logging-levels Update the test framework and add test coverage. --- src/logging.cpp | 10 +++++++--- src/logging.h | 3 ++- src/test/i2p_tests.cpp | 2 +- src/test/logging_tests.cpp | 14 +++++++------- src/test/util/setup_common.cpp | 2 +- test/functional/test_framework/test_node.py | 2 +- 6 files changed, 19 insertions(+), 14 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index 0de74c4913..a609a021d1 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -202,6 +202,8 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) std::string BCLog::Logger::LogLevelToStr(BCLog::Level level) const { switch (level) { + case BCLog::Level::Trace: + return "trace"; case BCLog::Level::Debug: return "debug"; case BCLog::Level::Info: @@ -286,7 +288,9 @@ std::string LogCategoryToStr(BCLog::LogFlags category) static std::optional GetLogLevel(const std::string& level_str) { - if (level_str == "debug") { + 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; @@ -320,9 +324,9 @@ std::vector BCLog::Logger::LogCategoriesList() const } /** Log severity levels that can be selected by the user. */ -static constexpr std::array LogLevelsList() +static constexpr std::array LogLevelsList() { - return {BCLog::Level::Info, BCLog::Level::Debug}; + return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace}; } std::string BCLog::Logger::LogLevelsString() const diff --git a/src/logging.h b/src/logging.h index 1288efa0fe..fe91ee43a5 100644 --- a/src/logging.h +++ b/src/logging.h @@ -69,7 +69,8 @@ namespace BCLog { ALL = ~(uint32_t)0, }; enum class Level { - Debug = 0, // High-volume or detailed logging for development/debugging + Trace = 0, // High-volume or detailed logging for development/debugging + Debug, // Reasonably noisy logging, but still usable in production Info, // Default Warning, Error, diff --git a/src/test/i2p_tests.cpp b/src/test/i2p_tests.cpp index 6fb104622d..43e4303ae3 100644 --- a/src/test/i2p_tests.cpp +++ b/src/test/i2p_tests.cpp @@ -21,7 +21,7 @@ BOOST_FIXTURE_TEST_SUITE(i2p_tests, BasicTestingSetup) BOOST_AUTO_TEST_CASE(unlimited_recv) { const auto prev_log_level{LogInstance().LogLevel()}; - LogInstance().SetLogLevel(BCLog::Level::Debug); + LogInstance().SetLogLevel(BCLog::Level::Trace); auto CreateSockOrig = CreateSock; // Mock CreateSock() to create MockSock. diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 352b517890..a6f3a62c71 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -172,18 +172,18 @@ BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup) { LogInstance().EnableCategory(BCLog::LogFlags::ALL); - LogInstance().SetLogLevel(BCLog::Level::Info); + 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::Debug, "foo2: %s. This log level is lower than the global one.\n", "bar2"); + 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 lower than the category-specific one.\n", "bar6"); + 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 = { @@ -220,7 +220,7 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup) ResetLogger(); ArgsManager args; args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); - const char* argv_test[] = {"bitcoind", "-loglevel=net:debug"}; + const char* argv_test[] = {"bitcoind", "-loglevel=net:trace"}; std::string err; BOOST_REQUIRE(args.ParseParameters(2, argv_test, err)); init::SetLoggingLevel(args); @@ -229,7 +229,7 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup) 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::Debug); + BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace); } // Set both global log level and category-specific log level @@ -237,7 +237,7 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup) ResetLogger(); ArgsManager args; args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); - const char* argv_test[] = {"bitcoind", "-loglevel=debug", "-loglevel=net:debug", "-loglevel=http:info"}; + const char* argv_test[] = {"bitcoind", "-loglevel=debug", "-loglevel=net:trace", "-loglevel=http:info"}; std::string err; BOOST_REQUIRE(args.ParseParameters(4, argv_test, err)); init::SetLoggingLevel(args); @@ -248,7 +248,7 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup) 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::Debug); + 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()); diff --git a/src/test/util/setup_common.cpp b/src/test/util/setup_common.cpp index 872310f1ca..e8e96b9051 100644 --- a/src/test/util/setup_common.cpp +++ b/src/test/util/setup_common.cpp @@ -108,7 +108,7 @@ BasicTestingSetup::BasicTestingSetup(const std::string& chainName, const std::ve "-logsourcelocations", "-logtimemicros", "-logthreadnames", - "-loglevel=debug", + "-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 e28d458f69..e35cae006f 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -119,7 +119,7 @@ class TestNode(): if self.version_is_at_least(219900): self.args.append("-logsourcelocations") if self.version_is_at_least(239000): - self.args.append("-loglevel=debug") + self.args.append("-loglevel=trace") self.cli = TestNodeCLI(bitcoin_cli, self.datadir) self.use_cli = use_cli From 1abaa31aa3d833caf2290d6c90f57f7f79d146c0 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Thu, 18 Aug 2022 15:05:55 +0200 Subject: [PATCH 11/12] Update -debug and -debugexclude help docs for severity level logging --- src/init/common.cpp | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/init/common.cpp b/src/init/common.cpp index 3261c18e5a..f2d2c5640a 100644 --- a/src/init/common.cpp +++ b/src/init/common.cpp @@ -24,10 +24,10 @@ namespace init { 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); From 958048057087e6562b474f9028316c00ec03c2e4 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Sat, 20 Aug 2022 11:09:09 +0200 Subject: [PATCH 12/12] Update debug logging section in the developer notes --- doc/developer-notes.md | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/doc/developer-notes.md b/doc/developer-notes.md index 1aa4e4d690..abd6c7bb59 100644 --- a/doc/developer-notes.md +++ b/doc/developer-notes.md @@ -386,8 +386,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 bitcoind is running with the `logging` +RPC. For instance, launching bitcoind 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.