From bd971bffb02c7b06aac9a479f7e5ed8f71de2bec Mon Sep 17 00:00:00 2001 From: laanwj <126646+laanwj@users.noreply.github.com> Date: Tue, 24 May 2022 19:52:49 +0200 Subject: [PATCH 1/4] logging: Unconditionally log levels >= WARN Messages with level `WARN` or higher should be logged even when the category is not provided with `-debug=`, to make sure important warnings are not lost. --- src/dbwrapper.cpp | 4 ++-- src/logging.h | 13 +++++++++---- src/timedata.cpp | 2 +- src/wallet/coinselection.cpp | 2 +- 4 files changed, 13 insertions(+), 8 deletions(-) diff --git a/src/dbwrapper.cpp b/src/dbwrapper.cpp index 50a601c6843..83b59dc56d9 100644 --- a/src/dbwrapper.cpp +++ b/src/dbwrapper.cpp @@ -19,7 +19,7 @@ public: // This code is adapted from posix_logger.h, which is why it is using vsprintf. // Please do not do this in normal code void Logv(const char * format, va_list ap) override { - if (!LogAcceptCategory(BCLog::LEVELDB)) { + if (!LogAcceptCategory(BCLog::LEVELDB, BCLog::Level::Debug)) { return; } char buffer[500]; @@ -186,7 +186,7 @@ CDBWrapper::~CDBWrapper() bool CDBWrapper::WriteBatch(CDBBatch& batch, bool fSync) { - const bool log_memory = LogAcceptCategory(BCLog::LEVELDB); + const bool log_memory = LogAcceptCategory(BCLog::LEVELDB, BCLog::Level::Debug); double mem_before = 0; if (log_memory) { mem_before = DynamicMemoryUsage() / 1024.0 / 1024; diff --git a/src/logging.h b/src/logging.h index 421c3395c2c..8b4459400bb 100644 --- a/src/logging.h +++ b/src/logging.h @@ -166,9 +166,14 @@ namespace BCLog { BCLog::Logger& LogInstance(); -/** Return true if log accepts specified category */ -static inline bool LogAcceptCategory(BCLog::LogFlags category) +/** Return true if log accepts specified category, at the specified level. */ +static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level level) { + // Log messages at Warning and Error level unconditionally, so that + // important troubleshooting information doesn't get lost. + if (level >= BCLog::Level::Warning) { + return true; + } return LogInstance().WillLogCategory(category); } @@ -203,14 +208,14 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st // evaluating arguments when logging for the category is not enabled. #define LogPrint(category, ...) \ do { \ - if (LogAcceptCategory((category))) { \ + if (LogAcceptCategory((category), BCLog::Level::Debug)) { \ LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__); \ } \ } while (0) #define LogPrintLevel(level, category, ...) \ do { \ - if (LogAcceptCategory((category))) { \ + if (LogAcceptCategory((category), (level))) { \ LogPrintLevel_(category, level, __VA_ARGS__); \ } \ } while (0) diff --git a/src/timedata.cpp b/src/timedata.cpp index 06659871e5e..7faf22aba0d 100644 --- a/src/timedata.cpp +++ b/src/timedata.cpp @@ -99,7 +99,7 @@ void AddTimeData(const CNetAddr& ip, int64_t nOffsetSample) } } - if (LogAcceptCategory(BCLog::NET)) { + if (LogAcceptCategory(BCLog::NET, BCLog::Level::Debug)) { std::string log_message{"time data samples: "}; for (const int64_t n : vSorted) { log_message += strprintf("%+d ", n); diff --git a/src/wallet/coinselection.cpp b/src/wallet/coinselection.cpp index e710787a263..07df8d9fc8a 100644 --- a/src/wallet/coinselection.cpp +++ b/src/wallet/coinselection.cpp @@ -307,7 +307,7 @@ std::optional KnapsackSolver(std::vector& groups, } } - if (LogAcceptCategory(BCLog::SELECTCOINS)) { + if (LogAcceptCategory(BCLog::SELECTCOINS, BCLog::Level::Debug)) { std::string log_message{"Coin selection best subset: "}; for (unsigned int i = 0; i < applicable_groups.size(); i++) { if (vfBest[i]) { From 18ec120bb9e1fc9d27d2419da4c580bd3cde7e86 Mon Sep 17 00:00:00 2001 From: laanwj <126646+laanwj@users.noreply.github.com> Date: Tue, 24 May 2022 19:54:47 +0200 Subject: [PATCH 2/4] http: Use severity-based logging for messages from libevent Map libevent's severity to our own severity level for logging. --- src/httpserver.cpp | 20 ++++++++++++++++---- 1 file changed, 16 insertions(+), 4 deletions(-) diff --git a/src/httpserver.cpp b/src/httpserver.cpp index b9a1fc672a3..c463b1b8ab9 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -344,10 +344,22 @@ static void HTTPWorkQueueRun(WorkQueue* queue, int worker_num) /** libevent event log callback */ static void libevent_log_cb(int severity, const char *msg) { - if (severity >= EVENT_LOG_WARN) // Log warn messages and higher without debug category - LogPrintf("libevent: %s\n", msg); - else - LogPrint(BCLog::LIBEVENT, "libevent: %s\n", msg); + BCLog::Level level; + switch (severity) { + case EVENT_LOG_DEBUG: + level = BCLog::Level::Debug; + break; + case EVENT_LOG_MSG: + level = BCLog::Level::Info; + break; + case EVENT_LOG_WARN: + level = BCLog::Level::Warning; + break; + default: // EVENT_LOG_ERR and others are mapped to error + level = BCLog::Level::Error; + break; + } + LogPrintLevel(level, BCLog::LIBEVENT, "%s\n", msg); } bool InitHTTPServer() From ce920713bf0810614c2c0c994511b50d4f660bce Mon Sep 17 00:00:00 2001 From: laanwj <126646+laanwj@users.noreply.github.com> Date: Tue, 24 May 2022 19:55:56 +0200 Subject: [PATCH 3/4] leveldb: Log messages from leveldb with category and debug level --- src/dbwrapper.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/dbwrapper.cpp b/src/dbwrapper.cpp index 83b59dc56d9..89146736ac4 100644 --- a/src/dbwrapper.cpp +++ b/src/dbwrapper.cpp @@ -63,7 +63,7 @@ public: assert(p <= limit); base[std::min(bufsize - 1, (int)(p - base))] = '\0'; - LogPrintf("leveldb: %s", base); /* Continued */ + LogPrintLevel(BCLog::Level::Debug, BCLog::LEVELDB, "%s", base); /* Continued */ if (base != buffer) { delete[] base; } From c4e77177276ea2b79c4675cb2678ee2cc757b743 Mon Sep 17 00:00:00 2001 From: laanwj <126646+laanwj@users.noreply.github.com> Date: Wed, 25 May 2022 11:31:58 +0200 Subject: [PATCH 4/4] refactor: Change LogPrintLevel order to category, severity This is more consistent with the other functions, as well as with the logging output itself. If we want to make this change, we should do it before it's all over the place. --- src/dbwrapper.cpp | 2 +- src/httpserver.cpp | 2 +- src/logging.h | 2 +- src/net.cpp | 14 +++++++------- src/test/logging_tests.cpp | 8 ++++---- 5 files changed, 14 insertions(+), 14 deletions(-) diff --git a/src/dbwrapper.cpp b/src/dbwrapper.cpp index 89146736ac4..a2f1f327808 100644 --- a/src/dbwrapper.cpp +++ b/src/dbwrapper.cpp @@ -63,7 +63,7 @@ public: assert(p <= limit); base[std::min(bufsize - 1, (int)(p - base))] = '\0'; - LogPrintLevel(BCLog::Level::Debug, BCLog::LEVELDB, "%s", base); /* Continued */ + LogPrintLevel(BCLog::LEVELDB, BCLog::Level::Debug, "%s", base); /* Continued */ if (base != buffer) { delete[] base; } diff --git a/src/httpserver.cpp b/src/httpserver.cpp index c463b1b8ab9..44937dc5239 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -359,7 +359,7 @@ static void libevent_log_cb(int severity, const char *msg) level = BCLog::Level::Error; break; } - LogPrintLevel(level, BCLog::LIBEVENT, "%s\n", msg); + LogPrintLevel(BCLog::LIBEVENT, level, "%s\n", msg); } bool InitHTTPServer() diff --git a/src/logging.h b/src/logging.h index 8b4459400bb..8a896b6b335 100644 --- a/src/logging.h +++ b/src/logging.h @@ -213,7 +213,7 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st } \ } while (0) -#define LogPrintLevel(level, category, ...) \ +#define LogPrintLevel(category, level, ...) \ do { \ if (LogAcceptCategory((category), (level))) { \ LogPrintLevel_(category, level, __VA_ARGS__); \ diff --git a/src/net.cpp b/src/net.cpp index 918249c8131..a28937f5619 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 { - LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "getsockname failed\n"); + LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "getsockname failed\n"); } } return addr_bind; @@ -454,7 +454,7 @@ CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCo } /// debug print - LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "trying connection %s lastseen=%.1fhrs\n", + LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "trying connection %s lastseen=%.1fhrs\n", pszDest ? pszDest : addrConnect.ToString(), pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime) / 3600.0); @@ -1140,7 +1140,7 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket) { } if (!addr.SetSockAddr((const struct sockaddr*)&sockaddr)) { - LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "Unknown socket family\n"); + LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "Unknown socket family\n"); } else { addr = CAddress{MaybeFlipIPv6toCJDNS(addr), NODE_NONE}; } @@ -2398,14 +2398,14 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError, if (!addrBind.GetSockAddr((struct sockaddr*)&sockaddr, &len)) { strError = strprintf(Untranslated("Bind address family for %s not supported"), addrBind.ToString()); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original); return false; } std::unique_ptr sock = CreateSock(addrBind); if (!sock) { 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); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%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)); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original); return false; } LogPrintf("Bound to %s\n", addrBind.ToString()); @@ -2450,7 +2450,7 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError, if (listen(sock->Get(), SOMAXCONN) == SOCKET_ERROR) { strError = strprintf(_("Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError())); - LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", strError.original); return false; } diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 1f09a079872..3f6a605945f 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -99,10 +99,10 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) 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"); + 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"); + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo10: %s\n", "bar10"); std::ifstream file{tmp_log_path}; std::vector log_lines; for (std::string log; std::getline(file, log);) {