cryptogera/bitcoin
1
0
Fork 0
mirror of https://github.com/bitcoin/bitcoin.git synced 2026-01-31 18:51:12 +00:00
Code Issues Packages Projects Releases Wiki Activity

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

Browse Source 
fa8a5d215c5a81a7282fd5dd1098f9d3fa40e5db log: Remove brittle and confusing LogPrintLevel (MarcoFalke)
fac24bbec85fc930900ff755192a9954c7c2e27c test: Clarify logging_SeverityLevels test (MarcoFalke)
f2731676619d14fa4527aa9086fb73078d20f26f ipc: separate log statements per level (stickies-v)
94c51ae540723f5f648477789c11f6395730ae05 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 fa8a5d215c5a81a7282fd5dd1098f9d3fa40e5db
  ajtowns:
    ACK fa8a5d215c5a81a7282fd5dd1098f9d3fa40e5db
  pablomartin4btc:
    re-ACK fa8a5d215c5a81a7282fd5dd1098f9d3fa40e5db

Tree-SHA512: 9fbb04962d9c26e566338694a7725b3c0e88ef733322d890bcc6aeddb45266c754e7c885c69bbfebd1588cc09912c6784cfc00e69882f1271a8c87d201490478
This commit is contained in:
merge-script 2025-12-14 12:30:48 +00:00
commit 2210feb446
No known key found for this signature in database
GPG Key ID: 2EEB9F5CC09526C1
8 changed files with 58 additions and 74 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

10
src/httpserver.cpp
View File

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

8
src/i2p.cpp
View File

@ -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();
}

42
src/ipc/capnp/protocol.cpp
View File

@ -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

15
src/logging.h
View File

@ -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

2
src/mapport.cpp
View File

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

10
src/test/i2p_tests.cpp
View File

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

41
src/test/logging_tests.cpp
View File

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

4
test/functional/p2p_i2p_sessions.py
View File

@ -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")