log: don't rate-limit "new peer" with -debug=net

0xB10C commented at 5:51 pm on December 4, 2025: contributor

Previously, when debug=net is enabled, we log “New [..] peer connected” for new inbound peers with LogPrintf. However, LogPrintf will get rate-limited since #32604. When we specifically turn on debug=net, we don’t want these log messages to be rate-limited.

To fix this, use LogDebug if debug=net is enabled. Otherwise use LogPrintf. This means we don’t rate-limit the message with debug=net (due to LogDebug not being rate-limited) but still rate-limit it without debug=net with using LogPrintf.

–

I ran into this message getting rate-limited on one of my monitoring nodes with -logsourcelocations=1: With logsourcelocations, one of these lines is about 338 chars (or 338 bytes) long. We rate-limit after more than 1048576 bytes per hour, which results in about 3100 in- and outbound connections per hour. With evicted and instantly reconnecting connections from an entity like LinkingLion, this can be reached fairly quickly.

log: don't rate-limit "new peer" with -debug=net

Previously, when `debug=net` is enabled, we log "New [..] peer connected"
for new inbound peers with LogPrintf. However, LogPrintf will get rate-
limited since https://github.com/bitcoin/bitcoin/pull/32604. When we
specifically turn on `debug=net`, we don't want these log messages to be
rate-limited.

To fix this, use LogDebug if debug=net is enabled. Otherwise use
LogPrintf. This means, we don't rate-limit the message with debug=net
(due to LogDebug not being rate-limited) but still rate-limit it
without debug=net with using LogPrintf.

--

I ran into this message getting rate-limited on one of my monitoring
nodes with `-logsourcelocations=1`: With logsourcelocations, one of
these lines is about 338 chars (or 338 bytes) long. We rate-limit
after more than 1048576 bytes per hour, which results in about
3100 in- and outbound connections per hour. With evicted and
instantly reconnecting connections from an entity like LinkingLion,
this can be reached fairly quickly.

Co-Authored-By: Eugene Siegel <elzeigel@gmail.com>

57eef67c53

DrahtBot added the label Utils/log/libs on Dec 4, 2025

DrahtBot commented at 5:51 pm on December 4, 2025: contributor

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Code Coverage & Benchmarks

For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/34008.

Reviews

See the guideline for information on the review process.

Type	Reviewers
Concept ACK	stickies-v

If your review is incorrectly listed, please copy-paste <!–meta-tag:bot-skip–> into the comment that the bot should ignore.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#34018 (log: exempt all category-specific logs from ratelimiting when running with debug by stickies-v)
#29641 (scripted-diff: Use LogInfo over LogPrintf by maflcko)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

in src/net_processing.cpp:3668 in 57eef67c53

3670-                      TransportTypeAsString(pfrom.m_transport->GetInfo().transport_type),
3671-                      pfrom.nVersion.load(), peer->m_starting_height,
3672-                      pfrom.GetId(), pfrom.LogIP(fLogIPs),
3673-                      (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : ""));
3674+            // With "net" debug logging enabled, log this with LogDebug to not trigger rate-limiting.
3675+            // Keep the two log messages in sync!

0xB10C commented at 5:51 pm on December 4, 2025:

I’m not super happy with this approach of duplicating the log statement, but I think it’s the clearest to a reader. If someone feels strongly, I’m very happy to change it to something better! There are two alternatives that came to mind:

Use a macro to avoid duplicating the log statements: Not sure if we want to define a macro extra for this, but could be done. This was my initial approach I dismissed.
Extract the log message string and format it with e.g. std::format() first, then pass it to either one of the two log macros. This would mean this log message is the only one not formatted with tinyformat..

in src/net_processing.cpp:3683 in 57eef67c53

3685+                        pfrom.ConnectionTypeAsString(),
3686+                        TransportTypeAsString(pfrom.m_transport->GetInfo().transport_type),
3687+                        pfrom.nVersion.load(), peer->m_starting_height,
3688+                        pfrom.GetId(), pfrom.LogIP(fLogIPs),
3689+                        (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : ""));
3690+            }

ajtowns commented at 6:06 pm on December 4, 2025:

Perhaps

0auto mapped_as_info = [&]() -> std::string {
1    const auto mapped_as{m_connman.GetMappedAS(pfrom.addr);
2    return (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : "");
3};
4if (!pfrom.IsInboundconn()) {
5    LogInfo("New %s %s peer ...", ..., mapped_as_info());
6} else {
7    LogDebug(BCLog::NET, "New %s %s ...", ..., mapped_as_info());
8}

ajtowns commented at 6:08 pm on December 4, 2025:

Or could make it auto conn_details = [&]() ... and LogDebug(BCLog::NET, "New %s peer connected: %s", pfrom.ConnectionTypeAsString(), conn_details()) and move all the transport, version, mapped_as stuff into the lambda, moving the transport type to after the colon.

0xB10C commented at 7:15 pm on December 4, 2025:

Or could make it auto conn_details = [&]() ... and LogDebug(BCLog::NET, "New %s peer connected: %s", pfrom.ConnectionTypeAsString(), conn_details()) and move all the transport, version, mapped_as stuff into the lambda, moving the transport type to after the colon.

Could do

0const std::string details = std::format(
1    "transport={} version={} blocks={} peer={}{}{}",
2    TransportTypeAsString(pfrom.m_transport->GetInfo().transport_type),
3    pfrom.nVersion.load(),
4    int{peer->m_starting_height},
5    pfrom.GetId(),
6    (fLogIPs ? std::format(", addr={}", pfrom.LogIP(fLogIPs)) : ""),
7    (mapped_as ? std::format(", mapped_as={}", mapped_as) : "")
8);

0xB10C commented at 7:21 pm on December 4, 2025:

I guess the lambda helps to not create the details string if we don’t end up logging it.

ajtowns commented at 1:07 pm on December 7, 2025:

Yeah. If it’s not obvious, the whole thing would look something like:

 0        auto new_peer_info = [&]() {
 1            // lambda so that this info is only calculated if needed
 2            const auto mapped_as{m_connman.GetMappedAS(pfrom.addr)};
 3            return strprintf("transport: %s version: %d, blocks=%d, peer=%d%s%s\n",
 4                        TransportTypeAsString(pfrom.m_transport->GetInfo().transport_type),
 5                        pfrom.nVersion.load(), peer->m_starting_height,
 6                        pfrom.GetId(), pfrom.LogIP(fLogIPs),
 7                        (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : ""));
 8        };
 9
10        if (!pfrom.IsInboundConn()) {
11            // Log successful connections unconditionally for outbound...
12            LogInfo("New %s peer connected: %s",
13                    pfrom.ConnectionTypeAsString(), new_peer_info());
14        } else {
15            // ... but not for inbound as those can be triggered by an attacker at high rate.
16            LogDebug(BCLog::NET, "New %s peer connected: %s",
17                     pfrom.ConnectionTypeAsString(), new_peer_info());
18        }

fanquake commented at 7:12 pm on December 4, 2025: member

cc @dergoegge

stickies-v commented at 7:49 pm on December 4, 2025: contributor

Concept ACK

Another approach could be to exempt all (not just debug) logs from a debug-enabled category? I think conceptually that makes sense, and I suspect there will be more places where this is helpful so we can minimize the workarounds needed?

For example:

 0diff --git a/src/logging.h b/src/logging.h
 1index defff61d30..074096ed5f 100644
 2--- a/src/logging.h
 3+++ b/src/logging.h
 4@@ -377,16 +377,18 @@ inline void LogPrintFormatInternal(std::source_location&& source_loc, BCLog::Log
 5 
 6 // Log by prefixing the output with the passed category name and severity level. This can either
 7 // log conditionally if the category is allowed or unconditionally if level >= BCLog::Level::Info
 8-// is passed. If this function logs unconditionally, logging to disk is rate-limited. This is
 9-// important so that callers don't need to worry about accidentally introducing a disk-fill
10-// vulnerability if level >= Info is used. Additionally, users specifying -debug are assumed to be
11-// developers or power users who are aware that -debug may cause excessive disk usage due to logging.
12-#define LogPrintLevel(category, level, ...)                           \
13-    do {                                                              \
14-        if (LogAcceptCategory((category), (level))) {                 \
15-            bool rate_limit{level >= BCLog::Level::Info};             \
16-            LogPrintLevel_(category, level, rate_limit, __VA_ARGS__); \
17-        }                                                             \
18+// is passed. If this function logs unconditionally, logging to disk is rate-limited unless debug
19+// logging is enabled for that category. This is important so that callers don't need to worry
20+// about accidentally introducing a disk-fill vulnerability if level >= Info is used.
21+// Users specifying -debug are assumed to be developers or power users who are aware that this may
22+// cause excessive disk usage due to logging, so rate limiting is disabled for those categories.
23+#define LogPrintLevel(category, level, ...)                                                  \
24+    do {                                                                                     \
25+        if (LogAcceptCategory((category), (level))) {                                        \
26+            bool debug_category_enabled{LogAcceptCategory((category), BCLog::Level::Debug)}; \
27+            bool rate_limit{level >= BCLog::Level::Info && !debug_category_enabled};         \
28+            LogPrintLevel_(category, level, rate_limit, __VA_ARGS__);                        \
29+        }                                                                                    \
30     } while (0)
31 
32 // Log conditionally, prefixing the output with the passed category name.
33diff --git a/src/net_processing.cpp b/src/net_processing.cpp
34index 9cab246176..eff85190f2 100644
35--- a/src/net_processing.cpp
36+++ b/src/net_processing.cpp
37@@ -3663,12 +3663,13 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
38         // can be triggered by an attacker at high rate.
39         if (!pfrom.IsInboundConn() || LogAcceptCategory(BCLog::NET, BCLog::Level::Debug)) {
40             const auto mapped_as{m_connman.GetMappedAS(pfrom.addr)};
41-            LogPrintf("New %s %s peer connected: version: %d, blocks=%d, peer=%d%s%s\n",
42-                      pfrom.ConnectionTypeAsString(),
43-                      TransportTypeAsString(pfrom.m_transport->GetInfo().transport_type),
44-                      pfrom.nVersion.load(), peer->m_starting_height,
45-                      pfrom.GetId(), pfrom.LogIP(fLogIPs),
46-                      (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : ""));
47+            LogPrintLevel(BCLog::NET, BCLog::Level::Info,
48+                          "New %s %s peer connected: version: %d, blocks=%d, peer=%d%s%s\n",
49+                          pfrom.ConnectionTypeAsString(),
50+                          TransportTypeAsString(pfrom.m_transport->GetInfo().transport_type),
51+                          pfrom.nVersion.load(), peer->m_starting_height,
52+                          pfrom.GetId(), pfrom.LogIP(fLogIPs),
53+                          (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : ""));
54         }
55 
56         if (pfrom.GetCommonVersion() >= SHORT_IDS_BLOCKS_VERSION) {
57diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
58index 3cf261a429..24884fa7c2 100644
59--- a/src/test/logging_tests.cpp
60+++ b/src/test/logging_tests.cpp
61@@ -389,6 +389,7 @@ enum class Location {
62     INFO_2,
63     DEBUG_LOG,
64     INFO_NOLIMIT,
65+    INFO_CATEGORY,
66 };
67 
68 void LogFromLocation(Location location, const std::string& message) {
69@@ -405,6 +406,9 @@ void LogFromLocation(Location location, const std::string& message) {
70     case Location::INFO_NOLIMIT:
71         LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/false, "%s\n", message);
72         return;
73+    case Location::INFO_CATEGORY:
74+        LogPrintLevel(BCLog::LogFlags::HTTP, BCLog::Level::Info, "%s\n", message);
75+        return;
76     } // no default case, so the compiler can warn about missing cases
77     assert(false);
78 }
79@@ -482,6 +486,16 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
80             TestLogFromLocation(location, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
81         }
82     }
83+
84+    // Check that Info-level logs with a specific category are NOT rate-limited
85+    // when that category has debug logging enabled.
86+    limiter = scheduler.GetLimiter(bytes_quota, time_window);
87+    LogInstance().SetRateLimiting(limiter);
88+    BOOST_CHECK(!limiter->SuppressionsActive());
89+
90+    for (int i = 0; i < num_lines + 2; ++i) {
91+        TestLogFromLocation(Location::INFO_CATEGORY, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
92+    }
93 }
94 
95 BOOST_AUTO_TEST_SUITE_END()

in src/net_processing.cpp:3677 in 57eef67c53

3679+                        TransportTypeAsString(pfrom.m_transport->GetInfo().transport_type),
3680+                        pfrom.nVersion.load(), peer->m_starting_height,
3681+                        pfrom.GetId(), pfrom.LogIP(fLogIPs),
3682+                        (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : ""));
3683+            } else {
3684+                LogPrintf("New %s %s peer connected: version: %d, blocks=%d, peer=%d%s%s\n",

rkrux commented at 11:39 am on December 5, 2025:

It’s documented that LogPrintf is deprecated, prefer to avoid its usage?

https://github.com/bitcoin/bitcoin/blob/0c9ab0f8f8c85719ff3aa4aefe3198cd2f8d63d1/src/logging.h#L372-L373

fanquake commented at 12:06 pm on December 5, 2025:

Yes. It should be removed soon: #29641.

0xB10C commented at 1:19 pm on December 5, 2025:

Will change this to LogInfo once I figured out a better approach (or when I rebase on merged #29641).

0xB10C commented at 1:23 pm on December 5, 2025: contributor

Another approach could be to exempt all (not just debug) logs from a debug-enabled category? I think conceptually that makes sense, and I suspect there will be more places where this is helpful so we can minimize the workarounds needed?

That would work too, and is a way cleaner approach than duplicating stuff here. I probably won’t get to picking that up anytime soon though, so if you want to open an alternative to this PR, feel free to do so!

I’ll mark this as draft until I figure out a good approach. Review time is probably best spent on #29641 right now.

0xB10C marked this as a draft on Dec 5, 2025

stickies-v commented at 3:54 pm on December 5, 2025: contributor

I probably won’t get to picking that up anytime soon though, so if you want to open an alternative to this PR, feel free to do so!

I’ve opened #34018 as an alternative!

DrahtBot added the label Needs rebase on Dec 6, 2025

DrahtBot commented at 2:40 pm on December 6, 2025: contributor

🐙 This pull request conflicts with the target branch and needs rebase.

Ataraxia009 commented at 4:25 am on December 7, 2025: none

Personally I prefer this approach over #34018 @0xB10C @stickies-v

The only problem I see with this approach is the code duplication. Which I think you solved right? Using:

0const std::string details = std::format(
1    "transport={} version={} blocks={} peer={}{}{}",
2    TransportTypeAsString(pfrom.m_transport->GetInfo().transport_type),
3    pfrom.nVersion.load(),
4    int{peer->m_starting_height},
5    pfrom.GetId(),
6    (fLogIPs ? std::format(", addr={}", pfrom.LogIP(fLogIPs)) : ""),
7    (mapped_as ? std::format(", mapped_as={}", mapped_as) : "")
8);

Why doesnt this work?

log: don’t rate-limit “new peer” with -debug=net #34008

Code Coverage & Benchmarks

Reviews

Conflicts