diff options
| -rw-r--r-- | src/logging.cpp | 109 | ||||
| -rw-r--r-- | src/logging.h | 35 | ||||
| -rw-r--r-- | src/test/logging_tests.cpp | 120 |
3 files changed, 253 insertions, 11 deletions
diff --git a/src/logging.cpp b/src/logging.cpp index a5e5fdb4cd..f1a86f0dce 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -171,7 +171,7 @@ const CLogCategoryDesc LogCategories[] = bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) { - if (str == "") { + if (str.empty()) { flag = BCLog::ALL; return true; } @@ -184,6 +184,91 @@ 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::BENCH: + 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::RAND: + 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::UTIL: + return "util"; + case BCLog::LogFlags::BLOCKSTORE: + return "blockstorage"; + case BCLog::LogFlags::ALL: + return "all"; + } + assert(false); +} + std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const { // Sort log categories by alphabetical order. @@ -249,11 +334,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 ae8cad906c..421c3395c2 100644 --- a/src/logging.h +++ b/src/logging.h @@ -67,6 +67,13 @@ namespace BCLog { BLOCKSTORE = (1 << 26), ALL = ~(uint32_t)0, }; + enum class Level { + Debug = 0, + None = 1, + Info = 2, + Warning = 3, + Error = 4, + }; class Logger { @@ -105,7 +112,7 @@ namespace BCLog { std::atomic<bool> 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 @@ -173,7 +180,7 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str); // peer can fill up a user's disk with debug.log entries. template <typename... Args> -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; @@ -183,19 +190,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/test/logging_tests.cpp b/src/test/logging_tests.cpp index cbfb6c67c3..1f09a07987 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -5,13 +5,55 @@ #include <logging.h> #include <logging/timer.h> #include <test/util/setup_common.h> +#include <util/string.h> #include <chrono> +#include <fstream> +#include <iostream> +#include <utility> +#include <vector> #include <boost/test/unit_test.hpp> 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<std::string> log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + std::vector<std::string> 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<std::string> log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + std::vector<std::string> 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<std::pair<BCLog::LogFlags, std::string>> 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<std::string> 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<std::string> 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() |