From f7ce5ac08c669ac763e275bb7c82dcfb2b1b6c33 Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Tue, 22 Aug 2023 13:23:38 +1000 Subject: [PATCH] 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',