From 94c51ae540723f5f648477789c11f6395730ae05 Mon Sep 17 00:00:00 2001 From: stickies-v Date: Tue, 9 Dec 2025 11:37:42 +0000 Subject: [PATCH 1/4] libevent: separate log statements per level Avoids ratelimiting unconditional log statements when debug logging is enabled. Introduces slight behaviour change by removing the category from unconditional logs, making them more uniform with the other unconditional logs in the codebase. Also, in a slight behavior change, prefix the info-level (and higher) messages with "libevent:". --- src/httpserver.cpp | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/src/httpserver.cpp b/src/httpserver.cpp index abfcb455e14..6cf47eba736 100644 --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -422,22 +422,20 @@ static void HTTPWorkQueueRun(WorkQueue* 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) From f2731676619d14fa4527aa9086fb73078d20f26f Mon Sep 17 00:00:00 2001 From: stickies-v Date: Tue, 9 Dec 2025 11:44:40 +0000 Subject: [PATCH 2/4] ipc: separate log statements per level Avoids ratelimiting unconditional log statements when debug logging is enabled. Introduces slight behaviour change by removing the category from unconditional logs, making them more uniform with the other unconditional logs in the codebase. Also, in a slight behavior change, prefix the info-level (and higher) messages with "ipc:". --- src/ipc/capnp/protocol.cpp | 42 ++++++++++++++++++++++---------------- 1 file changed, 24 insertions(+), 18 deletions(-) diff --git a/src/ipc/capnp/protocol.cpp b/src/ipc/capnp/protocol.cpp index 27ef73e84e5..ff93b0a7675 100644 --- a/src/ipc/capnp/protocol.cpp +++ b/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 From fac24bbec85fc930900ff755192a9954c7c2e27c Mon Sep 17 00:00:00 2001 From: MarcoFalke <*~=`'#}+{/-|&$^_@721217.xyz> Date: Fri, 12 Dec 2025 11:32:16 +0100 Subject: [PATCH 3/4] test: Clarify logging_SeverityLevels test The test was a bit confusing, because it just referred to the "global log level" without explicitly specifying what it is. The level is set though the LogSetup constructor. However, it is easier to follow unit tests, if they are self-contained. So just set the level to Debug explicitly here. Also, add a new debug_3 log, to further document the intended behavior of the unit test. Also, replace the LogPrintLevel with the shorter and exact replacements LogTrace and LogDebug. --- src/test/logging_tests.cpp | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 42658e940a7..809f27b28ff 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -203,22 +203,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"); + LogTrace(BCLog::HTTP, "trace_%s. This log level is lower than the global one.", 2); + LogDebug(BCLog::HTTP, "debug_%s", 3); LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Warning, "foo3: %s\n", "bar3"); LogPrintLevel(BCLog::RPC, BCLog::Level::Error, "foo4: %s\n", "bar4"); // 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"); + 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); LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo7: %s\n", "bar7"); std::vector expected = { "[http:info] foo1: bar1", + "[http] debug_3", "[validation:warning] foo3: bar3", "[rpc:error] foo4: bar4", "[net:warning] foo5: bar5", From fa8a5d215c5a81a7282fd5dd1098f9d3fa40e5db Mon Sep 17 00:00:00 2001 From: MarcoFalke <*~=`'#}+{/-|&$^_@721217.xyz> Date: Thu, 11 Dec 2025 19:59:49 +0100 Subject: [PATCH 4/4] log: Remove brittle and confusing LogPrintLevel --- src/i2p.cpp | 8 +++---- src/logging.h | 15 ++++++------- src/mapport.cpp | 2 +- src/test/i2p_tests.cpp | 10 ++++----- src/test/logging_tests.cpp | 34 +++++------------------------ test/functional/p2p_i2p_sessions.py | 4 ++-- 6 files changed, 25 insertions(+), 48 deletions(-) diff --git a/src/i2p.cpp b/src/i2p.cpp index b43574705bc..04093ea1007 100644 --- a/src/i2p.cpp +++ b/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(); } diff --git a/src/logging.h b/src/logging.h index 4a6f1d1659c..29f51085854 100644 --- a/src/logging.h +++ b/src/logging.h @@ -9,6 +9,7 @@ #include #include #include +#include #include #include #include @@ -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 diff --git a/src/mapport.cpp b/src/mapport.cpp index e71bb1afa57..6024e26818c 100644 --- a/src/mapport.cpp +++ b/src/mapport.cpp @@ -47,7 +47,7 @@ static void ProcessPCP() // Local functor to handle result from PCP/NATPMP mapping. auto handle_mapping = [&](std::variant &res) -> void { if (MappingResult* mapping = std::get_if(&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); diff --git a/src/test/i2p_tests.cpp b/src/test/i2p_tests.cpp index da9cbb5d228..6d6b99f3c76 100644 --- a/src/test/i2p_tests.cpp +++ b/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; diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 809f27b28ff..2a34aefae18 100644 --- a/src/test/logging_tests.cpp +++ b/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 log_lines{ReadDebugLogLines()}; - std::vector 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); @@ -208,24 +190,20 @@ BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup) LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info"); // Global log level - LogPrintLevel(BCLog::HTTP, BCLog::Level::Info, "foo1: %s\n", "bar1"); + 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); - LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Warning, "foo3: %s\n", "bar3"); - LogPrintLevel(BCLog::RPC, BCLog::Level::Error, "foo4: %s\n", "bar4"); + LogWarning("warn_%s", 4); + LogError("err_%s", 5); // Category-specific log level - LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo5: %s\n", "bar5"); 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); - LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo7: %s\n", "bar7"); std::vector expected = { - "[http:info] foo1: bar1", + "info_1", "[http] debug_3", - "[validation:warning] foo3: bar3", - "[rpc:error] foo4: bar4", - "[net:warning] foo5: bar5", - "[net:error] foo7: bar7", + "[warning] warn_4", + "[error] err_5", }; std::vector log_lines{ReadDebugLogLines()}; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); diff --git a/test/functional/p2p_i2p_sessions.py b/test/functional/p2p_i2p_sessions.py index 67474f6c0ea..4b0686e9bb3 100755 --- a/test/functional/p2p_i2p_sessions.py +++ b/test/functional/p2p_i2p_sessions.py @@ -23,12 +23,12 @@ class I2PSessions(BitcoinTestFramework): 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")