Merge bitcoin#25202: log: Use severity-based logging for leveldb/libevent messages, reverse LogPrintLevel order

c4e7717 refactor: Change LogPrintLevel order to category, severity (laanwj)
ce92071 leveldb: Log messages from leveldb with category and debug level (laanwj)
18ec120 http: Use severity-based logging for messages from libevent (laanwj)
bd971bf logging: Unconditionally log levels >= WARN (laanwj)

Pull request description:

  Log messages from leveldb and libevent libraries in the severity+level based log format introduced in bitcoin#24464.

  Example of messages before:
  ```
  2022-05-24T18:11:57Z [libevent] libevent: event_add: event: 0x55da963fcc10 (fd 10), EV_READ    call 0x7f1c7a254620
  2022-05-24T18:11:57Z [libevent] libevent: Epoll ADD(1) on fd 10 okay. Old events were 0; read change was 1 (add); write change was 0 (none); close change was 0 (none)
  2022-05-24T18:12:08Z leveldb: Generated table #609127@1: 6445 keys, 312916 bytes
  2022-05-24T18:12:08Z leveldb: Generated table #609128@1: 5607 keys, 268548 bytes
  2022-05-24T18:12:08Z leveldb: Generated table #609129@1: 189 keys, 9384 bytes
  2022-05-24T18:12:08Z leveldb: Generated table #609130@1: 293 keys, 13818 bytes
  ```

  Example of messages after:
  ```
  2022-05-24T17:59:52Z [libevent:debug] event_add: event: 0x5652f44dac10 (fd 10), EV_READ    call 0x7f210f2e6620
  2022-05-24T17:59:52Z [libevent:debug] Epoll ADD(1) on fd 10 okay. Old events were 0; read change was 1 (add); write change was 0 (none); close change was 0 (none)
  2022-05-24T17:59:53Z [leveldb:debug] Recovering log dashpay#1072
  2022-05-24T17:59:53Z [leveldb:debug] Level-0 table dashpay#1082: started
  2022-05-24T17:59:53Z [leveldb:debug] Level-0 table dashpay#1082: 193 bytes OK
  2022-05-24T17:59:53Z [leveldb:debug] Delete type=3 dashpay#1070
  2022-05-24T17:59:53Z [leveldb:debug] Delete type=0 dashpay#1072
  ```

  The first commit changes it so that messages with level Warning and Error are always logged independent of the `-debug` setting. I think this is useful to make sure warnings and errors, which tend to be important, are not lost. In the future this should be made more configurable.

  Last commit changes LogPrintLevel argument 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.

ACKs for top commit:
  jonatack:
    Tested ACK c4e7717

Tree-SHA512: ea48a1517f8c1b23760e59933bbd64ebf09c32eb947e31b8c2696b4630ac1f4303b126720183e2de052bcede3a17e475bbf3fbb6378a12b0fa8f3582d610930d

Author: laanwj

src/dbwrapper.cpp

@@ -19,7 +19,7 @@ class CBitcoinLevelDBLogger : public leveldb::Logger {
     // 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];
@@ -63,7 +63,7 @@ class CBitcoinLevelDBLogger : public leveldb::Logger {
 
                 assert(p <= limit);
                 base[std::min(bufsize - 1, (int)(p - base))] = '\0';
-                LogPrintf("leveldb: %s", base);  /* Continued */
+                LogPrintLevel(BCLog::LEVELDB, BCLog::Level::Debug, "%s", base);  /* Continued */
                 if (base != buffer) {
                     delete[] base;
                 }
@@ -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;

src/httpserver.cpp

@@ -344,10 +344,22 @@ static void HTTPWorkQueueRun(WorkQueue<HTTPClosure>* 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(BCLog::LIBEVENT, level, "%s\n", msg);
 }
 
 bool InitHTTPServer()

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, ...)               \
+#define LogPrintLevel(category, level, ...)               \
     do {                                                  \
-        if (LogAcceptCategory((category))) {              \
+        if (LogAcceptCategory((category), (level))) {     \
             LogPrintLevel_(category, level, __VA_ARGS__); \
         }                                                 \
     } while (0)

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> 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;
     }
 

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<std::string> log_lines;
     for (std::string log; std::getline(file, log);) {

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);

src/wallet/coinselection.cpp

@@ -307,7 +307,7 @@ std::optional<SelectionResult> KnapsackSolver(std::vector<OutputGroup>& 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]) {