Intermittent failure in feature_fee_estimation.py in check_raw_estimates feerate = float(e["feerate"]) KeyError: 'feerate'

maflcko commented at 11:54 am on February 24, 2025: member

( Reminds me of #30640 )

https://cirrus-ci.com/task/5862559074484224?logs=ci#L2975:

 0 node1 2025-02-21T16:00:41.934000Z [httpworker.9] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
 1 node2 2025-02-21T16:00:41.935013Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:34802 
 2 node2 2025-02-21T16:00:41.935352Z [httpworker.13] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
 3 node2 2025-02-21T16:00:41.936338Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:34802 
 4 node2 2025-02-21T16:00:41.936547Z [httpworker.14] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblock user=__cookie__ 
 5 node1 2025-02-21T16:00:41.939972Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:54186 
 6 node1 2025-02-21T16:00:41.940135Z [httpworker.11] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=estimaterawfee user=__cookie__ 
 7 node1 2025-02-21T16:00:41.940489Z [httpworker.11] [policy/fees.cpp:398] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 95% decay 0.96200: feerate: 366047 from (348912 - 424105) 100.00% 18.8/(18.8 0 mem 0.0 out) Fail: (301403 - 348912) 77.41% 24.0/(24.0 7 mem 0.0 out) 
 8 node1 2025-02-21T16:00:41.940868Z [httpworker.11] [policy/fees.cpp:398] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 95% decay 0.99520: feerate: 435306 from (384675 - 515502) 100.00% 23.6/(23.6 0 mem 0.0 out) Fail: (301403 - 384675) 87.01% 46.9/(46.9 7 mem 0.0 out) 
 9 node1 2025-02-21T16:00:41.943365Z [httpworker.11] [policy/fees.cpp:398] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 95% decay 0.99931: feerate: -1 from (-1 - -1) 0.00% 0.0/(0.0 0 mem 0.0 out) Fail: (301403 - 1e+99) 92.37% 169.5/(169.5 14 mem 0.0 out) 
10 test  2025-02-21T16:00:41.944000Z TestFramework (ERROR): Key error 
11                                   Traceback (most recent call last):
12                                     File "/ci_container_base/test/functional/test_framework/test_framework.py", line 135, in main
13                                       self.run_test()
14                                     File "/ci_container_base/ci/scratch/build-x86_64-pc-linux-gnu/test/functional/feature_fee_estimation.py", line 449, in run_test
15                                       self.sanity_check_estimates_range()
16                                     File "/ci_container_base/ci/scratch/build-x86_64-pc-linux-gnu/test/functional/feature_fee_estimation.py", line 223, in sanity_check_estimates_range
17                                       check_estimates(self.nodes[1], self.fees_per_kb)
18                                     File "/ci_container_base/ci/scratch/build-x86_64-pc-linux-gnu/test/functional/feature_fee_estimation.py", line 120, in check_estimates
19                                       check_raw_estimates(node, fees_seen)
20                                     File "/ci_container_base/ci/scratch/build-x86_64-pc-linux-gnu/test/functional/feature_fee_estimation.py", line 80, in check_raw_estimates
21                                       feerate = float(e["feerate"])
22                                                       ~^^^^^^^^^^^
23                                   KeyError: 'feerate'

maflcko added the label CI failed on Feb 24, 2025

maflcko added the label TX fees and policy on Feb 24, 2025

maflcko commented at 12:05 pm on February 24, 2025: member

It is actually possible to reliably reproduce this:

0./bld-cmake/test/functional/feature_fee_estimation.py --randomseed=2986529890161488286

ismaelsadeeq commented at 11:38 pm on March 4, 2025: member

The failure occurs in sanity_check_estimates_range on the first iteration of the for loop.

https://github.com/bitcoin/bitcoin/blob/88debb3e4297ef4ebc8966ffe599359bc7b231d0/test/functional/feature_fee_estimation.py#L210-L223

It occurs in check_raw_estimates on confirmation target 1. The fee rate results in estimaterawfee long stats has insufficient data to produce an estimate.

short

 0  "feerate": Decimal("0.00366047"),
 1  "decay": Decimal("0.962"),
 2  "scale": 1,
 3  "pass": {
 4    "startrange": 348912,
 5    "endrange": 424105,
 6    "withintarget": Decimal("18.82"),
 7    "totalconfirmed": Decimal("18.82"),
 8    "inmempool": 0,
 9    "leftmempool": 0
10  },
11  "fail": {
12    "startrange": 301403,
13    "endrange": 348912,
14    "withintarget": Decimal("23.99"),
15    "totalconfirmed": Decimal("23.99"),
16    "inmempool": 7,
17    "leftmempool": 0
18  }
19}

medium

 0  "feerate": Decimal("0.00435306"),
 1  "decay": Decimal("0.9952"),
 2  "scale": 2,
 3  "pass": {
 4    "startrange": 384675,
 5    "endrange": 515502,
 6    "withintarget": Decimal("23.61"),
 7    "totalconfirmed": Decimal("23.61"),
 8    "inmempool": 0,
 9    "leftmempool": 0
10  },
11  "fail": {
12    "startrange": 301403,
13    "endrange": 384675,
14    "withintarget": Decimal("46.87"),
15    "totalconfirmed": Decimal("46.87"),
16    "inmempool": 7,
17    "leftmempool": 0
18  }
19}

long

 0  "decay": Decimal("0.99931"),
 1  "scale": 24,
 2  "fail": {
 3    "startrange": 301403,
 4    "endrange": Decimal("1E+99"),
 5    "withintarget": Decimal("169.53"),
 6    "totalconfirmed": Decimal("169.53"),
 7    "inmempool": 14,
 8    "leftmempool": 0
 9  },
10  "errors": ["Insufficient data or no feerate found which meets threshold"]
11}

I ran the test using the provided random seed, and it fails consistently.

( Reminds me of #30640 )

This seems orthogonal since, in transact_and_mine, we sync the mempool of the nodes before mining.

I checked that the nodes have the same mempool before mining, and after mining, their chain tips match as well.

It appears that the random nature of the number of transactions (along with the random selection of their feerates) generated 10 times to mine in transact_and_mine results in a long stats unable to provide an estimate.

tnndbtc commented at 4:33 pm on May 24, 2025: none

@maflcko @ismaelsadeeq

I dug further into this test failure in bitcoind process and found following: When test fails, it’s because TxConfirmStats::EstimateMedianVal (in src/policy/fees.cpp) has gone into the error path:

double curPct = nConf / (totalNum + failNum + extraNum); // Check to see if we are no longer getting confirmed at the success rate if (curPct < successBreakPoint) { // error path } else { // happy path }

At this particular test case, curPct is 0.92371745878662281 and fall below successBreakPoint (0.94999999999999996) This is because extraNum (14) has dragged the current percentage down (lldb) fr v curPct successBreakPoint nConf totalNum failNum extraNum (double) curPct = 0.92371745878662281 (double) successBreakPoint = 0.94999999999999996 // calculated by curPct = nConf / (totalNum + failNum + extraNum); (double) nConf = 169.52823303092737 (double) totalNum = 169.52823303092737 (double) failNum = 0 (int) extraNum = 14

In happy path during the test, extraNum is small, and failNum is 0, so curPct is bigger than expected successBreakPoint (0.94999999999999996)

In reality, extraNum could be a larger number as there might be more unconfirmed transactions in mempool, so I believe a lower than expected success break point is a real scenario. Therefore, the expectation that it always returns a greater than 0 feerate in check_raw_estimates in test/functional/feature_fee_estimation.py does not always hold true. feerate = float(e[“feerate”]) assert_greater_than(feerate, 0)

So, I would suggest we simply log a message when feerate does not exist in check_raw_estimates and continue the test.

What do you think?

Include more logs from debug.out in node1 which shows the failed messages:

feature_fee_estimation_0/node1/regtest/debug.out 2025-04-03T20:35:00.810609Z [httpworker.10] [policy/fees.cpp:398] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 95% decay 0.96200: feerate: 366047 from (348912 - 424105) 100.00% 18.8/(18.8 0 mem 0.0 out) Fail: (301403 - 348912) 77.41% 24.0/(24.0 7 mem 0.0 out) 2025-04-03T20:35:00.810971Z [httpworker.10] [policy/fees.cpp:398] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 95% decay 0.99520: feerate: 435306 from (384675 - 515502) 100.00% 23.6/(23.6 0 mem 0.0 out) Fail: (301403 - 384675) 87.01% 46.9/(46.9 7 mem 0.0 out) 2025-04-03T20:35:00.815082Z [httpworker.10] [policy/fees.cpp:398] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 95% decay 0.99931: feerate: -1 from (-1 - -1) 0.00% 0.0/(0.0 0 mem 0.0 out) Fail: (301403 - 1e+99) 92.37% 169.5/(169.5 14 mem 0.0 out)

tnndbtc referenced this in commit b365ae9702 on May 25, 2025

tnndbtc commented at 7:50 pm on May 25, 2025: none

Include @Empact who originally worked on this test to review PR# 32615

Intermittent failure in feature_fee_estimation.py in check_raw_estimates feerate = float(e[“feerate”]) KeyError: ‘feerate’ #31944