Intermittent CI failure "fee too high" in wallet

jonatack commented at 5:51 AM on May 18, 2022: member

https://cirrus-ci.com/task/6295015969259520

wallet_send.py --descriptors

 test  2022-04-22T21:26:09.984000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 133, in main
                                       self.run_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/wallet_send.py", line 560, in run_test
                                       assert_fee_amount(testres["fees"]["base"], testres["vsize"], Decimal(0.0001))
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/util.py", line 46, in assert_fee_amount
                                       raise AssertionError("Fee of %s BTC too high! (Should be %s BTC)" % (str(fee), str(target_fee)))
                                   AssertionError: Fee of 0.00003160 BTC too high! (Should be 0.0000313 BTC)

jonatack added the label Bug on May 18, 2022

jonatack commented at 5:54 AM on May 18, 2022: member

It's 3 weeks old, closing, will re-open if see a new one. I think I recall seeing this more recently, though.

jonatack closed this on May 18, 2022

bitcoin locked this on May 18, 2023

bitcoin unlocked this on Jul 6, 2023

maflcko commented at 10:18 AM on July 6, 2023: member

https://cirrus-ci.com/task/4746240760479744?logs=ci#L2770

 node0 2023-06-30T14:46:07.294496Z [httpworker.1] [rpc/request.cpp:181] [parse] [rpc] ThreadRPCServer method=testmempoolaccept user=__cookie__ 
 test  2023-06-30T14:46:07.295000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 131, in main
                                       self.run_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/wallet_send.py", line 580, in run_test
                                       assert_fee_amount(testres["fees"]["base"], testres["vsize"], Decimal(0.0001))
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/util.py", line 52, in assert_fee_amount
                                       raise AssertionError("Fee of %s BTC too high! (Should be %s BTC)" % (str(fee), str(target_fee)))
                                   AssertionError: Fee of 0.00002520 BTC too high! (Should be 0.0000249 BTC)

maflcko reopened this on Jul 6, 2023

jonatack commented at 11:39 PM on August 1, 2023: member

Seen in wallet_send.py --legacy-wallet

https://cirrus-ci.com/task/6115877712560128?logs=ci#L3429

 node0 2023-08-01T23:17:59.093565Z [httpworker.1] [rpc/request.cpp:181] [parse] [rpc] ThreadRPCServer method=testmempoolaccept user=__cookie__ 
 test  2023-08-01T23:17:59.094000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 131, in main
                                       self.run_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/wallet_send.py", line 580, in run_test
                                       assert_fee_amount(testres["fees"]["base"], testres["vsize"], Decimal(0.0001))
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/util.py", line 52, in assert_fee_amount
                                       raise AssertionError("Fee of %s BTC too high! (Should be %s BTC)" % (str(fee), str(target_fee)))
                                   AssertionError: Fee of 0.00002520 BTC too high! (Should be 0.0000249 BTC)

jonatack renamed this:
~~Intermittent CI failure "fee too high" in wallet_send.py --descriptors~~
Intermittent CI failure "fee too high" in wallet_send.py
on Aug 1, 2023

mzumsande commented at 8:14 PM on December 1, 2023: contributor

It still happens: https://cirrus-ci.com/task/6418676576944128

 node0 2023-11-29T05:48:26.130808Z [httpworker.3] [txmempool.cpp:678] [check] [mempool] Checking mempool with 0 transactions and 0 inputs 
 test  2023-11-29T05:48:26.131000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 131, in main
                                       self.run_test()
                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/wallet_send.py", line 577, in run_test
                                       assert_fee_amount(testres["fees"]["base"], testres["vsize"], Decimal(0.0001))
                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/util.py", line 52, in assert_fee_amount
                                       raise AssertionError("Fee of %s BTC too high! (Should be %s BTC)" % (str(fee), str(target_fee)))
                                   AssertionError: Fee of 0.00002520 BTC too high! (Should be 0.0000249 BTC)

maflcko added the label Wallet on Dec 2, 2023

maflcko added the label Tests on Dec 2, 2023

stratospher commented at 4:35 AM on January 22, 2024: contributor

happened here too: https://cirrus-ci.com/task/4577902440742912?logs=ci#L2654

maflcko added the label CI failed on Jan 24, 2024

m3dwards commented at 10:55 AM on February 22, 2024: contributor

Seen this on my local windows machine:

2024-02-21T21:14:35.394000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2024-02-21T21:14:36.537000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "C:\Users\Max\source\bitcoin\test\functional\test_framework\test_framework.py", line 131, in main
    self.run_test()
  File "C:\Users\Max\source\bitcoin/test/functional/wallet_send.py", line 577, in run_test
    assert_fee_amount(testres["fees"]["base"], testres["vsize"], Decimal(0.0001))
  File "C:\Users\Max\source\bitcoin\test\functional\test_framework\util.py", line 52, in assert_fee_amount
    raise AssertionError("Fee of %s BTC too high! (Should be %s BTC)" % (str(fee), str(target_fee)))
AssertionError: Fee of 0.00002520 BTC too high! (Should be 0.0000249 BTC)
2024-02-21T21:14:36.546000Z TestFramework (DEBUG): Closing down network thread

Currently running the functional tests in a loop and this happened once in 57 runs (so far).

maflcko commented at 11:22 AM on February 22, 2024: member

@m3dwards Can you run the test with --tracerpc to get more relevant values?

maflcko commented at 9:50 AM on February 23, 2024: member

tracrpc:

-947-> testmempoolaccept [["020000000001025e84395d59a4af7b4f474089f038b218cffc3d897789106c1ab44e49294534400100000023220020c5f1c024f0f356de16a3d92568ed6018953e679557888a497a17d09c4af07b7efdffffff0d1ca8982f324c1a0ed4fd00b6c6f10606499c9a8b2f8063dbba620858962bcd0000000000fdffffff02285bcd1d000000001600140b85e98d35cc0ad560471e7f40dc3ae36af4944f002f685900000000160014d1ba99364539d6100b8298ea0f6ee85758758c4603463043021f6bb7da3ea2a872f1f2262ff7ac2e6053514ed09f05ee11e29d2093ccaf81d202200da4d86dfc7fb061f1ca07a2785cac597734f38d23fe1c3c9206d7a7a43c6650012103f4ae50fc994a2ac8d51106b756c4257ff0116afa3a36a67d42df549dc4ecb52e1976a9141ca5b97909bf44347c9cd041639ba93de5601a9d88ac02463043021f427eecb117e9de506282507ef35ae6be968e5914dbf501a9014d9a31c62772022037f565d04ea8ff7f15f150329bf42ba789e7b8f872ee3b31b79d78b500f0ddb2012102fedc3d1130f01b5bd8731d2aa1dba526bca499157135c863e9c45d4d227e786600000000"]]
<-947- [0.000885] [{"txid": "2d57da659baff0592246fa64f6064a42026ba38b050434c8ca79620d847954ab", "wtxid": "0966f9996761e8bb4a635b1495ca9c0c9b883e1153a53573b14f188ed5bb4884", "allowed": true, "vsize": 249, "fees": {"base": "0.00002520", "effective-feerate": "0.00010120", "effective-includes": ["0966f9996761e8bb4a635b1495ca9c0c9b883e1153a53573b14f188ed5bb4884"]}}]

maflcko commented at 9:55 AM on February 23, 2024: member

Not sure how to best fix this. I guess increasing the wiggle room by a few more bytes will make it closer to impossible to hit:

diff --git a/test/functional/test_framework/util.py b/test/functional/test_framework/util.py
index b4b05b1597..97d0d9ca37 100644
--- a/test/functional/test_framework/util.py
+++ b/test/functional/test_framework/util.py
@@ -46,8 +46,8 @@ def assert_fee_amount(fee, tx_size, feerate_BTC_kvB):
     target_fee = get_fee(tx_size, feerate_BTC_kvB)
     if fee < target_fee:
         raise AssertionError("Fee of %s BTC too low! (Should be %s BTC)" % (str(fee), str(target_fee)))
-    # allow the wallet's estimation to be at most 2 bytes off
-    high_fee = get_fee(tx_size + 2, feerate_BTC_kvB)
+    # allow the wallet's estimation to be at most 3 bytes off
+    high_fee = get_fee(tx_size + 3, feerate_BTC_kvB)
     if fee > high_fee:
         raise AssertionError("Fee of %s BTC too high! (Should be %s BTC)" % (str(fee), str(target_fee)))

maflcko added this to the milestone 27.0 on Feb 23, 2024

m3dwards commented at 4:41 PM on February 27, 2024: contributor

When passing, this test's expected fee of 0.00002500 does not match the actual of 0.00002520. It passes because of the 2 byte allowance in assert_fee_amount. This happens because the calculation for the expected weight of an input is slightly off. I believe a better weight calculation would remove the 1 byte buffers and correctly calculate the length of the number of scriptWitnesses rather than just adding the count directly to the weight. After speaking with @achow101 the buffers were added to account for the fact that sometimes ECDSA signatures can be 1 byte shorter than normal but in that case the buffer makes the estimate even further from the reality so I have simply removed them.

diff --git a/test/functional/wallet_send.py b/test/functional/wallet_send.py
index 6ce2a56bfc..fed34c250b 100755
--- a/test/functional/wallet_send.py
+++ b/test/functional/wallet_send.py
@@ -543,11 +543,16 @@ class WalletSendTest(BitcoinTestFramework):
                 break
         psbt_in = dec["inputs"][input_idx]
         # Calculate the input weight
-        # (prevout + sequence + length of scriptSig + scriptsig + 1 byte buffer) * WITNESS_SCALE_FACTOR + num scriptWitness stack items + (length of stack item + stack item) * N stack items + 1 byte buffer
+        # (prevout + sequence + length of scriptSig + scriptsig) * WITNESS_SCALE_FACTOR + len of num scriptWitness stack items + (length of stack item + stack item) * N stack items
+        # Note that occasionally this weight estimate may be slightly larger than the real weight
+        # as sometimes ECDSA signatures are one byte shorter than expected with a probability of 1/128
         len_scriptsig = len(psbt_in["final_scriptSig"]["hex"]) // 2 if "final_scriptSig" in psbt_in else 0
-        len_scriptsig += len(ser_compact_size(len_scriptsig)) + 1
-        len_scriptwitness = (sum([(len(x) // 2) + len(ser_compact_size(len(x) // 2)) for x in psbt_in["final_scriptwitness"]]) + len(psbt_in["final_scriptwitness"]) + 1) if "final_scriptwitness" in psbt_in else 0
-        input_weight = ((40 + len_scriptsig) * WITNESS_SCALE_FACTOR) + len_scriptwitness
+        len_scriptsig += len(ser_compact_size(len_scriptsig))
+        len_scriptwitness = (sum([(len(x) // 2) + len(ser_compact_size(len(x) // 2)) for x in psbt_in["final_scriptwitness"]]) + len(ser_compact_size(len(psbt_in["final_scriptwitness"])))) if "final_scriptwitness" in psbt_in else 0
+        len_prevout_txid = 32
+        len_prevout_index = 4
+        len_sequence = 4
+        input_weight = ((len_prevout_txid + len_prevout_index + len_sequence + len_scriptsig) * WITNESS_SCALE_FACTOR) + len_scriptwitness

         # Input weight error conditions
         assert_raises_rpc_error(

The reason for the flake was because with a probability of 1/128, the signatures on the transaction can be 1 byte shorter potentially making the whole transaction 249 vbytes. The proposed change above not only makes the expected and actual fees match (usually) but would also prevent the flake as the real fee of 0.00002500 would be within 2 bytes of the expected fee of 0.00002490 as afforded by assert_fee_amount. @achow101 also suggested that an alternative solution could be to change the test to use taproot instead which has predictable signature lengths.

If we are happy with the solution proposed above, I can submit as PR.

maflcko commented at 5:22 PM on February 27, 2024: member

@achow101 also suggested that an alternative solution could be to change the test to use taproot instead which has predictable signature lengths.

I also wanted to suggest this, but I wasn't sure if we wanted to test other address types, as long as they are supported by the wallet. I am not sure, but I presume the test currently only used the current default address type?

m3dwards commented at 9:39 PM on February 27, 2024: contributor

That's correct, test that includes weight doesn't include other address types. Changing address types would just change coverage rather than add coverage.

I think the test is valid with the address type it has and the assert takes care of the fact the signatures can vary a bit in length so in my humble opinion just correcting the weight calculation is good.

maflcko commented at 9:43 PM on February 27, 2024: member

Makes sense, and thanks for looking into this. Feel free to create a pull with the fix. It should be easy to adjust, if reviewers prefer something else.

fanquake commented at 1:59 AM on March 1, 2024: member

https://cirrus-ci.com/task/5938282698113024?logs=ci#L3358

fanquake closed this on Mar 5, 2024

fanquake referenced this in commit 2b260eadf7 on Mar 5, 2024

bitcoin locked this on Mar 5, 2025

Intermittent CI failure "fee too high" in wallet_send.py #25164