Followups to #32604.
There are two behavior changes:
[*] is done to all logs (regardless of should_ratelimit) per this comment.-disableratelimitlogging flag is added by default to functional tests so they don’t encounter rate limiting.
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/33011.
See the guideline for information on the review process.
| Type | Reviewers |
|---|---|
| ACK | stickies-v, l0rinc, achow101 |
| Stale ACK | maflcko |
If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.
No conflicts as of last run.
Addressed in this PR:
Not addressed:
Won’t address:
BOOST_CHECK_THROW and BOOST_CHECK_NO_THROW, so no longer relevant.
🚧 At least one of the CI tasks failed.
Task previous releases, depends DEBUG: https://github.com/bitcoin/bitcoin/runs/46279969042
LLM reason (✨ experimental): Build error due to incomplete type in std::pair’s second member caused by missing full definition of BCLog::LogRateLimiter::Stats.
Try to run the tests locally, according to the documentation. However, a CI failure may still happen due to a number of reasons, for example:
Possibly due to a silent merge conflict (the changes in this pull request being incompatible with the current code in the target branch). If so, make sure to rebase on the latest commit of the target branch.
A sanitizer issue, which can only be found by compiling with the sanitizer and running the affected test.
An intermittent issue.
Leave a comment here, if you need help tracking down a confusing failure.
103@@ -104,46 +104,30 @@ namespace BCLog {
104 };
105 constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
106 constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging
107- constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes that can be logged within one window
108+ constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the specified time-window
nit on 35585c54b57bbb05bfc4de63880c1767931e3696: more consistent parameterise both:
0diff --git a/src/init.cpp b/src/init.cpp
1index 63244c802e..863b2e088e 100644
2--- a/src/init.cpp
3+++ b/src/init.cpp
4@@ -1382,7 +1382,7 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
5 LogInstance().SetRateLimiting(std::make_unique<BCLog::LogRateLimiter>(
6 [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); },
7 BCLog::RATELIMIT_MAX_BYTES,
8- 1h));
9+ BCLog::RATELIMIT_WINDOW));
10
11 assert(!node.validation_signals);
12 node.validation_signals = std::make_unique<ValidationSignals>(std::make_unique<SerialTaskRunner>(scheduler));
13diff --git a/src/logging.h b/src/logging.h
14index 5437d73c78..a2cbbf51f7 100644
15--- a/src/logging.h
16+++ b/src/logging.h
17@@ -104,7 +104,8 @@ namespace BCLog {
18 };
19 constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
20 constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging
21- constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the specified time-window
22+ constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the RATELIMIT_WINDOW
23+ constexpr auto RATELIMIT_WINDOW{1h}; // time window after which log ratelimit stats are reset
24
25 //! Fixed window rate limiter for logging.
26 class LogRateLimiter
317
318 using Status = BCLog::LogRateLimiter::Status;
319- auto source_loc_1{std::source_location::current()};
320- auto source_loc_2{std::source_location::current()};
321+ std::source_location source_loc_1{std::source_location::current()};
322+ std::source_location source_loc_2{std::source_location::current()};
auto can sometimes make things less readable, but I think in all of these changes that’s not the case. Repeating types (e.g. std::source_location source_loc_1{std::source_location::current()} is just overly verbose imo), and for the others the name/literal is already explanatory. For sched_func, I think the logic is now drowned in rather unimportant type definitions. I think this addresses this comment, but I personally don’t think there’s anything wrong with mixing auto and explicit types, we should use whichever is most appropriate at each time imo.
389-void LogFromLocation(int location, std::string message)
390-{
391+namespace {
392+
393+enum class Location {
394+ FIRST,
INFO_1, INFO_2, DEBUG, INFO_NOLIMIT
DEBUG to DEBUG_LOG since the former is a macro
445 LogInstance().m_log_sourcelocations = false;
446- bool prev_log_threadnames = LogInstance().m_log_threadnames;
447+ bool prev_log_threadnames{LogInstance().m_log_threadnames};
448 LogInstance().m_log_threadnames = false;
449
450+ int64_t line_length{1023};
nit: I find setting line_length{1024} and documenting the subtraction more straightforward:
0diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
1index 81c0bacba0..245940f284 100644
2--- a/src/test/logging_tests.cpp
3+++ b/src/test/logging_tests.cpp
4@@ -414,11 +414,10 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
5 bool prev_log_threadnames{LogInstance().m_log_threadnames};
6 LogInstance().m_log_threadnames = false;
7
8- int64_t line_length{1023};
9+ int64_t line_length{1024};
10 int64_t num_lines{1024};
11
12- // Add 1 to line_length because of newline.
13- int64_t bytes_quota{(line_length + 1) * num_lines};
14+ int64_t bytes_quota{line_length * num_lines};
15
16 std::chrono::seconds time_window{20};
17
18@@ -430,7 +429,7 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
19 std::unique_ptr<BCLog::LogRateLimiter> limiter{std::make_unique<BCLog::LogRateLimiter>(sched_func, bytes_quota, time_window)};
20 LogInstance().SetRateLimiting(std::move(limiter));
21
22- std::string log_message(line_length, 'a');
23+ std::string log_message(line_length - 1, 'a'); // subtract one for newline
24
25 std::string utf8_path{LogInstance().m_file_path.utf8string()};
26 const char* log_path{utf8_path.c_str()};
Also, constants could be marked as such. Diff including the previous suggestion:
0diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
1index 81c0bacba0..62c92287dd 100644
2--- a/src/test/logging_tests.cpp
3+++ b/src/test/logging_tests.cpp
4@@ -407,20 +407,17 @@ void LogFromLocationAndExpect(Location location, const std::string& message, con
5
6 BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
7 {
8- bool prev_log_timestamps{LogInstance().m_log_timestamps};
9+ const bool prev_log_timestamps{LogInstance().m_log_timestamps};
10 LogInstance().m_log_timestamps = false;
11- bool prev_log_sourcelocations{LogInstance().m_log_sourcelocations};
12+ const bool prev_log_sourcelocations{LogInstance().m_log_sourcelocations};
13 LogInstance().m_log_sourcelocations = false;
14- bool prev_log_threadnames{LogInstance().m_log_threadnames};
15+ const bool prev_log_threadnames{LogInstance().m_log_threadnames};
16 LogInstance().m_log_threadnames = false;
17
18- int64_t line_length{1023};
19- int64_t num_lines{1024};
20-
21- // Add 1 to line_length because of newline.
22- int64_t bytes_quota{(line_length + 1) * num_lines};
23-
24- std::chrono::seconds time_window{20};
25+ constexpr int64_t line_length{1024};
26+ constexpr int64_t num_lines{1024};
27+ constexpr int64_t bytes_quota{line_length * num_lines};
28+ constexpr std::chrono::seconds time_window{20};
29
30 CScheduler scheduler{};
31 scheduler.m_service_thread = std::thread([&] { scheduler.serviceQueue(); });
32@@ -430,9 +427,8 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
33 std::unique_ptr<BCLog::LogRateLimiter> limiter{std::make_unique<BCLog::LogRateLimiter>(sched_func, bytes_quota, time_window)};
34 LogInstance().SetRateLimiting(std::move(limiter));
35
36- std::string log_message(line_length, 'a');
37-
38- std::string utf8_path{LogInstance().m_file_path.utf8string()};
39+ const std::string log_message(line_length - 1, 'a'); // subtract one for newline
40+ const std::string utf8_path{LogInstance().m_file_path.utf8string()};
41 const char* log_path{utf8_path.c_str()};
42
43 // Use GetFileSize because fs::file_size may require a flush to be accurate.
507+ BOOST_CHECK(log_file_size < GetFileSize(log_path));
508
509 log_file_size = GetFileSize(log_path);
510 {
511 ASSERT_DEBUG_LOG("Restarting logging");
512 MockForwardAndSync(scheduler, 1min);
nit: use variable
0 MockForwardAndSync(scheduler, time_window);
551-
552- BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 3 should be exempt from rate limiting");
553-
554 LogInstance().m_log_timestamps = prev_log_timestamps;
555 LogInstance().m_log_sourcelocations = prev_log_sourcelocations;
556 LogInstance().m_log_threadnames = prev_log_threadnames;
Note: this is already handled by the LogSetup fixture, so I think we can remove this logic here.
On that note: I think LogSetup could benefit from explicitly setting LogInstance().SetRateLimiting(nullptr); in both its constructor and destructor?
137@@ -154,7 +138,7 @@ namespace BCLog {
138 * reset_window interval.
139 * @param max_bytes Maximum number of bytes that can be logged for each source
140 * location.
141- * @param reset_window Time window after which the byte counters are reset.
142+ * @param reset_window Time window after which the stats are reset.
143 */
144 LogRateLimiter(SchedulerFunction scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window);
There are some lifetime concerns wrt scheduler_func, that are okay in our current codebase, but make the contract perhaps more fragile than it needs to be. Specifically: Logger has a std::unique_ptr<LogRateLimiter> m_limiter member. The node’s scheduler holds a reference to the limiter. This means that the limiter may not be destroyed before the scheduler is stopped. In our current code, this is fine, because the logger is a static global, so it can never be destroyed before the node is shutdown (which stops the scheduler).
I ran into this dependency while reviewing / drafting my suggestion on #32604 when I was writing the test code, when I realized that writing an RAII struct (as now e.g. implemented here) for the limiter was not really possible using the std::unique_ptr approach. I kept it as-is because the non-test code was fine, and I didn’t want to overcomplicate things, but perhaps this follow-up is a good place to at least reconsider this.
Conceptually, I think it makes sense to make m_limiter a std::shared_ptr since it has two users: the thing that uses it to consume logs (in our case Logger), and the thing that uses it to reset stats (in our case CScheduler). With a shared pointer, we can safely and explicitly manage these dependencies without introducing coupling between the logger and the scheduler.
After playing around with it, it turns out the implementation is actually rather straightforward:
0diff --git a/src/init.cpp b/src/init.cpp
1index 63244c802e..75db37397c 100644
2--- a/src/init.cpp
3+++ b/src/init.cpp
4@@ -1379,7 +1379,7 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
5 }
6 }, std::chrono::minutes{5});
7
8- LogInstance().SetRateLimiting(std::make_unique<BCLog::LogRateLimiter>(
9+ LogInstance().SetRateLimiting(BCLog::LogRateLimiter::Create(
10 [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); },
11 BCLog::RATELIMIT_MAX_BYTES,
12 1h));
13diff --git a/src/logging.cpp b/src/logging.cpp
14index e2c27ec54d..3d42bd9bc8 100644
15--- a/src/logging.cpp
16+++ b/src/logging.cpp
17@@ -371,12 +371,21 @@ static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
18 memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
19 }
20
21-BCLog::LogRateLimiter::LogRateLimiter(
22- SchedulerFunction scheduler_func,
23- uint64_t max_bytes,
24- std::chrono::seconds reset_window) : m_max_bytes{max_bytes}, m_reset_window{reset_window}
25+BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window)
26+ : m_max_bytes{max_bytes}, m_reset_window{reset_window} {}
27+
28+std::shared_ptr<BCLog::LogRateLimiter> BCLog::LogRateLimiter::Create(
29+ SchedulerFunction scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window)
30 {
31- scheduler_func([this] { Reset(); }, reset_window);
32+ auto limiter{std::shared_ptr<LogRateLimiter>(new LogRateLimiter(max_bytes, reset_window))};
33+ std::weak_ptr<LogRateLimiter> weak_limiter{limiter};
34+ scheduler_func([weak_limiter] {
35+ if (auto shared_limiter{weak_limiter.lock()}) {
36+ shared_limiter->Reset();
37+ }
38+ },
39+ limiter->m_reset_window);
40+ return limiter;
41 }
42
43 BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume(
44diff --git a/src/logging.h b/src/logging.h
45index 5437d73c78..12905f1e47 100644
46--- a/src/logging.h
47+++ b/src/logging.h
48@@ -18,6 +18,7 @@
49 #include <cstring>
50 #include <functional>
51 #include <list>
52+#include <memory>
53 #include <mutex>
54 #include <source_location>
55 #include <string>
56@@ -107,7 +108,7 @@ namespace BCLog {
57 constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the specified time-window
58
59 //! Fixed window rate limiter for logging.
60- class LogRateLimiter
61+ class LogRateLimiter : public std::enable_shared_from_this<LogRateLimiter>
62 {
63 public:
64 //! Keeps track of an individual source location and how many available bytes are left for logging from it.
65@@ -129,6 +130,7 @@ namespace BCLog {
66 std::unordered_map<std::source_location, Stats, SourceLocationHasher, SourceLocationEqual> m_source_locations GUARDED_BY(m_mutex);
67 //! Whether any log locations are suppressed. Cached view on m_source_locations for performance reasons.
68 std::atomic<bool> m_suppression_active{false};
69+ LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window);
70
71 public:
72 using SchedulerFunction = std::function<void(std::function<void()>, std::chrono::milliseconds)>;
73@@ -140,7 +142,10 @@ namespace BCLog {
74 * location.
75 * [@param](/bitcoin-bitcoin/contributor/param/) reset_window Time window after which the stats are reset.
76 */
77- LogRateLimiter(SchedulerFunction scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window);
78+ static std::shared_ptr<LogRateLimiter> Create(
79+ SchedulerFunction scheduler_func,
80+ uint64_t max_bytes,
81+ std::chrono::seconds reset_window);
82 //! Maximum number of bytes logged per location per window.
83 const uint64_t m_max_bytes;
84 //! Interval after which the window is reset.
85@@ -160,6 +165,8 @@ namespace BCLog {
86 void Reset() EXCLUSIVE_LOCKS_REQUIRED(!m_mutex);
87 //! Returns true if any log locations are currently being suppressed.
88 bool SuppressionsActive() const { return m_suppression_active; }
89+ //! The function that is used to schedule the reset window.
90+ SchedulerFunction m_scheduler_func;
91 };
92
93 class Logger
94@@ -185,7 +192,7 @@ namespace BCLog {
95 size_t m_buffer_lines_discarded GUARDED_BY(m_cs){0};
96
97 //! Manages the rate limiting of each log location.
98- std::unique_ptr<LogRateLimiter> m_limiter GUARDED_BY(m_cs);
99+ std::shared_ptr<LogRateLimiter> m_limiter GUARDED_BY(m_cs);
100
101 //! Category-specific log level. Overrides `m_log_level`.
102 std::unordered_map<LogFlags, Level> m_category_log_levels GUARDED_BY(m_cs);
103@@ -254,7 +261,7 @@ namespace BCLog {
104 /** Only for testing */
105 void DisconnectTestLogger() EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
106
107- void SetRateLimiting(std::unique_ptr<LogRateLimiter>&& limiter) EXCLUSIVE_LOCKS_REQUIRED(!m_cs)
108+ void SetRateLimiting(std::shared_ptr<LogRateLimiter> limiter) EXCLUSIVE_LOCKS_REQUIRED(!m_cs)
109 {
110 StdLockGuard scoped_lock(m_cs);
111 m_limiter = std::move(limiter);
112diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
113index 81c0bacba0..ea0297367d 100644
114--- a/src/test/logging_tests.cpp
115+++ b/src/test/logging_tests.cpp
116@@ -311,7 +311,8 @@ BOOST_AUTO_TEST_CASE(logging_log_rate_limiter)
117 BCLog::LogRateLimiter::SchedulerFunction sched_func{[&scheduler](std::function<void()> func, std::chrono::milliseconds window) {
118 scheduler.scheduleEvery(std::move(func), window);
119 }};
120- BCLog::LogRateLimiter limiter{sched_func, max_bytes, reset_window};
121+ auto limiter_{BCLog::LogRateLimiter::Create(sched_func, max_bytes, reset_window)};
122+ auto& limiter{*limiter_};
123
124 using Status = BCLog::LogRateLimiter::Status;
125 std::source_location source_loc_1{std::source_location::current()};
126@@ -427,8 +428,7 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
127 BCLog::LogRateLimiter::SchedulerFunction sched_func{[&scheduler](std::function<void()> func, std::chrono::milliseconds window) {
128 scheduler.scheduleEvery(std::move(func), window);
129 }};
130- std::unique_ptr<BCLog::LogRateLimiter> limiter{std::make_unique<BCLog::LogRateLimiter>(sched_func, bytes_quota, time_window)};
131- LogInstance().SetRateLimiting(std::move(limiter));
132+ LogInstance().SetRateLimiting(BCLog::LogRateLimiter::Create(sched_func, bytes_quota, time_window));
133
134 std::string log_message(line_length, 'a');
135
What do you think?
Will implement, the ScopedScheduler is better imo and std::shared_ptr makes more sense over std::unique_ptr.
With a shared pointer, we can safely and explicitly manage these dependencies without introducing coupling between the logger and the scheduler.
I think there will always be coupling between the two since Reset may call LogPrintLevel_?
The test has definitely improved in both functionality and readability, but I find it’s still quite clunky (e.g. lots of repeated code) and unspecific (e.g. using any increase in filesize as measurement, not accurately checking the (non) existence of certain log statements most of the time), so I dove into a little rabbit hole today to see what my ideal test would look like, and I think it’d be close to something like this: https://github.com/stickies-v/bitcoin/commit/e55c03bf7954122fd0a23bfb60599d19be507877. The main conceptual difference is that I added a separate function that quite exhaustively compares all the attributes of all the produced on-disk log output with its expected values. Most of the code changes then accommodates that / reduces duplication.
It has two helper commits (one already mentioned in another comment), and it also incorporates a bunch of the changes I’ve left in smaller comments on this PR. What do you think?
m_limiter lifetime guarantees, and on the logging_filesize_rate_limit tests. Both are not essential, but I think it could make sense to include them here.
Co-Authored-By: l0rinc <pap.lorinc@gmail.com>
Co-Authored-By: l0rinc <pap.lorinc@gmail.com>
Co-Authored-By: stickies-v <stickies-v@protonmail.com>
🚧 At least one of the CI tasks failed.
Task MSan, depends: https://github.com/bitcoin/bitcoin/runs/46865525511
LLM reason (✨ experimental): The CI failure is caused by a macro name conflict where DEBUG is redefined as 1, causing syntax errors during compilation.
Try to run the tests locally, according to the documentation. However, a CI failure may still happen due to a number of reasons, for example:
Possibly due to a silent merge conflict (the changes in this pull request being incompatible with the current code in the target branch). If so, make sure to rebase on the latest commit of the target branch.
A sanitizer issue, which can only be found by compiling with the sanitizer and running the affected test.
An intermittent issue.
Leave a comment here, if you need help tracking down a confusing failure.
The latest push 526403df23a2db781709e4494da3a9f79284531d:
m_limiter a std::shared_ptrSourceLocationHasher (b8e92fb3d4137f91fe6a54829867fc54357da648)logging_filesize_rate_limit to dedupe logic and explicitly check for certain rate-limiting logsThe CI is failing with DEBUG_LOCKCONTENTION as ReadDebugLogLines is matching against a log from the scheduler having lock contention. Will investigate.
Latest push 526403df23a2db781709e4494da3a9f79284531d -> d434155db5f9c34b8ab3e19038d824d161b34195 modifies logging_filesize_rate_limit to scan ReadDebugLogLines for the [warning] Restarting logging string in one place. This is hacky and is needed to make the CI pass when DEBUG_LOCKCONTENTION is specified.
The failure happens because:
Reset is in the task queue of the schedulerMockForwardAndSync calls MockForwardReset will be called and will schedule another Reset. This will lock newTaskMutex.scheduleFromNow call in MockForwardAndSync will lock newTaskMutex.If there’s lock contention here, it will trigger the failure. The logs will look like:
0[14:38:33.794] [*] [warning] Excessive logging detected from test/logging_tests.cpp:392 (void logging_tests::(anonymous namespace)::LogFromLocation(Location, const std::string &)): >1048576 bytes logged during the last time window of 20s. Suppressing logging to disk from this source location until time window resets. Console logging unaffected. Last log entry.
1[14:38:33.794] [*] a
2[14:38:33.794] [*] b
3[14:38:33.794] [*] c
4[14:38:33.794] [lock] Enter: lock contention newTaskMutex, scheduler.cpp:74 started
5[14:38:33.794] [warning] Restarting logging from test/logging_tests.cpp:392 (void logging_tests::(anonymous namespace)::LogFromLocation(Location, const std::string &)): 4 bytes were dropped during the last 20s.
6[14:38:33.794] [lock] Enter: lock contention newTaskMutex, scheduler.cpp:74 completed (10μs)
7[14:38:33.794] [lock] Enter: lock contention newTaskMutex, scheduler.cpp:74 started
8[14:38:33.794] [lock] Enter: lock contention newTaskMutex, scheduler.cpp:74 completed (36μs)
9[14:38:33.794] test/logging_tests.cpp(469): [1;31;49merror: in "logging_tests/logging_filesize_rate_limit": check ReadDebugLogLines().back().starts_with("[warning] Restarting logging") has failed[0;39;49m
538- ASSERT_DEBUG_LOG("Restarting logging");
539- MockForwardAndSync(scheduler, 1min);
540+ scheduler.MockForwardAndSync(time_window);
541+ auto log_lines{ReadDebugLogLines()};
542+ auto restart_pred = [](std::string& s) { return s.starts_with("[warning] Restarting logging"); };
543+ BOOST_CHECK(std::any_of(log_lines.begin(), log_lines.end(), restart_pred));
Re #33011 (comment):
Nice find re the lock contention. I was able to hit this from other locations in the test too on my machine. As you suggested offline, I think the best fix is to disable the LOCK category for this test. It might be helpful to first add a commit to prevent leaking categories across tests (e.g. https://github.com/stickies-v/bitcoin/commit/3d96ff75f161419654b14a7e9fd884e52aec26c4), and then the below diff should work?
0diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
1index 919222f5f8..df00d2e570 100644
2--- a/src/test/logging_tests.cpp
3+++ b/src/test/logging_tests.cpp
4@@ -451,6 +451,12 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
5 LogInstance().m_log_sourcelocations = false;
6 LogInstance().m_log_threadnames = false;
7
8+// This test's scheduler schedules new tasks on 2 threads, potentially causing (non-circular)
9+// lock contentions. Disable those logs so we can maintain a tight accounting.
10+#ifdef DEBUG_LOCKCONTENTION
11+ LogInstance().DisableCategory(BCLog::LogFlags::LOCK);
12+#endif
13+
14 constexpr int64_t line_length{1024};
15 constexpr int64_t num_lines{1024};
16 constexpr int64_t bytes_quota{line_length * num_lines};
17@@ -470,9 +476,7 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
18 TestLogFromLocation(Location::INFO_2, "c", Status::UNSUPPRESSED, /*suppressions_active=*/true);
19 {
20 scheduler.MockForwardAndSync(time_window);
21- auto log_lines{ReadDebugLogLines()};
22- auto restart_pred = [](std::string& s) { return s.starts_with("[warning] Restarting logging"); };
23- BOOST_CHECK(std::any_of(log_lines.begin(), log_lines.end(), restart_pred));
24+ BOOST_CHECK(ReadDebugLogLines().back().starts_with("[warning] Restarting logging"));
25 }
26 // Check that logging from previously suppressed location is unsuppressed again.
27 TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
LogInstance().EnableCategory(BCLog::LogFlags::NONE); line.
LogInstance().DisableCategory(BCLog::LogFlags::ALL);. I still think that’s worth keeping, so we can always assume LogTest starts without any categories (as is default)?
#ifdef DEBUG_LOCKCONTENTION since the category masks are now properly reset between tests (thanks!).
Latest push d434155db5f9c34b8ab3e19038d824d161b34195 -> f57496e:
logging_filesize_rate_limit to disable BCLog::LogFlags::LOCK if DEBUG_LOCKCONTENTION is definedThis gets rid of the test flake without hacking around ReadDebugLogLines.
🚧 At least one of the CI tasks failed.
Task MSan, depends: https://github.com/bitcoin/bitcoin/runs/47136399385
LLM reason (✨ experimental): The CI failure is caused by the “logging_tests” test failing during execution.
Try to run the tests locally, according to the documentation. However, a CI failure may still happen due to a number of reasons, for example:
Possibly due to a silent merge conflict (the changes in this pull request being incompatible with the current code in the target branch). If so, make sure to rebase on the latest commit of the target branch.
A sanitizer issue, which can only be found by compiling with the sanitizer and running the affected test.
An intermittent issue.
Leave a comment here, if you need help tracking down a confusing failure.
413- }
414+ return;
415+ case Location::DEBUG_LOG:
416+ LogDebug(BCLog::LogFlags::HTTP, "%s\n", message);
417+ return;
418+ case Location::INFO_NOLIMIT:
(source location is unrelated, just wanted to get into thread mode) I wanted to add something to this this thread.
I didn’t review the original PR, but I would appreciate an -ratelimitlogging option for the sake of testing, undocumented / DEBUG_ONLY would be fine for me:
feature_taproot.py, p2p_headers_sync_with_minchainwork.py, wallet_avoidreuse.py, wallet_taproot.py). Having suppressed logs could make it harder to debug these in case of Errors.
Rate logging could also be unset by default by the functional tests.LogPrintLevel_ / should_ratelimit=false statements or a category, which will also log other additional stuff.
116@@ -117,6 +117,7 @@ def __init__(self, i, datadir_path, *, chain, rpchost, timewait, timeout_factor,
117 "-debugexclude=leveldb",
118 "-debugexclude=rand",
119 "-uacomment=testnode%d" % i, # required for subversion uniqueness across peers
120+ "-disableratelimitlogging",
logthreadnames below
feature_taproot.py go away.
Latest push 31ef2b6 -> 8dd5c0a:
Should the DEBUG_ONLY flag get a release note?
1380@@ -1381,10 +1381,12 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
1381 }
1382 }, std::chrono::minutes{5});
1383
1384- LogInstance().SetRateLimiting(std::make_unique<BCLog::LogRateLimiter>(
1385- [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); },
1386- BCLog::RATELIMIT_MAX_BYTES,
1387- 1h));
1388+ if (!args.IsArgSet("-disableratelimitlogging")) {
This is a bit brittle, e.g. if started with -disableratelimitlogging=0 this would still disable ratelimiting. I’d suggest using the actual boolean value rather than checking if the argument is set. Also, ArgsManager has a built-in negation system: arguments also have a “no{arg}” option to disable it, which currently would be -nodisableratelimitlogging which is getting quite verbose.
Would prefer keeping options positive, and switch to -{no}logratelimit instead, keeping naming in line with other log options.
Full diff to implement that:
0diff --git a/src/init.cpp b/src/init.cpp
1index 5f882cefb5..fc6d02246f 100644
2--- a/src/init.cpp
3+++ b/src/init.cpp
4@@ -1381,11 +1381,13 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
5 }
6 }, std::chrono::minutes{5});
7
8- if (!args.IsArgSet("-disableratelimitlogging")) {
9+ if (args.GetBoolArg("-logratelimit", BCLog::DEFAULT_LOGRATELIMIT)) {
10 LogInstance().SetRateLimiting(BCLog::LogRateLimiter::Create(
11 [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); },
12 BCLog::RATELIMIT_MAX_BYTES,
13 BCLog::RATELIMIT_WINDOW));
14+ } else {
15+ LogInfo("Log ratelimiting disabled.");
16 }
17
18 assert(!node.validation_signals);
19diff --git a/src/init/common.cpp b/src/init/common.cpp
20index b5710be45d..c6236365ea 100644
21--- a/src/init/common.cpp
22+++ b/src/init/common.cpp
23@@ -38,9 +38,9 @@ void AddLoggingArgs(ArgsManager& argsman)
24 argsman.AddArg("-logsourcelocations", strprintf("Prepend debug output with name of the originating source location (source file, line number and function name) (default: %u)", DEFAULT_LOGSOURCELOCATIONS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
25 argsman.AddArg("-logtimemicros", strprintf("Add microsecond precision to debug timestamps (default: %u)", DEFAULT_LOGTIMEMICROS), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
26 argsman.AddArg("-loglevelalways", strprintf("Always prepend a category and level (default: %u)", DEFAULT_LOGLEVELALWAYS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
27+ argsman.AddArg("-logratelimit", strprintf("Apply ratelimiting to unconditional logging to mitigate disk-filling attacks (default: %u)", BCLog::DEFAULT_LOGRATELIMIT), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
28 argsman.AddArg("-printtoconsole", "Send trace/debug info to console (default: 1 when no -daemon. To disable logging to file, set -nodebuglogfile)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
29 argsman.AddArg("-shrinkdebugfile", "Shrink debug.log file on client startup (default: 1 when no -debug)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
30- argsman.AddArg("-disableratelimitlogging", "Disable rate limit logging", ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
31 }
32
33 void SetLoggingOptions(const ArgsManager& args)
34diff --git a/src/logging.h b/src/logging.h
35index 623bd97e56..3d97b460cc 100644
36--- a/src/logging.h
37+++ b/src/logging.h
38@@ -107,6 +107,7 @@ namespace BCLog {
39 constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging
40 constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the RATELIMIT_WINDOW
41 constexpr auto RATELIMIT_WINDOW{1h}; // time window after which log ratelimit stats are reset
42+ constexpr bool DEFAULT_LOGRATELIMIT{true};
43
44 //! Fixed window rate limiter for logging.
45 class LogRateLimiter : public std::enable_shared_from_this<LogRateLimiter>
46diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py
47index 09d611128c..3b0814635a 100755
48--- a/test/functional/test_framework/test_node.py
49+++ b/test/functional/test_framework/test_node.py
50@@ -137,7 +137,7 @@ class TestNode():
51 if self.version_is_at_least(239000):
52 self.args.append("-loglevel=trace")
53 if self.version_is_at_least(299900):
54- self.args.append("-disableratelimitlogging")
55+ self.args.append("-nologratelimit")
56
57 # Default behavior from global -v2transport flag is added to args to persist it over restarts.
58 # May be overwritten in individual tests, using extra_args.
src/logging.h.
39@@ -40,6 +40,7 @@ void AddLoggingArgs(ArgsManager& argsman)
40 argsman.AddArg("-loglevelalways", strprintf("Always prepend a category and level (default: %u)", DEFAULT_LOGLEVELALWAYS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
41 argsman.AddArg("-printtoconsole", "Send trace/debug info to console (default: 1 when no -daemon. To disable logging to file, set -nodebuglogfile)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
42 argsman.AddArg("-shrinkdebugfile", "Shrink debug.log file on client startup (default: 1 when no -debug)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
43+ argsman.AddArg("-disableratelimitlogging", "Disable rate limit logging", ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
Probably good to add this to release notes?
0diff --git a/doc/release-notes-32604.md b/doc/release-notes-32604.md
1index d4d3726e86..1aaebc185b 100644
2--- a/doc/release-notes-32604.md
3+++ b/doc/release-notes-32604.md
4@@ -4,7 +4,8 @@ Unconditional logging to disk is now rate limited by giving each source location
5 a quota of 1MiB per hour. Unconditional logging is any logging with a log level
6 higher than debug, that is `info`, `warning`, and `error`. All logs will be
7 prefixed with `[*]` if there is at least one source location that is currently
8-being suppressed. (#32604)
9+being suppressed. Ratelimiting can be disabled globally with
10+`-nologratelimit`. (#32604)
11
12 When `-logsourcelocations` is enabled, the log output now contains the entire
13 function signature instead of just the function name. (#32604)
Isn’t -logratelimit a DEBUG_ONLY param? As far as I know we don’t usually document those:
dbbatchsizefastprunetxreconciliationpeertimeout (only a commit message mention back when we added those)peertimeoutetc
minimumchainwork, mentioning it as a hidden debug arg: https://github.com/bitcoin/bitcoin/blob/master/doc/release-notes/release-notes-0.15.1.md?plain=1#L125-L129
and for a few RPC settings.Given, that we didn’t even want to include this at first, I’m not sure it’s worth documenting it.
(sorry, should have edited my previous comment instead of deleting it, I misunderstood what you were replying to)
You’re right that we shouldn’t advertise it. I thought adding it to release notes made sense for downstream projects that e.g. have their own test suite that could break because of this. I’m happy for the commit to be dropped, or be updated to highlight that it’s a DEBUG_ONLY option.
ACK 8dd5c0a0447bbb6fe597aabfa725b397276da166
It’s a debug-only option, so I suppose not technically a blocker, but would be best to change the -disableratelimitlogging option before merging.
re-ACK 7bc28668cc791d28fe824476d2c1f236c5a772d0
Thanks for addressing all comments and keeping everything super organized all the time. A pleasure to review your PR, again.
569- if (bytes > m_available_bytes) {
570- m_dropped_bytes += bytes;
571- m_available_bytes = 0;
572+ if (bytes > available_bytes) {
573+ dropped_bytes += bytes;
574+ available_bytes = 0;
m_ prefix. This would also make the diff smaller.
166@@ -176,6 +167,8 @@ namespace BCLog {
167 void Reset() EXCLUSIVE_LOCKS_REQUIRED(!m_mutex);
168 //! Returns true if any log locations are currently being suppressed.
169 bool SuppressionsActive() const { return m_suppression_active; }
170+ //! The function that is used to schedule the reset window.
171+ SchedulerFunction m_scheduler_func;
398@@ -394,6 +399,7 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
399 LogInstance().m_log_sourcelocations = false;
400 bool prev_log_threadnames = LogInstance().m_log_threadnames;
401 LogInstance().m_log_threadnames = false;
402+ LogInstance().EnableCategory(BCLog::LogFlags::HTTP);
LogFromLocation can log with the BCLog::LogFlags::HTTP flag (the tests share the single LogInstance()). I do agree that it’s a little awkward in this commit.
HTTP in the next commit, in f8b218418e8e716e210ee247e143172f6ef4fc93 all the levels are still Info, had me confused for a bit too.
433 {
434- ASSERT_DEBUG_LOG(expect);
435+ using Status = BCLog::LogRateLimiter::Status;
436+ if (!suppressions_active) assert(status == Status::UNSUPPRESSED); // developer error
437+
438+ std::ofstream ofs(LogInstance().m_file_path, std::ios::out | std::ios::trunc); // clear debug log
nit in eb333104efd91b5cd994b1937cd4f81b8dd8c851: Why does truncation work, when this isn’t flushed (ofs remains in scope), and even if it was flushed, is it guaranteed to be picked up by the other open file descriptor, which doesn’t flush either after writes?
Would it be better to ftell and then read from there?
ftell would work and avoids the issue of multiple file descriptors. The only downside is that m_fileout would need a getter or to no longer be private which may encourage somebody to use it outside of the test?
Here’s my guess why this works (may be wrong!):
std::ofstream truncates the file since std::ios::trunc is used, this doesn’t need a flush (there’s no buffering afaict). m_fileout (see manpage for truncate)LogFromLocation is called. Note two things… 1) the file was opened in append mode, and 2) buffering is disabled. Since the file was opened in append mode, each write will move the file offset to the end of the now-truncated file (see the part about O_APPEND in the manpage for the write syscall here)ReadDebugLogLines call will correctly read the bytes written in LogFromLocation.EDIT: It seems like the open syscall used in std::ofstream uses O_TRUNC rather than using the truncate syscall as linked above. From what I read, this doesn’t seem to need any buffering though.
nothing blocking, just very minor nits/questions.
review ACK 7bc28668cc791d28fe824476d2c1f236c5a772d0 🕙
Signature:
0untrusted comment: signature from minisign secret key on empty file; verify via: minisign -Vm "${path_to_any_empty_file}" -P RWTRmVTMeKV5noAMqVlsMugDDCyyTSbA3Re5AkUrhvLVln0tSaFWglOw -x "${path_to_this_whole_four_line_signature_blob}"
1RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
2trusted comment: review ACK 7bc28668cc791d28fe824476d2c1f236c5a772d0 🕙
3uUQiEQGUzj9jy99YEHObbOge+6ZfW5SIo6syrKomp3j0n6SYixr7vX43b6jXDN4DOO63UXBKS0C0plRGNiuaCQ==
Clean up the noisy LogLimitStats and remove references to the time
window.
Co-Authored-By: stickies-v <stickies-v@protonmail.com>
In LogPrintStr_:
- remove an unnecessary BCLog since we are in the BCLog namespace.
- remove an unnecessary \n when rate limiting is triggered since
FormatLogStrInPlace will add it.
- move the ratelimit bool into an else if block.
- prefix all log lines with [*] when suppressions exist. Previously this
was only done if should_ratelimit was true.
In Reset:
- remove an unnecessary \n since FormatLogStrInPlace will add it.
- Change Level::Info to Level::Warning.
re-ACK f1d25abcaa6a85fec08ea760036f2c7c02945ba8
No changes except addressing review nits.
51- .Write(std::hash<std::string_view>{}(s.file_name()))
52- .Write(s.line())
53- .Finalize());
54+ return size_t(CSipHasher(0, 0)
55+ .Write(s.line())
56+ .Write(MakeUCharSpan(std::string_view{s.file_name()}))
387+ scheduler_func([weak_limiter] {
388+ if (auto shared_limiter{weak_limiter.lock()}) {
389+ shared_limiter->Reset();
390+ }
391+ },
392+ limiter->m_reset_window);
The formatting is clang-format output, but it can also be simplified to:
0 auto reset = [weak_limiter] {
1 if (auto shared_limiter{weak_limiter.lock()}) shared_limiter->Reset();
2 };
3 scheduler_func(reset, limiter->m_reset_window);
380+
381+std::shared_ptr<BCLog::LogRateLimiter> BCLog::LogRateLimiter::Create(
382+ SchedulerFunction scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window)
383 {
384- scheduler_func([this] { Reset(); }, reset_window);
385+ auto limiter{std::shared_ptr<LogRateLimiter>(new LogRateLimiter(max_bytes, reset_window))};
I didn’t like the shared_ptr + weak_ptr change at first, but to decouple the two lifecycles it may be better than before.
Q: Are you sure this allocation is correct? I don’t see the problem with it, but my linter is complaining that Allocated memory is leaked: Reports memory allocations (using either 'new' or 'malloc()') that were not released before becoming inaccessible.
Maybe we could use a std::make_shared here (we may need to adjust the constructor for that)
make_shared approach?
-fsanitize=leak, nothing reported.
How would you implement the make_shared approach?
According to the docs:
std::shared_ptr<T>(new T(args...))may call a non-public constructor ofTif executed in context where it is accessible, whilestd::make_sharedrequires public access to the selected constructor.
so something like:
0diff --git a/src/logging.cpp b/src/logging.cpp
1index 2ed6835197..840d2ac8c6 100644
2--- a/src/logging.cpp
3+++ b/src/logging.cpp
4@@ -377,11 +377,11 @@ BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds r
5 std::shared_ptr<BCLog::LogRateLimiter> BCLog::LogRateLimiter::Create(
6 SchedulerFunction&& scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window)
7 {
8- auto limiter{std::shared_ptr<LogRateLimiter>(new LogRateLimiter(max_bytes, reset_window))};
9- std::weak_ptr<LogRateLimiter> weak_limiter{limiter};
10- auto reset = [weak_limiter] {
11+ auto limiter{std::make_shared<LogRateLimiter>(max_bytes, reset_window)};
12+ std::weak_ptr weak_limiter{limiter};
13+ auto reset{[weak_limiter] {
14 if (auto shared_limiter{weak_limiter.lock()}) shared_limiter->Reset();
15- };
16+ }};
17 scheduler_func(reset, limiter->m_reset_window);
18 return limiter;
19 }
20diff --git a/src/logging.h b/src/logging.h
21index 9419e245bd..a551cdba20 100644
22--- a/src/logging.h
23+++ b/src/logging.h
24@@ -131,9 +131,10 @@ namespace BCLog {
25 std::unordered_map<std::source_location, Stats, SourceLocationHasher, SourceLocationEqual> m_source_locations GUARDED_BY(m_mutex);
26 //! Whether any log locations are suppressed. Cached view on m_source_locations for performance reasons.
27 std::atomic<bool> m_suppression_active{false};
28- LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window);
29
30 public:
31+ LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window);
32+
33 using SchedulerFunction = std::function<void(std::function<void()>, std::chrono::milliseconds)>;
34 /**
35 * [@param](/bitcoin-bitcoin/contributor/param/) scheduler_func Callable object used to schedule resetting the window. The first
could work. I’m not getting a warning this way + test are passing.
377- std::chrono::seconds reset_window) : m_max_bytes{max_bytes}, m_reset_window{reset_window}
378+BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window)
379+ : m_max_bytes{max_bytes}, m_reset_window{reset_window} {}
380+
381+std::shared_ptr<BCLog::LogRateLimiter> BCLog::LogRateLimiter::Create(
382+ SchedulerFunction scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window)
scheduler_func is copied for each invocation
BCLog::LogRateLimiter::Create to take SchedulerFunction&&.
137- {
138- return m_dropped_bytes;
139- }
140- };
141+ //! Keeps track of an individual source location and how many available bytes are left for logging from it.
142+ struct Stats {
443-void LogFromLocationAndExpect(int location, std::string message, std::string expect)
444+/**
445+ * For a given `location` and `message`, ensure that the on-disk debug log behaviour resembles what
446+ * we'd expect it to be for `status` and `suppressions_active`.
447+ */
448+void TestLogFromLocation(Location location, const std::string& message,
140- };
141+ //! Keeps track of an individual source location and how many available bytes are left for logging from it.
142+ struct Stats {
143+ //! Remaining bytes
144+ uint64_t m_available_bytes;
145+ //! Number of bytes that were consumed but didn't fit in the available bytes.
m_dropped_bytes from bytes that were not consumed to bytes that were consumed but didn't fit
Stats::Consume, but didn’t fit, so they were dropped.
333 auto reset_window{1min};
334- auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); };
335- BCLog::LogRateLimiter limiter{sched_func, max_bytes, reset_window};
336+ ScopedScheduler scheduler{};
337+ auto limiter_{scheduler.GetLimiter(max_bytes, reset_window)};
338+ auto& limiter{*Assert(limiter_)};
limiter. usages to limiter-> if we had const auto limiter{Assert(scheduler.GetLimiter(max_bytes, reset_window))};?
I have done a quick scan over the commits only, left nits and questions, nothing critical.
Lightweight code review ACK f1d25abcaa6a85fec08ea760036f2c7c02945ba8
Note: I understand that this likely isn’t consensus critical change but I would have preferred modifying the code once, in the original PR. Or maybe adding cleanup commits in a separate PR before the change. But if we need 12 follow-up commits, I think it tells us that the original one might have been merged a bit too quickly.
111+ constexpr bool DEFAULT_LOGRATELIMIT{true};
112
113- //! Keeps track of an individual source location and how many available bytes are left for logging from it.
114- class LogLimitStats
115+ //! Fixed window rate limiter for logging.
116+ class LogRateLimiter : public std::enable_shared_from_this<LogRateLimiter>
nit: sorry, std::enable_shared_from_this<LogRateLimiter> was from an earlier approach, can be removed now
0 class LogRateLimiter
This allows us to safely and explicitly manage the dual dependency
on the limiter: one for the Logger, and one for the CScheduler.
Deduplicates repeated usage of the same functionality.
This ensures log tests behave consistently when other tests modify
the log category mask.
- Add helper functions and structs to improve readability and
reusability of test code
- Make tests more specific by comparing all produced log lines with
expected log lines instead of relying on approximations or proxies.
Use -nologratelimit by default in functional tests if the bitcoind
version supports it.
Co-Authored-By: stickies-v <stickies-v@protonmail.com>
The latest push f1d25ab -> 5c74a0b:
-logratelimitLogRateLimiter in 3d630c2544e19480268426cda245796d4ce34ac3
301+struct ScopedScheduler {
302+ CScheduler scheduler{};
303+
304+ ScopedScheduler()
305+ {
306+ scheduler.m_service_thread = std::thread([this] { scheduler.serviceQueue(); });
468 m_limiter->m_max_bytes,
469 Ticks<std::chrono::seconds>(m_limiter->m_reset_window)),
470 std::source_location::current(), LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false); // with should_ratelimit=false, this cannot lead to infinite recursion
471+ } else if (status == LogRateLimiter::Status::STILL_SUPPRESSED) {
472+ ratelimit = true;
473 }
We already have a should_ratelimit and we’re calculating the ratelimit again. The distinction isn’t immediately obvious.
Maybe the should_ratelimit parameter could be called rate_limit_enabled, while the line limiting could maybe be is_rate_limited though that still isn’t as clear as I’d like it to be.
Also, the else if makew it more complicated in my opinion (we have to look what the value is if we entered the NEWLY_SUPPRESSED branch). We can just assign it if we entered here:
0 is_rate_limited = (status == LogRateLimiter::Status::STILL_SUPPRESSED);
rate_limit_enabled is probably better than should_ratelimit, I agree, though I think naming is really a preference.
For the else if, I was implementing this comment: #32604 (review). I personally don’t find it too confusing.
478- str_prefixed.insert(0, "[*] ");
479- }
480+ }
481+
482+ // To avoid confusion caused by dropped log messages when debugging an issue,
483+ // we prefix log lines with "[*]" when there are any suppressed source locations.
I’m not sure I understand what “debugging” or “issue” mean in this context:
0 // Prefix log lines while any source is rate-limited to indicate logs are incomplete.
479- }
480+ }
481+
482+ // To avoid confusion caused by dropped log messages when debugging an issue,
483+ // we prefix log lines with "[*]" when there are any suppressed source locations.
484+ if (m_limiter && m_limiter->SuppressionsActive()) {
👍 for the m_limiter guard, but learning from the fact that we forgot to do it, maybe we can extract this:
0bool is_rate_limited{false};
1if (m_limiter) {
2 if (rate_limit_enabled) {
3 auto status{m_limiter->Consume(source_loc, str_prefixed)};
4 if (status == LogRateLimiter::Status::NEWLY_SUPPRESSED) {
5 // NOLINTNEXTLINE(misc-no-recursion)
6 LogPrintStr_(strprintf(
7 "Excessive logging detected from %s:%d (%s): >%d bytes logged during "
8 "the last time window of %is. Suppressing logging to disk from this "
9 "source location until time window resets. Console logging "
10 "unaffected. Last log entry.",
11 source_loc.file_name(), source_loc.line(), source_loc.function_name(),
12 m_limiter->m_max_bytes,
13 Ticks<std::chrono::seconds>(m_limiter->m_reset_window)),
14 std::source_location::current(), LogFlags::ALL, Level::Warning, /*rate_limit_enabled=*/false); // with rate_limit_enabled=false, this cannot lead to infinite recursion
15 }
16 is_rate_limited = (status == LogRateLimiter::Status::STILL_SUPPRESSED);
17 }
18
19 // Prefix log lines while any source is rate-limited to indicate logs are incomplete.
20 if (m_limiter->SuppressionsActive()) str_prefixed.insert(0, "[*] ");
21}
461 LogPrintStr_(strprintf(
462 "Excessive logging detected from %s:%d (%s): >%d bytes logged during "
463 "the last time window of %is. Suppressing logging to disk from this "
464 "source location until time window resets. Console logging "
465- "unaffected. Last log entry.\n",
466+ "unaffected. Last log entry.",
but it’s not always the last log entry, right?
0"source location until time window resets. Console logging unaffected.
Code review ACK 5c74a0b397cb3db94761bad78801eed4544155b9
I still have a few suggestion that I think should be addressed, but I’m not blocking.
