Merge bitcoin/bitcoin#24464: logging: Add severity level to logs

e11cdc9303  logging: Add log severity level to net.cpp (klementtan)
a8290649a6 logging: Add severity level to logs. (klementtan)

Pull request description:

  **Overview**: This PR introduces a new macro, `LogPrintLevel`, that allows developers to add logs with the severity level. Additionally, it will also print the log category if it is specified.

  Sample log:
  ```
  2022-03-04T16:41:15Z [opencon] [net:debug] trying connection XX.XX.XXX.XXX:YYYYY lastseen=2.7hrs
  ```

  **Motivation**: This feature was suggested in #20576 and I believe that it will bring the following benefits:
  * Allow for easier filtering of logs in `debug.log`
  * Can be extended to allow users to select the minimum level of logs they would like to view (not in the scope of this PR)

  **Details**:
  * New log format. `... [category:level]...`. ie:
    * Do not print category if `category == NONE`
    * Do not print level if `level == NONE`
    * If `category == NONE` and `level == NONE`, do not print any fields (current behaviour)
  * Previous logging functions:
    * `LogPrintf`:  no changes in log as it calls `LogPrintf_` with `category = NONE` and `level = NONE`
    * `LogPrint`: prints additional `[category]` field as it calls `LogPrintf_` with `category = category` and `level = NONE`
  * `net.cpp`: As a proof of concept, updated logs with obvious severity (ie prefixed with `Warning/Error:..`) to use the new logging with severity.

  **Testing**:
  * Compiling and running `bitcoind` with this PR should instantly display logs with the category name (ie `net/tor/...`)
  * Grepping for `net:debug` in `debug.log` should display the updated logs with severity level:
    <details>
    <summary>Code</summary>

    ```
    $ grep "net:debug" debug.log

    2022-03-04T16:41:15Z [opencon] [net:debug] trying connection XXX:YYY lastseen=2.7hrs
    2022-03-04T16:41:16Z [opencon] [net:debug] trying connection XXX:YYY lastseen=16.9hrs
    2022-03-04T16:41:17Z [opencon] [net:debug] trying connection XXX:YYY lastseen=93.2hrs
    2022-03-04T16:41:18Z [opencon] [net:debug] trying connection XXX:YYY lastseen=2.7hrs
    ```
    </details>

ACKs for top commit:
  laanwj:
    Code review and lightly tested ACK e11cdc9303

Tree-SHA512: 89a8c86667ccc0688e5acfdbd399aac1f5bec9f978a160e40b0210b0d9b8fdc338479583fc5bd2e2bc785821363f174f578d52136d228e8f638a20abbf0a568f

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 + "] ");
     }

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,18 +190,28 @@ 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__);          \
+            LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__); \
+        }                                                              \
+    } while (0)
+
+#define LogPrintLevel(level, category, ...)               \
+    do {                                                  \
+        if (LogAcceptCategory((category))) {              \
+            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 {
-            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",
+    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);
+                  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());
+        strError = strprintf(Untranslated("Bind address family for %s not supported"), addrBind.ToString());
-        LogPrintf("%s\n", strError.original);
+        LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original);
         return false;
     }
 
     std::unique_ptr<Sock> sock = CreateSock(addrBind);
     if (!sock) {
-        strError = strprintf(Untranslated("Error: Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError()));
+        strError = strprintf(Untranslated("Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError()));
-        LogPrintf("%s\n", strError.original);
+        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()));
+        strError = strprintf(_("Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError()));
-        LogPrintf("%s\n", strError.original);
+        LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original);
         return false;
     }
 

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