log: Add rate limiting to LogPrintf, LogInfo, LogWarning, LogError, LogPrintLevel

To mitigate disk-filling attacks caused by unsafe usages of LogPrintf and
friends, we rate-limit them by passing a should_ratelimit bool that
eventually makes its way to LogPrintStr which may call
LogRateLimiter::Consume. The rate limiting is accomplished by
adding a LogRateLimiter member to BCLog::Logger which tracks source
code locations for the given logging window.

Every hour, a source location can log up to 1MiB of data. Source
locations that exceed the limit will have their logs suppressed for the
rest of the window determined by m_limiter.

This change affects the public LogPrintLevel function if called with
a level >= BCLog::Level::Info.

The UpdateTipLog function has been changed to use the private LogPrintLevel_
macro with should_ratelimit set to false. This allows UpdateTipLog to log
during IBD without hitting the rate limit.

Note that on restart, a source location that was rate limited before the
restart will be able to log until it hits the rate limit again.

Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
Co-Authored-By: stickies-v <stickies-v@protonmail.com>

src/test/logging_tests.cpp

@@ -6,6 +6,7 @@
 #include <logging.h>
 #include <logging/timer.h>
 #include <scheduler.h>
+#include <test/util/logging.h>
 #include <test/util/setup_common.h>
 #include <tinyformat.h>
 #include <util/fs.h>
@@ -15,8 +16,10 @@
 #include <chrono>
 #include <fstream>
 #include <future>
+#include <ios>
 #include <iostream>
 #include <source_location>
+#include <string>
 #include <unordered_map>
 #include <utility>
 #include <vector>
@@ -113,7 +116,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
     std::vector<std::string> expected;
     for (auto& [msg, category, level, prefix, loc] : cases) {
         expected.push_back(tfm::format("[%s:%s] [%s] %s%s", util::RemovePrefix(loc.file_name(), "./"), loc.line(), loc.function_name(), prefix, msg));
-        LogInstance().LogPrintStr(msg, std::move(loc), category, level);
+        LogInstance().LogPrintStr(msg, std::move(loc), category, level, /*should_ratelimit=*/false);
     }
     std::ifstream file{tmp_log_path};
     std::vector<std::string> log_lines;
@@ -366,4 +369,106 @@ BOOST_AUTO_TEST_CASE(logging_log_limit_stats)
     BOOST_CHECK_EQUAL(counter.GetDroppedBytes(), 500ull);
 }
 
+void LogFromLocation(int location, std::string message)
+{
+    switch (location) {
+    case 0:
+        LogInfo("%s\n", message);
+        break;
+    case 1:
+        LogInfo("%s\n", message);
+        break;
+    case 2:
+        LogPrintLevel(BCLog::LogFlags::NONE, BCLog::Level::Info, "%s\n", message);
+        break;
+    case 3:
+        LogPrintLevel(BCLog::LogFlags::ALL, BCLog::Level::Info, "%s\n", message);
+        break;
+    }
+}
+
+void LogFromLocationAndExpect(int location, std::string message, std::string expect)
+{
+    ASSERT_DEBUG_LOG(expect);
+    LogFromLocation(location, message);
+}
+
+BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
+{
+    bool prev_log_timestamps = LogInstance().m_log_timestamps;
+    LogInstance().m_log_timestamps = false;
+    bool prev_log_sourcelocations = LogInstance().m_log_sourcelocations;
+    LogInstance().m_log_sourcelocations = false;
+    bool prev_log_threadnames = LogInstance().m_log_threadnames;
+    LogInstance().m_log_threadnames = false;
+
+    CScheduler scheduler{};
+    scheduler.m_service_thread = std::thread([&] { scheduler.serviceQueue(); });
+    auto sched_func = [&scheduler](auto func, auto window) { scheduler.scheduleEvery(std::move(func), window); };
+    auto limiter = std::make_unique<BCLog::LogRateLimiter>(sched_func, 1024 * 1024, 20s);
+    LogInstance().SetRateLimiting(std::move(limiter));
+
+    // Log 1024-character lines (1023 plus newline) to make the math simple.
+    std::string log_message(1023, 'a');
+
+    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.
+    std::streamsize log_file_size{static_cast<std::streamsize>(GetFileSize(log_path))};
+
+    // Logging 1 MiB should be allowed.
+    for (int i = 0; i < 1024; ++i) {
+        LogFromLocation(0, log_message);
+    }
+    BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "should be able to log 1 MiB from location 0");
+
+    log_file_size = GetFileSize(log_path);
+
+    BOOST_CHECK_NO_THROW(LogFromLocationAndExpect(0, log_message, "Excessive logging detected"));
+    BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "the start of the suppression period should be logged");
+
+    log_file_size = GetFileSize(log_path);
+    for (int i = 0; i < 1024; ++i) {
+        LogFromLocation(0, log_message);
+    }
+
+    BOOST_CHECK_MESSAGE(log_file_size == GetFileSize(log_path), "all further logs from location 0 should be dropped");
+
+    BOOST_CHECK_THROW(LogFromLocationAndExpect(1, log_message, "Excessive logging detected"), std::runtime_error);
+    BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 1 should be unaffected by other locations");
+
+    log_file_size = GetFileSize(log_path);
+    {
+        ASSERT_DEBUG_LOG("Restarting logging");
+        MockForwardAndSync(scheduler, 1min);
+    }
+
+    BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "the end of the suppression period should be logged");
+
+    BOOST_CHECK_THROW(LogFromLocationAndExpect(1, log_message, "Restarting logging"), std::runtime_error);
+
+    // Attempt to log 1MiB from location 2 and 1MiB from location 3. These exempt locations should be allowed to log
+    // without limit.
+    log_file_size = GetFileSize(log_path);
+    for (int i = 0; i < 1024; ++i) {
+        BOOST_CHECK_THROW(LogFromLocationAndExpect(2, log_message, "Excessive logging detected"), std::runtime_error);
+    }
+
+    BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 2 should be exempt from rate limiting");
+
+    log_file_size = GetFileSize(log_path);
+    for (int i = 0; i < 1024; ++i) {
+        BOOST_CHECK_THROW(LogFromLocationAndExpect(3, log_message, "Excessive logging detected"), std::runtime_error);
+    }
+
+    BOOST_CHECK_MESSAGE(log_file_size < GetFileSize(log_path), "location 3 should be exempt from rate limiting");
+
+    LogInstance().m_log_timestamps = prev_log_timestamps;
+    LogInstance().m_log_sourcelocations = prev_log_sourcelocations;
+    LogInstance().m_log_threadnames = prev_log_threadnames;
+    scheduler.stop();
+    LogInstance().SetRateLimiting(nullptr);
+}
+
 BOOST_AUTO_TEST_SUITE_END()