test: modify logging_filesize_rate

Crypt-iQ commented at 6:28 pm on August 18, 2025: contributor

Change time_window from 20s to 1h so Reset is not accidentally called if the test takes a while.

Change num_lines from 1024 to 10 since LogRateLimiter is parameterized and does not require logging 1MiB of data.

Fixes #33195

DrahtBot added the label Tests on Aug 18, 2025

DrahtBot commented at 6:28 pm on August 18, 2025: contributor

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

Code Coverage & Benchmarks

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

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	stickies-v, janb84, dergoegge
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.

Crypt-iQ marked this as ready for review on Aug 18, 2025

Crypt-iQ commented at 8:33 pm on August 18, 2025: contributor

cc @stickies-v

achow101 added this to the milestone 30.0 on Aug 18, 2025

achow101 commented at 9:52 pm on August 18, 2025: member

If we believe it is due to the reset window, then we could set set the reset window to 5 hours, which is the longest CI timeout, so if that were to ever be reached, CI would be failing anyways. But 1 hour is also fine.

maflcko commented at 8:32 am on August 19, 2025: member

Thx. This is a nice and simple change to make the test log smaller and thus easier to debug in case of failure. Also, increasing the window should be harmless and could avoid intermittent issues on slow IO.

review ACK ab5c3be4b384d48d514b06dc8a391f1efa51ea38 🌤

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 ab5c3be4b384d48d514b06dc8a391f1efa51ea38 🌤
3c6XGbFdRH7qQITdhwFl6uTRmkfjfxd5/tI/vFU8WOvXxttikOceA9qapIUsYQFpgETKJNQj41YGASdIYWGwuCA==

stickies-v approved

stickies-v commented at 10:54 am on August 19, 2025: contributor

ACK ab5c3be4b384d48d514b06dc8a391f1efa51ea38

then we could set set the reset window to 5 hours

That would require more changes to CScheduler because MockForward is currently capped at 1h.

I considered previously to also add log_lines to the boost test context, but decided not to for brevity, but it would’ve been helpful in debugging this. I think the below diff would be a helpful change, leading to the below output in case of test failure:

0../src/test/logging_tests.cpp:438: error: in "logging_tests/logging_filesize_rate_limit": check false has failed
1Failure occurred in a following context:
2    TestLogFromLocation called from ../src/test/logging_tests.cpp:470
3    2 log_lines read: 
4[*] [warning] Excessive logging detected from ../src/test/logging_tests.cpp:397 (void logging_tests::(anonymous namespace)::LogFromLocation(Location, const std::string &)): >10240 bytes logged during the last time window of 3600s. Suppressing logging to disk from this source location until time window resets. Console logging unaffected. Last log entry.
5[*] a

 0diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
 1index 9a84fd65b9..2e3b1c390b 100644
 2--- a/src/test/logging_tests.cpp
 3+++ b/src/test/logging_tests.cpp
 4@@ -417,30 +417,29 @@ void TestLogFromLocation(Location location, const std::string& message,
 5                          BCLog::LogRateLimiter::Status status, bool suppressions_active,
 6                          std::source_location source = std::source_location::current())
 7 {
 8+    BOOST_TEST_INFO_SCOPE("TestLogFromLocation called from " << source.file_name() << ":" << source.line());
 9     using Status = BCLog::LogRateLimiter::Status;
10     if (!suppressions_active) assert(status == Status::UNSUPPRESSED); // developer error
11 
12     std::ofstream ofs(LogInstance().m_file_path, std::ios::out | std::ios::trunc); // clear debug log
13     LogFromLocation(location, message);
14     auto log_lines{ReadDebugLogLines()};
15+    BOOST_TEST_INFO_SCOPE(log_lines.size() << " log_lines read: \n" << util::Join(log_lines, "\n"));
16 
17-    BOOST_TEST_CONTEXT("TestLogFromLocation failed from " << source.file_name() << ":" << source.line())
18-    {
19-        if (status == Status::STILL_SUPPRESSED) {
20-            BOOST_CHECK_EQUAL(log_lines.size(), 0);
21-            return;
22-        }
23+    if (status == Status::STILL_SUPPRESSED) {
24+        BOOST_CHECK_EQUAL(log_lines.size(), 0);
25+        return;
26+    }
27 
28-        if (status == Status::NEWLY_SUPPRESSED) {
29-            BOOST_REQUIRE_EQUAL(log_lines.size(), 2);
30-            BOOST_CHECK(log_lines[0].starts_with("[*] [warning] Excessive logging detected"));
31-            log_lines.erase(log_lines.begin());
32-        }
33-        BOOST_REQUIRE_EQUAL(log_lines.size(), 1);
34-        auto& payload{log_lines.back()};
35-        BOOST_CHECK_EQUAL(suppressions_active, payload.starts_with("[*]"));
36-        BOOST_CHECK(payload.ends_with(message));
37+    if (status == Status::NEWLY_SUPPRESSED) {
38+        BOOST_REQUIRE_EQUAL(log_lines.size(), 2);
39+        BOOST_CHECK(log_lines[0].starts_with("[*] [warning] Excessive logging detected"));
40+        log_lines.erase(log_lines.begin());
41     }
42+    BOOST_REQUIRE_EQUAL(log_lines.size(), 1);
43+    auto& payload{log_lines.back()};
44+    BOOST_CHECK_EQUAL(suppressions_active, payload.starts_with("[*]"));
45+    BOOST_CHECK(payload.ends_with(message));
46 }
47 
48 } // namespace

(nit: the diff also changes “failed from” to “called from” because I’m not sure if there are e.g. verbose settings that dump boost test context when there is no failure)

janb84 commented at 11:56 am on August 19, 2025: contributor

approach ACK ab5c3be4b384d48d514b06dc8a391f1efa51ea38

PR increases the test rest window to 1 hour from 20 seconds, to accommodate slow test execution. And reduces test log.

Small worry is by increasing the test rest window to 1h is that this will impact CI if a test will hang for some reason, it is a big increase.

stickies-v commented at 1:04 pm on August 19, 2025: contributor

Small worry is by increasing the test rest window to 1h is that this will impact CI if a test will hang for some reason, it is a big increase.

Any test can slow down or hang for multiple reasons, that’s why we have CI timeouts. I don’t think it’s pragmatic to use unexpected program flow to control timeouts.

maflcko commented at 1:38 pm on August 19, 2025: member

Small worry is by increasing the test rest window to 1h is that this will impact CI if a test will hang for some reason, it is a big increase.

The timeout is purely virtual and never waited on or synced on in real wall-clock time, so I don’t think this comment applies?

janb84 commented at 1:44 pm on August 19, 2025: contributor

Small worry is by increasing the test rest window to 1h is that this will impact CI if a test will hang for some reason, it is a big increase.

The timeout is purely virtual and never waited on or synced on in real wall-clock time, so I don’t think this comment applies?

Small worry is by increasing the test rest window to 1h is that this will impact CI if a test will hang for some reason, it is a big increase.

Any test can slow down or hang for multiple reasons, that’s why we have CI timeouts. I don’t think it’s pragmatic to use unexpected program flow to control timeouts.

Ok unwarranted worry :) I stand corrected. Thank you both for the answers

ACK ab5c3be4b384d48d514b06dc8a391f1efa51ea38

test: modify logging_filesize_rate_limit params

Change time_window from 20s to 1h so Reset is not accidentally called
if the test takes a while.

Change num_lines from 1024 to 10 since LogRateLimiter is parameterized
and does not require logging 1MiB of data.

Co-Authored-By: stickies-v <stickies-v@protonmail.com>

5dda364c4b

Crypt-iQ force-pushed on Aug 19, 2025

Crypt-iQ commented at 4:57 pm on August 19, 2025: contributor

Latest push ab5c3be -> 5dda364c adds the diff referenced in this comment so that test failures are more informative. No other changes.

stickies-v commented at 5:35 pm on August 19, 2025: contributor

re-ACK 5dda364c4b1965da586db7b81de8be90b6919414 for more helpful failure logging, no other changes

DrahtBot requested review from janb84 on Aug 19, 2025

DrahtBot requested review from maflcko on Aug 19, 2025

janb84 commented at 6:27 pm on August 19, 2025: contributor

re ACK 5dda364c4b1965da586db7b81de8be90b6919414

changes since last ACK:

more informative test failure loggin

dergoegge approved

dergoegge commented at 9:17 am on August 20, 2025: member

utACK 5dda364c4b1965da586db7b81de8be90b6919414

fanquake merged this on Aug 20, 2025

fanquake closed this on Aug 20, 2025

fanquake referenced this in commit 0022e25333 on Aug 20, 2025

fanquake commented at 11:19 am on August 20, 2025: member

Backported to 29.x in #33225.

test: modify logging_filesize_rate_limit params #33211

Code Coverage & Benchmarks

Reviews