diff --git a/src/logging.cpp b/src/logging.cpp index 5ac21e344b..68516b20f9 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -188,7 +188,7 @@ const CLogCategoryDesc LogCategories[] = bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) { - if (str == "") { + if (str.empty()) { flag = BCLog::ALL; return true; } @@ -201,6 +201,123 @@ 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::BENCHMARK: + 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::RANDOM: + 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::BLOCKSTORE: + return "blockstorage"; + case BCLog::LogFlags::TXRECONCILIATION: + return "txreconciliation"; + /* Start Dash */ + case BCLog::LogFlags::CHAINLOCKS: + return "chainlocks"; + case BCLog::LogFlags::GOBJECT: + return "gobject"; + case BCLog::LogFlags::INSTANTSEND: + return "instantsend"; + case BCLog::LogFlags::LLMQ: + return "llmq"; + case BCLog::LogFlags::LLMQ_DKG: + return "llmq-dkg"; + case BCLog::LogFlags::LLMQ_SIGS: + return "llmq-sigs"; + case BCLog::LogFlags::MNPAYMENTS: + return "mnpayments"; + case BCLog::LogFlags::MNSYNC: + return "mnsync"; + case BCLog::LogFlags::COINJOIN: + return "coinjoin"; + case BCLog::LogFlags::SPORK: + return "spork"; + case BCLog::LogFlags::NETCONN: + return "netconn"; + case BCLog::LogFlags::CREDITPOOL: + return "creditpool"; + case BCLog::LogFlags::EHF: + return "ehf"; + case BCLog::LogFlags::DASH: + return "dash"; + case BCLog::LogFlags::NET_NETCONN: + return "net|netconn"; + /* End Dash */ + case BCLog::LogFlags::ALL: + return "all"; + } + assert(false); +} + std::vector BCLog::Logger::LogCategoriesList(bool enabled_only) const { // Sort log categories by alphabetical order. @@ -268,11 +385,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 c88bae4957..3e085db5fb 100644 --- a/src/logging.h +++ b/src/logging.h @@ -91,6 +91,13 @@ namespace BCLog { ALL = ~(uint64_t)0, }; + enum class Level { + Debug = 0, + None = 1, + Info = 2, + Warning = 3, + Error = 4, + }; class Logger { @@ -130,7 +137,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 @@ -211,7 +218,7 @@ std::string SafeStringFormat(const std::string& fmt, const Args&... args) // 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; @@ -221,19 +228,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 3b54c7422c..49fa69941d 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -481,7 +481,7 @@ static CAddress GetBindAddress(const Sock& sock) if (!sock.GetSockName((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; @@ -509,14 +509,14 @@ CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCo /// debug print if (fLogIPs) { - LogPrint(BCLog::NET, "trying %s connection %s lastseen=%.1fhrs\n", - use_v2transport ? "v2" : "v1", - pszDest ? pszDest : addrConnect.ToStringAddrPort(), - pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0); + LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "trying %s connection %s lastseen=%.1fhrs\n", + use_v2transport ? "v2" : "v1", + pszDest ? pszDest : addrConnect.ToStringAddrPort(), + pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0); } else { - LogPrint(BCLog::NET, "trying %s connection lastseen=%.1fhrs\n", - use_v2transport ? "v2" : "v1", - pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0); + LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "trying %s connection lastseen=%.1fhrs\n", + use_v2transport ? "v2" : "v1", + pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0); } // Resolve @@ -1963,7 +1963,7 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket, CMasternodeSy } 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}; } @@ -4068,14 +4068,14 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError, if (!addrBind.GetSockAddr((struct sockaddr*)&sockaddr, &len)) { strError = strprintf(Untranslated("Error: Bind address family for %s not supported"), addrBind.ToStringAddrPort()); - LogPrintf("%s\n", strError.original); + 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; } @@ -4110,7 +4110,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.ToStringAddrPort(), PACKAGE_NAME); else strError = strprintf(_("Unable to bind to %s on this computer (bind returned error %s)"), addrBind.ToStringAddrPort(), 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.ToStringAddrPort()); @@ -4118,8 +4118,8 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError, // Listen for incoming connections if (sock->Listen(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 84ddbc50c6..2ce9060074 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()