log: Mitigate disk filling attacks by rate limiting LogPrintf, LogInfo, LogWarning, LogError #32604

pull Crypt-iQ wants to merge 7 commits into bitcoin:master from Crypt-iQ:log_ratelimiting_05192025 changing 6 files +374 −54
  1. Crypt-iQ commented at 8:48 pm on May 23, 2025: contributor

    This revives the work done by dergoegge in #21603. The approach is largely the same except that std::source_location is used under-the-hood now that we can use c++20 features. The logging functions have also changed slightly since that PR was opened, so work has been done to preserve the intent of the original rate limiting change. I have tried to give commit attribution where possible (unfortunately I was not able to figure out how to type ö in vim).

    Approach: Each source code location is given an hourly logging quota of 1MiB of logging per hour. Logging is only dropped from source locations that exceed the quota.

    • Only logging to disk is rate limited. Logging to console is not rate limited.
    • Printing with the category argument is not rate limited.
    • UpdateTip: new best=[…] is logged with the new UNCONDITIONAL_ALWAYS category to avoid rate limiting. High log volume is expected for that source location during IBD.
    • When logging is restarted a tally of how many messages/bytes were dropped is printed.
    • Log rate limiting can be disabled with the -ratelimitlogging config option.
    • All logs will be prefixed with [*] if there is at least one source location that is currently being suppressed.

    I’ve repurposed the old logging rpc mentioned in #21603 in another branch for testing here. This can be used to log from source locations and test out the new changes in logging behavior. Note that the setmocktime RPC needs to be used to set the mock time past the current clock time to reset the logging messages.

    Example usage:

    0bitcoin-cli -regtest excessivelog 1 1048500 # log just under 1MiB
    1bitcoin-cli -regtest excessivelog 1 100 # this should get the total amount logged above 1MiB
    2                                        # and the rate limiting logic should kick in
    3bitcoin-cli -regtest excessivelog 2 1048500
    4bitcoin-cli -regtest excessivelog 2 100 # trigger rate limiting from another location
    5bitcoin-cli -regtest setmocktime <N> # set this past the current clock time because of how `LogRateLimiter` is initialized
    6bitcoin-cli -regtest excessivelog 1 100 # this should trigger logging to resume and will log the source locations that were reset
    

    Example output:

    0[*] Excessive logging detected from rpc/node.cpp:139 (RPCHelpMan excessivelog()): >1 MiB logged during the last hour.Suppressing logging to disk from this source location for up to one hour. Console logging unaffected. Last log entry.2025-06-11T16:32:41Z aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
    1[*] Excessive logging detected from rpc/node.cpp:142 (RPCHelpMan excessivelog()): >1 MiB logged during the last hour.Suppressing logging to disk from this source location for up to one hour. Console logging unaffected. Last log entry.2025-06-11T16:33:04Z aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
    2Restarting logging from rpc/node.cpp:139 (RPCHelpMan excessivelog()): (1 MiB) were dropped during the last hour.
    3Restarting logging from rpc/node.cpp:142 (RPCHelpMan excessivelog()): (0 MiB) were dropped during the last hour.
    
  2. DrahtBot commented at 8:48 pm on May 23, 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/32604.

    Reviews

    See the guideline for information on the review process.

    Type Reviewers
    Concept ACK davidgumberg, dergoegge, brunoerg, l0rinc
    Approach ACK stickies-v
    Stale ACK janb84

    If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

    Conflicts

    Reviewers, this pull request conflicts with the following ones:

    • #29641 (scripted-diff: Use LogInfo over LogPrintf [WIP, NOMERGE, DRAFT] by maflcko)
    • #29256 (log, refactor: Allow log macros to accept context arguments by ryanofsky)
    • #26812 (test: add end-to-end tests for CConnman and PeerManager by vasild)

    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.

  3. DrahtBot added the label Utils/log/libs on May 23, 2025
  4. davidgumberg commented at 9:00 pm on May 23, 2025: contributor
    Concept ACK
  5. gmaxwell commented at 9:34 pm on May 23, 2025: contributor
    Any thoughts about adding some kind of dying gasp so that if a node crashes or hits some fatal error the most recent unfiltered log can be saved?
  6. DrahtBot added the label CI failed on May 23, 2025
  7. DrahtBot commented at 9:47 pm on May 23, 2025: contributor

    🚧 At least one of the CI tasks failed. Task lint: https://github.com/bitcoin/bitcoin/runs/42810774045 LLM reason (✨ experimental): The CI failure is due to linting errors related to std::filesystem and locale dependence.

    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.

  8. Crypt-iQ commented at 8:49 pm on May 24, 2025: contributor

    if a node crashes or hits some fatal error the most recent unfiltered log can be saved?

    Does unfiltered here mean a log line that was rate limited or does it mean something else in this context? I think that we would need to know ahead of time if we were going to crash to save the most recent unfiltered log unless we somehow always cache it?

  9. dergoegge commented at 12:07 pm on May 26, 2025: member

    Concept ACK

    Thanks for picking this up!

  10. in src/logging.h:33 in 0bc6ed61cf outdated
    30@@ -27,10 +31,29 @@ static const bool DEFAULT_LOGTIMESTAMPS = true;
    31 static const bool DEFAULT_LOGTHREADNAMES = false;
    32 static const bool DEFAULT_LOGSOURCELOCATIONS = false;
    33 static constexpr bool DEFAULT_LOGLEVELALWAYS = false;
    


    janb84 commented at 1:22 pm on May 26, 2025:
    nit: would be nice to align the other initializations to the new C++ 11 {} style in a follow up PR, to keep the code base consistent.

    Crypt-iQ commented at 4:23 pm on May 29, 2025:
    I can do that in a follow-up
  11. janb84 commented at 1:41 pm on May 26, 2025: contributor

    ACK 0bc6ed61cfab6d97e74103efd41c46faf5941ff6

    Ratelimits loging to disk if loggin exceeds 1 MiB in 1 hour (WINDOW_MAX_BYTES const & WINDOW_SIZE const)

    • code review
    • build & tested
  12. DrahtBot requested review from davidgumberg on May 26, 2025
  13. DrahtBot requested review from dergoegge on May 26, 2025
  14. brunoerg commented at 7:47 pm on May 26, 2025: contributor
    Concept ACK
  15. Crypt-iQ force-pushed on May 28, 2025
  16. Crypt-iQ commented at 4:22 pm on May 29, 2025: contributor
    The tidy job is failing because it doesn’t like the logging macros being used in lambda functions. It seems like this is pre-existing so I’m not sure why it’s failing now. The windows cross-built job is failing on the rate_limiting test at every file-size comparison. I don’t have a windows machine to debug this, but I think maybe fs::file_size is failing or some other quirk is showing up?
  17. in src/logging.h:98 in 6dece0553c outdated
    124+        BLOCKSTORAGE               = (CategoryMask{1} << 25),
    125+        TXRECONCILIATION           = (CategoryMask{1} << 26),
    126+        SCAN                       = (CategoryMask{1} << 27),
    127+        TXPACKAGES                 = (CategoryMask{1} << 28),
    128+        UNCONDITIONAL_RATE_LIMITED = (CategoryMask{1} << 29),
    129+        UNCONDITIONAL_ALWAYS       = (CategoryMask{1} << 30),
    


    stickies-v commented at 9:34 am on May 30, 2025:
    nit: I think a brief docstring on their suggested usage here would be helpful here

    l0rinc commented at 9:49 am on June 3, 2025:
    I’m not sure introducing two extra category flags is a good abstraction here - feels noisy. Wouldn’t it be cleaner to decide based on exposure to the attack surface instead? For example, during IBD (or any state with zero peer connections) we could leave all logs unrestricted, and always enable rate-limiting when node is reachable by peers.

    Crypt-iQ commented at 2:08 pm on June 3, 2025:
    See #32604 (review), will change. Imo, having to determine whether we are in IBD or have zero peer connections is heading into too much complexity. This PR shouldn’t cause IBD debug logs to be rate-limited, but if it does we should fix that.

    Crypt-iQ commented at 5:50 pm on June 4, 2025:
    Resolving as I’ve removed categories.
  18. in src/init/common.cpp:43 in 6dece0553c outdated
    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("-ratelimitlogging", strprintf("Rate limit unconditional logging to disk (default: %u)", DEFAULT_RATELIMITLOGGING), ArgsManager::ALLOW_ANY, OptionsCategory::OPTIONS);
    


    stickies-v commented at 9:40 am on May 30, 2025:
    Is there a good use case for disabling rate limiting? I can’t think of one. Letting the user define the amount of rate limiting is an alternative, but even then, I’m not sure. If an attacker or bug is able to reach the sane default maximum, then is the user really going to get any benefit from being to inspect the additional volume of un-ratelimited logs? I’m not sure. If so, I think it would make sense to not have this as a configurable option.

    Crypt-iQ commented at 11:33 am on May 30, 2025:
    That’s a good point, I can’t think of any concrete use case to disable rate limiting here.

    fanquake commented at 12:54 pm on May 30, 2025:
    @dergoegge might remember why this was added?

    stickies-v commented at 1:05 pm on May 30, 2025:
    fwiw: I can’t find any discussion about it in #21603, and the option was present from the first version of the PR (https://github.com/bitcoin/bitcoin/commit/4648b6d207139ec0ab2994f56c0a47f81cdf516a#diff-b1e19192258d83199d8adaa5ac31f067af98f63554bfdd679bd8e8073815e69d)

    l0rinc commented at 9:22 am on June 3, 2025:

    When I’m benchmarking IBD, I don’t want any artificial size or rate limits. Since the attack only matters when peers can influence us, could we simply disable rate-limiting for all logs during IBD/reindexes/assumeutxo?


    Should the docs explicitly state the 1 MiB-per-hour cap, or could we replace the boolean flag with a numeric “MiB per hour” parameter (retaining 0 and 1 as the current meanings)?


    fanquake commented at 10:14 am on June 3, 2025:

    Since the attack only matters when peers can influence us, could we simply disable rate-limiting for all logs during IBD

    ?


    l0rinc commented at 10:33 am on June 3, 2025:
    Can you be more specific :)?

    fanquake commented at 10:39 am on June 3, 2025:
    What do you mean by “peers not being able to influence us during IBD”?

    l0rinc commented at 10:59 am on June 3, 2025:

    I meant that during IBD we’re mostly replaying validated history, and my understanding is that rate-limiting is meant to protect logs caused by peer-supplied invalid data, not the deterministic IBD progress logs (e.g. -debug=bench or -debug=leveldb, which are very verbose (way over the 1MiB/h), but isn’t related to a user-sent serialization error or similar cheap attack). “Attacking” a node that is still in the original IBD seems less severe to me than skipped logs. I also understand if you disagree with this and I would appreciate an explanation, I want to understand.

    We can still get invalid data (thanks for triggering a clarification), but maybe the guard should added per LogFlags and we may want to blacklist instead of whitelisting. Or is this meant as a final catch-all for all the unknowns, e.g. maybe there’s a trick to enable LevelDB logs externally and this should still guard against that?


    Crypt-iQ commented at 1:32 pm on June 3, 2025:
    I believe that if somebody is using -debug=bench or -debug=leveldb, the fact that they are using a category should bypass the rate limit if LogDebug is used. I think the mitigation should be in place whether or not we’re in IBD – if we have any peers (inbound or outbound), we need to be cautious. This patch is meant to be the “final catch-all” like you said to fully eliminate this class of attack.

    l0rinc commented at 3:04 pm on June 3, 2025:
    Thanks for clarifying

    stickies-v commented at 9:33 am on June 5, 2025:
    It seems like this startup option is still in the latest force-push (5914a2ee6c915585b7213217047ad1644b873376), but from this discussion it doesn’t seem like there are good arguments to keep it? I’m not sure if @l0rinc still needs it for IBD bench reasons, but imo that’s way too much of a niche to keep it as a startup option?
  19. in src/logging.h:184 in 6dece0553c outdated
    180@@ -113,17 +181,17 @@ namespace BCLog {
    181         std::atomic<Level> m_log_level{DEFAULT_LOG_LEVEL};
    182 
    183         /** Log categories bitfield. */
    184-        std::atomic<CategoryMask> m_categories{BCLog::NONE};
    185+        std::atomic<CategoryMask> m_categories{DEFAULT_LOG_FLAGS};
    


    stickies-v commented at 10:03 am on May 30, 2025:

    Hmm, I’m feeling uneasy about using m_categories, when rate limiting flags fundamentally don’t represent a category. I can see how it reduces the diff, but I’m not sure that’s worth it. I’ll think about an alternative approach - have you considered any already?

    Since the user doesn’t have to be able to configure any of this, and we only have a single UNCONDITIONAL_ALWAYS use case (and likely won’t have (many) more in the future), I think adding an is_conditional=True arg to LogPrintLevel and a LogInfoAlways macro might be an alternative?


    Crypt-iQ commented at 11:44 am on May 30, 2025:
    I haven’t considered alternative approaches, but I think adding a boolean is better than adding special-cased categories.

    stickies-v commented at 12:43 pm on May 30, 2025:

    Or perhaps even better than a boolean is a uint64_t rate_limit=DEFAULT_RATE_LIMIT so we can do away with the distinction between ratelimited and non-ratelimited logging entirely? We could use rate_limit=0 as a synonym for non-ratelimited logging, but I think even UpdateTipLog() doesn’t have to be exempt from rate limiting, we could still set a sane value that allows doing entire IBD in one hour, for example.

    Then UpdateTipLog() could just use:

    0    LogInfo(/*rate_limit=*/100, "%s%s: new best=%s height=%d version=0x%08x log2_work=%f tx=%lu date='%s' progress=%f cache=%.1fMiB(%utxo)%s\n",
    

    Crypt-iQ commented at 4:21 pm on May 30, 2025:
    I think callers just need to be aware that they cannot set the rate limit very high in certain cases. Maybe this change and a comment will suffice?

    Crypt-iQ commented at 7:56 pm on June 3, 2025:

    While implementing this, I came to the conclusion that because macros don’t have default arguments, skipping the rate limiting for UpdateTipLog means that we need to: 1) introduce a new macro for IBD specifically for UpdateTipLog, or 2) modify all call-sites of whichever macro UpdateTipLog uses to accept a rate_limit argument.

    I am partial to introducing a new macro for UpdateTipLog since it gets rid of the noise in the categories logic. I think that option 2) to modify all call-sites to pass in a rate-limiting argument is cumbersome when most callers don’t need to be aware of rate limiting and it should instead be done under-the-hood (i.e. UpdateTipLog is the exception to the rule). I think using a boolean for rate-limiting vs no-rate-limiting is better than a uint64_t because then the proposed SourceLocationCounter needs to also keep track of this window-scaling value (i.e. multiple of WINDOW_MAX_BYTES).

    I might be wrong here, curious to hear thoughts.


    stickies-v commented at 2:07 pm on June 4, 2025:
    1. to modify all call-sites to pass in a rate-limiting argument is cumbersome

    Absolutely agree that would not be an improvement.

    I think using a boolean for rate-limiting vs no-rate-limiting is better than a uint64_t

    I think either will work fine, the uint64_t generalizes a bit nicer but we probably won’t be needing the generalization in the future, so whichever ends up being the most elegant implementation now is what I think we should go for.

    I am partial to introducing a new macro for UpdateTipLog

    That seems sensible to me, yes.


    Crypt-iQ commented at 5:45 pm on June 4, 2025:
    I’ve changed this so that the logging macros eventually pass a should_ratelimit bool to LogPrintStr. Instead of introducing a new macro for UpdateTipLog, it now uses LogPrintLevel which can bypass the rate-limiting. I’m not sure how I feel about using LogPrintLevel as I don’t want to encourage more usage of it in the codebase as it could be a potential footgun.
  20. stickies-v commented at 10:21 am on May 30, 2025: contributor
    Concept ACK on locking down this attack vector, and the code changes required seem acceptable. Also nice to start using std::source_location here.
  21. fanquake commented at 10:57 am on May 30, 2025: member

    The windows cross-built job is failing on the rate_limiting test at every file-size comparison. I don’t have a windows machine to debug this, but I think maybe fs::file_size is failing or some other quirk is showing up? @hebasto can you take a look here? I ran test_bitcoin.exe from this branch (rebased) under wine and didn’t see any failures.

  22. in src/logging.cpp:374 in 6dece0553c outdated
    367@@ -364,33 +368,71 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l
    368 
    369 static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
    370 {
    371-    return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
    372+    return buflog.str.size() + buflog.logging_function.size() + strlen(buflog.source_loc.file_name()) + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
    373 }
    374 
    375-void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, std::string_view source_file, int source_line, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const
    376+bool BCLog::Logger::FormatLogStrAndRateLimit(std::string& str, BCLog::LogFlags category, BCLog::Level level, const std::source_location& source_loc, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime)
    


    stickies-v commented at 12:19 pm on May 30, 2025:

    I think it’s unintuitive that this function returns true when the operation failed. It seems like the rate limiting can be carved out pretty much as-is into a separate bool NeedsRateLimiting() function? There are only 2 callsites of FormatLogStrAndRateLimit, and the first one (StartLogging) doesn’t look like it needs rate limiting because we already have a max buffer size?

    edit: this would pair fairly well with my suggestion here


    Crypt-iQ commented at 4:20 pm on May 30, 2025:
    Yup, this makes sense as well. Can change.

    Crypt-iQ commented at 5:48 pm on June 4, 2025:
    I’ve carved this out into a NeedsRateLimiting function and have kept the logic of FormatLogStrInPlace mostly unchanged. The reason I had the original change is because FormatLogStrInPlace inserts a timestamp at the beginning of str and I wanted the prepended rate-limiting logs to occur after the timestamp. With the new change, the rate-limiting logs are first in str followed by the time-stamp. I think now the logs look a little wonky, but I like the code change better. I could also extract the time-stamp prepend logic so it’s called after NeedsRateLimiting.
  23. hebasto commented at 12:20 pm on May 30, 2025: member

    The windows cross-built job is failing on the rate_limiting test at every file-size comparison. I don’t have a windows machine to debug this, but I think maybe fs::file_size is failing or some other quirk is showing up?

    @hebasto can you take a look here? I ran test_bitcoin.exe from this branch (rebased) under wine and didn’t see any failures.

    It seems to be related to MSVCRT behaviour, as binaries linked to UCRT pass all unit tests.

  24. in src/logging.h:144 in 6dece0553c outdated
    112+    //! Fixed window rate limiter for logging.
    113+    class LogRateLimiter
    114+    {
    115+    private:
    116+        //! Timestamp of the last window reset.
    117+        std::chrono::time_point<NodeClock> m_last_reset;
    


    stickies-v commented at 12:30 pm on May 30, 2025:

    Not a big issue, but since we have quite a few log source locations, this class will be instantiated a fair amount of (N) times. An alternative approach would be to have a single LogRateLimiter instance that encapsulates most of the logic in 6b54362c19ca9baf9dfa9be9281f6faeda169420, and has a single m_last_reset member, spawning a minimal SourceLocationCounter struct for each source location, containing just the m_available_bytes and m_dropped_bytes members.

    This:

    • reduces N std::chrono::time_point<NodeClock> instances to just 1
    • allows LogRateLimiter to completely clean up memory for log locations that haven’t been triggered in the last hour
    • improves code encapsulation

    Overall, this shouldn’t be a big change from what you have now, mostly just moving code around into a new class?


    Crypt-iQ commented at 4:18 pm on May 30, 2025:
    Yup I had thought about this and wasn’t sure how to evaluate the overhead. I’ll change it.

    Crypt-iQ commented at 5:40 pm on June 4, 2025:
    Implemented this change, lmk what you think. I think this encapsulates code a bit better, but it probably could still be improved.

    stickies-v commented at 9:44 am on June 5, 2025:
    I’ve left some comments for further encapsulation, but yeah I think this a step in the right direction, thanks!
  25. in src/logging.cpp:404 in 6dece0553c outdated
    404+
    405+            str.insert(0, strprintf("Restarting logging from %s:%d (%s): "
    406+                                    "(%d MiB) were dropped during the last hour.\n",
    407+                                    source_loc.file_name(), source_loc.line(), logging_function,
    408+                                    dropped_bytes / (1024 * 1024)));
    409+        } else if (is_ratelimited && !was_ratelimited) {
    


    stickies-v commented at 12:49 pm on May 30, 2025:

    nit: It would be nice if we could catch this in debug builds (ideally even at a fraction, say 20% of the limit), to help inform if our default limit needs to change. Assume() is an option, but that would probably break unit tests in debug builds.

    nit, because 1MB is small enough that it should prevent issues even on devices with little disk size (unless an attacker finds multiple log vulnerabilities), and large enough that no single unconditional logging statement should ever hit that in the foreseeable future, so I think “driving blind” is acceptable here.


    Crypt-iQ commented at 5:39 pm on June 4, 2025:
    I want to address this because I think it would be useful to catch in debug builds via Assume but also don’t want to break tests. Do you think this should be addressed?
  26. dergoegge commented at 8:47 am on June 3, 2025: member
    I vaguely remember having trouble with the unit tests on windows too. Iirc it had something to do with windows line endings being different (i.e. \r\n on windows vs \n on linux), which throws off the size accounting.
  27. in src/logging.h:172 in 6dece0553c outdated
    167@@ -105,6 +168,11 @@ namespace BCLog {
    168         size_t m_cur_buffer_memusage GUARDED_BY(m_cs){0};
    169         size_t m_buffer_lines_discarded GUARDED_BY(m_cs){0};
    170 
    171+        //! Fixed window rate limiters for each source location that has attempted to log something.
    172+        std::unordered_map<std::source_location, LogRateLimiter, SourceLocationHasher, SourceLocationEqual> m_ratelimiters GUARDED_BY(m_cs);
    


    l0rinc commented at 9:57 am on June 3, 2025:
    Do we ever clear m_ratelimiters, or does that map only grow over the lifetime of the process?

    Crypt-iQ commented at 2:09 pm on June 3, 2025:
    This never gets cleared. I haven’t calculated the overhead of the map, but it could make sense to clear it periodically. Do you think it should just be on a timer or something?

    stickies-v commented at 2:13 pm on June 3, 2025:
    note: this is part of my suggestion in #32604 (review)

    l0rinc commented at 3:03 pm on June 3, 2025:
    @stickies-v, my mistake, I quickly wanted to make sure this doesn’t affect my IBD benchmarks, didn’t have time to review it in detail yet

    Crypt-iQ commented at 5:51 pm on June 4, 2025:
    Both the map and set are now cleared if LogRateLimiter determines that the logging window should be reset.
  28. maflcko commented at 10:03 am on June 3, 2025: member

    The tidy job is failing because it doesn’t like the logging macros being used in lambda functions. It seems like this is pre-existing so I’m not sure why it’s failing now.

    It happens after commit dfbc3e46b8661b112a91c5f00a4dce439f4f5914 and looks unrelated. Maybe just use the workaround from ./src/util/check.h?

  29. l0rinc commented at 10:09 am on June 3, 2025: contributor

    Concept ACK, but I’m not yet sure about the approach. Let me know if I misunderstood something important here.

    Edit:

    All logs will be prefixed with [*] if there is at least one source location that is currently being suppressed

    Will that appear on the console as well, which didn’t have any messages dropped?

  30. l0rinc changes_requested
  31. Crypt-iQ force-pushed on Jun 4, 2025
  32. Crypt-iQ commented at 5:58 pm on June 4, 2025: contributor

    The latest change uses a single BCLog::LogRateLimiter instance and uses a slimmer way of tracking the amount of logging bytes left per std::source_location. I like the approach better as m_categories is no longer being used. I would like to point out that the rate-limiting logic can be bypassed if LogPrintLevel is used. I think LogPrintLevel callers need to be cautious and I kind of think this macro shouldn’t be used if level >= BCLog::Level::Info.

    Will that appear on the console as well, which didn’t have any messages dropped?

    Yes this appears in the console as well. I actually was unsure if console-logging should be rate-limited or not. Hopefully users have sensible limits on their terminal history?

    I will work on fixing the CI, I think review can still happen in the meantime while I debug the windows failure and fix the tidy job.

  33. Crypt-iQ force-pushed on Jun 4, 2025
  34. DrahtBot removed the label CI failed on Jun 4, 2025
  35. in src/logging.h:40 in bec7462686 outdated
    33@@ -31,6 +34,24 @@ extern const char * const DEFAULT_DEBUGLOGFILE;
    34 
    35 extern bool fLogIPs;
    36 
    37+struct SourceLocationEqual {
    38+    bool operator()(const std::source_location& lhs, const std::source_location& rhs) const noexcept
    39+    {
    40+        return strcmp(lhs.file_name(), rhs.file_name()) == 0 && lhs.line() == rhs.line();
    


    stickies-v commented at 8:38 am on June 5, 2025:

    in bec74626867abefbfc55da5aaaf8a0c030663f3a:

    nit: comparing ints is more performant than comparing strings, and is more differentiating than the filename, so would do the line comparison first

    0        return lhs.line() == rhs.line() && strcmp(lhs.file_name(), rhs.file_name()) == 0 ;
    
  36. in src/logging.cpp:379 in 5535df69a2 outdated
    372@@ -364,17 +373,63 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l
    373 
    374 static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
    375 {
    376-    return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
    377+    return buflog.str.size() + buflog.logging_function.size() + strlen(buflog.source_loc.file_name()) + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
    378 }
    379 
    380-void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, std::string_view source_file, int source_line, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const
    381+bool BCLog::Logger::NeedsRateLimiting(bool should_ratelimit, const std::source_location& source_loc, std::string& str, std::string_view logging_function)
    


    stickies-v commented at 9:27 am on June 5, 2025:

    NeedsRateLimiting as well as the underlying maps imo belong to LogRateLimiter rather than Logger. I also don’t think should_ratelimit is a meaningful parameter, the function should just not be called if that’s false. I also don’t understand why logging_function is a separate parameter - can’t we just get that from source_loc?

    Suggested diff that incorporates all of those suggestions:

      0diff --git a/src/logging.cpp b/src/logging.cpp
      1index 1e20c10368..c4ae881ffd 100644
      2--- a/src/logging.cpp
      3+++ b/src/logging.cpp
      4@@ -5,6 +5,7 @@
      5 
      6 #include <logging.h>
      7 #include <memusage.h>
      8+#include <sync.h>
      9 #include <util/check.h>
     10 #include <util/fs.h>
     11 #include <util/string.h>
     12@@ -376,41 +377,40 @@ static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
     13     return buflog.str.size() + buflog.logging_function.size() + strlen(buflog.source_loc.file_name()) + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
     14 }
     15 
     16-bool BCLog::Logger::NeedsRateLimiting(bool should_ratelimit, const std::source_location& source_loc, std::string& str, std::string_view logging_function)
     17+bool BCLog::LogRateLimiter::NeedsRateLimiting(const std::source_location& source_loc, std::string& str)
     18 {
     19+    StdLockGuard scoped_lock(m_cs);
     20     // Whether or not logging to disk was/is ratelimited for this source location.
     21     bool was_ratelimited{false};
     22     bool is_ratelimited{false};
     23 
     24-    if (m_ratelimit && should_ratelimit) {
     25-        // Check to see if we were rate limited before calling ResetWindow.
     26-        was_ratelimited = m_suppressed_locations.find(source_loc) != m_suppressed_locations.end();
     27+    // Check to see if we were rate limited before calling ResetWindow.
     28+    was_ratelimited = m_suppressed_locations.find(source_loc) != m_suppressed_locations.end();
     29 
     30-        // If the m_limiter window has elapsed, then we need to clear the unordered map and set.
     31-        if (m_limiter.ResetWindow()) {
     32-            m_source_locations.clear();
     33-            m_suppressed_locations.clear();
     34-        }
     35+    // If the m_limiter window has elapsed, then we need to clear the unordered map and set.
     36+    if (ResetWindow()) {
     37+        m_source_locations.clear();
     38+        m_suppressed_locations.clear();
     39+    }
     40 
     41-        is_ratelimited = !m_source_locations[source_loc].Consume(str.size());
     42+    is_ratelimited = !m_source_locations[source_loc].Consume(str.size());
     43 
     44-        if (!is_ratelimited && was_ratelimited) {
     45-            uint64_t dropped_bytes = m_source_locations[source_loc].GetDroppedBytes();
     46+    if (!is_ratelimited && was_ratelimited) {
     47+        uint64_t dropped_bytes{m_source_locations[source_loc].GetDroppedBytes()};
     48 
     49-            str.insert(0, strprintf("Restarting logging from %s:%d (%s): "
     50-                                    "(%d MiB) were dropped during the last hour.\n",
     51-                                    source_loc.file_name(), source_loc.line(), logging_function,
     52-                                    dropped_bytes / (1024 * 1024)));
     53-        } else if (is_ratelimited && !was_ratelimited) {
     54-            // Logging from this source location will be suppressed until the current window resets.
     55-            m_suppressed_locations.insert(source_loc);
     56+        str.insert(0, strprintf("Restarting logging from %s:%d (%s): "
     57+                                "(%d MiB) were dropped during the last hour.\n",
     58+                                source_loc.file_name(), source_loc.line(), source_loc.function_name(),
     59+                                dropped_bytes / (1024 * 1024)));
     60+    } else if (is_ratelimited && !was_ratelimited) {
     61+        // Logging from this source location will be suppressed until the current window resets.
     62+        m_suppressed_locations.insert(source_loc);
     63 
     64-            str.insert(0, strprintf("Excessive logging detected from %s:%d (%s): >%d MiB logged during the last hour."
     65-                                    "Suppressing logging to disk from this source location for up to one hour. "
     66-                                    "Console logging unaffected. Last log entry.",
     67-                                    source_loc.file_name(), source_loc.line(), logging_function,
     68-                                    LogRateLimiter::WINDOW_MAX_BYTES / (1024 * 1024)));
     69-        }
     70+        str.insert(0, strprintf("Excessive logging detected from %s:%d (%s): >%d MiB logged during the last hour."
     71+                                "Suppressing logging to disk from this source location for up to one hour. "
     72+                                "Console logging unaffected. Last log entry.",
     73+                                source_loc.file_name(), source_loc.line(), source_loc.function_name(),
     74+                                LogRateLimiter::WINDOW_MAX_BYTES / (1024 * 1024)));
     75     }
     76 
     77     // To avoid confusion caused by dropped log messages when debugging an issue,
     78@@ -479,7 +479,7 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_
     79     }
     80 
     81     FormatLogStrInPlace(str_prefixed, category, level, source_loc, logging_function, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime());
     82-    bool ratelimit = NeedsRateLimiting(should_ratelimit, source_loc, str_prefixed, logging_function);
     83+    bool ratelimit = m_ratelimit && should_ratelimit && m_limiter.NeedsRateLimiting(source_loc, str_prefixed);
     84 
     85     if (m_print_to_console) {
     86         // print to console
     87diff --git a/src/logging.h b/src/logging.h
     88index b94b9cb495..f9441f6913 100644
     89--- a/src/logging.h
     90+++ b/src/logging.h
     91@@ -48,7 +48,7 @@ struct SourceLocationHasher {
     92     {
     93         // Use CSipHasher(0, 0) as a simple way to get uniform distribution.
     94         return static_cast<size_t>(CSipHasher(0, 0)
     95-                                       .Write(std::hash<std::string>{}(s.file_name()))
     96+                                       .Write(std::hash<std::string_view>{}(s.file_name()))
     97                                        .Write(std::hash<int>{}(s.line()))
     98                                        .Finalize());
     99     }
    100@@ -106,13 +106,18 @@ namespace BCLog {
    101     constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
    102     constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging
    103 
    104+    class SourceLocationCounter;
    105     //! Fixed window rate limiter for logging.
    106     class LogRateLimiter
    107     {
    108     private:
    109         //! Timestamp of the last window reset.
    110         std::chrono::time_point<NodeClock> m_last_reset;
    111-
    112+        //! Counters for each source location that has attempted to log something.
    113+        std::unordered_map<std::source_location, SourceLocationCounter, SourceLocationHasher, SourceLocationEqual> m_source_locations GUARDED_BY(m_cs);
    114+        //! Set of source file locations that were dropped on the last log attempt.
    115+        std::unordered_set<std::source_location, SourceLocationHasher, SourceLocationEqual> m_suppressed_locations GUARDED_BY(m_cs);
    116+        mutable StdMutex m_cs; // TODO: does LogRateLimiter need to use Logger:m_cs instead? Didn't investigate.
    117     public:
    118         //! Interval after which the window is reset.
    119         static constexpr std::chrono::hours WINDOW_SIZE{1};
    120@@ -120,6 +125,8 @@ namespace BCLog {
    121         static constexpr uint64_t WINDOW_MAX_BYTES{1024 * 1024};
    122         //! Attempts to reset the window if the window interval has passed. Returns true if the window was reset.
    123         bool ResetWindow();
    124+        //! Check if we need to rate limit a source_location.
    125+        bool NeedsRateLimiting(const std::source_location& source_loc, std::string& str) EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
    126 
    127         LogRateLimiter() : m_last_reset{NodeClock::now()} {}
    128 
    129@@ -176,10 +183,6 @@ namespace BCLog {
    130 
    131         //! Keeps track of the last time we've reset the logging window.
    132         LogRateLimiter m_limiter GUARDED_BY(m_cs);
    133-        //! Counters for each source location that has attempted to log something.
    134-        std::unordered_map<std::source_location, SourceLocationCounter, SourceLocationHasher, SourceLocationEqual> m_source_locations GUARDED_BY(m_cs);
    135-        //! Set of source file locations that were dropped on the last log attempt.
    136-        std::unordered_set<std::source_location, SourceLocationHasher, SourceLocationEqual> m_suppressed_locations GUARDED_BY(m_cs);
    137 
    138         //! Category-specific log level. Overrides `m_log_level`.
    139         std::unordered_map<LogFlags, Level> m_category_log_levels GUARDED_BY(m_cs);
    140@@ -193,9 +196,6 @@ namespace BCLog {
    141 
    142         void FormatLogStrInPlace(std::string& str, LogFlags category, Level level, const std::source_location& source_loc, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const;
    143 
    144-        /** Check if we need to rate limit a source_location. */
    145-        bool NeedsRateLimiting(bool should_ratelimit, const std::source_location& source_loc, std::string& str, std::string_view logging_function) EXCLUSIVE_LOCKS_REQUIRED(m_cs);
    146-
    147         std::string LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const;
    148 
    149         /** Slots that connect to the print signal */
    

    Note: I didn’t think about thread safety much yet, so I just threw in another m_cs to make it compile and pass tests, might be wrong/unsafe as-is.


    Crypt-iQ commented at 8:11 pm on June 5, 2025:
    I’ve removed logging_function and __func__ usage. I think it makes the function names a little longer in the map, but I’m ok with it. I think m_cs is unnecessary if m_ratelimiter is guarded by m_cs?

    stickies-v commented at 9:24 am on June 6, 2025:

    I think it makes the function names a little longer in the map, but I’m ok with it.

    Oh interesting, I didn’t realize that. On my machine, __func__ contains just the function name, whereas function_name() returns the entire signature, e.g.:

    0__func__: AppInitParameterInteraction
    1source_location: bool AppInitParameterInteraction(const ArgsManager &)
    

    I don’t see how this affects any maps, though? I think it just affects the messages when we stop and restart logging?

    I think m_cs is unnecessary if m_ratelimiter is guarded by m_cs?

    Yeah nice, that seems correct. Probably good to add “This class is not thread-safe.” to the LogRateLimiter docstring, given that it is likely to be used in a multithreaded context.


    Crypt-iQ commented at 4:00 pm on June 6, 2025:

    I don’t see how this affects any maps, though? I think it just affects the messages when we stop and restart logging?

    Oh, I think I mistakenly thought that function_name was included in the map somehow or used when hashing std::source_location, but I see that’s not actually the case.

  37. in src/logging.h:51 in 5535df69a2 outdated
    46+struct SourceLocationHasher {
    47+    size_t operator()(const std::source_location& s) const noexcept
    48+    {
    49+        // Use CSipHasher(0, 0) as a simple way to get uniform distribution.
    50+        return static_cast<size_t>(CSipHasher(0, 0)
    51+                                       .Write(std::hash<std::string>{}(s.file_name()))
    


    stickies-v commented at 9:27 am on June 5, 2025:

    nit: string_view to avoid unnecessary string construction

    0                                       .Write(std::hash<std::string_view>{}(s.file_name()))
    
  38. in src/logging.h:358 in 5535df69a2 outdated
    359-            LogPrintLevel_(category, level, __VA_ARGS__); \
    360-        }                                                 \
    361+// Note that conditional logging is performed WITHOUT rate limiting. Users specifying
    362+// -debug are assumed to be developers or power users who are aware that -debug may cause
    363+// excessive disk usage due to logging.
    364+#define LogPrintLevel(category, level, ...)                                           \
    


    stickies-v commented at 9:44 am on June 5, 2025:

    The previous docstring is misleading, LogPrintLevel() can also be used for unconditional logging when a Level::Info is passed as level, as is e.g. done in mapport.cpp and in a few other places. I don’t think this is a robust way of deciding on rate limiting.

    I think I would prefer either:

    1. using LogPrintLevel_ directly in UpdateTipLog(), with a comment on why we’re using a private function and not enabling rate limiting here. A LogInfoAlways macro could be an alternative.
    2. refactoring logging.h replace a lot of the current macros to become regular functions using std::source_location, allowing easier overloads for ratelimiting. This probably makes more sense in a separate pull, so imo going with 1. in this PR and then improving with 2. separately would be nice?

    Crypt-iQ commented at 8:10 pm on June 5, 2025:
    I’ve changed the misleading docstring and I’ve implemented suggestion 1. and I will pick up suggestion 2. as well. I think this might conflict a bit with the work in #29256.

    stickies-v commented at 10:04 am on June 6, 2025:
    Nice. Since af86b55f996cf06e8e9179d5c1fe7ce3d94fa3c6 now uses LogPrintLevel_ directly, I think the changes to LogPrintLevel in ed3c0a592b60a565ec5dade7c3af62e7f4cf75a1 can now be reverted and rate limiting applied consistently to all “public” macros? (would also require an update to the UpdateTipLog docstring)

    Crypt-iQ commented at 4:35 pm on June 6, 2025:
    I’m a little unsure about adding rate-limiting to LogPrintLevel as then if a user runs with -debug, they could potentially hit the rate-limit via LogDebug or by some of the existing LogPrintLevel calls. I think it is in the user’s best interest to have rate-limiting applied to all public macros like you suggested, but I also don’t want to potentially confuse users as to why their debug.log is incomplete due to rate-limiting when they are just running with -debug.

    stickies-v commented at 11:18 am on June 9, 2025:

    Oh no I agree, debug logs should be exempt from ratelimiting. My point is just that I think it’s bad to have different logging behaviour depending on whether LogInfo() or LogPrintLevel(..., BCLog::Info) is used, so I think something like the below would work well?

     0diff --git a/src/logging.h b/src/logging.h
     1index d588ef86dc..5f298405e7 100644
     2--- a/src/logging.h
     3+++ b/src/logging.h
     4@@ -349,17 +349,13 @@ inline void LogPrintFormatInternal(const std::source_location& source_loc, const
     5 // Use a macro instead of a function for conditional logging to prevent
     6 // evaluating arguments when logging for the category is not enabled.
     7 
     8-// Log by prefixing the output with the passed category name and severity level. This can either
     9-// log conditionally if the category is allowed or unconditionally if level >= BCLog::Level::Info
    10-// is passed. Note that this function bypasses rate limiting. Callers need to take care to ensure
    11-// that an attacker cannot trigger a disk-fill vulnerability if level >= Info is used. Additionally,
    12-// users specifying -debug are assumed to be developers or power users who are aware that -debug
    13-// may cause excessive disk usage due to logging.
    14-#define LogPrintLevel(category, level, ...)                                           \
    15-    do {                                                                              \
    16-        if (LogAcceptCategory((category), (level))) {                                 \
    17-            LogPrintLevel_(category, level, /*should_ratelimit=*/false, __VA_ARGS__); \
    18-        }                                                                             \
    19+// Log conditionally, prefixing the output with the passed category name and severity level.
    20+#define LogPrintLevel(category, level, ...)                             \
    21+    do {                                                                \
    22+        if (LogAcceptCategory((category), (level))) {                   \
    23+            bool rate_limit{level >= BCLog::Info};                      \
    24+            LogPrintLevel_(category, level, rate_limit, __VA_ARGS__);   \
    25+        }                                                               \
    26     } while (0)
    27 
    28 // Log conditionally, prefixing the output with the passed category name.
    

    Crypt-iQ commented at 1:04 pm on June 9, 2025:
    Oh I completely misunderstood! I like this suggestion a lot and I think it plugs the hole. I am not sure the future plans for LogPrintLevel but I wonder if eventually all instances of LogPrintLevel with level >= BCLog::Info could instead be converted to LogInfo or the equivalent?

    stickies-v commented at 2:03 pm on June 9, 2025:

    In a general sense, having a generalized logging function is helpful when the loglevel isn’t known in advance, as is e.g. the case here: https://github.com/bitcoin/bitcoin/blob/f3bbc746647d1fd23bf5cfe357e32f38c5f6319c/src/httpserver.cpp#L440

    It seems like we currently don’t really need it in our codebase, but I would keep that discussion for a separate PR because it would lead us astray a bit much here?


    Crypt-iQ commented at 3:27 pm on June 11, 2025:
    Resolving as it’s now addressed.
  39. in src/logging.cpp:393 in 5535df69a2 outdated
    390+
    391+        // If the m_limiter window has elapsed, then we need to clear the unordered map and set.
    392+        if (m_limiter.ResetWindow()) {
    393+            m_source_locations.clear();
    394+            m_suppressed_locations.clear();
    395+        }
    


    stickies-v commented at 10:15 am on June 5, 2025:

    This logic should be encapsulated in ResetWindow imo, so probably this statement could just be:

    0        m_limiter.MaybeResetWindow();
    
  40. Crypt-iQ force-pushed on Jun 5, 2025
  41. Crypt-iQ force-pushed on Jun 5, 2025
  42. DrahtBot added the label CI failed on Jun 5, 2025
  43. DrahtBot commented at 6:57 pm on June 5, 2025: contributor

    🚧 At least one of the CI tasks failed. Task previous releases, depends DEBUG: https://github.com/bitcoin/bitcoin/runs/43565644662 LLM reason (✨ experimental): The build failed due to a compilation error caused by incomplete type declaration of BCLog::SourceLocationCounter.

    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.

  44. Crypt-iQ force-pushed on Jun 5, 2025
  45. Crypt-iQ commented at 8:12 pm on June 5, 2025: contributor

    The latest push encapsulates things a bit more. I think there’s still room for improvement and am open to suggestions – I don’t like how WINDOW_MAX_BYTES is not a LogRateLimiter member and I also dislike the friend class Logger usage.

    I think the windows cross-built job is failing because a static BCLog::Logger* is shared across tests and is triggering the rate-limiting logic before the logging tests are run. The CI logs have an asterisk: Mismatch at position 0: [*] foo5: bar5 != foo5: bar5

  46. Crypt-iQ force-pushed on Jun 5, 2025
  47. Crypt-iQ force-pushed on Jun 5, 2025
  48. DrahtBot removed the label CI failed on Jun 5, 2025
  49. in src/logging.h:107 in 911ee520c8 outdated
    103@@ -82,15 +104,68 @@ 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 WINDOW_MAX_BYTES{1024 * 1024}; // maximum number of bytes that can be logged within one window
    


    stickies-v commented at 7:53 am on June 6, 2025:
    nit: moving it into the BCLog namespace seems fine, but BCLog::WINDOW_MAX_BYTES is not a very helpful name. RATELIMIT_MAX_BYTES probably better?
  50. in src/logging.h:147 in 911ee520c8 outdated
    142+        //! Counters for each source location that has attempted to log something.
    143+        std::unordered_map<std::source_location, SourceLocationCounter, SourceLocationHasher, SourceLocationEqual> m_source_locations;
    144+        //! Set of source file locations that were dropped on the last log attempt.
    145+        std::unordered_set<std::source_location, SourceLocationHasher, SourceLocationEqual> m_suppressed_locations;
    146+
    147+        //! Attempts to reset the logging window if the window interval has passed. This will clear m_source_locations and m_suppressed_locations if a reset occurs.
    


    stickies-v commented at 8:04 am on June 6, 2025:

    nit: line length

    0        //! Attempts to reset the logging window if the window interval has passed. This will clear
    1        //! m_source_locations and m_suppressed_locations if a reset occurs.
    
  51. in src/logging.h:153 in 911ee520c8 outdated
    148+        void MaybeResetWindow();
    149+
    150+    public:
    151+        //! Interval after which the window is reset.
    152+        static constexpr std::chrono::hours WINDOW_SIZE{1};
    153+        //! Check if we need to rate limit a source location.
    


    stickies-v commented at 8:06 am on June 6, 2025:

    Docstring could be beefed up a bit to highlight that this is not a pure check but has side effects. E.g.:

    0        //! Consumes `source_loc`'s available bytes corresponding to the size of the (formatted)
    1        //! `str` and returns true if it exceeds the allowance in the current time window.
    
  52. in src/logging.cpp:399 in 911ee520c8 outdated
    395+        uint64_t dropped_bytes = m_source_locations[source_loc].GetDroppedBytes();
    396+
    397+        str.insert(0, strprintf("Restarting logging from %s:%d (%s): "
    398+                                "(%d MiB) were dropped during the last hour.\n",
    399+                                source_loc.file_name(), source_loc.line(), source_loc.function_name(),
    400+                                dropped_bytes / (1024 * 1024)));
    


    stickies-v commented at 9:28 am on June 6, 2025:
    This will now only be shown for a single source location per time window. I think this should be moved to MaybeResetWindow(), where we iterate over m_suppressed_locations before clearing it?

    Crypt-iQ commented at 3:31 pm on June 11, 2025:
    I’ve made this change, lmk what you think. MaybeResetWindow() now uses str.insert(0, ...) per m_suppressed_locations.
  53. in src/logging.cpp:422 in 911ee520c8 outdated
    425 
    426     str.insert(0, GetLogPrefix(category, level));
    427 
    428     if (m_log_sourcelocations) {
    429-        str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_file, "./"), source_line, logging_function));
    430+        str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_loc.file_name(), "./"), source_loc.line(), source_loc.function_name()));
    


    stickies-v commented at 9:43 am on June 6, 2025:
    As you pointed out, this changes the logging output by now including the full function signature instead of just the function name. I think that’s generally an improvement, but should probably be mentioned in the release notes (which would be good to have for the new rate limiting behaviour in general anyway) because it might break downstream log parsing. Would suggest adding commit at the top with release notes?
  54. in src/logging.cpp:454 in 911ee520c8 outdated
    449@@ -400,10 +450,8 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_
    450                 .now=SystemClock::now(),
    451                 .mocktime=GetMockTime(),
    452                 .str=str_prefixed,
    453-                .logging_function=std::string(logging_function),
    454-                .source_file=std::string(source_file),
    455                 .threadname=util::ThreadGetInternalName(),
    456-                .source_line=source_line,
    457+                .source_loc=source_loc,
    


    stickies-v commented at 9:46 am on June 6, 2025:

    Since source_loc is fairly large and this function is frequently called, I think it might make sense to optimize this a bit further and have LogPrintStr_ (and its callsites) take a std::source_location&& so we can move it here and avoid the copy?

      0diff --git a/src/logging.cpp b/src/logging.cpp
      1index e31e346549..006bac6a98 100644
      2--- a/src/logging.cpp
      3+++ b/src/logging.cpp
      4@@ -74,8 +74,7 @@ bool BCLog::Logger::StartLogging()
      5     // dump buffered messages from before we opened the log
      6     m_buffering = false;
      7     if (m_buffer_lines_discarded > 0) {
      8-        const auto source_loc{std::source_location::current()};
      9-        LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), source_loc, BCLog::ALL, Level::Info, /*should_ratelimit=*/false);
     10+        LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), std::source_location::current(), BCLog::ALL, Level::Info, /*should_ratelimit=*/false);
     11     }
     12     while (!m_msgs_before_open.empty()) {
     13         const auto& buflog = m_msgs_before_open.front();
     14@@ -434,13 +433,13 @@ void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags catego
     15     str.insert(0, LogTimestampStr(now, mocktime));
     16 }
     17 
     18-void BCLog::Logger::LogPrintStr(std::string_view str, const std::source_location& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
     19+void BCLog::Logger::LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
     20 {
     21     StdLockGuard scoped_lock(m_cs);
     22-    return LogPrintStr_(str, source_loc, category, level, should_ratelimit);
     23+    return LogPrintStr_(str, std::move(source_loc), category, level, should_ratelimit);
     24 }
     25 
     26-void BCLog::Logger::LogPrintStr_(std::string_view str, const std::source_location& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
     27+void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
     28 {
     29     std::string str_prefixed = LogEscapeMessage(str);
     30 
     31@@ -451,7 +450,7 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, const std::source_locatio
     32                 .mocktime=GetMockTime(),
     33                 .str=str_prefixed,
     34                 .threadname=util::ThreadGetInternalName(),
     35-                .source_loc=source_loc,
     36+                .source_loc=std::move(source_loc),
     37                 .category=category,
     38                 .level=level,
     39             };
     40diff --git a/src/logging.h b/src/logging.h
     41index d588ef86dc..edef5c074f 100644
     42--- a/src/logging.h
     43+++ b/src/logging.h
     44@@ -201,7 +201,7 @@ namespace BCLog {
     45         std::list<std::function<void(const std::string&)>> m_print_callbacks GUARDED_BY(m_cs) {};
     46 
     47         /** Send a string to the log output (internal) */
     48-        void LogPrintStr_(std::string_view str, const std::source_location& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
     49+        void LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
     50             EXCLUSIVE_LOCKS_REQUIRED(m_cs);
     51 
     52         std::string GetLogPrefix(LogFlags category, Level level) const;
     53@@ -220,7 +220,7 @@ namespace BCLog {
     54         std::atomic<bool> m_reopen_file{false};
     55 
     56         /** Send a string to the log output */
     57-        void LogPrintStr(std::string_view str, const std::source_location& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
     58+        void LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
     59             EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
     60 
     61         /** Returns whether logs will be written to any output */
     62@@ -320,7 +320,7 @@ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level leve
     63 bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str);
     64 
     65 template <typename... Args>
     66-inline void LogPrintFormatInternal(const std::source_location& source_loc, const BCLog::LogFlags flag, const BCLog::Level level, const bool should_ratelimit, util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args)
     67+inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLog::LogFlags flag, const BCLog::Level level, const bool should_ratelimit, util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args)
     68 {
     69     if (LogInstance().Enabled()) {
     70         std::string log_msg;
     71@@ -329,7 +329,7 @@ inline void LogPrintFormatInternal(const std::source_location& source_loc, const
     72         } catch (tinyformat::format_error& fmterr) {
     73             log_msg = "Error \"" + std::string{fmterr.what()} + "\" while formatting log message: " + fmt.fmt;
     74         }
     75-        LogInstance().LogPrintStr(log_msg, source_loc, flag, level, should_ratelimit);
     76+        LogInstance().LogPrintStr(log_msg, std::move(source_loc), flag, level, should_ratelimit);
     77     }
     78 }
     79 
     80diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
     81index 0043df182e..f5ce17aa23 100644
     82--- a/src/test/logging_tests.cpp
     83+++ b/src/test/logging_tests.cpp
     84@@ -97,12 +97,12 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
     85         std::source_location::current(),
     86         std::source_location::current(),
     87     };
     88-    LogInstance().LogPrintStr("foo1: bar1", source_locs[0], BCLog::LogFlags::NET, BCLog::Level::Debug, /*should_ratelimit=*/false);
     89-    LogInstance().LogPrintStr("foo2: bar2", source_locs[1], BCLog::LogFlags::NET, BCLog::Level::Info, /*should_ratelimit=*/false);
     90-    LogInstance().LogPrintStr("foo3: bar3", source_locs[2], BCLog::LogFlags::ALL, BCLog::Level::Debug, /*should_ratelimit=*/false);
     91-    LogInstance().LogPrintStr("foo4: bar4", source_locs[3], BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/false);
     92-    LogInstance().LogPrintStr("foo5: bar5", source_locs[4], BCLog::LogFlags::NONE, BCLog::Level::Debug, /*should_ratelimit=*/false);
     93-    LogInstance().LogPrintStr("foo6: bar6", source_locs[5], BCLog::LogFlags::NONE, BCLog::Level::Info, /*should_ratelimit=*/false);
     94+    LogInstance().LogPrintStr("foo1: bar1", std::move(source_locs[0]), BCLog::LogFlags::NET, BCLog::Level::Debug, /*should_ratelimit=*/false);
     95+    LogInstance().LogPrintStr("foo2: bar2", std::move(source_locs[1]), BCLog::LogFlags::NET, BCLog::Level::Info, /*should_ratelimit=*/false);
     96+    LogInstance().LogPrintStr("foo3: bar3", std::move(source_locs[2]), BCLog::LogFlags::ALL, BCLog::Level::Debug, /*should_ratelimit=*/false);
     97+    LogInstance().LogPrintStr("foo4: bar4", std::move(source_locs[3]), BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/false);
     98+    LogInstance().LogPrintStr("foo5: bar5", std::move(source_locs[4]), BCLog::LogFlags::NONE, BCLog::Level::Debug, /*should_ratelimit=*/false);
     99+    LogInstance().LogPrintStr("foo6: bar6", std::move(source_locs[5]), BCLog::LogFlags::NONE, BCLog::Level::Info, /*should_ratelimit=*/false);
    100     std::ifstream file{tmp_log_path};
    101     std::vector<std::string> log_lines;
    102     for (std::string log; std::getline(file, log);) {
    

    Crypt-iQ commented at 3:37 pm on June 11, 2025:
    I’ve sort of implemented this. I wasn’t able to use std::source_location&& in LogPrintStr_ because it’s passed to two functions (FormatLogStrInPlace and NeedsRateLimiting) and implicit invalidation might occur. Instead, I pass std::source_location& and call std::move only when needed to invoke the move constructor.

    Crypt-iQ commented at 5:33 pm on June 12, 2025:
    I am not sure how I feel about my approach here because the caller of LogPrintStr_ now needs to be aware that std::source_location& can be moved-from?
  55. stickies-v commented at 10:07 am on June 6, 2025: contributor
    Approach ACK. I think this PR needs release notes because of the behaviour change.
  56. Crypt-iQ force-pushed on Jun 11, 2025
  57. log: introduce BCLog::LogRateLimiter and BCLog::SourceLocationCounter
    LogRateLimiter will be used to keep track of source locations and our
    current time-based logging window. It contains an unordered_map and
    unordered_set to track source locations. This will be used in a later
    commit by BCLog::Logger to manage all of the rate limiting logic.
    
    SourceLocationCounter counts the available bytes left for logging per
    source location for the current logging window. It does not track actual
    source locations; it is used as a value in m_source_locations.
    
    Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
    54b03e9c59
  58. log: use std::source_location in place of __func__, __FILE__, __LINE__
    The std::source_location conveniently stores the file name, line number,
    and function name of a source code location. We switch to using it instead
    of the __func__ identifier and the __FILE__ and __LINE__ macros.
    
    Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
    3f5f48d8a6
  59. log: Add rate limiting to LogPrintf, LogInfo, LogWarning, and LogError
    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::NeedsRateLimiting. 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.
    
    Note that this rate limiting change does not affect callers that directly
    use LogPrintLevel with BCLog::Level >= BCLog::Level::Info.
    
    Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
    8a5957e770
  60. validation: use private LogPrintLevel_ to exempt UpdateTipLog from rate limiting
    Since UpdateTipLog logs heavily during IBD, we need to exempt it from
    rate limiting. This is done by using the LogPrintLevel_ macro so that
    we can explicitly set should_ratelimit to false. The public LogPrintLevel
    macro is intentionally un-used so as not to encourage potentially unsafe
    log macro usage.
    
    Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
    f2061dabe5
  61. test: Mark ~DebugLogHelper as noexcept(false)
    We mark ~DebugLogHelper as noexcept(false) to be able to catch the
    exception it throws. This lets us use it in test in combination with
    BOOST_CHECK_THROW and BOOST_CHECK_NO_THROW to check that certain log
    messages are (not) logged.
    
    Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
    950f9f0293
  62. test: introduce logging_sourcelocation_counter to test SourceLocationCounter
    Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
    eb510ccb32
  63. test: introduce rate_limiting test
    The rate_limiting test checks that:
    - rate limiting is disabled for exempt source locations
    - the debug.log file size changes as expected when rate limiting
    - the expected rate limiting-specific log messages are written
    
    Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
    a7bd7c9a69
  64. Crypt-iQ force-pushed on Jun 11, 2025
  65. DrahtBot added the label CI failed on Jun 11, 2025
  66. DrahtBot commented at 3:46 pm on June 11, 2025: contributor

    🚧 At least one of the CI tasks failed. Task ARM, unit tests, no functional tests: https://github.com/bitcoin/bitcoin/runs/43903011789 LLM reason (✨ experimental): The CI failure is caused by a compilation error in logging_tests.cpp due to a narrowing type conversion resulting in the build stopping.

    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.

  67. Crypt-iQ commented at 4:56 pm on June 11, 2025: contributor

    The latest push a7bd7c9a69de72739326026b7ab660181c8d02fb includes:

    • rate limiting for callers of LogPrintLevel with level >= BCLog::Level::Info.
    • fix for the windows cross-built CI by using GetFileSize instead of fs::file_size in logging_tests/rate_limiting

    I’ve repurposed the old logging rpc from #21603 in another branch for testing here. This can be used to log from source locations and test out the new changes in logging behavior. Note that the setmocktime RPC needs to be used to set the mock time past the current clock time to reset the logging messages.

    Example usage:

    0bitcoin-cli -regtest excessivelog 1 1048500 # log just under 1MiB
    1bitcoin-cli -regtest excessivelog 1 100 # this should get the total amount logged above 1MiB
    2                                        # and the rate limiting logic should kick in
    3bitcoin-cli -regtest excessivelog 2 1048500
    4bitcoin-cli -regtest excessivelog 2 100 # trigger rate limiting from another location
    5bitcoin-cli -regtest setmocktime <N> # set this past the current clock time because of how `LogRateLimiter` is initialized
    6bitcoin-cli -regtest excessivelog 1 100 # this should trigger logging to resume and will log the source locations that were reset
    

    Example output:

    0[*] Excessive logging detected from rpc/node.cpp:139 (RPCHelpMan excessivelog()): >1 MiB logged during the last hour.Suppressing logging to disk from this source location for up to one hour. Console logging unaffected. Last log entry.2025-06-11T16:32:41Z aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
    1[*] Excessive logging detected from rpc/node.cpp:142 (RPCHelpMan excessivelog()): >1 MiB logged during the last hour.Suppressing logging to disk from this source location for up to one hour. Console logging unaffected. Last log entry.2025-06-11T16:33:04Z aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
    2Restarting logging from rpc/node.cpp:139 (RPCHelpMan excessivelog()): (1 MiB) were dropped during the last hour.
    3Restarting logging from rpc/node.cpp:142 (RPCHelpMan excessivelog()): (0 MiB) were dropped during the last hour.
    
  68. DrahtBot removed the label CI failed on Jun 11, 2025

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2025-06-12 21:13 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me