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.
<!--e57a25ab6845829454e8d69fc972939a-->
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
<!--006a51241073e994b41acfe9ec718e94-->
For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/33011.
<!--021abf342d371248e50ceaed478a90ca-->
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.
<!--174a7506f384e20aa4161008e828411d-->
No conflicts as of last run.
<!--5faf32d7da4f0f540f40219e4f7537a3-->
Addressed in this PR:
Not addressed:
Won't address:
BOOST_CHECK_THROW and BOOST_CHECK_NO_THROW, so no longer relevant.
<!--85328a0da195eb286784d51f73fa0af9-->
🚧 At least one of the CI tasks failed.
<sub>Task previous releases, depends DEBUG: https://github.com/bitcoin/bitcoin/runs/46279969042</sub>
<sub>LLM reason (✨ experimental): Build error due to incomplete type in std::pair's second member caused by missing full definition of BCLog::LogRateLimiter::Stats.</sub>
<details><summary>Hints</summary>
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.
</details>
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:
<details> <summary>git diff on d0b3a80b7f</summary>
diff --git a/src/init.cpp b/src/init.cpp
index 63244c802e..863b2e088e 100644
--- a/src/init.cpp
+++ b/src/init.cpp
@@ -1382,7 +1382,7 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
LogInstance().SetRateLimiting(std::make_unique<BCLog::LogRateLimiter>(
[&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); },
BCLog::RATELIMIT_MAX_BYTES,
- 1h));
+ BCLog::RATELIMIT_WINDOW));
assert(!node.validation_signals);
node.validation_signals = std::make_unique<ValidationSignals>(std::make_unique<SerialTaskRunner>(scheduler));
diff --git a/src/logging.h b/src/logging.h
index 5437d73c78..a2cbbf51f7 100644
--- a/src/logging.h
+++ b/src/logging.h
@@ -104,7 +104,8 @@ namespace BCLog {
};
constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging
- constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the specified time-window
+ constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the RATELIMIT_WINDOW
+ constexpr auto RATELIMIT_WINDOW{1h}; // time window after which log ratelimit stats are reset
//! Fixed window rate limiter for logging.
class LogRateLimiter
</details>
Fixed in 8319a134684df2240057a5e8afaa6ae441fb8a58
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()};
nit: 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.
Fixed in 526403df23a2db781709e4494da3a9f79284531d
389 | -void LogFromLocation(int location, std::string message) 390 | -{ 391 | +namespace { 392 | + 393 | +enum class Location { 394 | + FIRST,
nit: using descriptive names might make more sense, e.g. INFO_1, INFO_2, DEBUG, INFO_NOLIMIT
Fixed in 526403df23a2db781709e4494da3a9f79284531d, renamed 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:
<details> <summary>git diff on d0b3a80b7f</summary>
diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
index 81c0bacba0..245940f284 100644
--- a/src/test/logging_tests.cpp
+++ b/src/test/logging_tests.cpp
@@ -414,11 +414,10 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
bool prev_log_threadnames{LogInstance().m_log_threadnames};
LogInstance().m_log_threadnames = false;
- int64_t line_length{1023};
+ int64_t line_length{1024};
int64_t num_lines{1024};
- // Add 1 to line_length because of newline.
- int64_t bytes_quota{(line_length + 1) * num_lines};
+ int64_t bytes_quota{line_length * num_lines};
std::chrono::seconds time_window{20};
@@ -430,7 +429,7 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
std::unique_ptr<BCLog::LogRateLimiter> limiter{std::make_unique<BCLog::LogRateLimiter>(sched_func, bytes_quota, time_window)};
LogInstance().SetRateLimiting(std::move(limiter));
- std::string log_message(line_length, 'a');
+ std::string log_message(line_length - 1, 'a'); // subtract one for newline
std::string utf8_path{LogInstance().m_file_path.utf8string()};
const char* log_path{utf8_path.c_str()};
</details>
Also, constants could be marked as such. Diff including the previous suggestion:
<details> <summary>git diff on d0b3a80b7f</summary>
diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
index 81c0bacba0..62c92287dd 100644
--- a/src/test/logging_tests.cpp
+++ b/src/test/logging_tests.cpp
@@ -407,20 +407,17 @@ void LogFromLocationAndExpect(Location location, const std::string& message, con
BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
{
- bool prev_log_timestamps{LogInstance().m_log_timestamps};
+ const bool prev_log_timestamps{LogInstance().m_log_timestamps};
LogInstance().m_log_timestamps = false;
- bool prev_log_sourcelocations{LogInstance().m_log_sourcelocations};
+ const bool prev_log_sourcelocations{LogInstance().m_log_sourcelocations};
LogInstance().m_log_sourcelocations = false;
- bool prev_log_threadnames{LogInstance().m_log_threadnames};
+ const bool prev_log_threadnames{LogInstance().m_log_threadnames};
LogInstance().m_log_threadnames = false;
- int64_t line_length{1023};
- int64_t num_lines{1024};
-
- // Add 1 to line_length because of newline.
- int64_t bytes_quota{(line_length + 1) * num_lines};
-
- std::chrono::seconds time_window{20};
+ constexpr int64_t line_length{1024};
+ constexpr int64_t num_lines{1024};
+ constexpr int64_t bytes_quota{line_length * num_lines};
+ constexpr std::chrono::seconds time_window{20};
CScheduler scheduler{};
scheduler.m_service_thread = std::thread([&] { scheduler.serviceQueue(); });
@@ -430,9 +427,8 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
std::unique_ptr<BCLog::LogRateLimiter> limiter{std::make_unique<BCLog::LogRateLimiter>(sched_func, bytes_quota, time_window)};
LogInstance().SetRateLimiting(std::move(limiter));
- std::string log_message(line_length, 'a');
-
- std::string utf8_path{LogInstance().m_file_path.utf8string()};
+ const std::string log_message(line_length - 1, 'a'); // subtract one for newline
+ const std::string utf8_path{LogInstance().m_file_path.utf8string()};
const char* log_path{utf8_path.c_str()};
// Use GetFileSize because fs::file_size may require a flush to be accurate.
</details>
Fixed in 526403df23a2db781709e4494da3a9f79284531d
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
MockForwardAndSync(scheduler, time_window);
Fixed in 526403df23a2db781709e4494da3a9f79284531d
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?
Fixed in 526403df23a2db781709e4494da3a9f79284531d
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:
<details> <summary>git diff on d0b3a80b7f</summary>
diff --git a/src/init.cpp b/src/init.cpp
index 63244c802e..75db37397c 100644
--- a/src/init.cpp
+++ b/src/init.cpp
@@ -1379,7 +1379,7 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
}
}, std::chrono::minutes{5});
- LogInstance().SetRateLimiting(std::make_unique<BCLog::LogRateLimiter>(
+ LogInstance().SetRateLimiting(BCLog::LogRateLimiter::Create(
[&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); },
BCLog::RATELIMIT_MAX_BYTES,
1h));
diff --git a/src/logging.cpp b/src/logging.cpp
index e2c27ec54d..3d42bd9bc8 100644
--- a/src/logging.cpp
+++ b/src/logging.cpp
@@ -371,12 +371,21 @@ static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
}
-BCLog::LogRateLimiter::LogRateLimiter(
- SchedulerFunction scheduler_func,
- uint64_t max_bytes,
- std::chrono::seconds reset_window) : m_max_bytes{max_bytes}, m_reset_window{reset_window}
+BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window)
+ : m_max_bytes{max_bytes}, m_reset_window{reset_window} {}
+
+std::shared_ptr<BCLog::LogRateLimiter> BCLog::LogRateLimiter::Create(
+ SchedulerFunction scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window)
{
- scheduler_func([this] { Reset(); }, reset_window);
+ auto limiter{std::shared_ptr<LogRateLimiter>(new LogRateLimiter(max_bytes, reset_window))};
+ std::weak_ptr<LogRateLimiter> weak_limiter{limiter};
+ scheduler_func([weak_limiter] {
+ if (auto shared_limiter{weak_limiter.lock()}) {
+ shared_limiter->Reset();
+ }
+ },
+ limiter->m_reset_window);
+ return limiter;
}
BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume(
diff --git a/src/logging.h b/src/logging.h
index 5437d73c78..12905f1e47 100644
--- a/src/logging.h
+++ b/src/logging.h
@@ -18,6 +18,7 @@
#include <cstring>
#include <functional>
#include <list>
+#include <memory>
#include <mutex>
#include <source_location>
#include <string>
@@ -107,7 +108,7 @@ namespace BCLog {
constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the specified time-window
//! Fixed window rate limiter for logging.
- class LogRateLimiter
+ class LogRateLimiter : public std::enable_shared_from_this<LogRateLimiter>
{
public:
//! Keeps track of an individual source location and how many available bytes are left for logging from it.
@@ -129,6 +130,7 @@ namespace BCLog {
std::unordered_map<std::source_location, Stats, SourceLocationHasher, SourceLocationEqual> m_source_locations GUARDED_BY(m_mutex);
//! Whether any log locations are suppressed. Cached view on m_source_locations for performance reasons.
std::atomic<bool> m_suppression_active{false};
+ LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window);
public:
using SchedulerFunction = std::function<void(std::function<void()>, std::chrono::milliseconds)>;
@@ -140,7 +142,10 @@ namespace BCLog {
* location.
* [@param](/bitcoin-bitcoin/contributor/param/) reset_window Time window after which the stats are reset.
*/
- LogRateLimiter(SchedulerFunction scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window);
+ static std::shared_ptr<LogRateLimiter> Create(
+ SchedulerFunction scheduler_func,
+ uint64_t max_bytes,
+ std::chrono::seconds reset_window);
//! Maximum number of bytes logged per location per window.
const uint64_t m_max_bytes;
//! Interval after which the window is reset.
@@ -160,6 +165,8 @@ namespace BCLog {
void Reset() EXCLUSIVE_LOCKS_REQUIRED(!m_mutex);
//! Returns true if any log locations are currently being suppressed.
bool SuppressionsActive() const { return m_suppression_active; }
+ //! The function that is used to schedule the reset window.
+ SchedulerFunction m_scheduler_func;
};
class Logger
@@ -185,7 +192,7 @@ namespace BCLog {
size_t m_buffer_lines_discarded GUARDED_BY(m_cs){0};
//! Manages the rate limiting of each log location.
- std::unique_ptr<LogRateLimiter> m_limiter GUARDED_BY(m_cs);
+ std::shared_ptr<LogRateLimiter> m_limiter GUARDED_BY(m_cs);
//! Category-specific log level. Overrides `m_log_level`.
std::unordered_map<LogFlags, Level> m_category_log_levels GUARDED_BY(m_cs);
@@ -254,7 +261,7 @@ namespace BCLog {
/** Only for testing */
void DisconnectTestLogger() EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
- void SetRateLimiting(std::unique_ptr<LogRateLimiter>&& limiter) EXCLUSIVE_LOCKS_REQUIRED(!m_cs)
+ void SetRateLimiting(std::shared_ptr<LogRateLimiter> limiter) EXCLUSIVE_LOCKS_REQUIRED(!m_cs)
{
StdLockGuard scoped_lock(m_cs);
m_limiter = std::move(limiter);
diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
index 81c0bacba0..ea0297367d 100644
--- a/src/test/logging_tests.cpp
+++ b/src/test/logging_tests.cpp
@@ -311,7 +311,8 @@ BOOST_AUTO_TEST_CASE(logging_log_rate_limiter)
BCLog::LogRateLimiter::SchedulerFunction sched_func{[&scheduler](std::function<void()> func, std::chrono::milliseconds window) {
scheduler.scheduleEvery(std::move(func), window);
}};
- BCLog::LogRateLimiter limiter{sched_func, max_bytes, reset_window};
+ auto limiter_{BCLog::LogRateLimiter::Create(sched_func, max_bytes, reset_window)};
+ auto& limiter{*limiter_};
using Status = BCLog::LogRateLimiter::Status;
std::source_location source_loc_1{std::source_location::current()};
@@ -427,8 +428,7 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
BCLog::LogRateLimiter::SchedulerFunction sched_func{[&scheduler](std::function<void()> func, std::chrono::milliseconds window) {
scheduler.scheduleEvery(std::move(func), window);
}};
- std::unique_ptr<BCLog::LogRateLimiter> limiter{std::make_unique<BCLog::LogRateLimiter>(sched_func, bytes_quota, time_window)};
- LogInstance().SetRateLimiting(std::move(limiter));
+ LogInstance().SetRateLimiting(BCLog::LogRateLimiter::Create(sched_func, bytes_quota, time_window));
std::string log_message(line_length, 'a');
</details>
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_?
Fixed in 65c8072757e58f9cad1198ddd8e403d656bb68e2
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?
This is better, will implement.
Implemented in 526403df23a2db781709e4494da3a9f79284531d, but I think there is a CI failure now.
code lgtm 8aa2726f1cfbc1e4267a796cb000c4eeae5910f5 - but would like to see if we can make improvements on the 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>
<!--85328a0da195eb286784d51f73fa0af9-->
🚧 At least one of the CI tasks failed.
<sub>Task MSan, depends: https://github.com/bitcoin/bitcoin/runs/46865525511</sub>
<sub>LLM reason (✨ experimental): The CI failure is caused by a macro name conflict where DEBUG is redefined as 1, causing syntax errors during compilation.</sub>
<details><summary>Hints</summary>
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.
</details>
Concept ACK
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:
[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.
[14:38:33.794] [*] a
[14:38:33.794] [*] b
[14:38:33.794] [*] c
[14:38:33.794] [lock] Enter: lock contention newTaskMutex, scheduler.cpp:74 started
[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.
[14:38:33.794] [lock] Enter: lock contention newTaskMutex, scheduler.cpp:74 completed (10μs)
[14:38:33.794] [lock] Enter: lock contention newTaskMutex, scheduler.cpp:74 started
[14:38:33.794] [lock] Enter: lock contention newTaskMutex, scheduler.cpp:74 completed (36μs)
[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?
<details> <summary>git diff on 3d96ff75f1</summary>
diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
index 919222f5f8..df00d2e570 100644
--- a/src/test/logging_tests.cpp
+++ b/src/test/logging_tests.cpp
@@ -451,6 +451,12 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
LogInstance().m_log_sourcelocations = false;
LogInstance().m_log_threadnames = false;
+// This test's scheduler schedules new tasks on 2 threads, potentially causing (non-circular)
+// lock contentions. Disable those logs so we can maintain a tight accounting.
+#ifdef DEBUG_LOCKCONTENTION
+ LogInstance().DisableCategory(BCLog::LogFlags::LOCK);
+#endif
+
constexpr int64_t line_length{1024};
constexpr int64_t num_lines{1024};
constexpr int64_t bytes_quota{line_length * num_lines};
@@ -470,9 +476,7 @@ BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
TestLogFromLocation(Location::INFO_2, "c", Status::UNSUPPRESSED, /*suppressions_active=*/true);
{
scheduler.MockForwardAndSync(time_window);
- auto log_lines{ReadDebugLogLines()};
- auto restart_pred = [](std::string& s) { return s.starts_with("[warning] Restarting logging"); };
- BOOST_CHECK(std::any_of(log_lines.begin(), log_lines.end(), restart_pred));
+ BOOST_CHECK(ReadDebugLogLines().back().starts_with("[warning] Restarting logging"));
}
// Check that logging from previously suppressed location is unsuppressed again.
TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
</details>
Yup, I had also hit the lock contention logging issue in other parts of the test. I ran the suggested diff 100 times without any error. Will add.
Fixed in latest push. Only modification to https://github.com/stickies-v/bitcoin/commit/3d96ff75f161419654b14a7e9fd884e52aec26c4 was that I removed the LogInstance().EnableCategory(BCLog::LogFlags::NONE); line.
Yeah sorry that should've been 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)?
Per offline discussion, removed the #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.
<!--85328a0da195eb286784d51f73fa0af9-->
🚧 At least one of the CI tasks failed.
<sub>Task MSan, depends: https://github.com/bitcoin/bitcoin/runs/47136399385</sub>
<sub>LLM reason (✨ experimental): The CI failure is caused by the "logging_tests" test failing during execution.</sub>
<details><summary>Hints</summary>
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.
</details>
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.
Oh, I did not know functional tests were hitting the limit. I will add an option to disable the rate limiting.
Should be fixed in 8dd5c0a0447bbb6fe597aabfa725b397276da166
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",
this has to be guarded, see e.g. the logthreadnames below
thanks, will fix.
should be fixed in 8dd5c0a0447bbb6fe597aabfa725b397276da166, I tested that the suppressed logs for 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:
<details> <summary>git diff on 8dd5c0a044</summary>
diff --git a/src/init.cpp b/src/init.cpp
index 5f882cefb5..fc6d02246f 100644
--- a/src/init.cpp
+++ b/src/init.cpp
@@ -1381,11 +1381,13 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
}
}, std::chrono::minutes{5});
- if (!args.IsArgSet("-disableratelimitlogging")) {
+ if (args.GetBoolArg("-logratelimit", BCLog::DEFAULT_LOGRATELIMIT)) {
LogInstance().SetRateLimiting(BCLog::LogRateLimiter::Create(
[&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); },
BCLog::RATELIMIT_MAX_BYTES,
BCLog::RATELIMIT_WINDOW));
+ } else {
+ LogInfo("Log ratelimiting disabled.");
}
assert(!node.validation_signals);
diff --git a/src/init/common.cpp b/src/init/common.cpp
index b5710be45d..c6236365ea 100644
--- a/src/init/common.cpp
+++ b/src/init/common.cpp
@@ -38,9 +38,9 @@ void AddLoggingArgs(ArgsManager& argsman)
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);
argsman.AddArg("-logtimemicros", strprintf("Add microsecond precision to debug timestamps (default: %u)", DEFAULT_LOGTIMEMICROS), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
argsman.AddArg("-loglevelalways", strprintf("Always prepend a category and level (default: %u)", DEFAULT_LOGLEVELALWAYS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
+ 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);
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);
argsman.AddArg("-shrinkdebugfile", "Shrink debug.log file on client startup (default: 1 when no -debug)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
- argsman.AddArg("-disableratelimitlogging", "Disable rate limit logging", ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
}
void SetLoggingOptions(const ArgsManager& args)
diff --git a/src/logging.h b/src/logging.h
index 623bd97e56..3d97b460cc 100644
--- a/src/logging.h
+++ b/src/logging.h
@@ -107,6 +107,7 @@ namespace BCLog {
constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging
constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes per source location that can be logged within the RATELIMIT_WINDOW
constexpr auto RATELIMIT_WINDOW{1h}; // time window after which log ratelimit stats are reset
+ constexpr bool DEFAULT_LOGRATELIMIT{true};
//! Fixed window rate limiter for logging.
class LogRateLimiter : public std::enable_shared_from_this<LogRateLimiter>
diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py
index 09d611128c..3b0814635a 100755
--- a/test/functional/test_framework/test_node.py
+++ b/test/functional/test_framework/test_node.py
@@ -137,7 +137,7 @@ class TestNode():
if self.version_is_at_least(239000):
self.args.append("-loglevel=trace")
if self.version_is_at_least(299900):
- self.args.append("-disableratelimitlogging")
+ self.args.append("-nologratelimit")
# Default behavior from global -v2transport flag is added to args to persist it over restarts.
# May be overwritten in individual tests, using extra_args.
</details>
Thanks, implemented. I was trying to avoid adding a constant to 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?
<details> <summary>git diff on 8dd5c0a044</summary>
diff --git a/doc/release-notes-32604.md b/doc/release-notes-32604.md
index d4d3726e86..1aaebc185b 100644
--- a/doc/release-notes-32604.md
+++ b/doc/release-notes-32604.md
@@ -4,7 +4,8 @@ Unconditional logging to disk is now rate limited by giving each source location
a quota of 1MiB per hour. Unconditional logging is any logging with a log level
higher than debug, that is `info`, `warning`, and `error`. All logs will be
prefixed with `[*]` if there is at least one source location that is currently
-being suppressed. (#32604)
+being suppressed. Ratelimiting can be disabled globally with
+`-nologratelimit`. (#32604)
When `-logsourcelocations` is enabled, the log output now contains the entire
function signature instead of just the function name. (#32604)
</details>
Added
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.
Good point, I'm going to drop the commit in the next push.
Resolving as I've dropped the commit.
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;
nit in 0716f0a69f37d611ead459eadf35a8c670e511f4 (doesn't matter much): Generally, when a function exists in a class, it is better to use the m_ prefix. This would also make the diff smaller.
Ah ok, will fix this one.
Fixed in 3c7cae49b692bb6bf5cae5ee23479091bed0b8be
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;
nit in 65c8072757e58f9cad1198ddd8e403d656bb68e2: Unused/stray hunk?
Oops, I should have caught this. Thanks, will fix.
Fixed in df7954e586688cacd942d4003771f74ddca1eae8
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);
f8b218418e8e716e210ee247e143172f6ef4fc93: why is this added?
should be in the next commit?
Now that the logging categories are reset between tests, the test would fail in this commit since 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.
Nah we only log from HTTP in the next commit, in f8b218418e8e716e210ee247e143172f6ef4fc93 all the levels are still Info, had me confused for a bit too.
Oh ok, yup will fix.
Moved to the proper commit (fb9c7dd4ff7786bfb64aa6c174227e9dfdf04f64).
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?
That is a good point, I need to think on this (I'm not sure if it's guaranteed). 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.
I wonder if this is related to #33195 - it seems like a possible candidate. I'm currently unable to reproduce the issue, and am also not familiar with these fs libraries.
nothing blocking, just very minor nits/questions.
review ACK 7bc28668cc791d28fe824476d2c1f236c5a772d0 🕙
<details><summary>Show signature</summary>
Signature:
untrusted 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}"
RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
trusted comment: review ACK 7bc28668cc791d28fe824476d2c1f236c5a772d0 🕙
uUQiEQGUzj9jy99YEHObbOge+6ZfW5SIo6syrKomp3j0n6SYixr7vX43b6jXDN4DOO63UXBKS0C0plRGNiuaCQ==
</details>
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.
ACK f1d25abcaa6a85fec08ea760036f2c7c02945ba8
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()}))
👍 for inverting the order compared to the originally proposed version
387 | + scheduler_func([weak_limiter] { 388 | + if (auto shared_limiter{weak_limiter.lock()}) { 389 | + shared_limiter->Reset(); 390 | + } 391 | + }, 392 | + limiter->m_reset_window);
nit: weird formatting
The formatting is clang-format output, but it can also be simplified to:
auto reset = [weak_limiter] {
if (auto shared_limiter{weak_limiter.lock()}) shared_limiter->Reset();
};
scheduler_func(reset, limiter->m_reset_window);
Will change in next push for readability.
Changed in 3d630c2544e19480268426cda245796d4ce34ac3
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)
I think the current approach is not exception safe wrt memory leak, but given that there are no complex ctors/allocators involved here and the function is called only sporadically, I think it's still the best alternative? How would you implement the make_shared approach?
I'm pretty sure this is correct. This reminded me to run with -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:
diff --git a/src/logging.cpp b/src/logging.cpp
index 2ed6835197..840d2ac8c6 100644
--- a/src/logging.cpp
+++ b/src/logging.cpp
@@ -377,11 +377,11 @@ BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds r
std::shared_ptr<BCLog::LogRateLimiter> BCLog::LogRateLimiter::Create(
SchedulerFunction&& scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window)
{
- auto limiter{std::shared_ptr<LogRateLimiter>(new LogRateLimiter(max_bytes, reset_window))};
- std::weak_ptr<LogRateLimiter> weak_limiter{limiter};
- auto reset = [weak_limiter] {
+ auto limiter{std::make_shared<LogRateLimiter>(max_bytes, reset_window)};
+ std::weak_ptr weak_limiter{limiter};
+ auto reset{[weak_limiter] {
if (auto shared_limiter{weak_limiter.lock()}) shared_limiter->Reset();
- };
+ }};
scheduler_func(reset, limiter->m_reset_window);
return limiter;
}
diff --git a/src/logging.h b/src/logging.h
index 9419e245bd..a551cdba20 100644
--- a/src/logging.h
+++ b/src/logging.h
@@ -131,9 +131,10 @@ namespace BCLog {
std::unordered_map<std::source_location, Stats, SourceLocationHasher, SourceLocationEqual> m_source_locations GUARDED_BY(m_mutex);
//! Whether any log locations are suppressed. Cached view on m_source_locations for performance reasons.
std::atomic<bool> m_suppression_active{false};
- LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window);
public:
+ LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window);
+
using SchedulerFunction = std::function<void(std::function<void()>, std::chrono::milliseconds)>;
/**
* [@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)
nit: scheduler_func is copied for each invocation
Thanks, will change in next push.
This is addressed in 3d630c2544e19480268426cda245796d4ce34ac3 by changing 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 {
👍 for struct
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,
👍, this makes the test a bit easier to read
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.
I'm a bit confused here that we're changing m_dropped_bytes from bytes that were not consumed to bytes that were consumed but didn't fit
Because they were consumed, through Stats::Consume, but didn't fit, so they were dropped.
I think this is a bit more clear, resolving.
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_)};
is this a trick to avoid changing limiter. usages to limiter-> if we had const auto limiter{Assert(scheduler.GetLimiter(max_bytes, reset_window))};?
Correct.
Personally, I would rather vote for simpler final code than a bit more involved diff
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
class LogRateLimiter
Fixed in 3d630c2544e19480268426cda245796d4ce34ac3, nice job spotting this.
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
re-ACK 5c74a0b397cb3db94761bad78801eed4544155b9
301 | +struct ScopedScheduler { 302 | + CScheduler scheduler{}; 303 | + 304 | + ScopedScheduler() 305 | + { 306 | + scheduler.m_service_thread = std::thread([this] { scheduler.serviceQueue(); });
I thought this looks like a good opportunity to try out the updated https://en.cppreference.com/w/cpp/thread/jthread.html here, but I couldn't quickly get it working locally, so maybe next time
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:
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:
// Prefix log lines while any source is rate-limited to indicate logs are incomplete.
This refers to situations that could pop up like if functional tests were failing and the logs were being suppressed. Or even somebody having an issue with a production node.
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:
bool is_rate_limited{false};
if (m_limiter) {
if (rate_limit_enabled) {
auto status{m_limiter->Consume(source_loc, str_prefixed)};
if (status == LogRateLimiter::Status::NEWLY_SUPPRESSED) {
// NOLINTNEXTLINE(misc-no-recursion)
LogPrintStr_(strprintf(
"Excessive logging detected from %s:%d (%s): >%d bytes logged during "
"the last time window of %is. Suppressing logging to disk from this "
"source location until time window resets. Console logging "
"unaffected. Last log entry.",
source_loc.file_name(), source_loc.line(), source_loc.function_name(),
m_limiter->m_max_bytes,
Ticks<std::chrono::seconds>(m_limiter->m_reset_window)),
std::source_location::current(), LogFlags::ALL, Level::Warning, /*rate_limit_enabled=*/false); // with rate_limit_enabled=false, this cannot lead to infinite recursion
}
is_rate_limited = (status == LogRateLimiter::Status::STILL_SUPPRESSED);
}
// Prefix log lines while any source is rate-limited to indicate logs are incomplete.
if (m_limiter->SuppressionsActive()) str_prefixed.insert(0, "[*] ");
}
Adding the guard on the outside like you've done here would be better I agree. FWIW I don't think I forgot to add it? I had to add it when moving this statement outside of the block in this PR.
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?
"source location until time window resets. Console logging unaffected.
I could see where this might be confusing. It will print the actual last log entry just after this before suppressing logs from this location -- I was trying to maintain behavior of previous iterations of the PRs here.
Code review ACK 5c74a0b397cb3db94761bad78801eed4544155b9
I still have a few suggestion that I think should be addressed, but I'm not blocking.
ACK 5c74a0b397cb3db94761bad78801eed4544155b9
