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

pull Crypt-iQ wants to merge 6 commits into bitcoin:master from Crypt-iQ:log_ratelimiting_05192025 changing 7 files +376 −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 without 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.
    • 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
    ACK dergoegge, stickies-v
    Concept ACK davidgumberg, brunoerg, l0rinc
    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?

    l0rinc commented at 9:41 am on June 24, 2025:

    I’m doing a reindex benchmark to check if the current implementation has any performance burden

    Edit: reindexing until 900k indicates there’s no slowdown caused by this change

     0COMMITS="e95bfc1d537e06d223dfcaec510181aa3d3f8386 f29b081b9277332523b7025394cad15b02cc53d2"; \
     1STOP=900000; DBCACHE=2500; \
     2CC=gcc; CXX=g++; \
     3BASE_DIR="/mnt/my_storage"; DATA_DIR="$BASE_DIR/BitcoinData"; LOG_DIR="$BASE_DIR/logs"; \
     4(echo ""; for c in $COMMITS; do git fetch -q origin $c && git log -1 --pretty='%h %s' $c || exit 1; done; echo "") && \
     5hyperfine \
     6  --sort command \
     7  --runs 1 \
     8  --export-json "$BASE_DIR/rdx-$(sed -E 's/(\w{8})\w+ ?/\1-/g;s/-$//'<<<"$COMMITS")-$STOP-$DBCACHE-$CC.json" \
     9  --parameter-list COMMIT ${COMMITS// /,} \
    10  --prepare "killall bitcoind; rm -f $DATA_DIR/debug.log; git checkout {COMMIT}; git clean -fxd; git reset --hard && \
    11    cmake -B build -G Ninja -DCMAKE_BUILD_TYPE=Release && ninja -C build bitcoind && \
    12    ./build/bin/bitcoind -datadir=$DATA_DIR -stopatheight=$STOP -dbcache=1000 -printtoconsole=0; sleep 10" \
    13  --cleanup "cp $DATA_DIR/debug.log $LOG_DIR/debug-{COMMIT}-$(date +%s).log" \
    14  "COMPILER=$CC ./build/bin/bitcoind -datadir=$DATA_DIR -stopatheight=$STOP -dbcache=$DBCACHE -reindex -blocksonly -connect=0 -printtoconsole=0"
    

    e95bfc1d53 Merge bitcoin/bitcoin#32797: doc: archive 28.2 release notes f29b081b92 doc: add release notes for new rate limiting logging behavior

    0Benchmark 1: COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -stopatheight=900000 -dbcache=2500 -reindex -blocksonly -connect=0 -printtoconsole=0 (COMMIT = e95bfc1d537e06d223dfcaec510181aa3d3f8386)
    1  Time (abs ):        29033.291 s               [User: 43597.672 s, System: 1644.619 s]
    2 
    3Benchmark 2: COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -stopatheight=900000 -dbcache=2500 -reindex -blocksonly -connect=0 -printtoconsole=0 (COMMIT = f29b081b9277332523b7025394cad15b02cc53d2)
    4  Time (abs ):        28875.472 s               [User: 43552.019 s, System: 1541.380 s]
    
    0Relative speed comparison
    1        1.01          COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -stopatheight=900000 -dbcache=2500 -reindex -blocksonly -connect=0 -printtoconsole=0 (COMMIT = e95bfc1d537e06d223dfcaec510181aa3d3f8386)
    2        1.00          COMPILER=gcc ./build/bin/bitcoind -datadir=/mnt/my_storage/BitcoinData -stopatheight=900000 -dbcache=2500 -reindex -blocksonly -connect=0 -printtoconsole=0 (COMMIT = f29b081b9277332523b7025394cad15b02cc53d2)
    

    Crypt-iQ commented at 12:40 pm on June 26, 2025:
    Sweet, thanks for doing this! I was curious about any performance hits.
  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.

    stickies-v commented at 12:24 pm on June 19, 2025:
    Yeah, that looks good, thanks. It’s unfortunate that these message are counted in is_ratelimited = !m_source_locations[source_loc].Consume(str.size());, but suppressions should be extremely rare, so triggering enough of them to cause a meaningful difference here seems impractical. A solution with not too much change could be to change to MaybeResetWindow(const std::string& str, std::string& resume_msg), so we can keep separate accounting, but yeah not sure that’s worth it/important.

    Crypt-iQ commented at 8:50 pm on June 23, 2025:
    Deciding to keep as-is
  53. in src/logging.cpp:420 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?

    Crypt-iQ commented at 8:50 pm on June 23, 2025:
    Done
  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?

    Crypt-iQ commented at 11:18 pm on June 12, 2025:
    I misunderstood the original suggestion and have now implemented it in ca0c1a7a9ce9198c950e123d36c9e4bb13db13da
  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. Crypt-iQ force-pushed on Jun 11, 2025
  58. DrahtBot added the label CI failed on Jun 11, 2025
  59. 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.

  60. 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.
    
  61. DrahtBot removed the label CI failed on Jun 11, 2025
  62. Crypt-iQ force-pushed on Jun 12, 2025
  63. in src/logging.cpp:398 in b7d9c669ca outdated
    396+    if (is_ratelimited && !was_ratelimited) {
    397+        // Logging from this source location will be suppressed until the current window resets.
    398+        m_suppressed_locations.insert(source_loc);
    399+
    400+        str.insert(0, strprintf("Excessive logging detected from %s:%d (%s): >%d MiB logged during the last hour."
    401+                                "Suppressing logging to disk from this source location for up to one hour. "
    


    DrahtBot commented at 9:40 am on June 13, 2025:
    In the two-part string literal in NeedsRateLimiting: “…during the last hour.”“Suppressing logging…” -> “…during the last hour. Suppressing logging…” [missing space between sentences due to C++ literal concatenation]
  64. in src/logging.h:51 in b7d9c669ca outdated
    46+    size_t operator()(const std::source_location& s) const noexcept
    47+    {
    48+        // Use CSipHasher(0, 0) as a simple way to get uniform distribution.
    49+        return static_cast<size_t>(CSipHasher(0, 0)
    50+                                       .Write(std::hash<std::string_view>{}(s.file_name()))
    51+                                       .Write(std::hash<int>{}(s.line()))
    


    stickies-v commented at 10:47 am on June 19, 2025:

    nit: I don’t think hashing the line is necessary?

    0                                       .Write(s.line())
    

    Crypt-iQ commented at 8:51 pm on June 23, 2025:
    Yup good catch
  65. in src/logging.cpp:392 in b7d9c669ca outdated
    389+    was_ratelimited = m_suppressed_locations.find(source_loc) != m_suppressed_locations.end();
    390+
    391+    // If the window has elapsed, then we need to clear the unordered map and set.
    392+    MaybeResetWindow(str);
    393+
    394+    is_ratelimited = !m_source_locations[source_loc].Consume(str.size());
    


    stickies-v commented at 11:07 am on June 19, 2025:

    nit: I think this can be simplified a bit:

     0diff --git a/src/logging.cpp b/src/logging.cpp
     1index 827d1bad10..fec8e5ec58 100644
     2--- a/src/logging.cpp
     3+++ b/src/logging.cpp
     4@@ -379,17 +379,13 @@ static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
     5 
     6 bool BCLog::LogRateLimiter::NeedsRateLimiting(const std::source_location& source_loc, std::string& str)
     7 {
     8-    // Whether or not logging to disk was/is ratelimited for this source location.
     9-    bool was_ratelimited{false};
    10-    bool is_ratelimited{false};
    11-
    12     // Check to see if we were rate limited before calling MaybeResetWindow.
    13-    was_ratelimited = m_suppressed_locations.find(source_loc) != m_suppressed_locations.end();
    14+    bool was_ratelimited{m_suppressed_locations.contains(source_loc)};
    15 
    16     // If the window has elapsed, then we need to clear the unordered map and set.
    17     MaybeResetWindow(str);
    18 
    19-    is_ratelimited = !m_source_locations[source_loc].Consume(str.size());
    20+    bool is_ratelimited{!m_source_locations[source_loc].Consume(str.size())};
    21 
    22     if (is_ratelimited && !was_ratelimited) {
    23         // Logging from this source location will be suppressed until the current window resets.
    
  66. in src/logging.h:202 in ca0c1a7a9c outdated
    195@@ -196,15 +196,15 @@ namespace BCLog {
    196         /** Log categories bitfield. */
    197         std::atomic<CategoryMask> m_categories{BCLog::NONE};
    198 
    199-        void FormatLogStrInPlace(std::string& str, LogFlags category, 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;
    200+        void FormatLogStrInPlace(std::string& str, LogFlags category, Level level, const std::source_location& source_loc, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const;
    


    stickies-v commented at 11:10 am on June 19, 2025:
    nit: updating the ca0c1a7a9ce9198c950e123d36c9e4bb13db13da commit message with a brief mention of the behaviour change for -logsourcelocations would be helpful for both review and historical documentation purposes.
  67. in src/logging.cpp:368 in ca0c1a7a9c outdated
    364@@ -364,7 +365,7 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l
    365 
    366 static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
    367 {
    368-    return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
    369+    return buflog.str.size() + strlen(buflog.source_loc.function_name()) + strlen(buflog.source_loc.file_name()) + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
    


    stickies-v commented at 11:30 am on June 19, 2025:
    nit: I don’t think it’s crucial to be super precise here, since it’s only used briefly during startup, but I think this underestimating the std::source_location size a bit. It’s not accounting the 2*4 bytes for line and column, nor the pointers (3 on gcc) used to implement std::source_location. If people think it’s crucial to get this (more) right, probably adding a separate MemUsage(const std::source_location&) could make sense.

    Crypt-iQ commented at 12:49 pm on June 19, 2025:
    I also noticed this and wasn’t sure if it was worth bringing up.

    stickies-v commented at 3:46 pm on June 19, 2025:

    I was long overdue for my biannual confusion about (dynamic) memory usage, but luckily here it is. It seems like I got it entirely backwards in my previous comment. The memory pointed to by std::source_location is static, so I don’t think we need to account for any of it beyond what the memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>)) statement is already doing.

    Orthogonal, but since we’re touching the line anyway: dynamic memory usage of std::string should be measured with .capacity() instead of .size(). Or even better, use the DynamicUsage(const std::string&) function we already have to also account for small string optimization, which, of course, is totally a thing.

    So the function could become:

    0static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
    1{
    2    return memusage::DynamicUsage(buflog.str) +
    3           memusage::DynamicUsage(buflog.threadname) +
    4           memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
    5}
    

    All in all, this should mean that thanks to ca0c1a7a9ce9198c950e123d36c9e4bb13db13da we can now buffer quite a bit more messages within our 1MB limit. Obviously not going to change anything meaningful, but wouldn’t hurt to add a line to commit msg to highlight that.


    Crypt-iQ commented at 8:51 pm on June 23, 2025:
    Nice catch, I missed that std::source_location was part of BufferedLog and therefore included in the MallocUsage call.

    l0rinc commented at 9:47 am on June 24, 2025:
    👍
  68. in src/logging.cpp:425 in ca0c1a7a9c outdated
    418@@ -418,13 +419,13 @@ void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags catego
    419     str.insert(0, LogTimestampStr(now, mocktime));
    420 }
    421 
    422-void BCLog::Logger::LogPrintStr(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
    423+void BCLog::Logger::LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level)
    424 {
    425     StdLockGuard scoped_lock(m_cs);
    426-    return LogPrintStr_(str, logging_function, source_file, source_line, category, level);
    427+    return LogPrintStr_(str, std::move(source_loc), category, level);
    


    stickies-v commented at 11:32 am on June 19, 2025:
    nit: requires #include <utility>
  69. in src/test/logging_tests.cpp:125 in b7d9c669ca outdated
    132+        "[" + file_name + ":" + util::ToString(source_locs[0].line()) + "] [" + function_name + "] [net] foo1: bar1",
    133+        "[" + file_name + ":" + util::ToString(source_locs[1].line()) + "] [" + function_name + "] [net:info] foo2: bar2",
    134+        "[" + file_name + ":" + util::ToString(source_locs[2].line()) + "] [" + function_name + "] [debug] foo3: bar3",
    135+        "[" + file_name + ":" + util::ToString(source_locs[3].line()) + "] [" + function_name + "] foo4: bar4",
    136+        "[" + file_name + ":" + util::ToString(source_locs[4].line()) + "] [" + function_name + "] [debug] foo5: bar5",
    137+        "[" + file_name + ":" + util::ToString(source_locs[5].line()) + "] [" + function_name + "] foo6: bar6",
    


    stickies-v commented at 11:50 am on June 19, 2025:

    nit: can be cleaned up a bit:

     0diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
     1index c9b7913ee4..d673792ab6 100644
     2--- a/src/test/logging_tests.cpp
     3+++ b/src/test/logging_tests.cpp
     4@@ -114,15 +114,16 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
     5     for (std::string log; std::getline(file, log);) {
     6         log_lines.push_back(log);
     7     }
     8-    std::string file_name = util::RemovePrefix(source_locs[0].file_name(), "./");
     9-    std::string function_name{source_locs[0].function_name()};
    10+    auto format_source_location = [](const std::source_location& loc) {
    11+        return tfm::format("[%s:%s] [%s]", util::RemovePrefixView(loc.file_name(), "./"), loc.line(), loc.function_name());
    12+    };
    13     std::vector<std::string> expected = {
    14-        "[" + file_name + ":" + util::ToString(source_locs[0].line()) + "] [" + function_name + "] [net] foo1: bar1",
    15-        "[" + file_name + ":" + util::ToString(source_locs[1].line()) + "] [" + function_name + "] [net:info] foo2: bar2",
    16-        "[" + file_name + ":" + util::ToString(source_locs[2].line()) + "] [" + function_name + "] [debug] foo3: bar3",
    17-        "[" + file_name + ":" + util::ToString(source_locs[3].line()) + "] [" + function_name + "] foo4: bar4",
    18-        "[" + file_name + ":" + util::ToString(source_locs[4].line()) + "] [" + function_name + "] [debug] foo5: bar5",
    19-        "[" + file_name + ":" + util::ToString(source_locs[5].line()) + "] [" + function_name + "] foo6: bar6",
    20+        format_source_location(source_locs[0]) + " [net] foo1: bar1",
    21+        format_source_location(source_locs[1]) + " [net:info] foo2: bar2",
    22+        format_source_location(source_locs[2]) + " [debug] foo3: bar3",
    23+        format_source_location(source_locs[3]) + " foo4: bar4",
    24+        format_source_location(source_locs[4]) + " [debug] foo5: bar5",
    25+        format_source_location(source_locs[5]) + " foo6: bar6",
    26     };
    27     BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
    28 }
    

    Crypt-iQ commented at 8:51 pm on June 23, 2025:
    done
  70. in src/validation.cpp:2981 in b7d9c669ca outdated
    2985-        coins_tip.DynamicMemoryUsage() * (1.0 / (1 << 20)),
    2986-        coins_tip.GetCacheSize(),
    2987-        !warning_messages.empty() ? strprintf(" warning='%s'", warning_messages) : "");
    2988+
    2989+    // We use the private LogPrintLevel_ macro here because we want to disable rate limiting from this location. This code
    2990+    // could use LogPrintLevel with the Info level to bypass rate-limiting, but it is more opaque. Using LogPrintLevel_
    


    stickies-v commented at 12:02 pm on June 19, 2025:

    This code could use LogPrintLevel with the Info level to bypass rate-limiting

    I don’t think that’s correct? I’m not sure a long docstring is required here anyway, we already have decent documentation for the macros and functions involved. A brief “don’t rate limit because this can be hit frequently during IBD” seems sufficient to me without overloading the reader with information.


    Crypt-iQ commented at 12:48 pm on June 19, 2025:
    I think this is an old comment, will change.
  71. in src/test/util/logging.h:38 in b7d9c669ca outdated
    32@@ -33,7 +33,7 @@ class DebugLogHelper
    33 
    34 public:
    35     explicit DebugLogHelper(std::string message, MatchFn match = [](const std::string*){ return true; });
    36-    ~DebugLogHelper() { check_found(); }
    37+    ~DebugLogHelper() noexcept(false) { check_found(); }
    


    stickies-v commented at 12:05 pm on June 19, 2025:
    nit: (a brief version of) the commit message in 32615bffa6424625078e5bd9f6d79c7e99c9a322 would probably be helpful here as a docstring too?
  72. in src/logging.cpp:400 in b7d9c669ca outdated
    397+        // Logging from this source location will be suppressed until the current window resets.
    398+        m_suppressed_locations.insert(source_loc);
    399+
    400+        str.insert(0, strprintf("Excessive logging detected from %s:%d (%s): >%d MiB logged during the last hour."
    401+                                "Suppressing logging to disk from this source location for up to one hour. "
    402+                                "Console logging unaffected. Last log entry.",
    


    stickies-v commented at 12:18 pm on June 19, 2025:
    Should probably terminate with \n?
  73. stickies-v approved
  74. stickies-v commented at 12:28 pm on June 19, 2025: contributor

    utACK b7d9c669cadf666f595a3e20ee3726a9ede88acd modulo missing release notes

    Thanks for quickly addressing my copious amounts of comments, it’s been fun reviewing this. I’ve left a few (final?) nits, but none are blocking. Would prefer to squash the last 2 test commits into the 2 commits where the relevant functionality was introduced, but either is fine.

  75. DrahtBot requested review from brunoerg on Jun 19, 2025
  76. DrahtBot requested review from janb84 on Jun 19, 2025
  77. DrahtBot requested review from l0rinc on Jun 19, 2025
  78. 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>
    40298a86d2
  79. 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.
    
    Since BufferedLog has a std::source_location member and the function name
    is no longer stored in BufferedLog, we can fit more BufferedLog in our 1MB
    buffering limit.
    
    This also changes the behavior of -logsourcelocations as std::source_location
    includes the entire function signature.
    
    Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
    d41a39e43c
  80. 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::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.
    
    This change also affects the public LogPrintLevel function if called with
    a level >= BCLog::Level::Info.
    
    Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
    b44d31455a
  81. 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.
    
    Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
    5fe08e0138
  82. 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>
    3c30ee9107
  83. doc: add release notes for new rate limiting logging behavior 2ac8696b53
  84. Crypt-iQ force-pushed on Jun 23, 2025
  85. in src/logging.h:41 in 2ac8696b53
    34@@ -31,6 +35,24 @@ extern const char * const DEFAULT_DEBUGLOGFILE;
    35 
    36 extern bool fLogIPs;
    37 
    38+struct SourceLocationEqual {
    39+    bool operator()(const std::source_location& lhs, const std::source_location& rhs) const noexcept
    40+    {
    41+        return lhs.line() == rhs.line() && strcmp(lhs.file_name(), rhs.file_name()) == 0;
    


    l0rinc commented at 7:32 am on June 24, 2025:

    nit: I find mixing C++20 code with C API a bit clunky, if you touch again, consider either comparing their std::string_view wrappers or maybe even adding such a helper to string.h for const char* values.

    edit: also note that equality check may be easier to optimize internally than a comparison

  86. in src/logging.cpp:115 in 2ac8696b53
    107@@ -106,6 +108,15 @@ void BCLog::Logger::DisconnectTestLogger()
    108     m_msgs_before_open.clear();
    109 }
    110 
    111+void BCLog::Logger::ResetLimiter()
    112+{
    113+    StdLockGuard scoped_lock(m_cs);
    114+    const auto now{NodeClock::now()};
    115+    m_limiter.m_last_reset = now;
    


    l0rinc commented at 7:34 am on June 24, 2025:

    I understand when the time is split off from the measured code to make sure it’s accurate - but I don’t see how that’s the case here, consider inlining it:

    0    m_limiter.m_last_reset = NodeClock::now();
    
  87. in src/logging.h:344 in 2ac8696b53
    342 
    343-#define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__)
    344+#define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(std::source_location::current(), category, level, should_ratelimit, __VA_ARGS__)
    345 
    346-// Log unconditionally.
    347+// Log unconditionally. Uses basic rate limiting to mitigate disk filling attacks.
    


    l0rinc commented at 7:44 am on June 24, 2025:
    Seems to me the first two sentences contradict each other now: “log unconditionally, unless it doesn’t fulfill the rate limiting condition”

    stickies-v commented at 12:15 pm on June 24, 2025:

    Semantically, I agree. But practically, I think it’s fine as is. Conditional vs unconditional are at this point fairly established concepts in our logging code in that they indicate whether or not logging categories need to be enabled or not. Rate limiting should in practice never occur, so for all intents and purposes, it is indeed unconditional.

    How would you suggest to improve this? I can’t think of an improvement.


    l0rinc commented at 12:20 pm on June 24, 2025:
    I don’t consider “established” a relevant argument in this case - it just prevents new contributors from understanding the codebase. But if you think this isn’t confusing, I don’t mind resolving the comment, I did eventually understand it, just got sidetracked by the contradiction and wanted to simplify it to the next person. If we do correct it, we could be more specific instead of overly generalizing it (ie specify the restrictions instead of claiming there are none).

    Crypt-iQ commented at 7:22 pm on June 26, 2025:

    I don’t think this is confusing because of prior context. I can understand the point about newer contributors. I’ve come across other places in the codebase where I’ve had to learn the context by combing through IRC, PRs, commit messages, blogs, etc. I think it’s similar to adding the information in the commit message rather than including a comment since a user must search for the commit message info.

    EDIT: That said, I’m open to suggestions, but I thought the context was pretty clear for me because I went through the code and the original PR.

  88. in src/logging.h:363 in 2ac8696b53
    370+// Log by prefixing the output with the passed category name and severity level. This can either
    371+// log conditionally if the category is allowed or unconditionally if level >= BCLog::Level::Info
    372+// is passed. If this function logs unconditionally, logging to disk is rate-limited. This is
    373+// important so that callers don't need to worry about accidentally introducing a disk-fill
    374+// vulnerability if level >= Info is used. Additionally, users specifying -debug are assumed to be
    375+// developers or power users who are aware that -debug may cause excessive disk usage due to logging.
    


    l0rinc commented at 7:49 am on June 24, 2025:
    That’s a reasonable assumption - if a bug could trigger debug logging, we’d likely have bigger problems I guess
  89. in src/test/logging_tests.cpp:71 in 2ac8696b53
    66@@ -60,6 +67,9 @@ struct LogSetup : public BasicTestingSetup {
    67 
    68         LogInstance().SetLogLevel(BCLog::Level::Debug);
    69         LogInstance().SetCategoryLogLevel({});
    70+
    71+        // Prevent tests from getting rate-limited.
    


    l0rinc commented at 7:50 am on June 24, 2025:
    Does this “prevent” rate limiting or just allows one more megabyte?

    stickies-v commented at 12:10 pm on June 24, 2025:
    The latter. “Ensure tests don’t use each other’s rate limiting budget” could be an alternative?
  90. in src/test/logging_tests.cpp:106 in 2ac8696b53
    107+        std::source_location::current(),
    108+        std::source_location::current(),
    109+        std::source_location::current(),
    110+        std::source_location::current(),
    111+        std::source_location::current(),
    112+    };
    


    l0rinc commented at 7:59 am on June 24, 2025:

    this seems a bit hacky to me - this is basically a parameterized test where we implicitly verify the inputs produce the desired outputs, line-by-line. It could make sense to store it in a way that indicates more clearly which outputs we’re expecting for which inputs.

    We do need separate ::current() calls to capture that the lines are assigned properly, we could add those to the parameterized test values as well.

    I also find it a bit awkward that we’re concatenating the result of a tfm::format with strings instead of having a final formatter.

    Lastly, do we really need the RemovePrefix here, given that we know the exact file structiure?

    Please consider something like this for clarity:

     0BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
     1{
     2    LogInstance().m_log_sourcelocations = true;
     3
     4    struct Case {
     5        std::string msg;
     6        BCLog::LogFlags cat;
     7        BCLog::Level level;
     8        std::string prefix;
     9        std::source_location loc;
    10    };
    11
    12    std::vector<Case> cases = {
    13        {"foo1: bar1", BCLog::NET,  BCLog::Level::Debug, "[net] ",      std::source_location::current()},
    14        {"foo2: bar2", BCLog::NET,  BCLog::Level::Info,  "[net:info] ", std::source_location::current()},
    15        {"foo3: bar3", BCLog::ALL,  BCLog::Level::Debug, "[debug] ",    std::source_location::current()},
    16        {"foo4: bar4", BCLog::ALL,  BCLog::Level::Info,  "",            std::source_location::current()},
    17        {"foo5: bar5", BCLog::NONE, BCLog::Level::Debug, "[debug] ",    std::source_location::current()},
    18        {"foo6: bar6", BCLog::NONE, BCLog::Level::Info,  "",            std::source_location::current()},
    19    };
    20
    21    std::vector<std::string> expected;
    22    for (auto& [msg, cat, level, prefix, loc] : cases) {
    23        expected.push_back(tfm::format("[%s:%s] [%s] %s%s", loc.file_name(), loc.line(), loc.function_name(), prefix, msg));
    24        LogInstance().LogPrintStr(msg, std::move(loc), cat, level, /*should_ratelimit=*/false);
    25    }
    26    std::ifstream file{tmp_log_path};
    27    std::string line;
    28    for (const auto& exp : expected) {
    29        BOOST_REQUIRE(std::getline(file, line));
    30        BOOST_CHECK_EQUAL(line, exp);
    31    }
    32    BOOST_CHECK(!std::getline(file, line));
    33}
    
  91. in src/test/logging_tests.cpp:300 in 2ac8696b53
    296@@ -276,4 +297,126 @@ BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
    297     }
    298 }
    299 
    300+BOOST_AUTO_TEST_CASE(logging_sourcelocation_counter)
    


    l0rinc commented at 8:26 am on June 24, 2025:
    👍 nice and clear test
  92. in src/logging.h:48 in 2ac8696b53
    43+};
    44+
    45+struct SourceLocationHasher {
    46+    size_t operator()(const std::source_location& s) const noexcept
    47+    {
    48+        // Use CSipHasher(0, 0) as a simple way to get uniform distribution.
    


    l0rinc commented at 8:35 am on June 24, 2025:

    I’m not a fan of dead comments, could we rather extract it to a named variable, something like CSipHasher uniform(0, 0) instead of explaining code with text?


    nit: Maybe my formatter is off, but do we really need to push the formatted lines so far out?


    stickies-v commented at 10:49 am on June 24, 2025:
    I don’t think this is a dead comment, the choice for using siphash over e.g. std::hash is not obvious (to me), and just naming the variable uniform would not have been clear to me. Would prefer keeping this as is.

    l0rinc commented at 10:51 am on June 24, 2025:
    Can we name the variable such that the choice is obvious instead of adding extra comments?

    l0rinc commented at 10:58 am on June 24, 2025:
    By “dead” I meant that it doesn’t bite back (like code does), it can state absolutely anything and the compiler won’t help us. Comments usually seem to me like we’ve given up on trying to express our design within the boundaries of the language. In a few cases here I think the code can be slightly improved to eliminate the need for extra comments.

    stickies-v commented at 12:03 pm on June 24, 2025:
    The choice of a hashing algorithm has many dimensions (distribution, performance, collision resistance, …). Capturing that rationale in a variable name seems an unrealistic expectation. I’m all for removing dead comments but this seems not the place to me.

    l0rinc commented at 12:06 pm on June 24, 2025:
    It’s possible that this isn’t the place, but it doesn’t currently explain performance or collision resistance either - but if those are importance, maybe we could explain them in the commit message instead.
  93. in src/logging.h:105 in 2ac8696b53
    103@@ -82,15 +104,74 @@ namespace BCLog {
    104     };
    105     constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
    


    l0rinc commented at 8:37 am on June 24, 2025:
    I find this confusing (either the name or the value), by default debug logs aren’t displayed…

    stickies-v commented at 12:08 pm on June 24, 2025:
    This variable is not used or changed in this PR.

    l0rinc commented at 12:14 pm on June 24, 2025:
    This argument may not be, but the test is validating the changed code, dead parameter names don’t increase my confidence in the correctness of the PR. It may have an obvious explanation, but it seemed related to me, given that we’re touching surrounding code

    stickies-v commented at 12:22 pm on June 24, 2025:
    What do you mean with “dead parameter names”? This variable defines the default log level, which indeed is debug level. If you run bitcoind -debug=net, you’ll start seeing net debug logs, you don’t have to set -loglevel=debug.

    l0rinc commented at 12:30 pm on June 24, 2025:
    I replied to the wrong thread here, thanks for the explanation, please resolve it.
  94. in src/logging.h:110 in 2ac8696b53
    103@@ -82,15 +104,74 @@ namespace BCLog {
    104     };
    105     constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
    106     constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging
    107+    constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes that can be logged within one window
    108+
    109+    //! Keeps track of an individual source location and how many available bytes are left for logging from it.
    110+    class SourceLocationCounter
    


    l0rinc commented at 8:43 am on June 24, 2025:
    naming nit again: we’re not counting the source locations, rather assigning the statistics we collect here to a std::source_location later - we’re mixing abstraction levels this way, we’re naming something based on how we’re planning on using it later (instead of what it is or what it does), such as LogLimitStats or something similar.
  95. in src/test/logging_tests.cpp:331 in 2ac8696b53
    326+    case 0:
    327+        LogInfo("%s\n", message);
    328+        break;
    329+    case 1:
    330+        LogInfo("%s\n", message);
    331+        break;
    


    l0rinc commented at 8:50 am on June 24, 2025:
    These two cases are basically the same and they depend on a magic int that I will have to tie to some other integers somewhere else to understand what it means. Could we make this a parameterized test as well, maybe with a std::function and more type safety instead of an int with only 4 allowed values
  96. in src/test/logging_tests.cpp:370 in 2ac8696b53
    365+    const char* log_path{utf8_path.c_str()};
    366+
    367+    // Use GetFileSize because fs::file_size may require a flush to be accurate.
    368+    std::streamsize log_file_size{static_cast<std::streamsize>(GetFileSize(log_path))};
    369+
    370+    // Logging 1 MiB should be allowed.
    


    l0rinc commented at 8:53 am on June 24, 2025:
    can we make this value parameterizable instead of referencing a value in a comment? It’s not trivial that the 1024 (or 512 + 512 in other places) has to coincide with the 1_MiB in another place.
  97. in src/validation.cpp:2980 in 2ac8696b53
    2984-        chainman.GuessVerificationProgress(tip),
    2985-        coins_tip.DynamicMemoryUsage() * (1.0 / (1 << 20)),
    2986-        coins_tip.GetCacheSize(),
    2987-        !warning_messages.empty() ? strprintf(" warning='%s'", warning_messages) : "");
    2988+
    2989+    // Disable rate limiting in LogPrintLevel_ so that this location is not rate limited during IBD.
    


    l0rinc commented at 8:55 am on June 24, 2025:
    the code already states /*should_ratelimit=*/false, there’s no point in repeating that a few more times in a comment

    stickies-v commented at 12:26 pm on June 24, 2025:
    The point of the docstring is to explain why we don’t ratelimit, which is because we don’t want IBD tip logs to be suppressed. Documenting that absolutely seems helpful to me.

    l0rinc commented at 12:28 pm on June 24, 2025:
    Yes, that part does seem helpful and we can’t express it with code, we should keep that part!
  98. in src/logging.h:121 in 40298a86d2 outdated
    116+        uint64_t m_dropped_bytes{0};
    117+
    118+    public:
    119+        //! Consume bytes from the window if enough bytes are available.
    120+        //!
    121+        //! Returns whether or not enough bytes were available.
    


    l0rinc commented at 8:59 am on June 24, 2025:
    0        //! Returns whether enough bytes were available.
    
  99. in src/logging.cpp:532 in 40298a86d2 outdated
    527+    const auto now{NodeClock::now()};
    528+    if ((now - m_last_reset) >= WINDOW_SIZE) {
    529+        m_last_reset = now;
    530+
    531+        // Iterate through m_suppressed_locations and log that we're resetting the window for each
    532+        // suppressed location.
    


    l0rinc commented at 9:03 am on June 24, 2025:
    The comment duplicates the code, this is already clear from the method name and from what follows.
  100. in src/logging.h:107 in 40298a86d2 outdated
    103@@ -82,6 +104,65 @@ namespace BCLog {
    104     };
    105     constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
    106     constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging
    107+    constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024}; // maximum number of bytes that can be logged within one window
    


    l0rinc commented at 9:10 am on June 24, 2025:
    do we need to mix the two system here, base 1000 with base 1024?

    stickies-v commented at 12:06 pm on June 24, 2025:
    Both are frequently used throughout the codebase. RATELIMIT_MAX_BYTES and DEFAULT_MAX_LOG_BUFFER are not related to eachother beyond both being used in logging. I don’t see any footgun potential between using one or the other, so this seems like an either-is-fine option that can be left to the author to decide, and very quickly becomes bikeshedding otherwise.
  101. in src/logging.cpp:369 in d41a39e43c outdated
    365@@ -364,7 +366,9 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l
    366 
    367 static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
    368 {
    369-    return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
    370+    return memusage::DynamicUsage(buflog.str) +
    


    l0rinc commented at 9:16 am on June 24, 2025:

    I think this memory usage change needs a commit message explanation in d41a39e43c219eb0b06b8df2c2c5d24baaf015c4 (it explains why logging_function counting was removed, but not why source_file was as far as I can tell)


    Did you validate in any way that this is indeed representative of the memory consumption? Or it’s just a guess anyway, so it’s not important?


    Crypt-iQ commented at 12:33 pm on June 26, 2025:
    I didn’t validate it, but I can. I think it is important that the new and old versions of MemUsage are roughly the same.
  102. in src/logging.cpp:418 in d41a39e43c outdated
    417@@ -414,13 +418,13 @@ void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags catego
    418     str.insert(0, LogTimestampStr(now, mocktime));
    


    l0rinc commented at 9:22 am on June 24, 2025:
    isn’t it expensive to insert so often in front of the string?
  103. in test/functional/feature_config_args.py:85 in d41a39e43c outdated
    81@@ -82,7 +82,7 @@ def test_negated_config(self):
    82 
    83         self.log.debug('Verifying that disabling of the config file means garbage inside of it does ' \
    84             'not prevent the node from starting, and message about existing config file is logged')
    85-        ignored_file_message = [f'[InitConfig] Data directory "{self.nodes[0].datadir_path}" contains a "bitcoin.conf" file which is explicitly ignored using -noconf.']
    86+        ignored_file_message = [f'Data directory "{self.nodes[0].datadir_path}" contains a "bitcoin.conf" file which is explicitly ignored using -noconf.']
    


    l0rinc commented at 9:26 am on June 24, 2025:
    Can you please explain in the commit message which change caused the removal of [InitConfig] here?
  104. in src/logging.cpp:1 in b44d31455a outdated


    l0rinc commented at 9:32 am on June 24, 2025:
    Commit message claims a source location can log up to 1MiB of data, but code states constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000}; // buffer up to 1MB of log data prior to StartLogging - I’m confused why we have this discrepancy

    stickies-v commented at 10:53 am on June 24, 2025:
    They could be the same value, but they’re unrelated things, and I don’t think it’s relevant in this PR. DEFAULT_MAX_LOG_BUFFER represents the max size of the buffer that holds log messages (across all locations) that are produced before we start writing them to file.

    l0rinc commented at 10:55 am on June 24, 2025:
    Misunderstood that part, thanks. The different base part still applies (though I know this isn’t uncommon in the code base)
  105. in src/logging.cpp:469 in b44d31455a outdated
    465@@ -457,6 +466,7 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& so
    466     }
    467 
    468     FormatLogStrInPlace(str_prefixed, category, level, source_loc, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime());
    469+    bool ratelimit = should_ratelimit && m_limiter.NeedsRateLimiting(source_loc, str_prefixed);
    


    l0rinc commented at 9:33 am on June 24, 2025:
    can we move this closer to its usage?

    stickies-v commented at 12:17 pm on June 24, 2025:
    That would mean the rate limiting warnings are no longer logged to console and callbacks (NeedsRateLimiting has side effects), so I think keeping this as-is is better.

    l0rinc commented at 12:22 pm on June 24, 2025:

    Ah, so there’s a side-effect here that wasn’t obvious to me, thanks for clarifying.

    Edit: this seems like a code smell, doesn’t this indicate that NeedsRateLimiting does too many things and should be split out to smaller, more focused methods? If we can’t give it a proper name that reflects what it does, that’s usually a good sign that it’s not as simple as it could be


    stickies-v commented at 9:58 pm on June 24, 2025:
    I agree NeedsRateLimiting has too many responsibilities. I think it’s okay as-is, but your comment nerdsniped me into revisiting this. I’m working on a branch that removes the side effects from NeedsRateLimiting and a couple of other improvements. I’m not sure yet if it’ll be too much of a detour for this PR, but at least it’ll be interesting to be able to compare. Should have it ready tomorrow.

    stickies-v commented at 4:23 pm on June 27, 2025:

    Sorry for the wait, branch is ready: https://github.com/stickies-v/bitcoin/commits/2025-06/schedule-ratelimit-reset/ . I added the “fixup” comments as commits that should be squashable into the current branch as-is (requiring rebase for the commits above, though). Hopefully the isolation of the changes makes this easier to review and potentially adopt into this PR.

    The main change is that I’ve carved out scheduling from LogRateLimiter (leaving that to CScheduler), which allows quite a bit of subsequent improvements. Specifically for this thread, I’ve refactored NeedsRateLimiting into Consume that does not have any side-effects (except update internal accounting, as expected by the Consume name).

    The other changes (see diff) I’ve implemented in this branch include:

    • change Logger::m_limiter to a pointer so it can more easily be (re)set, allowing for easier testing.
    • add unit tests specifically for the LogRateLimiter interface that I find quite a bit easier to understand than the existing rate_limit tests, but there may be merit in keeping both (I’ve updated the latter so they don’t break, but they should probably be deduplicated at least somewhat)
    • made LogRateLimiter thread-safe since it is now used in multiple threads
    • various cleanups, including removing the unnecessary m_suppressed_locations (now a m_suppression_active boolean), parameterizing the max_bytes and reset_window, …
    • removes the need for the test-only BCLog::Logger::ResetLimiter() function

    I think the PR is in a good enough shape as it is, and I don’t want to block progress. I like the new interface of my suggestion quite a bit better than the old one, and I think it is worth the time and effort to overhaul this (I spent a lot of time carving everything out in separate commits to make rebasing easy), but I understand this PR has had a lot of back-and-forth already. I’ll leave it up to the author if he wants to change the approach here, of if I’ll do it in a follow-up (which unfortunately would be a lot of churn). In either case, I’ll shortly do a full re-review.


    Crypt-iQ commented at 3:19 pm on June 30, 2025:
    Leaving a note that I am going to implement these changes and plan to push up either later today or tomorrow.

    l0rinc commented at 4:09 pm on June 30, 2025:
    Sweet, I’m planning on reviewing it this week!
  106. l0rinc approved
  107. l0rinc commented at 9:49 am on June 24, 2025: contributor

    Can you please update the PR descripton now that there’s no UNCONDITIONAL_ALWAYS category?

    I’m mostly ok with the change, I’m testing if it introduces any slowdown and would prefer making the tests a bit more typesafe and compact (and the failure seems related to the change) and some of the new classes could use a more descriptive naming in my opinion.

  108. dergoegge changes_requested
  109. dergoegge commented at 11:10 am on June 25, 2025: member

    Code review ACK 2ac8696b53e455dd27c8341828404a23b5cb68a9

    I think the commit order needs to change, so that 3c30ee9107fd0e916f9784b091a4d02f3a73ce46 comes before the tests that make use of the change?

    nit: I’d also suggest to squash b44d31455ad46ca3ed95690dfc0a913445b9c1c9 and 5fe08e01384c4a4c8525060d365fa38c312758f0 into one commit, so there is no intermediate state between the commits where the validation logs are rate limited.

  110. DrahtBot requested review from stickies-v on Jun 25, 2025
  111. DrahtBot requested review from l0rinc on Jun 25, 2025
  112. stickies-v commented at 4:33 pm on June 27, 2025: contributor

    This thread nerdsniped me into reimplementing this PR with a different approach, leaving the scheduled resetting to CScheduler. This feels like a much more natural fit to me, and allows a couple of other improvements. See branch here, or diff here.

    Either way, I’ll do a full re-review soon. I think the PR achieves its (important) stated goals, and while I think my suggested improvement is worthwhile, it isn’t necessary or blocking. Making progress is more important than getting it perfectly right here.

  113. DrahtBot requested review from stickies-v on Jun 27, 2025
  114. in src/logging.cpp:551 in 2ac8696b53
    546+            uint64_t dropped_bytes = m_source_locations[source_loc].GetDroppedBytes();
    547+
    548+            str.insert(0, strprintf("Restarting logging from %s:%d (%s): "
    549+                                    "(%d MiB) were dropped during the last hour.\n",
    550+                                    source_loc.file_name(), source_loc.line(), source_loc.function_name(),
    551+                                    dropped_bytes / (1024 * 1024)));
    


    stickies-v commented at 1:48 pm on June 30, 2025:

    nit:

    log strings currently look like:

    Restarting logging from ../../src/rpc/request.cpp:140 (GenerateAuthCookieResult GenerateAuthCookie(const std::optionalfs::perms &, std::string &, std::string &)): (0 MiB) were dropped during the last hour.

    Would suggest printing this as bytes and removing the parentheses.

    0                                    "%d bytes were dropped during the last hour.\n",
    1                                    source_loc.file_name(), source_loc.line(), source_loc.function_name(),
    2                                    dropped_bytes));
    
  115. in src/logging.h:173 in 2ac8696b53
    170         struct BufferedLog {
    171             SystemClock::time_point now;
    172             std::chrono::seconds mocktime;
    173-            std::string str, logging_function, source_file, threadname;
    174-            int source_line;
    175+            std::string str, threadname;
    


    stickies-v commented at 2:02 pm on June 30, 2025:

    nit

    0            std::string str threadname;
    
  116. in doc/release-notes-32604.md:6 in 2ac8696b53
    0@@ -0,0 +1,6 @@
    1+Logging
    2+-------
    3+Unconditional logging to disk via LogPrintf, LogInfo, LogWarning, LogError, and
    4+LogPrintLevel is now rate limited by giving each source location a logging quota of
    5+1MiB per hour. This affects -logsourcelocation as the entire function signature is
    6+logged rather than only the name.
    


    stickies-v commented at 2:27 pm on June 30, 2025:

    nit: the -logsourcelocation behaviour change is unrelated to the rate limiting, so I think this phrasing is a bit confusing. Would put it in a separate paragraph:

    0Unconditional logging to disk via LogPrintf, LogInfo, LogWarning, LogError, and
    1LogPrintLevel is now rate limited by giving each source location a logging quota of
    21MiB per hour. (#32604)
    3
    4When `-logsourcelocation` is enabled, the log output now contains the entire function signature
    5instead of just the function name. (#32604)
    
  117. stickies-v approved
  118. stickies-v commented at 2:36 pm on June 30, 2025: contributor

    ACK 2ac8696b53e455dd27c8341828404a23b5cb68a9

    I still would prefer the approach I suggested here (and am happy to re-review), but I think the PR is fine as is now too.


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-07-01 18:13 UTC

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