From c5c76dc615677d226c9f6b3f2b66d833315d40da Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Tue, 22 Aug 2023 13:59:32 +1000 Subject: [PATCH 1/8] logging: refactor: pull prefix code out --- src/logging.cpp | 24 ++++++++++++++++-------- src/logging.h | 4 +++- src/test/logging_tests.cpp | 2 ++ 3 files changed, 21 insertions(+), 9 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index 08bfa1f7a49..c4bd221e040 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -202,7 +202,7 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) return false; } -std::string BCLog::Logger::LogLevelToStr(BCLog::Level level) const +std::string BCLog::Logger::LogLevelToStr(BCLog::Level level) { switch (level) { case BCLog::Level::Trace: @@ -341,7 +341,7 @@ static constexpr std::array LogLevelsList() 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); }); + return Join(std::vector{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); }); } std::string BCLog::Logger::LogTimestampStr(const std::string& str) @@ -392,12 +392,9 @@ namespace BCLog { } } // namespace BCLog -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) +std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const { - StdLockGuard scoped_lock(m_cs); - std::string str_prefixed = LogEscapeMessage(str); - - if ((category != LogFlags::NONE || level != Level::None) && m_started_new_line) { + if (category != LogFlags::NONE || level != Level::None) { std::string s{"["}; if (category != LogFlags::NONE) { @@ -414,7 +411,18 @@ void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& loggi } s += "] "; - str_prefixed.insert(0, s); + return s; + } + return {}; +} + +void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level) +{ + StdLockGuard scoped_lock(m_cs); + std::string str_prefixed = LogEscapeMessage(str); + + if (m_started_new_line) { + str_prefixed.insert(0, GetLogPrefix(category, level)); } if (m_log_sourcelocations && m_started_new_line) { diff --git a/src/logging.h b/src/logging.h index f7380d89283..bb4a3e2ca33 100644 --- a/src/logging.h +++ b/src/logging.h @@ -124,6 +124,8 @@ namespace BCLog { fs::path m_file_path; std::atomic m_reopen_file{false}; + std::string GetLogPrefix(LogFlags category, Level level) const; + /** Send a string to the log output */ 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); @@ -194,7 +196,7 @@ namespace BCLog { std::string LogLevelsString() const; //! Returns the string representation of a log level. - std::string LogLevelToStr(BCLog::Level level) const; + static std::string LogLevelToStr(BCLog::Level level); bool DefaultShrinkDebugFile() const; }; diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index e448805e692..2caabd12c78 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -87,6 +87,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::None, "foo2: %s\n", "bar2"); LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo3: %s\n", "bar3"); LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::NONE, BCLog::Level::None, "foo4: %s\n", "bar4"); + LogPrintf_("fn5", "src5", 5, BCLog::LogFlags::NONE, BCLog::Level::Info, "foo5: %s\n", "bar5"); std::ifstream file{tmp_log_path}; std::vector log_lines; for (std::string log; std::getline(file, log);) { @@ -97,6 +98,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) "[src2:2] [fn2] [net] foo2: bar2", "[src3:3] [fn3] [debug] foo3: bar3", "[src4:4] [fn4] foo4: bar4", + "[src5:5] [fn5] [info] foo5: bar5", }; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } From dfe98b6874da04e45f68d17575c1e8a5431ca9bc Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Tue, 22 Aug 2023 14:17:53 +1000 Subject: [PATCH 2/8] logging: make [cat:debug] and [info] implicit --- src/logging.cpp | 33 ++++++++++++++++++--------------- src/test/logging_tests.cpp | 6 +++--- 2 files changed, 21 insertions(+), 18 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index c4bd221e040..b23a6f96eba 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -394,26 +394,29 @@ namespace BCLog { std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const { - if (category != LogFlags::NONE || level != Level::None) { - std::string s{"["}; + const bool has_category{category != LogFlags::NONE}; - if (category != LogFlags::NONE) { - s += LogCategoryToStr(category); - } + if (!has_category && level == Level::None) return {}; - if (category != LogFlags::NONE && level != Level::None) { - // Only add separator if both flag and level are not NONE - s += ":"; - } + // If there is no category, Info is implied + if (!has_category && level == Level::Info) return {}; - if (level != Level::None) { - s += LogLevelToStr(level); - } + std::string s{"["}; + if (has_category) { + s += LogCategoryToStr(category); - s += "] "; - return s; + // If there is a category, Debug is implied + if (level == Level::Debug) level = Level::None; } - return {}; + + if (level != Level::None) { + // Only add separator if we have a category + if (has_category) s += ":"; + s += Logger::LogLevelToStr(level); + } + + s += "] "; + return s; } 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) diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 2caabd12c78..ad3664b2bbd 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -94,11 +94,11 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) log_lines.push_back(log); } std::vector expected = { - "[src1:1] [fn1] [net:debug] foo1: bar1", + "[src1:1] [fn1] [net] foo1: bar1", "[src2:2] [fn2] [net] foo2: bar2", "[src3:3] [fn3] [debug] foo3: bar3", "[src4:4] [fn4] foo4: bar4", - "[src5:5] [fn5] [info] foo5: bar5", + "[src5:5] [fn5] foo5: bar5", }; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } @@ -120,7 +120,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) std::vector expected = { "foo5: bar5", "[net] foo6: bar6", - "[net:debug] foo7: bar7", + "[net] foo7: bar7", "[net:info] foo8: bar8", "[net:warning] foo9: bar9", "[net:error] foo10: bar10", From ab34dc6012351e7b8aab871dd9d2b38ade1cd9bc Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Wed, 23 Aug 2023 10:02:03 +1000 Subject: [PATCH 3/8] logging: Log Info messages unconditionally Previously Info-level logging when a category was specified (via LogPrintLevel) would only print the corresponding log message if `-debug=category` were specified, while Info-level logging without a category would always be printed. Make this more consistent by having Info messages always be logged, whether they include a category or not. --- src/logging.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index b23a6f96eba..d516cd65a51 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -126,9 +126,9 @@ bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const bool BCLog::Logger::WillLogCategoryLevel(BCLog::LogFlags category, BCLog::Level level) const { - // Log messages at Warning and Error level unconditionally, so that + // Log messages at Info, Warning and Error level unconditionally, so that // important troubleshooting information doesn't get lost. - if (level >= BCLog::Level::Warning) return true; + if (level >= BCLog::Level::Info) return true; if (!WillLogCategory(category)) return false; From 667ce3e3297645527b07314e1d5a82275fb25845 Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Tue, 22 Aug 2023 14:38:38 +1000 Subject: [PATCH 4/8] logging: Drop BCLog::Level::None Now that Info-level logging is always logged, there is no further need for the "None" level, so remove it. --- src/logging.cpp | 13 +++---------- src/logging.h | 16 +++++----------- src/test/logging_tests.cpp | 10 ++++------ 3 files changed, 12 insertions(+), 27 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index d516cd65a51..f6cd4049718 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -215,8 +215,6 @@ std::string BCLog::Logger::LogLevelToStr(BCLog::Level level) return "warning"; case BCLog::Level::Error: return "error"; - case BCLog::Level::None: - return ""; } assert(false); } @@ -307,8 +305,6 @@ static std::optional GetLogLevel(const std::string& level_str) 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; } @@ -396,20 +392,17 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l { const bool has_category{category != LogFlags::NONE}; - if (!has_category && level == Level::None) return {}; - // If there is no category, Info is implied if (!has_category && level == Level::Info) return {}; std::string s{"["}; if (has_category) { s += LogCategoryToStr(category); - - // If there is a category, Debug is implied - if (level == Level::Debug) level = Level::None; } - if (level != Level::None) { + if (!has_category || level != Level::Debug) { + // If there is a category, Debug is implied, so don't add the level + // Only add separator if we have a category if (has_category) s += ":"; s += Logger::LogLevelToStr(level); diff --git a/src/logging.h b/src/logging.h index bb4a3e2ca33..b93617f7add 100644 --- a/src/logging.h +++ b/src/logging.h @@ -77,7 +77,6 @@ namespace BCLog { Info, // Default Warning, Error, - None, // Internal use only }; constexpr auto DEFAULT_LOG_LEVEL{Level::Debug}; @@ -236,22 +235,14 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st #define LogPrintLevel_(category, level, ...) LogPrintf_(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) // Log unconditionally. -#define LogPrintf(...) LogPrintLevel_(BCLog::LogFlags::NONE, BCLog::Level::None, __VA_ARGS__) +#define LogPrintf(...) LogPrintLevel_(BCLog::LogFlags::NONE, BCLog::Level::Info, __VA_ARGS__) // Log unconditionally, prefixing the output with the passed category name. -#define LogPrintfCategory(category, ...) LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__) +#define LogPrintfCategory(category, ...) LogPrintLevel_(category, BCLog::Level::Info, __VA_ARGS__) // Use a macro instead of a function for conditional logging to prevent // evaluating arguments when logging for the category is not enabled. -// Log conditionally, prefixing the output with the passed category name. -#define LogPrint(category, ...) \ - do { \ - if (LogAcceptCategory((category), BCLog::Level::Debug)) { \ - LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__); \ - } \ - } while (0) - // Log conditionally, prefixing the output with the passed category name and severity level. #define LogPrintLevel(category, level, ...) \ do { \ @@ -260,6 +251,9 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st } \ } while (0) +// Log conditionally, prefixing the output with the passed category name. +#define LogPrint(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__) + template bool error(const char* fmt, const Args&... args) { diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index ad3664b2bbd..acc52afb456 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -84,10 +84,9 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) { LogInstance().m_log_sourcelocations = true; LogPrintf_("fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug, "foo1: %s\n", "bar1"); - LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::None, "foo2: %s\n", "bar2"); + LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::Info, "foo2: %s\n", "bar2"); LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo3: %s\n", "bar3"); - LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::NONE, BCLog::Level::None, "foo4: %s\n", "bar4"); - LogPrintf_("fn5", "src5", 5, BCLog::LogFlags::NONE, BCLog::Level::Info, "foo5: %s\n", "bar5"); + LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::NONE, BCLog::Level::Info, "foo4: %s\n", "bar4"); std::ifstream file{tmp_log_path}; std::vector log_lines; for (std::string log; std::getline(file, log);) { @@ -95,10 +94,9 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) } std::vector expected = { "[src1:1] [fn1] [net] foo1: bar1", - "[src2:2] [fn2] [net] foo2: bar2", + "[src2:2] [fn2] [net:info] foo2: bar2", "[src3:3] [fn3] [debug] foo3: bar3", "[src4:4] [fn4] foo4: bar4", - "[src5:5] [fn5] foo5: bar5", }; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } @@ -124,7 +122,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) "[net:info] foo8: bar8", "[net:warning] foo9: bar9", "[net:error] foo10: bar10", - "[validation] foo11: bar11", + "[validation:info] foo11: bar11", }; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } From 782bb6a05663ad7a53908e910d0f42b49b881e09 Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Tue, 12 Sep 2023 18:13:25 +1000 Subject: [PATCH 5/8] logging: treat BCLog::ALL like BCLog::NONE --- src/logging.cpp | 4 +++- src/test/logging_tests.cpp | 8 ++++++-- 2 files changed, 9 insertions(+), 3 deletions(-) diff --git a/src/logging.cpp b/src/logging.cpp index f6cd4049718..6004abf9991 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -390,7 +390,9 @@ namespace BCLog { std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const { - const bool has_category{category != LogFlags::NONE}; + if (category == LogFlags::NONE) category = LogFlags::ALL; + + const bool has_category{category != LogFlags::ALL}; // If there is no category, Info is implied if (!has_category && level == Level::Info) return {}; diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index acc52afb456..abc878c5a56 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -85,8 +85,10 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) LogInstance().m_log_sourcelocations = true; LogPrintf_("fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug, "foo1: %s\n", "bar1"); LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::Info, "foo2: %s\n", "bar2"); - LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo3: %s\n", "bar3"); - LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::NONE, BCLog::Level::Info, "foo4: %s\n", "bar4"); + LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::ALL, BCLog::Level::Debug, "foo3: %s\n", "bar3"); + LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::ALL, BCLog::Level::Info, "foo4: %s\n", "bar4"); + LogPrintf_("fn5", "src5", 5, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo5: %s\n", "bar5"); + LogPrintf_("fn6", "src6", 6, BCLog::LogFlags::NONE, BCLog::Level::Info, "foo6: %s\n", "bar6"); std::ifstream file{tmp_log_path}; std::vector log_lines; for (std::string log; std::getline(file, log);) { @@ -97,6 +99,8 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) "[src2:2] [fn2] [net:info] foo2: bar2", "[src3:3] [fn3] [debug] foo3: bar3", "[src4:4] [fn4] foo4: bar4", + "[src5:5] [fn5] [debug] foo5: bar5", + "[src6:6] [fn6] foo6: bar6", }; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } From fbd7642c8e5b70327e019382320f5ef0a651ecc5 Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Tue, 12 Sep 2023 14:27:26 +1000 Subject: [PATCH 6/8] logging: add -loglevelalways=1 option This option tells the logging system to always include a "[cat:level]" prefix, so [net] becomes [net:debug], LogInfo/LogPrint statements will have an [all:info] prefix, and LogWarning and LogError logs will become [all:warning] and [all:error]. This may be easier for automated parsing of logs, particularly if additional prefixes such as thread or source location are enabled. --- src/init/common.cpp | 2 ++ src/logging.cpp | 4 ++-- src/logging.h | 2 ++ 3 files changed, 6 insertions(+), 2 deletions(-) diff --git a/src/init/common.cpp b/src/init/common.cpp index f3f7c696c54..6560258ef50 100644 --- a/src/init/common.cpp +++ b/src/init/common.cpp @@ -40,6 +40,7 @@ void AddLoggingArgs(ArgsManager& argsman) #endif argsman.AddArg("-logsourcelocations", strprintf("Prepend debug output with name of the originating source location (source file, line number and function name) (default: %u)", DEFAULT_LOGSOURCELOCATIONS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); argsman.AddArg("-logtimemicros", strprintf("Add microsecond precision to debug timestamps (default: %u)", DEFAULT_LOGTIMEMICROS), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST); + argsman.AddArg("-loglevelalways", strprintf("Always prepend a category and level (default: %u)", DEFAULT_LOGLEVELALWAYS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); argsman.AddArg("-printtoconsole", "Send trace/debug info to console (default: 1 when no -daemon. To disable logging to file, set -nodebuglogfile)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); argsman.AddArg("-shrinkdebugfile", "Shrink debug.log file on client startup (default: 1 when no -debug)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); } @@ -55,6 +56,7 @@ void SetLoggingOptions(const ArgsManager& args) LogInstance().m_log_threadnames = args.GetBoolArg("-logthreadnames", DEFAULT_LOGTHREADNAMES); #endif LogInstance().m_log_sourcelocations = args.GetBoolArg("-logsourcelocations", DEFAULT_LOGSOURCELOCATIONS); + LogInstance().m_always_print_category_level = args.GetBoolArg("-loglevelalways", DEFAULT_LOGLEVELALWAYS); fLogIPs = args.GetBoolArg("-logips", DEFAULT_LOGIPS); } diff --git a/src/logging.cpp b/src/logging.cpp index 6004abf9991..42f100ded6e 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -392,7 +392,7 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l { if (category == LogFlags::NONE) category = LogFlags::ALL; - const bool has_category{category != LogFlags::ALL}; + const bool has_category{m_always_print_category_level || category != LogFlags::ALL}; // If there is no category, Info is implied if (!has_category && level == Level::Info) return {}; @@ -402,7 +402,7 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l s += LogCategoryToStr(category); } - if (!has_category || level != Level::Debug) { + if (m_always_print_category_level || !has_category || level != Level::Debug) { // If there is a category, Debug is implied, so don't add the level // Only add separator if we have a category diff --git a/src/logging.h b/src/logging.h index b93617f7add..9b56f7af0dd 100644 --- a/src/logging.h +++ b/src/logging.h @@ -25,6 +25,7 @@ static const bool DEFAULT_LOGIPS = false; static const bool DEFAULT_LOGTIMESTAMPS = true; static const bool DEFAULT_LOGTHREADNAMES = false; static const bool DEFAULT_LOGSOURCELOCATIONS = false; +static constexpr bool DEFAULT_LOGLEVELALWAYS = false; extern const char * const DEFAULT_DEBUGLOGFILE; extern bool fLogIPs; @@ -119,6 +120,7 @@ namespace BCLog { bool m_log_time_micros = DEFAULT_LOGTIMEMICROS; bool m_log_threadnames = DEFAULT_LOGTHREADNAMES; bool m_log_sourcelocations = DEFAULT_LOGSOURCELOCATIONS; + bool m_always_print_category_level = DEFAULT_LOGLEVELALWAYS; fs::path m_file_path; std::atomic m_reopen_file{false}; From f7ce5ac08c669ac763e275bb7c82dcfb2b1b6c33 Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Tue, 22 Aug 2023 13:23:38 +1000 Subject: [PATCH 7/8] logging: add LogError, LogWarning, LogInfo, LogDebug, LogTrace These provide simple and clear ways to write the most common logging operations: LogInfo("msg"); LogDebug(BCLog::LogFlags::NET, "msg"); LogError("msg"); LogWarning("msg"); LogTrace(BCLog::LogFlags::NET, "msg"); For cases where the level cannot be hardcoded, LogPrintLevel(category, level, ...) remains available. --- doc/developer-notes.md | 45 ++++++++++++++++++++++++++++++-- src/logging.h | 13 ++++++--- src/test/logging_tests.cpp | 24 ++++++++++++++++- test/lint/lint-format-strings.py | 5 ++++ 4 files changed, 81 insertions(+), 6 deletions(-) diff --git a/doc/developer-notes.md b/doc/developer-notes.md index 80353bcdd26..f94b96a3123 100644 --- a/doc/developer-notes.md +++ b/doc/developer-notes.md @@ -723,6 +723,47 @@ General Bitcoin Core - *Explanation*: If the test suite is to be updated for a change, this has to be done first. +Logging +------- + +The macros `LogInfo`, `LogDebug`, `LogTrace`, `LogWarning` and `LogError` are available for +logging messages. They should be used as follows: + +- `LogDebug(BCLog::CATEGORY, fmt, params...)` is what you want + most of the time, and it should be used for log messages that are + useful for debugging and can reasonably be enabled on a production + system (that has sufficient free storage space). They will be logged + if the program is started with `-debug=category` or `-debug=1`. + Note that `LogPrint(BCLog::CATEGORY, fmt, params...)` is a deprecated + alias for `LogDebug`. + +- `LogInfo(fmt, params...)` should only be used rarely, eg for startup + messages or for infrequent and important events such as a new block tip + being found or a new outbound connection being made. These log messages + are unconditional so care must be taken that they can't be used by an + attacker to fill up storage. Note that `LogPrintf(fmt, params...)` is + a deprecated alias for `LogInfo`. + +- `LogError(fmt, params...)` should be used in place of `LogInfo` for + severe problems that require the node (or a subsystem) to shut down + entirely (eg, insufficient storage space). + +- `LogWarning(fmt, params...)` should be used in place of `LogInfo` for + severe problems that the node admin should address, but are not + severe enough to warrant shutting down the node (eg, system time + appears to be wrong, unknown soft fork appears to have activated). + +- `LogTrace(BCLog::CATEGORY, fmt, params...) should be used in place of + `LogDebug` for log messages that would be unusable on a production + system, eg due to being too noisy in normal use, or too resource + intensive to process. These will be logged if the startup + options `-debug=category -loglevel=category:trace` or `-debug=1 + -loglevel=trace` are selected. + +Note that the format strings and parameters of `LogDebug` and `LogTrace` +are only evaluated if the logging category is enabled, so you must be +careful to avoid side-effects in those expressions. + Wallet ------- @@ -891,7 +932,7 @@ Strings and formatting `wcstoll`, `wcstombs`, `wcstoul`, `wcstoull`, `wcstoumax`, `wcswidth`, `wcsxfrm`, `wctob`, `wctomb`, `wctrans`, `wctype`, `wcwidth`, `wprintf` -- For `strprintf`, `LogPrint`, `LogPrintf` formatting characters don't need size specifiers. +- For `strprintf`, `LogInfo`, `LogDebug`, etc formatting characters don't need size specifiers. - *Rationale*: Bitcoin Core uses tinyformat, which is type safe. Leave them out to avoid confusion. @@ -903,7 +944,7 @@ Strings and formatting - *Rationale*: Although this is guaranteed to be safe starting with C++11, `.data()` communicates the intent better. - - Do not use it when passing strings to `tfm::format`, `strprintf`, `LogPrint[f]`. + - Do not use it when passing strings to `tfm::format`, `strprintf`, `LogInfo`, `LogDebug`, etc. - *Rationale*: This is redundant. Tinyformat handles strings. diff --git a/src/logging.h b/src/logging.h index 9b56f7af0dd..525e0aec6d7 100644 --- a/src/logging.h +++ b/src/logging.h @@ -237,9 +237,12 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st #define LogPrintLevel_(category, level, ...) LogPrintf_(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) // Log unconditionally. -#define LogPrintf(...) LogPrintLevel_(BCLog::LogFlags::NONE, BCLog::Level::Info, __VA_ARGS__) +#define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, __VA_ARGS__) +#define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning, __VA_ARGS__) +#define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error, __VA_ARGS__) -// Log unconditionally, prefixing the output with the passed category name. +// Deprecated unconditional logging. +#define LogPrintf(...) LogInfo(__VA_ARGS__) #define LogPrintfCategory(category, ...) LogPrintLevel_(category, BCLog::Level::Info, __VA_ARGS__) // Use a macro instead of a function for conditional logging to prevent @@ -254,7 +257,11 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st } while (0) // Log conditionally, prefixing the output with the passed category name. -#define LogPrint(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__) +#define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__) +#define LogTrace(category, ...) LogPrintLevel(category, BCLog::Level::Trace, __VA_ARGS__) + +// Deprecated conditional logging +#define LogPrint(category, ...) LogDebug(category, __VA_ARGS__) template bool error(const char* fmt, const Args&... args) diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index abc878c5a56..88e3ec94b7c 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -105,10 +105,11 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } -BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) +BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacrosDeprecated, LogSetup) { LogPrintf("foo5: %s\n", "bar5"); LogPrint(BCLog::NET, "foo6: %s\n", "bar6"); + LogPrintLevel(BCLog::NET, BCLog::Level::Trace, "foo4: %s\n", "bar4"); // not logged 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"); @@ -131,6 +132,27 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } +BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) +{ + LogTrace(BCLog::NET, "foo6: %s\n", "bar6"); // not logged + LogDebug(BCLog::NET, "foo7: %s\n", "bar7"); + LogInfo("foo8: %s\n", "bar8"); + LogWarning("foo9: %s\n", "bar9"); + LogError("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 = { + "[net] foo7: bar7", + "foo8: bar8", + "[warning] foo9: bar9", + "[error] foo10: bar10", + }; + BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); +} + BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup) { LogInstance().EnableCategory(BCLog::LogFlags::ALL); diff --git a/test/lint/lint-format-strings.py b/test/lint/lint-format-strings.py index 5ac5840ecff..09d858e131d 100755 --- a/test/lint/lint-format-strings.py +++ b/test/lint/lint-format-strings.py @@ -20,6 +20,11 @@ FUNCTION_NAMES_AND_NUMBER_OF_LEADING_ARGUMENTS = [ 'fprintf,1', 'tfm::format,1', # Assuming tfm::::format(std::ostream&, ... 'LogConnectFailure,1', + 'LogError,0', + 'LogWarning,0', + 'LogInfo,0', + 'LogDebug,1', + 'LogTrace,1', 'LogPrint,1', 'LogPrintf,0', 'LogPrintfCategory,1', From e60fc7d5d34f23cccbff6e4f5f3d716fa8dad50c Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Tue, 22 Aug 2023 13:40:11 +1000 Subject: [PATCH 8/8] logging: Replace uses of LogPrintfCategory Replace LogPrintfCategory with alternative unconditional log statements. --- src/httpserver.cpp | 5 ++--- src/init.cpp | 2 +- src/net_processing.cpp | 2 +- src/torcontrol.cpp | 2 +- 4 files changed, 5 insertions(+), 6 deletions(-) diff --git a/src/httpserver.cpp b/src/httpserver.cpp index a83f4421d75..70bd01c9509 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -412,7 +412,7 @@ bool InitHTTPServer() LogPrint(BCLog::HTTP, "Initialized HTTP server\n"); int workQueueDepth = std::max((long)gArgs.GetIntArg("-rpcworkqueue", DEFAULT_HTTP_WORKQUEUE), 1L); - LogPrintfCategory(BCLog::HTTP, "creating work queue of depth %d\n", workQueueDepth); + LogDebug(BCLog::HTTP, "creating work queue of depth %d\n", workQueueDepth); g_work_queue = std::make_unique>(workQueueDepth); // transfer ownership to eventBase/HTTP via .release() @@ -434,9 +434,8 @@ static std::vector g_thread_http_workers; void StartHTTPServer() { - LogPrint(BCLog::HTTP, "Starting HTTP server\n"); int rpcThreads = std::max((long)gArgs.GetIntArg("-rpcthreads", DEFAULT_HTTP_THREADS), 1L); - LogPrintfCategory(BCLog::HTTP, "starting %d worker threads\n", rpcThreads); + LogInfo("Starting HTTP server with %d worker threads\n", rpcThreads); g_thread_http = std::thread(ThreadHTTP, eventBase); for (int i = 0; i < rpcThreads; i++) { diff --git a/src/init.cpp b/src/init.cpp index f0847bd4f75..2431f913cef 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1503,7 +1503,7 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info) if (status == node::ChainstateLoadStatus::SUCCESS) { uiInterface.InitMessage(_("Verifying blocks…").translated); if (chainman.m_blockman.m_have_pruned && options.check_blocks > MIN_BLOCKS_TO_KEEP) { - LogPrintfCategory(BCLog::PRUNE, "pruned datadir may not have more than %d blocks; only checking available blocks\n", + LogWarning("pruned datadir may not have more than %d blocks; only checking available blocks\n", MIN_BLOCKS_TO_KEEP); } std::tie(status, error) = catch_exceptions([&]{ return VerifyLoadedChainstate(chainman, options);}); diff --git a/src/net_processing.cpp b/src/net_processing.cpp index 6b415b3a1ea..cc54b9e92bb 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -4326,7 +4326,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, } if (received_new_header) { - LogPrintfCategory(BCLog::NET, "Saw new cmpctblock header hash=%s peer=%d\n", + LogInfo("Saw new cmpctblock header hash=%s peer=%d\n", blockhash.ToString(), pfrom.GetId()); } diff --git a/src/torcontrol.cpp b/src/torcontrol.cpp index 9cf976a7006..7d8be790d18 100644 --- a/src/torcontrol.cpp +++ b/src/torcontrol.cpp @@ -433,7 +433,7 @@ void TorController::add_onion_cb(TorControlConnection& _conn, const TorControlRe return; } service = LookupNumeric(std::string(service_id+".onion"), Params().GetDefaultPort()); - LogPrintfCategory(BCLog::TOR, "Got service ID %s, advertising service %s\n", service_id, service.ToStringAddrPort()); + LogInfo("Got tor service ID %s, advertising service %s\n", service_id, service.ToStringAddrPort()); if (WriteBinaryFile(GetPrivateKeyFile(), private_key)) { LogPrint(BCLog::TOR, "Cached service private key to %s\n", fs::PathToString(GetPrivateKeyFile())); } else {