Repository: bitcoin/bitcoin
File: src/test/logging_tests.cpp (C++)

Code before:
    LogInstance().m_log_timestamps = false;
    LogInstance().m_log_sourcelocations = false;
    LogInstance().m_log_threadnames = false;

    constexpr int64_t line_length{1024};
    constexpr int64_t num_lines{1024};
    constexpr int64_t bytes_quota{line_length * num_lines};
    constexpr auto time_window{20s};

    ScopedScheduler scheduler{};
    auto limiter{scheduler.GetLimiter(bytes_quota, time_window)};
    LogInstance().SetRateLimiting(limiter);

    const std::string log_message(line_length - 1, 'a'); // subtract one for newline

    for (int i = 0; i < num_lines; ++i) {
        TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
    }
    TestLogFromLocation(Location::INFO_1, "a", Status::NEWLY_SUPPRESSED, /*suppressions_active=*/true);
    TestLogFromLocation(Location::INFO_1, "b", Status::STILL_SUPPRESSED, /*suppressions_active=*/true);
    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));
    }
    // Check that logging from previously suppressed location is unsuppressed again.
    TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
    // Check that conditional logging, and unconditional logging with should_ratelimit=false is
    // not being ratelimited.
    for (Location location : {Location::DEBUG_LOG, Location::INFO_NOLIMIT}) {
        for (int i = 0; i < num_lines + 2; ++i) {
            TestLogFromLocation(location, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
        }
    }
}

BOOST_AUTO_TEST_SUITE_END()


Review comment (bug):
Re https://github.com/bitcoin/bitcoin/pull/33011#issuecomment-3136494016:

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
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>


Code after:

BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
{
    using Status = BCLog::LogRateLimiter::Status;
    LogInstance().m_log_timestamps = false;
    LogInstance().m_log_sourcelocations = false;
    LogInstance().m_log_threadnames = false;
    LogInstance().EnableCategory(BCLog::LogFlags::HTTP);

    constexpr int64_t line_length{1024};
    constexpr int64_t num_lines{1024};
    constexpr int64_t bytes_quota{line_length * num_lines};
    constexpr auto time_window{20s};

    ScopedScheduler scheduler{};
    auto limiter{scheduler.GetLimiter(bytes_quota, time_window)};
    LogInstance().SetRateLimiting(limiter);

    const std::string log_message(line_length - 1, 'a'); // subtract one for newline

    for (int i = 0; i < num_lines; ++i) {
        TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
    }
    TestLogFromLocation(Location::INFO_1, "a", Status::NEWLY_SUPPRESSED, /*suppressions_active=*/true);
    TestLogFromLocation(Location::INFO_1, "b", Status::STILL_SUPPRESSED, /*suppressions_active=*/true);
    TestLogFromLocation(Location::INFO_2, "c", Status::UNSUPPRESSED, /*suppressions_active=*/true);
    {
        scheduler.MockForwardAndSync(time_window);
        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);
    // Check that conditional logging, and unconditional logging with should_ratelimit=false is
    // not being ratelimited.
    for (Location location : {Location::DEBUG_LOG, Location::INFO_NOLIMIT}) {
        for (int i = 0; i < num_lines + 2; ++i) {
            TestLogFromLocation(location, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
        }
    }
}

BOOST_AUTO_TEST_SUITE_END()