From fa8a5d215c5a81a7282fd5dd1098f9d3fa40e5db Mon Sep 17 00:00:00 2001 From: MarcoFalke <*~=`'#}+{/-|&$^_@721217.xyz> Date: Thu, 11 Dec 2025 19:59:49 +0100 Subject: [PATCH] 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")