fees: fix noisy flushing log #32748

pull ismaelsadeeq wants to merge 1 commits into bitcoin:master from ismaelsadeeq:06-2025-prevent-redundant-estimate-flushes changing 2 files +5 −4
  1. ismaelsadeeq commented at 5:53 am on June 14, 2025: member

    This is a simple PR that updates the flushing log to use debug-level logging under the estimatefee category. It also ensures the log consistently includes only the full file path. The motivation behind this is that the “Flushed fee estimates to fee_estimates.dat.” logs can become noisy; it’s done after one hour, so hiding it in the debug estimatefee category seems reasonable.


    I left the logs when the file is not found as info because that should only occur when you start a fresh node, change datadir, or explicitly delete the file

  2. DrahtBot commented at 5:53 am on June 14, 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/32748.

    Reviews

    See the guideline for information on the review process.

    Type Reviewers
    ACK furszy, l0rinc, sipa, achow101
    Concept ACK Eunovo

    If your review is incorrectly listed, please copy-paste <!–meta-tag:bot-skip–> into the comment that the bot should ignore.

    Conflicts

    Reviewers, this pull request conflicts with the following ones:

    • #29641 (scripted-diff: Use LogInfo over LogPrintf [WIP, NOMERGE, DRAFT] by maflcko)

    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. ismaelsadeeq force-pushed on Jun 14, 2025
  4. DrahtBot added the label CI failed on Jun 14, 2025
  5. DrahtBot commented at 6:05 am on June 14, 2025: contributor

    🚧 At least one of the CI tasks failed. Task fuzzer,address,undefined,integer, no depends: https://github.com/bitcoin/bitcoin/runs/44091090061 LLM reason (✨ experimental): The CI failure is caused by a thread-safety analysis error in policy_estimator.cpp due to unsafe mutex usage during a function call.

    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.

  6. DrahtBot removed the label CI failed on Jun 14, 2025
  7. in src/policy/fees.cpp:563 in 48a3e8f577 outdated
    559@@ -560,18 +560,18 @@ CBlockPolicyEstimator::CBlockPolicyEstimator(const fs::path& estimation_filepath
    560     AutoFile est_file{fsbridge::fopen(m_estimation_filepath, "rb")};
    561 
    562     if (est_file.IsNull()) {
    563-        LogPrintf("%s is not found. Continue anyway.\n", fs::PathToString(m_estimation_filepath));
    564+        LogPrintf("%s is not found. Continue anyway.\n", fs::PathToString(m_estimation_filepath.filename()));
    


    Eunovo commented at 6:47 am on June 19, 2025:
    LogPrintf is deprecated, See https://github.com/bitcoin/bitcoin/blob/master/src/logging.h#L265-L266 Consisder using LogInfo instead

    ismaelsadeeq commented at 1:34 pm on June 19, 2025:
    Done
  8. in src/policy/fees.cpp:569 in 48a3e8f577 outdated
    566     }
    567 
    568     std::chrono::hours file_age = GetFeeEstimatorFileAge();
    569     if (file_age > MAX_FILE_AGE && !read_stale_estimates) {
    570-        LogPrintf("Fee estimation file %s too old (age=%lld > %lld hours) and will not be used to avoid serving stale estimates.\n", fs::PathToString(m_estimation_filepath), Ticks<std::chrono::hours>(file_age), Ticks<std::chrono::hours>(MAX_FILE_AGE));
    571+        LogPrintf("Fee estimation file %s too old (age=%lld > %lld hours) and will not be used to avoid serving stale estimates.\n", fs::PathToString(m_estimation_filepath.filename()), Ticks<std::chrono::hours>(file_age), Ticks<std::chrono::hours>(MAX_FILE_AGE));
    


    Eunovo commented at 7:11 am on June 19, 2025:
    • Also don’t log the full file path, just the filename.

    What’s the reason for this? This reduces debugging information and bitcoin-core generally uses file path logging over filename logging.


    ismaelsadeeq commented at 1:34 pm on June 19, 2025:
    Thats right, this is fixed now.
  9. Eunovo commented at 7:36 am on June 19, 2025: contributor
  10. ismaelsadeeq force-pushed on Jun 19, 2025
  11. ismaelsadeeq commented at 1:36 pm on June 19, 2025: member
    Addressed comments by @Eunovo thanks for review 21f0deaf1..458fdac
  12. ismaelsadeeq force-pushed on Jun 19, 2025
  13. DrahtBot added the label CI failed on Jun 19, 2025
  14. DrahtBot removed the label CI failed on Jun 19, 2025
  15. DrahtBot added the label Needs rebase on Jul 3, 2025
  16. in src/policy/fees.cpp:968 in 26c78d611d outdated
    959@@ -960,6 +960,13 @@ void CBlockPolicyEstimator::Flush() {
    960 
    961 void CBlockPolicyEstimator::FlushFeeEstimates()
    962 {
    963+    {
    964+        LOCK(m_cs_fee_estimator);
    965+        // We should only flush the fee estimates if usable estimates are available.
    966+        // This prevents redundant flushes e.g during IBD.
    967+        if (!MaxUsableEstimate()) return;
    968+    }
    


    furszy commented at 11:54 pm on July 3, 2025:

    nit: could write this in a single line instead.

    0if (WITH_LOCK(m_cs_fee_estimator, return !MaxUsableEstimate())) return;
    

    Also, it would be nice to explain why MaxUsableEstimate returning 0 means “nothing to do”. It is not immediately clear to me without checking the MaxUsableEstimate internals.


    ismaelsadeeq commented at 3:07 pm on July 5, 2025:

    Taken, also added an explanation.

    I also note a behavior change introduced by this. It is possible that we may track some unconfirmed transactions and, in rare cases, see some unconfirmed transactions get evicted. However, since we have no confirmations yet, if we shut down in this state, we will lose that data and have to start from scratch. To mitigate this, we need a way to detect when we are in such a state.

    I see two possible approaches:

    1. Brute-force check : Go through all the stats to ensure we have no useful data.
    2. Smart tracking : Add some of flag or tracker to each stat that indicates whether there is any useful data available. This would require extra processing when adding transactions to the mempool and, in rare cases, when transactions are evicted from the mempool.

    Also related to this: checking whether MaxUsableEstimate is non-zero is not sufficient to decide whether we should avoid updating the unconfirmed circular buffer or decaying all exponential averages.

    Additionally, simply tracking whether we have ever seen an unconfirmed transaction or a failure is not enough. There is an edge case where you may have seen that event,but if the relevant data has since decayed, you could end up updating with effectively empty stats. The indicator would need to account for data decay to provide an accurate signal.

    Given this, I am starting to doubt whether the performance gain is worth the added complexity cc @l0rinc .


    ismaelsadeeq commented at 5:32 pm on February 2, 2026:
    This change is now gone.
  17. ismaelsadeeq force-pushed on Jul 5, 2025
  18. DrahtBot removed the label Needs rebase on Jul 5, 2025
  19. DrahtBot added the label Needs rebase on Jul 25, 2025
  20. ismaelsadeeq force-pushed on Jul 29, 2025
  21. DrahtBot removed the label Needs rebase on Jul 29, 2025
  22. ismaelsadeeq force-pushed on Aug 12, 2025
  23. DrahtBot added the label Needs rebase on Oct 28, 2025
  24. ismaelsadeeq force-pushed on Oct 29, 2025
  25. ismaelsadeeq force-pushed on Oct 29, 2025
  26. DrahtBot removed the label Needs rebase on Oct 29, 2025
  27. DrahtBot added the label TX fees and policy on Oct 29, 2025
  28. ismaelsadeeq force-pushed on Nov 7, 2025
  29. DrahtBot added the label Needs rebase on Nov 12, 2025
  30. sedited commented at 11:52 am on February 2, 2026: contributor
    Can you rebase this?
  31. ismaelsadeeq force-pushed on Feb 2, 2026
  32. ismaelsadeeq renamed this:
    fees: prevent redundant estimates flushes
    fees: fix noisy flushing log
    on Feb 2, 2026
  33. DrahtBot renamed this:
    fees: fix noisy flushing log
    fees: fix noisy flushing log
    on Feb 2, 2026
  34. ismaelsadeeq commented at 5:42 pm on February 2, 2026: member

    Thanks for the ping @sedited

    I rebased a345c7760acac..30a726eb2b2

    I also reduced the scope of the PR from preventing redundant flushes to just fixing the noisy logging.

    The reason is that https://github.com/bitcoin/bitcoin/pull/32748/commits/f84ffeed8d981bae8c24393fb2c39f85418b56e0 is not enough to ensure that there are no changes that warrant a flush. There is an edge case where we refuse to flush while there is valid data that should be flushed. See #32748 (review). A more robust solution is to have a way to ensure the data in-memory is not the same as the data in the previous flush, that is, an amendment happened. This can be done using a hash or some sort of indicator.


    The redundant flushes occur in IBD and in low-network activity scenarios; it occurs hourly, so I am not really sure whether the complexity is worth the gain and whether fixing this is worth pursuing at this point. So I will push that up for grabs, or might come back to it later if there is appetite to fix it.

  35. DrahtBot removed the label Needs rebase on Feb 2, 2026
  36. in src/policy/fees/block_policy_estimator.cpp:564 in 30a726eb2b
    560@@ -561,7 +561,7 @@ CBlockPolicyEstimator::CBlockPolicyEstimator(const fs::path& estimation_filepath
    561     AutoFile est_file{fsbridge::fopen(m_estimation_filepath, "rb")};
    562 
    563     if (est_file.IsNull()) {
    564-        LogInfo("%s is not found. Continue anyway.", fs::PathToString(m_estimation_filepath));
    565+        LogInfo("%s is not found. Continue anyway.\n", fs::PathToString(m_estimation_filepath));
    


    l0rinc commented at 10:17 pm on February 2, 2026:
    No need for the final newline

    ismaelsadeeq commented at 1:55 pm on February 3, 2026:
    Yeah no need indeed fixed.
  37. in src/policy/fees/block_policy_estimator.cpp:975 in 30a726eb2b
    971@@ -972,7 +972,7 @@ void CBlockPolicyEstimator::FlushFeeEstimates()
    972         LogWarning("Failed to close fee estimates file %s: %s. Continuing anyway.", fs::PathToString(m_estimation_filepath), SysErrorString(errno));
    973         return;
    974     }
    975-    LogInfo("Flushed fee estimates to %s.", fs::PathToString(m_estimation_filepath.filename()));
    976+    LogDebug(BCLog::ESTIMATEFEE, "Flushed fee estimates to %s.\n", fs::PathToString(m_estimation_filepath));
    


    l0rinc commented at 10:17 pm on February 2, 2026:
    same

    ismaelsadeeq commented at 1:55 pm on February 3, 2026:
    fixed.
  38. in test/functional/feature_fee_estimation.py:335 in 30a726eb2b
    331@@ -332,7 +332,8 @@ def test_estimate_dat_is_flushed_periodically(self):
    332 
    333         # Verify if the string "Flushed fee estimates to fee_estimates.dat." is present in the debug log file.
    334         # If present, it indicates that fee estimates have been successfully flushed to disk.
    335-        with self.nodes[0].assert_debug_log(expected_msgs=["Flushed fee estimates to fee_estimates.dat."], timeout=1):
    336+        expected_message = f"Flushed fee estimates to {fee_dat}."
    


    l0rinc commented at 10:18 pm on February 2, 2026:

    we might as well store all expected messages here:

    0        expected_messages = [f"Flushed fee estimates to {fee_dat}."]
    

    which we could use as:

    0        with self.nodes[0].assert_debug_log(expected_messages, timeout=1):
    

    ismaelsadeeq commented at 1:55 pm on February 3, 2026:
    Thanks, taken.

    l0rinc commented at 2:42 pm on February 3, 2026:

    https://github.com/bitcoin/bitcoin/blob/5875a9c502632eb5c74df07e41af38582da6e884/test/functional/test_framework/test_node.py#L553 can simply accept the messages as a first parameter, no need to duplicate the name:

     0diff --git a/test/functional/feature_fee_estimation.py b/test/functional/feature_fee_estimation.py
     1--- a/test/functional/feature_fee_estimation.py	(revision 02b5f6078d65c3a2f9ba8b30474d8201516c5c4b)
     2+++ b/test/functional/feature_fee_estimation.py	(date 1770129590035)
     3@@ -333,7 +333,7 @@
     4         # Verify if the string "Flushed fee estimates to fee_estimates.dat." is present in the debug log file.
     5         # If present, it indicates that fee estimates have been successfully flushed to disk.
     6         expected_messages = [f"Flushed fee estimates to {fee_dat}."]
     7-        with self.nodes[0].assert_debug_log(expected_msgs=expected_messages, timeout=1):
     8+        with self.nodes[0].assert_debug_log(expected_messages, timeout=1):
     9             # Mock the scheduler for an hour to flush fee estimates to fee_estimates.dat
    10             self.nodes[0].mockscheduler(SECONDS_PER_HOUR)
    11 
    12@@ -343,7 +343,7 @@
    13         # Verify that the estimates remain the same if there are no blocks in the flush interval
    14         block_hash_before = self.nodes[0].getbestblockhash()
    15         fee_dat_initial_content = open(fee_dat, "rb").read()
    16-        with self.nodes[0].assert_debug_log(expected_msgs=expected_messages, timeout=1):
    17+        with self.nodes[0].assert_debug_log(expected_messages, timeout=1):
    18             # Mock the scheduler for an hour to flush fee estimates to fee_estimates.dat
    19             self.nodes[0].mockscheduler(SECONDS_PER_HOUR)
    20 
    21@@ -359,7 +359,7 @@
    22         assert_equal(fee_dat_current_content, fee_dat_initial_content)
    23 
    24         # Verify that the estimates are not the same if new blocks were produced in the flush interval
    25-        with self.nodes[0].assert_debug_log(expected_msgs=expected_messages, timeout=1):
    26+        with self.nodes[0].assert_debug_log(expected_messages, timeout=1):
    27             # Mock the scheduler for an hour to flush fee estimates to fee_estimates.dat
    28             self.generate(self.nodes[0], 5, sync_fun=self.no_op)
    29             self.nodes[0].mockscheduler(SECONDS_PER_HOUR)
    
  39. l0rinc changes_requested
  40. fees: make flushes log debug only
    - Also log the full file path of fee_estimates.dat consistently.
    02b5f6078d
  41. ismaelsadeeq force-pushed on Feb 3, 2026
  42. furszy commented at 2:38 pm on February 3, 2026: member
    utACK 02b5f6078d65c3a2f9ba8b30474d8201516c5c4b
  43. DrahtBot requested review from Eunovo on Feb 3, 2026
  44. l0rinc approved
  45. l0rinc commented at 2:43 pm on February 3, 2026: contributor

    Lightly tested ACK 02b5f6078d65c3a2f9ba8b30474d8201516c5c4b

    Left a nit, will gladly reack if taken.

  46. sipa commented at 2:43 pm on February 3, 2026: member
    utACK 02b5f6078d65c3a2f9ba8b30474d8201516c5c4b
  47. achow101 commented at 8:04 pm on February 3, 2026: member
    ACK 02b5f6078d65c3a2f9ba8b30474d8201516c5c4b
  48. achow101 merged this on Feb 3, 2026
  49. achow101 closed this on Feb 3, 2026

  50. ismaelsadeeq deleted the branch on Feb 4, 2026

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: 2026-02-04 21:13 UTC

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