Merge bitcoin#34051: log: Remove brittle and confusing LogPrintLevel

fa8a5d2 log: Remove brittle and confusing LogPrintLevel (MarcoFalke)
fac24bb test: Clarify logging_SeverityLevels test (MarcoFalke)
f273167 ipc: separate log statements per level (stickies-v)
94c51ae libevent: separate log statements per level (stickies-v)

Pull request description:

  `LogPrintLevel` has many issues:

  * It encourages to log several levels in one source location. This is problematic, because all levels (even warnings and errors) will be rate limited equally for the same location.
  * Its warning and error logs are specially formatted compared to all other warning and error logs in the codebase, making them harder to spot (both in the debug log and in the code).
  * It is verbose to type and read.
  * It is confusing, because the majority of code uses the `Log$LEVEL(...)` macros. Having less ways to achieve the same makes the code more consistent and easier to review.

  Fix all issues by removing it

ACKs for top commit:
  stickies-v:
    re-ACK fa8a5d2
  ajtowns:
    ACK fa8a5d2
  pablomartin4btc:
    re-ACK fa8a5d2

Tree-SHA512: 9fbb04962d9c26e566338694a7725b3c0e88ef733322d890bcc6aeddb45266c754e7c885c69bbfebd1588cc09912c6784cfc00e69882f1271a8c87d201490478

Author: fanquake

src/httpserver.cpp

@@ -422,22 +422,20 @@ static void HTTPWorkQueueRun(WorkQueue<HTTPClosure>* queue, int worker_num)
 /** libevent event log callback */
 static void libevent_log_cb(int severity, const char *msg)
 {
-    BCLog::Level level;
     switch (severity) {
     case EVENT_LOG_DEBUG:
-        level = BCLog::Level::Debug;
+        LogDebug(BCLog::LIBEVENT, "%s", msg);
         break;
     case EVENT_LOG_MSG:
-        level = BCLog::Level::Info;
+        LogInfo("libevent: %s", msg);
         break;
     case EVENT_LOG_WARN:
-        level = BCLog::Level::Warning;
+        LogWarning("libevent: %s", msg);
         break;
     default: // EVENT_LOG_ERR and others are mapped to error
-        level = BCLog::Level::Error;
+        LogError("libevent: %s", msg);
         break;
     }
-    LogPrintLevel(BCLog::LIBEVENT, level, "%s\n", msg);
 }
 
 bool InitHTTPServer(const util::SignalInterrupt& interrupt)

src/i2p.cpp

@@ -415,7 +415,7 @@ void Session::CreateIfNotCreatedAlready()
     const auto session_type = m_transient ? "transient" : "persistent";
     const auto session_id = GetRandHash().GetHex().substr(0, 10); // full is overkill, too verbose in the logs
 
-    LogDebug(BCLog::I2P, "Creating %s SAM session %s with %s\n", session_type, session_id, m_control_host.ToString());
+    LogDebug(BCLog::I2P, "Creating %s I2P SAM session %s with %s\n", session_type, session_id, m_control_host.ToString());
 
     auto sock = Hello();
 
@@ -452,7 +452,7 @@ void Session::CreateIfNotCreatedAlready()
     m_session_id = session_id;
     m_control_sock = std::move(sock);
 
-    LogPrintLevel(BCLog::I2P, BCLog::Level::Info, "%s SAM session %s created, my address=%s\n",
+    LogInfo("%s I2P SAM session %s created, my address=%s",
         Capitalize(session_type),
         m_session_id,
         m_my_addr.ToStringAddrPort());
@@ -483,9 +483,9 @@ void Session::Disconnect()
 {
     if (m_control_sock) {
         if (m_session_id.empty()) {
-            LogPrintLevel(BCLog::I2P, BCLog::Level::Info, "Destroying incomplete SAM session\n");
+            LogInfo("Destroying incomplete I2P SAM session");
         } else {
-            LogPrintLevel(BCLog::I2P, BCLog::Level::Info, "Destroying SAM session %s\n", m_session_id);
+            LogInfo("Destroying I2P SAM session %s", m_session_id);
         }
         m_control_sock.reset();
     }

src/ipc/capnp/protocol.cpp

@@ -31,22 +31,6 @@ namespace ipc {
 namespace capnp {
 namespace {
 
-BCLog::Level ConvertIPCLogLevel(mp::Log level)
-{
-    switch (level) {
-        case mp::Log::Trace: return BCLog::Level::Trace;
-        case mp::Log::Debug: return BCLog::Level::Debug;
-        case mp::Log::Info: return BCLog::Level::Info;
-        case mp::Log::Warning: return BCLog::Level::Warning;
-        case mp::Log::Error: return BCLog::Level::Error;
-        case mp::Log::Raise: return BCLog::Level::Error;
-    } // no default case, so the compiler can warn about missing cases
-
-    // Be conservative and assume that if MP ever adds a new log level, it
-    // should only be shown at our most verbose level.
-    return BCLog::Level::Trace;
-}
-
 mp::Log GetRequestedIPCLogLevel()
 {
     if (LogAcceptCategory(BCLog::IPC, BCLog::Level::Trace)) return mp::Log::Trace;
@@ -58,8 +42,30 @@ mp::Log GetRequestedIPCLogLevel()
 
 void IpcLogFn(mp::LogMessage message)
 {
-    LogPrintLevel(BCLog::IPC, ConvertIPCLogLevel(message.level), "%s\n", message.message);
-    if (message.level == mp::Log::Raise) throw Exception(message.message);
+    switch (message.level) {
+    case mp::Log::Trace:
+        LogTrace(BCLog::IPC, "%s", message.message);
+        return;
+    case mp::Log::Debug:
+        LogDebug(BCLog::IPC, "%s", message.message);
+        return;
+    case mp::Log::Info:
+        LogInfo("ipc: %s", message.message);
+        return;
+    case mp::Log::Warning:
+        LogWarning("ipc: %s", message.message);
+        return;
+    case mp::Log::Error:
+        LogError("ipc: %s", message.message);
+        return;
+    case mp::Log::Raise:
+        LogError("ipc: %s", message.message);
+        throw Exception(message.message);
+    } // no default case, so the compiler can warn about missing cases
+
+    // Be conservative and assume that if MP ever adds a new log level, it
+    // should only be shown at our most verbose level.
+    LogTrace(BCLog::IPC, "%s", message.message);
 }
 
 class CapnpProtocol : public Protocol

src/logging.h

@@ -9,6 +9,7 @@
 #include <crypto/siphash.h>
 #include <threadsafety.h>
 #include <tinyformat.h>
+#include <util/check.h>
 #include <util/fs.h>
 #include <util/string.h>
 #include <util/time.h>
@@ -372,22 +373,20 @@ inline void LogPrintFormatInternal(std::source_location&& source_loc, BCLog::Log
 // Use a macro instead of a function for conditional logging to prevent
 // evaluating arguments when logging for the category is not enabled.
 
-// Log by prefixing the output with the passed category name and severity level. This can either
-// log conditionally if the category is allowed or unconditionally if level >= BCLog::Level::Info
-// is passed. If this function logs unconditionally, logging to disk is rate-limited. This is
-// important so that callers don't need to worry about accidentally introducing a disk-fill
-// vulnerability if level >= Info is used. Additionally, users specifying -debug are assumed to be
+// Log by prefixing the output with the passed category name and severity level. This logs conditionally if
+// the category is allowed. No rate limiting is applied, because users specifying -debug are assumed to be
 // developers or power users who are aware that -debug may cause excessive disk usage due to logging.
-#define LogPrintLevel(category, level, ...)                           \
+#define detail_LogIfCategoryAndLevelEnabled(category, level, ...)     \
     do {                                                              \
         if (LogAcceptCategory((category), (level))) {                 \
             bool rate_limit{level >= BCLog::Level::Info};             \
+            Assume(!rate_limit);/*Only called with the levels below*/ \
             LogPrintLevel_(category, level, rate_limit, __VA_ARGS__); \
         }                                                             \
     } while (0)
 
 // Log conditionally, prefixing the output with the passed category name.
-#define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__)
-#define LogTrace(category, ...) LogPrintLevel(category, BCLog::Level::Trace, __VA_ARGS__)
+#define LogDebug(category, ...) detail_LogIfCategoryAndLevelEnabled(category, BCLog::Level::Debug, __VA_ARGS__)
+#define LogTrace(category, ...) detail_LogIfCategoryAndLevelEnabled(category, BCLog::Level::Trace, __VA_ARGS__)
 
 #endif // BITCOIN_LOGGING_H

src/mapport.cpp

@@ -47,7 +47,7 @@ static void ProcessPCP()
     // Local functor to handle result from PCP/NATPMP mapping.
     auto handle_mapping = [&](std::variant<MappingResult, MappingError> &res) -> void {
         if (MappingResult* mapping = std::get_if<MappingResult>(&res)) {
-            LogPrintLevel(BCLog::NET, BCLog::Level::Info, "portmap: Added mapping %s\n", mapping->ToString());
+            LogInfo("portmap: Added mapping %s", mapping->ToString());
             AddLocal(mapping->external, LOCAL_MAPPED);
             ret = true;
             actual_lifetime = std::min(actual_lifetime, mapping->lifetime);

src/test/i2p_tests.cpp

@@ -56,7 +56,7 @@ BOOST_AUTO_TEST_CASE(unlimited_recv)
     i2p::sam::Session session(gArgs.GetDataDirNet() / "test_i2p_private_key", sam_proxy, interrupt);
 
     {
-        ASSERT_DEBUG_LOG("Creating persistent SAM session");
+        ASSERT_DEBUG_LOG("Creating persistent I2P SAM session");
         ASSERT_DEBUG_LOG("too many bytes without a terminator");
 
         i2p::Connection conn;
@@ -121,10 +121,10 @@ BOOST_AUTO_TEST_CASE(listen_ok_accept_fail)
 
     i2p::Connection conn;
     for (size_t i = 0; i < 5; ++i) {
-        ASSERT_DEBUG_LOG("Creating persistent SAM session");
-        ASSERT_DEBUG_LOG("Persistent SAM session" /* ... created */);
+        ASSERT_DEBUG_LOG("Creating persistent I2P SAM session");
+        ASSERT_DEBUG_LOG("Persistent I2P SAM session" /* ... created */);
         ASSERT_DEBUG_LOG("Error accepting");
-        ASSERT_DEBUG_LOG("Destroying SAM session");
+        ASSERT_DEBUG_LOG("Destroying I2P SAM session");
         BOOST_REQUIRE(session.Listen(conn));
         BOOST_REQUIRE(!session.Accept(conn));
     }
@@ -161,7 +161,7 @@ BOOST_AUTO_TEST_CASE(damaged_private_key)
         i2p::sam::Session session(i2p_private_key_file, sam_proxy, interrupt);
 
         {
-            ASSERT_DEBUG_LOG("Creating persistent SAM session");
+            ASSERT_DEBUG_LOG("Creating persistent I2P SAM session");
             ASSERT_DEBUG_LOG(expected_error);
 
             i2p::Connection conn;

src/test/logging_tests.cpp

@@ -139,24 +139,6 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
     BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
 }
 
-BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacrosDeprecated, LogSetup)
-{
-    LogInstance().EnableCategory(BCLog::NET);
-    LogPrintLevel(BCLog::NET, BCLog::Level::Trace, "foo4: %s\n", "bar4"); // not logged
-    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::vector<std::string> log_lines{ReadDebugLogLines()};
-    std::vector<std::string> expected{
-        "[net] 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, LogSetup)
 {
     LogInstance().EnableCategory(BCLog::NET);
@@ -203,26 +185,25 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup)
 
 BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup)
 {
+    LogInstance().SetLogLevel(BCLog::Level::Debug);
     LogInstance().EnableCategory(BCLog::LogFlags::ALL);
     LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info");
 
     // Global log level
-    LogPrintLevel(BCLog::HTTP, BCLog::Level::Info, "foo1: %s\n", "bar1");
-    LogPrintLevel(BCLog::MEMPOOL, BCLog::Level::Trace, "foo2: %s. This log level is lower than the global one.\n", "bar2");
-    LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Warning, "foo3: %s\n", "bar3");
-    LogPrintLevel(BCLog::RPC, BCLog::Level::Error, "foo4: %s\n", "bar4");
+    LogInfo("info_%s", 1);
+    LogTrace(BCLog::HTTP, "trace_%s. This log level is lower than the global one.", 2);
+    LogDebug(BCLog::HTTP, "debug_%s", 3);
+    LogWarning("warn_%s", 4);
+    LogError("err_%s", 5);
 
     // Category-specific log level
-    LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo5: %s\n", "bar5");
-    LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo6: %s. This log level is the same as the global one but lower than the category-specific one, which takes precedence. \n", "bar6");
-    LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo7: %s\n", "bar7");
+    LogDebug(BCLog::NET, "debug_%s. This log level is the same as the global one but lower than the category-specific one, which takes precedence.", 6);
 
     std::vector<std::string> expected = {
-        "[http:info] foo1: bar1",
-        "[validation:warning] foo3: bar3",
-        "[rpc:error] foo4: bar4",
-        "[net:warning] foo5: bar5",
-        "[net:error] foo7: bar7",
+        "info_1",
+        "[http] debug_3",
+        "[warning] warn_4",
+        "[error] err_5",
     };
     std::vector<std::string> log_lines{ReadDebugLogLines()};
     BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());

test/functional/p2p_i2p_sessions.py

@@ -23,12 +23,12 @@ def run_test(self):
 
         self.log.info("Ensure we create a persistent session when -i2pacceptincoming=1")
         node0 = self.nodes[0]
-        with node0.assert_debug_log(expected_msgs=["Creating persistent SAM session"]):
+        with node0.assert_debug_log(expected_msgs=["Creating persistent I2P SAM session"]):
             node0.addnode(node=addr, command="onetry")
 
         self.log.info("Ensure we create a transient session when -i2pacceptincoming=0")
         node1 = self.nodes[1]
-        with node1.assert_debug_log(expected_msgs=["Creating transient SAM session"]):
+        with node1.assert_debug_log(expected_msgs=["Creating transient I2P SAM session"]):
             node1.addnode(node=addr, command="onetry")