Followups to #32604.
The only behavior change is that prefixing with [*] is done to all logs (regardless of should_ratelimit) per #32604 (review). This does not need a release note as the release notes were already a bit vague as pointed out in the comment.
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 |
|---|---|
| Concept ACK | l0rinc |
If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.
Reviewers, this pull request conflicts with the following ones:
If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.
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>
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.
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.
🚧 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)?
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.
This ensures log tests behave consistently when other tests modify
the log category mask.
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.
- 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 -disableratelimitlogging by default in functional tests.
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
Labels
Utils/log/libs
CI failed
Milestone
30.0