Repository: bitcoin/bitcoin (language: cpp)

Issue:
Avoid serving stale fees
After conversation on irc it appears there's some cases where Bitcoin core will serve feerate information even though it loaded a fairly old fee estimates file and is still syncing the chain. This is pretty dangerous for lightning nodes, at least on legacy channels or pre-package-relay.

The immediate improvement would be to store fee estimates to disk once an hour or so to reduce the chance of having an old file. From there this case could probably be detected and refuse to serve estimates until we sync.


Discussion / hints:
looks like one of my nodes had a similar issue with a clean shutdown and restart

 https://twitter.com/CoreFeeHelper/status/1655286815291588611 after restart, then an hour or so later: https://twitter.com/CoreFeeHelper/status/1655301916593668097

back up to expected min fee

Here's my guess on how this happens and explaining the behavior I'm seeing after reproducing it. It seems to be 100% reproducible on nodes, and repeatable after a few minutes of warmup when things fix themselves.

1) On node restart, there is no persistence of mempoolminfee
2) While mempool is importing, node receives transactions well below the old mempoolminfee, enters into mempool
3) mempool finishes loading(with some failures), resulting in no trimming on startup
4) `mempoolminfee` seems to be feeding into `estimatesmartfee` as a floor, so if node restarts, it starts naively giving out min incremental feerate
5) In `estimatesmartfee`, `fee_estimator.estimateSmartFee` is apparently returning a non-0 `CFeeRate` value, but which is lower than 1 sat/vbyte, which then allows mempoolminfee to take over the value.
6) Over time, if the mempool is actually busy, enough transactions enter the mempool to start trimming, stepping from min incremental relay all the way to the "actual" value once enough has been trimmed.

So you have this gap on restart where longer term estimates are way out of whack, and we're being sent INVs we will promptly evict anyways. It self-resolves in a few minutes it seems in the happy path.

I think https://github.com/bitcoin/bitcoin/pull/22722 has ended up hiding the particular `estimatefee` issue, since prior my guess is it would have simply not returned anything if was below min relay.

Two mitigations:
1) persist mempoolminfee across restarts to at least tell user a plausible value to stay in the mempool for a bit
2) investigate why `estimateSmartFee` is returning bogus values; require more certainty to return a result?
...
or get package relay deployed :P 


edit:

https://github.com/bitcoin/bitcoin/issues/19699#issuecomment-683787296 3-year ago me asking the same question as (2). oops.

edit2:

Looks like the estimator is giving something "real" from a bucket: 1000.0000000000035, so basically during these situations we're relying on mempoolminfee to save us, and it's failing after restart

Fix patch:
diff --git a/src/init.cpp b/src/init.cpp
index 38e1dbb4a2cc5..06c8d38036c2b 100644
--- a/src/init.cpp
+++ b/src/init.cpp
@@ -83,6 +83,7 @@
 #include <util/syserror.h>
 #include <util/thread.h>
 #include <util/threadnames.h>
+#include <util/time.h>
 #include <util/translation.h>
 #include <validation.h>
 #include <validationinterface.h>
@@ -586,6 +587,7 @@ void SetupServerArgs(ArgsManager& argsman)
     argsman.AddArg("-acceptnonstdtxn", strprintf("Relay and mine \"non-standard\" transactions (%sdefault: %u)", "testnet/regtest only; ", !testnetChainParams->RequireStandard()), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::NODE_RELAY);
     argsman.AddArg("-incrementalrelayfee=<amt>", strprintf("Fee rate (in %s/kvB) used to define cost of relay, used for mempool limiting and replacement policy. (default: %s)", CURRENCY_UNIT, FormatMoney(DEFAULT_INCREMENTAL_RELAY_FEE)), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::NODE_RELAY);
     argsman.AddArg("-dustrelayfee=<amt>", strprintf("Fee rate (in %s/kvB) used to define dust, the value of an output such that it will cost more than its value in fees at this fee rate to spend it. (default: %s)", CURRENCY_UNIT, FormatMoney(DUST_RELAY_TX_FEE)), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::NODE_RELAY);
+    argsman.AddArg("-acceptstalefeeestimates", strprintf("Read fee estimates even if they are stale (%sdefault: %u) fee estimates are considered stale if they are %s hours old", "regtest only; ", DEFAULT_ACCEPT_STALE_FEE_ESTIMATES, Ticks<std::chrono::hours>(MAX_FILE_AGE)), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
     argsman.AddArg("-bytespersigop", strprintf("Equivalent bytes per sigop in transactions for relay and mining (default: %u)", DEFAULT_BYTES_PER_SIGOP), ArgsManager::ALLOW_ANY, OptionsCategory::NODE_RELAY);
     argsman.AddArg("-datacarrier", strprintf("Relay and mine data carrier transactions (default: %u)", DEFAULT_ACCEPT_DATACARRIER), ArgsManager::ALLOW_ANY, OptionsCategory::NODE_RELAY);
     argsman.AddArg("-datacarriersize", strprintf("Maximum size of data in data carrier transactions we relay and mine (default: %u)", MAX_OP_RETURN_RELAY), ArgsManager::ALLOW_ANY, OptionsCategory::NODE_RELAY);
@@ -1253,7 +1255,17 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
     assert(!node.fee_estimator);
     // Don't initialize fee estimation with old data if we don't relay transactions,
     // as they would never get updated.
-    if (!ignores_incoming_txs) node.fee_estimator = std::make_unique<CBlockPolicyEstimator>(FeeestPath(args));
+    if (!ignores_incoming_txs) {
+        bool read_stale_estimates = args.GetBoolArg("-acceptstalefeeestimates", DEFAULT_ACCEPT_STALE_FEE_ESTIMATES);
+        if (read_stale_estimates && (chainparams.GetChainType() != ChainType::REGTEST)) {
+            return InitError(strprintf(_("acceptstalefeeestimates is not supported on %s chain."), chainparams.GetChainTypeString()));
+        }
+        node.fee_estimator = std::make_unique<CBlockPolicyEstimator>(FeeestPath(args), read_stale_estimates);
+
+        // Flush estimates to disk periodically
+        CBlockPolicyEstimator* fee_estimator = node.fee_estimator.get();
+        node.scheduler->scheduleEvery([fee_estimator] { fee_estimator->FlushFeeEstimates(); }, FEE_FLUSH_INTERVAL);
+    }
 
     // Check port numbers
     for (const std::string port_option : {
diff --git a/src/policy/fees.cpp b/src/policy/fees.cpp
index ae226f7011470..c8f2df781bc6c 100644
--- a/src/policy/fees.cpp
+++ b/src/policy/fees.cpp
@@ -24,6 +24,7 @@
 
 #include <algorithm>
 #include <cassert>
+#include <chrono>
 #include <cmath>
 #include <cstddef>
 #include <cstdint>
@@ -527,7 +528,7 @@ bool CBlockPolicyEstimator::_removeTx(const uint256& hash, bool inBlock)
     }
 }
 
-CBlockPolicyEstimator::CBlockPolicyEstimator(const fs::path& estimation_filepath)
+CBlockPolicyEstimator::CBlockPolicyEstimator(const fs::path& estimation_filepath, const bool read_stale_estimates)
     : m_estimation_filepath{estimation_filepath}
 {
     static_assert(MIN_BUCKET_FEERATE > 0, "Min feerate must be nonzero");
@@ -545,9 +546,22 @@ CBlockPolicyEstimator::CBlockPolicyEstimator(const fs::path& estimation_filepath
     shortStats = std::unique_ptr<TxConfirmStats>(new TxConfirmStats(buckets, bucketMap, SHORT_BLOCK_PERIODS, SHORT_DECAY, SHORT_SCALE));
     longStats = std::unique_ptr<TxConfirmStats>(new TxConfirmStats(buckets, bucketMap, LONG_BLOCK_PERIODS, LONG_DECAY, LONG_SCALE));
 
-    // If the fee estimation file is present, read recorded estimations
     AutoFile est_file{fsbridge::fopen(m_estimation_filepath, "rb")};
-    if (est_file.IsNull() || !Read(est_file)) {
+
+    // Whenever the fee estimation file is not present return early
+    if (est_file.IsNull()) {
+        LogPrintf("%s is not found. Continue anyway.\n", fs::PathToString(m_estimation_filepath));
+        return;
+    }
+
+    std::chrono::hours file_age = GetFeeEstimatorFileAge();
+    // fee estimate file must not be too old to avoid wrong fee estimates.
+    if (file_age > MAX_FILE_AGE && !read_stale_estimates) {
+        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));
+        return;
+    }
+
+    if (!Read(est_file)) {
         LogPrintf("Failed to read fee estimates from %s. Continue anyway.\n", fs::PathToString(m_estimation_filepath));
     }
 }
@@ -903,10 +917,16 @@ CFeeRate CBlockPolicyEstimator::estimateSmartFee(int confTarget, FeeCalculation
 
 void CBlockPolicyEstimator::Flush() {
     FlushUnconfirmed();
+    FlushFeeEstimates();
+}
 
+void CBlockPolicyEstimator::FlushFeeEstimates()
+{
     AutoFile est_file{fsbridge::fopen(m_estimation_filepath, "wb")};
     if (est_file.IsNull() || !Write(est_file)) {
         LogPrintf("Failed to write fee estimates to %s. Continue anyway.\n", fs::PathToString(m_estimation_filepath));
+    } else {
+        LogPrintf("Flushed fee estimates to %s.\n", fs::PathToString(m_estimation_filepath.filename()));
     }
 }
 
@@ -1011,6 +1031,13 @@ void CBlockPolicyEstimator::FlushUnconfirmed()
     LogPrint(BCLog::ESTIMATEFEE, "Recorded %u unconfirmed txs from mempool in %gs\n", num_entries, Ticks<SecondsDouble>(endclear - startclear));
 }
 
+std::chrono::hours CBlockPolicyEstimator::GetFeeEstimatorFileAge()
+{
+    auto file_time = std::filesystem::last_write_time(m_estimation_filepath);
+    auto now = std::filesystem::file_time_type::clock::now();
+    return std::chrono::duration_cast<std::chrono::hours>(now - file_time);
+}
+
 static std::set<double> MakeFeeSet(const CFeeRate& min_incremental_fee,
                                    double max_filter_fee_rate,
                                    double fee_filter_spacing)
diff --git a/src/policy/fees.h b/src/policy/fees.h
index 775a72a764655..52761f03ca7eb 100644
--- a/src/policy/fees.h
+++ b/src/policy/fees.h
@@ -14,12 +14,25 @@
 #include <util/fs.h>
 
 #include <array>
+#include <chrono>
 #include <map>
 #include <memory>
 #include <set>
 #include <string>
 #include <vector>
 
+
+// How often to flush fee estimates to fee_estimates.dat.
+static constexpr std::chrono::hours FEE_FLUSH_INTERVAL{1};
+
+/** fee_estimates.dat that are more than 60 hours (2.5 days) will not be read,
+ * as the estimates in the file are stale.
+ */
+static constexpr std::chrono::hours MAX_FILE_AGE{60};
+
+// Whether we allow importing a fee_estimates file older than MAX_FILE_AGE.
+static constexpr bool DEFAULT_ACCEPT_STALE_FEE_ESTIMATES{false};
+
 class AutoFile;
 class CTxMemPoolEntry;
 class TxConfirmStats;
@@ -183,7 +196,7 @@ class CBlockPolicyEstimator
     const fs::path m_estimation_filepath;
 public:
     /** Create new BlockPolicyEstimator and initialize stats tracking classes with default values */
-    CBlockPolicyEstimator(const fs::path& estimation_filepath);
+    CBlockPolicyEstimator(const fs::path& estimation_filepath, const bool read_stale_estimates);
     ~CBlockPolicyEstimator();
 
     /** Process all the transactions that have been included in a block */
@@ -239,6 +252,13 @@ class CBlockPolicyEstimator
     void Flush()
         EXCLUSIVE_LOCKS_REQUIRED(!m_cs_fee_estimator);
 
+    /** Record current fee estimations. */
+    void FlushFeeEstimates()
+        EXCLUSIVE_LOCKS_REQUIRED(!m_cs_fee_estimator);
+
+    /** Calculates the age of the file, since last modified */
+    std::chrono::hours GetFeeEstimatorFileAge();
+
 private:
     mutable Mutex m_cs_fee_estimator;
 


Test patch:
diff --git a/src/test/fuzz/policy_estimator.cpp b/src/test/fuzz/policy_estimator.cpp
index 116fbd9015c44..aa3cfe81df2dc 100644
--- a/src/test/fuzz/policy_estimator.cpp
+++ b/src/test/fuzz/policy_estimator.cpp
@@ -31,7 +31,7 @@ void initialize_policy_estimator()
 FUZZ_TARGET_INIT(policy_estimator, initialize_policy_estimator)
 {
     FuzzedDataProvider fuzzed_data_provider(buffer.data(), buffer.size());
-    CBlockPolicyEstimator block_policy_estimator{FeeestPath(*g_setup->m_node.args)};
+    CBlockPolicyEstimator block_policy_estimator{FeeestPath(*g_setup->m_node.args), DEFAULT_ACCEPT_STALE_FEE_ESTIMATES};
     LIMITED_WHILE(fuzzed_data_provider.ConsumeBool(), 10000) {
         CallOneOf(
             fuzzed_data_provider,
diff --git a/src/test/fuzz/policy_estimator_io.cpp b/src/test/fuzz/policy_estimator_io.cpp
index 7c3289cd2609a..3df40197d8be8 100644
--- a/src/test/fuzz/policy_estimator_io.cpp
+++ b/src/test/fuzz/policy_estimator_io.cpp
@@ -28,7 +28,7 @@ FUZZ_TARGET_INIT(policy_estimator_io, initialize_policy_estimator_io)
     FuzzedAutoFileProvider fuzzed_auto_file_provider = ConsumeAutoFile(fuzzed_data_provider);
     AutoFile fuzzed_auto_file{fuzzed_auto_file_provider.open()};
     // Re-using block_policy_estimator across runs to avoid costly creation of CBlockPolicyEstimator object.
-    static CBlockPolicyEstimator block_policy_estimator{FeeestPath(*g_setup->m_node.args)};
+    static CBlockPolicyEstimator block_policy_estimator{FeeestPath(*g_setup->m_node.args), DEFAULT_ACCEPT_STALE_FEE_ESTIMATES};
     if (block_policy_estimator.Read(fuzzed_auto_file)) {
         block_policy_estimator.Write(fuzzed_auto_file);
     }
diff --git a/src/test/util/setup_common.cpp b/src/test/util/setup_common.cpp
index 483404779e453..93a60db8322ab 100644
--- a/src/test/util/setup_common.cpp
+++ b/src/test/util/setup_common.cpp
@@ -179,7 +179,7 @@ ChainTestingSetup::ChainTestingSetup(const ChainType chainType, const std::vecto
     m_node.scheduler->m_service_thread = std::thread(util::TraceThread, "scheduler", [&] { m_node.scheduler->serviceQueue(); });
     GetMainSignals().RegisterBackgroundSignalScheduler(*m_node.scheduler);
 
-    m_node.fee_estimator = std::make_unique<CBlockPolicyEstimator>(FeeestPath(*m_node.args));
+    m_node.fee_estimator = std::make_unique<CBlockPolicyEstimator>(FeeestPath(*m_node.args), DEFAULT_ACCEPT_STALE_FEE_ESTIMATES);
     m_node.mempool = std::make_unique<CTxMemPool>(MemPoolOptionsForTest(m_node));
 
     m_cache_sizes = CalculateCacheSizes(m_args);
diff --git a/test/functional/feature_fee_estimation.py b/test/functional/feature_fee_estimation.py
index 05ee556ecefbe..03970415ac89d 100755
--- a/test/functional/feature_fee_estimation.py
+++ b/test/functional/feature_fee_estimation.py
@@ -7,6 +7,7 @@
 from decimal import Decimal
 import os
 import random
+import time
 
 from test_framework.messages import (
     COIN,
@@ -21,6 +22,8 @@
 )
 from test_framework.wallet import MiniWallet
 
+MAX_FILE_AGE = 60
+SECONDS_PER_HOUR = 60 * 60
 
 def small_txpuzzle_randfee(
     wallet, from_node, conflist, unconflist, amount, min_fee, fee_increment, batch_reqs
@@ -290,6 +293,95 @@ def sanity_check_rbf_estimates(self, utxos):
         est_feerate = node.estimatesmartfee(2)["feerate"]
         assert_equal(est_feerate, high_feerate_kvb)
 
+    def test_old_fee_estimate_file(self):
+        # Get the initial fee rate while node is running
+        fee_rate = self.nodes[0].estimatesmartfee(1)["feerate"]
+
+        # Restart node to ensure fee_estimate.dat file is read
+        self.restart_node(0)
+        assert_equal(self.nodes[0].estimatesmartfee(1)["feerate"], fee_rate)
+
+        fee_dat = self.nodes[0].chain_path / "fee_estimates.dat"
+
+        # Stop the node and backdate the fee_estimates.dat file more than MAX_FILE_AGE
+        self.stop_node(0)
+        last_modified_time = time.time() - (MAX_FILE_AGE + 1) * SECONDS_PER_HOUR
+        os.utime(fee_dat, (last_modified_time, last_modified_time))
+
+        # Start node and ensure the fee_estimates.dat file was not read
+        self.start_node(0)
+        assert_equal(self.nodes[0].estimatesmartfee(1)["errors"], ["Insufficient data or no feerate found"])
+
+
+    def test_estimate_dat_is_flushed_periodically(self):
+        fee_dat = self.nodes[0].chain_path / "fee_estimates.dat"
+        os.remove(fee_dat) if os.path.exists(fee_dat) else None
+
+        # Verify that fee_estimates.dat does not exist
+        assert_equal(os.path.isfile(fee_dat), False)
+
+        # Verify if the string "Flushed fee estimates to fee_estimates.dat." is present in the debug log file.
+        # If present, it indicates that fee estimates have been successfully flushed to disk.
+        with self.nodes[0].assert_debug_log(expected_msgs=["Flushed fee estimates to fee_estimates.dat."], timeout=1):
+            # Mock the scheduler for an hour to flush fee estimates to fee_estimates.dat
+            self.nodes[0].mockscheduler(SECONDS_PER_HOUR)
+
+        # Verify that fee estimates were flushed and fee_estimates.dat file is created
+        assert_equal(os.path.isfile(fee_dat), True)
+
+        # Verify that the estimates remain the same if there are no blocks in the flush interval
+        block_hash_before = self.nodes[0].getbestblockhash()
+        fee_dat_initial_content = open(fee_dat, "rb").read()
+        with self.nodes[0].assert_debug_log(expected_msgs=["Flushed fee estimates to fee_estimates.dat."], timeout=1):
+            # Mock the scheduler for an hour to flush fee estimates to fee_estimates.dat
+            self.nodes[0].mockscheduler(SECONDS_PER_HOUR)
+
+        # Verify that there were no blocks in between the flush interval
+        assert_equal(block_hash_before, self.nodes[0].getbestblockhash())
+
+        fee_dat_current_content = open(fee_dat, "rb").read()
+        assert_equal(fee_dat_current_content, fee_dat_initial_content)
+
+        # Verify that the estimates remain the same after shutdown with no blocks before shutdown
+        self.restart_node(0)
+        fee_dat_current_content = open(fee_dat, "rb").read()
+        assert_equal(fee_dat_current_content, fee_dat_initial_content)
+
+        # Verify that the estimates are not the same if new blocks were produced in the flush interval
+        with self.nodes[0].assert_debug_log(expected_msgs=["Flushed fee estimates to fee_estimates.dat."], timeout=1):
+            # Mock the scheduler for an hour to flush fee estimates to fee_estimates.dat
+            self.generate(self.nodes[0], 5, sync_fun=self.no_op)
+            self.nodes[0].mockscheduler(SECONDS_PER_HOUR)
+
+        fee_dat_current_content = open(fee_dat, "rb").read()
+        assert fee_dat_current_content != fee_dat_initial_content
+
+        fee_dat_initial_content = fee_dat_current_content
+
+        # Generate blocks before shutdown and verify that the fee estimates are not the same
+        self.generate(self.nodes[0], 5, sync_fun=self.no_op)
+        self.restart_node(0)
+        fee_dat_current_content = open(fee_dat, "rb").read()
+        assert fee_dat_current_content != fee_dat_initial_content
+
+
+    def test_acceptstalefeeestimates_option(self):
+        # Get the initial fee rate while node is running
+        fee_rate = self.nodes[0].estimatesmartfee(1)["feerate"]
+
+        self.stop_node(0)
+
+        fee_dat = self.nodes[0].chain_path / "fee_estimates.dat"
+
+        # Stop the node and backdate the fee_estimates.dat file more than MAX_FILE_AGE
+        last_modified_time = time.time() - (MAX_FILE_AGE + 1) * SECONDS_PER_HOUR
+        os.utime(fee_dat, (last_modified_time, last_modified_time))
+
+        # Restart node with -acceptstalefeeestimates option to ensure fee_estimate.dat file is read
+        self.start_node(0,extra_args=["-acceptstalefeeestimates"])
+        assert_equal(self.nodes[0].estimatesmartfee(1)["feerate"], fee_rate)
+
+
     def run_test(self):
         self.log.info("This test is time consuming, please be patient")
         self.log.info("Splitting inputs so we can generate tx's")
@@ -312,12 +404,21 @@ def run_test(self):
         self.log.info("Testing estimates with single transactions.")
         self.sanity_check_estimates_range()
 
+        self.log.info("Test fee_estimates.dat is flushed periodically")
+        self.test_estimate_dat_is_flushed_periodically()
+
         # check that the effective feerate is greater than or equal to the mempoolminfee even for high mempoolminfee
         self.log.info(
             "Test fee rate estimation after restarting node with high MempoolMinFee"
         )
         self.test_feerate_mempoolminfee()
 
+        self.log.info("Test acceptstalefeeestimates option")
+        self.test_acceptstalefeeestimates_option()
+
+        self.log.info("Test reading old fee_estimates.dat")
+        self.test_old_fee_estimate_file()
+
         self.log.info("Restarting node with fresh estimation")
         self.stop_node(0)
         fee_dat = os.path.join(self.nodes[0].datadir, self.chain, "fee_estimates.dat")