Intermittent failure in `wallet

mzumsande commented at 8:12 PM on August 26, 2022: contributor

https://cirrus-ci.com/task/6569439897321472?logs=functional_tests#L2462 :

File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\wallet_groups.py", line 150, in run_test
                                       txid6 = self.nodes[4].sendtoaddress(self.nodes[0].getnewaddress(), 2.95)
(...)
AssertionError: [node 4] Expected messages "['Fee non-grouped = 5520, grouped = 8240, using grouped']" does not partially match log

mzumsande added the label Bug on Aug 26, 2022

MarcoFalke added this to the milestone 24.0 on Aug 29, 2022

MarcoFalke commented at 9:11 AM on August 29, 2022: member

This seems to be happening quite often in CI across all tasks, but I can't reproduce locally.

Another example: https://cirrus-ci.com/task/5878826906419200?logs=ci#L3264

brunoerg commented at 2:13 PM on August 29, 2022: contributor

After running it several times on my machine, I got same error:

2022-08-29T13:59:03.850000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/Users/brunogarcia/projects/bitcoin-core-dev/test/functional/test_framework/test_framework.py", line 133, in main
    self.run_test()
  File "/Users/brunogarcia/projects/bitcoin-core-dev/./test/functional/wallet_groups.py", line 151, in run_test
    txid6 = self.nodes[4].sendtoaddress(self.nodes[0].getnewaddress(), 2.95)
  File "/opt/homebrew/Cellar/python@3.9/3.9.12/Frameworks/Python.framework/Versions/3.9/lib/python3.9/contextlib.py", line 126, in __exit__
    next(self.gen)
  File "/Users/brunogarcia/projects/bitcoin-core-dev/test/functional/test_framework/test_node.py", line 423, in assert_debug_log
    self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
  File "/Users/brunogarcia/projects/bitcoin-core-dev/test/functional/test_framework/test_node.py", line 167, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 4] Expected messages "['Fee non-grouped = 5520, grouped = 8240, using grouped']" does not partially match log:

 - 2022-08-29T13:59:01.964574Z [http] [httpserver.cpp:241] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49661
 - 2022-08-29T13:59:01.964783Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=sendtoaddress user=__cookie__
 - 2022-08-29T13:59:01.967513Z [httpworker.1] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool added 1 keys (0 internal), size=2 (1 internal)
 - 2022-08-29T13:59:02.020424Z [httpworker.1] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool reserve 2
 - 2022-08-29T13:59:02.020990Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 60% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 86.05% 12.3/(13.3 1 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.021075Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 2 > 85% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.021147Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 4 > 95% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.021224Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 60% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 86.05% 12.3/(13.3 1 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.021306Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 2 > 85% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.021404Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 4 > 95% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.023758Z [httpworker.1] [wallet/coinselection.cpp:320] [KnapsackSolver] [selectcoins] Coin selection best subset: 1.00 1.00 1.00 total 2.99995917
 - 2022-08-29T13:59:02.081274Z [httpworker.1] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool keep 2
 - 2022-08-29T13:59:02.081476Z [httpworker.1] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] Fee Calculation: Fee:5524 Bytes:276 Tgt:2 (requested 6) Reason:"Half Target 60% Threshold" Decay 0.96200: Estimation: (19613.1 - 1e+99) 86.05% 12.3/(13.3 1 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.083902Z [httpworker.1] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool added 1 keys (1 internal), size=2 (1 internal)
 - 2022-08-29T13:59:02.137461Z [httpworker.1] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool reserve 4
 - 2022-08-29T13:59:02.137973Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 60% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 86.05% 12.3/(13.3 1 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.138055Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 2 > 85% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.138124Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 4 > 95% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.138203Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 60% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 86.05% 12.3/(13.3 1 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.138272Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 2 > 85% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.138350Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 4 > 95% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.200202Z [httpworker.1] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool keep 4
 - 2022-08-29T13:59:02.200361Z [httpworker.1] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] Fee Calculation: Fee:8245 Bytes:412 Tgt:2 (requested 6) Reason:"Half Target 60% Threshold" Decay 0.96200: Estimation: (19613.1 - 1e+99) 86.05% 12.3/(13.3 1 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.200418Z [httpworker.1] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] Fee non-grouped = 5524, grouped = 8245, using non-grouped
 - 2022-08-29T13:59:02.200556Z [httpworker.1] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] CommitTransaction:
 - CTransaction(hash=63de543f9f, ver=2, vin.size=3, vout.size=2, nLockTime=88)
 -     CTxIn(COutPoint(bd00ef514b, 0), scriptSig=, nSequence=4294967293)
 -     CTxIn(COutPoint(97c1451f61, 1), scriptSig=, nSequence=4294967293)
 -     CTxIn(COutPoint(782bc30dbd, 0), scriptSig=, nSequence=4294967293)
 -     CScriptWitness(304402206e5bec091b1f13878b5a728312d2b5f149300872dfaa94b94da347ce1cf2de7102203aae2651dcdbf7f32642884521eafcc25db5227714d9a8878639ecec0993ecd801, 03f2660628e57b7ec921650248b41e1b270ff84332634776d79f1215fffa1585a0)
 -     CScriptWitness(304402203bd40ae7040bb065acb3fa1b1312dc6c647144db3c98c7dccd01d34be92f0aca02201d2c37ff8e9eeec6c96515529f92e401b9df5ce30aca598b09b3b701fcc99ea901, 03f2660628e57b7ec921650248b41e1b270ff84332634776d79f1215fffa1585a0)
 -     CScriptWitness(304402204822d244b3b704a670446ea0cb2faa27300d33352ca72a3b3f9d85fe659090090220575f8e8785031e403d10ff0771b4c4baa178f52b77a6205ed8aa7719ce22184e01, 03f2660628e57b7ec921650248b41e1b270ff84332634776d79f1215fffa1585a0)
 -     CTxOut(nValue=0.04994476, scriptPubKey=00142217fba66bb0e12889e672d587)
 -     CTxOut(nValue=2.95000000, scriptPubKey=0014debb3dd9d593090d70ce9e1138)
 - 2022-08-29T13:59:02.200694Z [httpworker.1] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] AddToWallet 63de543f9faf012dc93b11758723c6e54b22c5c84e1683e2c36dcfd7bc6934c6  newupdate
 - 2022-08-29T13:59:02.254239Z [httpworker.1] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] Submitting wtx 63de543f9faf012dc93b11758723c6e54b22c5c84e1683e2c36dcfd7bc6934c6 to mempool for relay
 - 2022-08-29T13:59:02.255631Z [httpworker.1] [txmempool.cpp:736] [check] [mempool] Checking mempool with 1 transactions and 3 inputs
 - 2022-08-29T13:59:02.255835Z [httpworker.1] [validationinterface.cpp:211] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=63de543f9faf012dc93b11758723c6e54b22c5c84e1683e2c36dcfd7bc6934c6 wtxid=019e676a04529e0d790c1716fd8b803570967d13477fc83ed6832ce78e868951
 - 2022-08-29T13:59:02.255910Z [httpworker.1] [txmempool.cpp:736] [check] [mempool] Checking mempool with 2 transactions and 6 inputs
 - 2022-08-29T13:59:02.255985Z [scheduler] [validationinterface.cpp:211] [operator()] [validation] TransactionAddedToMempool: txid=63de543f9faf012dc93b11758723c6e54b22c5c84e1683e2c36dcfd7bc6934c6 wtxid=019e676a04529e0d790c1716fd8b803570967d13477fc83ed6832ce78e868951
 - 2022-08-29T13:59:02.256412Z [scheduler] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] AddToWallet 63de543f9faf012dc93b11758723c6e54b22c5c84e1683e2c36dcfd7bc6934c6  2022-08-29T13:59:03.850000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/Users/brunogarcia/projects/bitcoin-core-dev/test/functional/test_framework/test_framework.py", line 133, in main
    self.run_test()
  File "/Users/brunogarcia/projects/bitcoin-core-dev/./test/functional/wallet_groups.py", line 151, in run_test
    txid6 = self.nodes[4].sendtoaddress(self.nodes[0].getnewaddress(), 2.95)
  File "/opt/homebrew/Cellar/python@3.9/3.9.12/Frameworks/Python.framework/Versions/3.9/lib/python3.9/contextlib.py", line 126, in __exit__
    next(self.gen)
  File "/Users/brunogarcia/projects/bitcoin-core-dev/test/functional/test_framework/test_node.py", line 423, in assert_debug_log
    self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
  File "/Users/brunogarcia/projects/bitcoin-core-dev/test/functional/test_framework/test_node.py", line 167, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 4] Expected messages "['Fee non-grouped = 5520, grouped = 8240, using grouped']" does not partially match log:

 - 2022-08-29T13:59:01.964574Z [http] [httpserver.cpp:241] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49661
 - 2022-08-29T13:59:01.964783Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=sendtoaddress user=__cookie__
 - 2022-08-29T13:59:01.967513Z [httpworker.1] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool added 1 keys (0 internal), size=2 (1 internal)
 - 2022-08-29T13:59:02.020424Z [httpworker.1] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool reserve 2
 - 2022-08-29T13:59:02.020990Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 60% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 86.05% 12.3/(13.3 1 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.021075Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 2 > 85% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.021147Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 4 > 95% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.021224Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 60% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 86.05% 12.3/(13.3 1 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.021306Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 2 > 85% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.021404Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 4 > 95% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.023758Z [httpworker.1] [wallet/coinselection.cpp:320] [KnapsackSolver] [selectcoins] Coin selection best subset: 1.00 1.00 1.00 total 2.99995917
 - 2022-08-29T13:59:02.081274Z [httpworker.1] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool keep 2
 - 2022-08-29T13:59:02.081476Z [httpworker.1] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] Fee Calculation: Fee:5524 Bytes:276 Tgt:2 (requested 6) Reason:"Half Target 60% Threshold" Decay 0.96200: Estimation: (19613.1 - 1e+99) 86.05% 12.3/(13.3 1 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.083902Z [httpworker.1] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool added 1 keys (1 internal), size=2 (1 internal)
 - 2022-08-29T13:59:02.137461Z [httpworker.1] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool reserve 4
 - 2022-08-29T13:59:02.137973Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 60% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 86.05% 12.3/(13.3 1 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.138055Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 2 > 85% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.138124Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 4 > 95% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.138203Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 1 > 60% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 86.05% 12.3/(13.3 1 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.138272Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 2 > 85% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.138350Z [httpworker.1] [policy/fees.cpp:381] [EstimateMedianVal] [estimatefee] FeeEst: 4 > 95% decay 0.96200: feerate: 20010.6 from (19613.1 - 1e+99) 100.00% 13.3/(13.3 0 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.200202Z [httpworker.1] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool keep 4
 - 2022-08-29T13:59:02.200361Z [httpworker.1] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] Fee Calculation: Fee:8245 Bytes:412 Tgt:2 (requested 6) Reason:"Half Target 60% Threshold" Decay 0.96200: Estimation: (19613.1 - 1e+99) 86.05% 12.3/(13.3 1 mem 0.0 out) Fail: (0 - 19613.1) 0.00% 0.0/(0.0 0 mem 0.0 out)
 - 2022-08-29T13:59:02.200418Z [httpworker.1] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] Fee non-grouped = 5524, grouped = 8245, using non-grouped
 - 2022-08-29T13:59:02.200556Z [httpworker.1] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] CommitTransaction:
 - CTransaction(hash=63de543f9f, ver=2, vin.size=3, vout.size=2, nLockTime=88)
 -     CTxIn(COutPoint(bd00ef514b, 0), scriptSig=, nSequence=4294967293)
 -     CTxIn(COutPoint(97c1451f61, 1), scriptSig=, nSequence=4294967293)
 -     CTxIn(COutPoint(782bc30dbd, 0), scriptSig=, nSequence=4294967293)
 -     CScriptWitness(304402206e5bec091b1f13878b5a728312d2b5f149300872dfaa94b94da347ce1cf2de7102203aae2651dcdbf7f32642884521eafcc25db5227714d9a8878639ecec0993ecd801, 03f2660628e57b7ec921650248b41e1b270ff84332634776d79f1215fffa1585a0)
 -     CScriptWitness(304402203bd40ae7040bb065acb3fa1b1312dc6c647144db3c98c7dccd01d34be92f0aca02201d2c37ff8e9eeec6c96515529f92e401b9df5ce30aca598b09b3b701fcc99ea901, 03f2660628e57b7ec921650248b41e1b270ff84332634776d79f1215fffa1585a0)
 -     CScriptWitness(304402204822d244b3b704a670446ea0cb2faa27300d33352ca72a3b3f9d85fe659090090220575f8e8785031e403d10ff0771b4c4baa178f52b77a6205ed8aa7719ce22184e01, 03f2660628e57b7ec921650248b41e1b270ff84332634776d79f1215fffa1585a0)
 -     CTxOut(nValue=0.04994476, scriptPubKey=00142217fba66bb0e12889e672d587)
 -     CTxOut(nValue=2.95000000, scriptPubKey=0014debb3dd9d593090d70ce9e1138)
 - 2022-08-29T13:59:02.200694Z [httpworker.1] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] AddToWallet 63de543f9faf012dc93b11758723c6e54b22c5c84e1683e2c36dcfd7bc6934c6  newupdate
 - 2022-08-29T13:59:02.254239Z [httpworker.1] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] Submitting wtx 63de543f9faf012dc93b11758723c6e54b22c5c84e1683e2c36dcfd7bc6934c6 to mempool for relay
 - 2022-08-29T13:59:02.255631Z [httpworker.1] [txmempool.cpp:736] [check] [mempool] Checking mempool with 1 transactions and 3 inputs
 - 2022-08-29T13:59:02.255835Z [httpworker.1] [validationinterface.cpp:211] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=63de543f9faf012dc93b11758723c6e54b22c5c84e1683e2c36dcfd7bc6934c6 wtxid=019e676a04529e0d790c1716fd8b803570967d13477fc83ed6832ce78e868951
 - 2022-08-29T13:59:02.255910Z [httpworker.1] [txmempool.cpp:736] [check] [mempool] Checking mempool with 2 transactions and 6 inputs
 - 2022-08-29T13:59:02.255985Z [scheduler] [validationinterface.cpp:211] [operator()] [validation] TransactionAddedToMempool: txid=63de543f9faf012dc93b11758723c6e54b22c5c84e1683e2c36dcfd7bc6934c6 wtxid=019e676a04529e0d790c1716fd8b803570967d13477fc83ed6832ce78e868951
 - 2022-08-29T13:59:02.256412Z [scheduler] [wallet/wallet.h:827] [WalletLogPrintf] [default wallet] AddToWallet 63de543f9faf012dc93b11758723c6e54b22c5c84e1683e2c36dcfd7bc6934c6

brunoerg commented at 2:47 PM on August 29, 2022: contributor

Maybe a fix? I think it would make the block generated by node0 not interfere with the sendtoaddress by node4.

diff --git a/test/functional/wallet_groups.py b/test/functional/wallet_groups.py
index 866c411db..e791fccfb 100755
--- a/test/functional/wallet_groups.py
+++ b/test/functional/wallet_groups.py
@@ -144,8 +144,9 @@ class WalletGroupTest(BitcoinTestFramework):
         # 1 sat higher, crossing the threshold from non-grouped to grouped.
         self.log.info("Test wallet option maxapsfee threshold from non-grouped to grouped")
         addr_aps3 = self.nodes[4].getnewaddress()
         [self.nodes[0].sendtoaddress(addr_aps3, 1.0) for _ in range(5)]
-        self.generate(self.nodes[0], 1)
+        self.generate(self.nodes[0], 1, sync_fun=self.no_op)
         with self.nodes[4].assert_debug_log([f'Fee non-grouped = {tx5_6_ungrouped_fee}, grouped = {tx5_6_grouped_fee}, using grouped']):
             txid6 = self.nodes[4].sendtoaddress(self.nodes[0].getnewaddress(), 2.95)
         tx6 = self.nodes[4].getrawtransaction(txid6, True)

MarcoFalke commented at 3:00 PM on August 29, 2022: member

setting sync_fun=self.no_op does not prevent a sync, you'd have to disconnect/stop the nodes. However, I wonder why the block generated does interfere?

brunoerg commented at 3:19 PM on August 29, 2022: contributor

you'd have to disconnect/stop the nodes

Yes, tks.

However, I wonder why the block generated does interfere?

Feel free to correct me, not sure if my logic is correct, but I think this new block (from node0) could be interfering on the fee estimation from node4.

MarcoFalke commented at 3:51 PM on August 29, 2022: member

If the fee is the issue, what about fixing it with -paytxfee=constant?

fanquake commented at 3:33 PM on August 30, 2022: member

https://cirrus-ci.com/task/6724130828451840 in the multiprocess job.

mzumsande commented at 3:51 PM on August 30, 2022: contributor

I could also reproduce it locally after ~40 runs or so. Since it started occurring quite frequently and never before, any recently merged PR this could be related to? #25865, which touched the test, maybe?

jonatack commented at 11:39 AM on August 31, 2022: contributor

https://cirrus-ci.com/task/5932652107661312?logs=functional_tests#L2424 in the win64 native job.

kouloumos commented at 4:02 PM on September 2, 2022: contributor

https://cirrus-ci.com/task/6751147112267776?logs=ci#L3263 in the previous releases job

Edit: And also failed on the re-run https://cirrus-ci.com/task/5933709877575680?logs=ci#L3254

stickies-v referenced this in commit 82e7d7b202 on Sep 2, 2022

stickies-v commented at 5:47 PM on September 2, 2022: contributor

As mzumsande also mentioned, empirical testing indicates this failure was significantly exacerbated or introduced by #25865, so I've created a quick-fix PR in #25988 to revert and unbreak CI while we figure out the root cause.

Edit: highlighted that #25865 may not have introduced the issue but just made it more visible.

brunoerg commented at 7:48 PM on September 2, 2022: contributor

I don't think it was introduced by #25865, I think it only increased the probability of error happening since it speeds up the tx relay / mempool sync.

stickies-v referenced this in commit 2186608172 on Sep 3, 2022

stickies-v commented at 12:32 AM on September 3, 2022: contributor

If the fee is the issue, what about fixing it with -paytxfee=constant?

This indeed seems to be the issue, fixed in #25990

MarcoFalke referenced this in commit dd3ada6ec4 on Sep 9, 2022

MarcoFalke closed this on Sep 9, 2022

sidhujag referenced this in commit 9bac3956f4 on Sep 11, 2022

bitcoin locked this on Sep 9, 2023

Intermittent failure in `wallet_groups.py` #25940