diff --git a/src/logging.cpp b/src/logging.cpp index a5e5fdb4cd291..f1a86f0dcec1d 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 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 ae8cad906c96a..421c3395c2c27 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 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 -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/net.cpp b/src/net.cpp index 676037a357dc1..918249c8131b1 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -430,7 +430,7 @@ static CAddress GetBindAddress(SOCKET sock) if (!getsockname(sock, (struct sockaddr*)&sockaddr_bind, &sockaddr_bind_len)) { addr_bind.SetSockAddr((const struct sockaddr*)&sockaddr_bind); } else { - LogPrint(BCLog::NET, "Warning: getsockname failed\n"); + LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "getsockname failed\n"); } } return addr_bind; @@ -454,9 +454,9 @@ CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCo } /// debug print - LogPrint(BCLog::NET, "trying connection %s lastseen=%.1fhrs\n", - pszDest ? pszDest : addrConnect.ToString(), - pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0); + LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "trying connection %s lastseen=%.1fhrs\n", + pszDest ? pszDest : addrConnect.ToString(), + pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime) / 3600.0); // Resolve const uint16_t default_port{pszDest != nullptr ? Params().GetDefaultPort(pszDest) : @@ -1140,7 +1140,7 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket) { } if (!addr.SetSockAddr((const struct sockaddr*)&sockaddr)) { - LogPrintf("Warning: Unknown socket family\n"); + LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "Unknown socket family\n"); } else { addr = CAddress{MaybeFlipIPv6toCJDNS(addr), NODE_NONE}; } @@ -2397,15 +2397,15 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError, socklen_t len = sizeof(sockaddr); if (!addrBind.GetSockAddr((struct sockaddr*)&sockaddr, &len)) { - strError = strprintf(Untranslated("Error: Bind address family for %s not supported"), addrBind.ToString()); - LogPrintf("%s\n", strError.original); + strError = strprintf(Untranslated("Bind address family for %s not supported"), addrBind.ToString()); + LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); return false; } std::unique_ptr sock = CreateSock(addrBind); if (!sock) { - strError = strprintf(Untranslated("Error: Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError())); - LogPrintf("%s\n", strError.original); + strError = strprintf(Untranslated("Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError())); + LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); return false; } @@ -2441,7 +2441,7 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError, strError = strprintf(_("Unable to bind to %s on this computer. %s is probably already running."), addrBind.ToString(), PACKAGE_NAME); else strError = strprintf(_("Unable to bind to %s on this computer (bind returned error %s)"), addrBind.ToString(), NetworkErrorString(nErr)); - LogPrintf("%s\n", strError.original); + LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); return false; } LogPrintf("Bound to %s\n", addrBind.ToString()); @@ -2449,8 +2449,8 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError, // Listen for incoming connections if (listen(sock->Get(), SOMAXCONN) == SOCKET_ERROR) { - strError = strprintf(_("Error: Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError())); - LogPrintf("%s\n", strError.original); + strError = strprintf(_("Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError())); + LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); return false; } diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index cbfb6c67c3e37..1f09a079872cf 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -5,13 +5,55 @@ #include #include #include +#include #include +#include +#include +#include +#include #include BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup) +struct LogSetup : public BasicTestingSetup { + fs::path prev_log_path; + fs::path tmp_log_path; + bool prev_reopen_file; + bool prev_print_to_file; + bool prev_log_timestamps; + bool prev_log_threadnames; + bool prev_log_sourcelocations; + + LogSetup() : prev_log_path{LogInstance().m_file_path}, + tmp_log_path{m_args.GetDataDirBase() / "tmp_debug.log"}, + prev_reopen_file{LogInstance().m_reopen_file}, + prev_print_to_file{LogInstance().m_print_to_file}, + prev_log_timestamps{LogInstance().m_log_timestamps}, + prev_log_threadnames{LogInstance().m_log_threadnames}, + prev_log_sourcelocations{LogInstance().m_log_sourcelocations} + { + LogInstance().m_file_path = tmp_log_path; + LogInstance().m_reopen_file = true; + LogInstance().m_print_to_file = true; + LogInstance().m_log_timestamps = false; + LogInstance().m_log_threadnames = false; + LogInstance().m_log_sourcelocations = true; + } + + ~LogSetup() + { + LogInstance().m_file_path = prev_log_path; + LogPrintf("Sentinel log to reopen log file\n"); + LogInstance().m_print_to_file = prev_print_to_file; + LogInstance().m_reopen_file = prev_reopen_file; + LogInstance().m_log_timestamps = prev_log_timestamps; + LogInstance().m_log_threadnames = prev_log_threadnames; + LogInstance().m_log_sourcelocations = prev_log_sourcelocations; + } +}; + BOOST_AUTO_TEST_CASE(logging_timer) { SetMockTime(1); @@ -30,4 +72,82 @@ BOOST_AUTO_TEST_CASE(logging_timer) BOOST_CHECK_EQUAL(sec_timer.LogMsg("test secs"), "tests: test secs (1.00s)"); } +BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) +{ + LogPrintf_("fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug, "foo1: %s", "bar1\n"); + LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::None, "foo2: %s", "bar2\n"); + LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo3: %s", "bar3\n"); + LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::NONE, BCLog::Level::None, "foo4: %s", "bar4\n"); + std::ifstream file{tmp_log_path}; + std::vector log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + std::vector expected = { + "[src1:1] [fn1] [net:debug] foo1: bar1", + "[src2:2] [fn2] [net] foo2: bar2", + "[src3:3] [fn3] [debug] foo3: bar3", + "[src4:4] [fn4] foo4: bar4", + }; + BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); +} + +BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) +{ + // Prevent tests from failing when the line number of the following log calls changes. + LogInstance().m_log_sourcelocations = false; + + LogPrintf("foo5: %s\n", "bar5"); + LogPrint(BCLog::NET, "foo6: %s\n", "bar6"); + LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "foo7: %s\n", "bar7"); + LogPrintLevel(BCLog::Level::Info, BCLog::NET, "foo8: %s\n", "bar8"); + LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "foo9: %s\n", "bar9"); + LogPrintLevel(BCLog::Level::Error, BCLog::NET, "foo10: %s\n", "bar10"); + std::ifstream file{tmp_log_path}; + std::vector log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + std::vector expected = { + "foo5: bar5", + "[net] foo6: bar6", + "[net:debug] foo7: bar7", + "[net:info] foo8: bar8", + "[net:warning] foo9: bar9", + "[net:error] foo10: bar10"}; + BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); +} + +BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup) +{ + // Prevent tests from failing when the line number of the following log calls changes. + LogInstance().m_log_sourcelocations = false; + LogInstance().EnableCategory(BCLog::LogFlags::ALL); + const auto concated_categery_names = LogInstance().LogCategoriesString(); + std::vector> expected_category_names; + const auto category_names = SplitString(concated_categery_names, ','); + for (const auto& category_name : category_names) { + BCLog::LogFlags category = BCLog::NONE; + const auto trimmed_category_name = TrimString(category_name); + BOOST_TEST(GetLogCategory(category, trimmed_category_name)); + expected_category_names.emplace_back(category, trimmed_category_name); + } + + std::vector expected; + for (const auto& [category, name] : expected_category_names) { + LogPrint(category, "foo: %s\n", "bar"); + std::string expected_log = "["; + expected_log += name; + expected_log += "] foo: bar"; + expected.push_back(expected_log); + } + + std::ifstream file{tmp_log_path}; + std::vector log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); +} + BOOST_AUTO_TEST_SUITE_END()