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

issue maflcko openend this issue on February 24, 2025
  1. 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'
    
  2. maflcko added the label CI failed on Feb 24, 2025
  3. maflcko added the label TX fees and policy on Feb 24, 2025
  4. 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
    
  5. 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.

  6. 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)

  7. tnndbtc referenced this in commit b365ae9702 on May 25, 2025
  8. tnndbtc commented at 7:50 pm on May 25, 2025: none
    Include @Empact who originally worked on this test to review PR# 32615

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-05-29 18:12 UTC

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