intermittent issue in wallet_backwards_compatibility.py: line 245, in run_test assert txs[3]["abandoned"] AssertionError

maflcko commented at 2:13 pm on April 4, 2024: member

https://cirrus-ci.com/task/5524545770094592?logs=ci#L3290

maflcko added the label Tests on Apr 15, 2024

maflcko added the label CI failed on Apr 15, 2024

stratospher commented at 4:56 pm on April 17, 2024: contributor

seen in #29898 too - https://cirrus-ci.com/task/5457627730149376?logs=ci#L3718

maflcko added the label Wallet on Apr 17, 2024

Randy808 commented at 2:55 pm on April 27, 2024: contributor

The relevant part of the test in wallet_backwards_compatibility.py creates tx3, calls bump fee to replace it in the wallet (creating tx4), and calls abandontransaction on tx3. Later on there’s an assertion to check if tx3 is marked as abandoned, but this is the call that sporadically fails.

The failure seems to occur because the TransactionAddedToMempool signal from the creation of tx3, and the TransactionRemovedFromMempool signal from the replacement of tx3 are handled after abandontransaction is called and overwrites the wallet’s version of the abandoned tx3.

In the logs posted in the first comment, we can see this in the timestamps (Enqueuing ... happens before abandontransaction is called, while the handling of the enqueued task occurs after):

 0node1 2024-04-03T22:38:25.781773Z [httpworker.0] [validationinterface.cpp:191] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=41ac814a7e27d942d5f8bd212d83090114dd3d28a2d264eeaa1a53873e727de6 wtxid=dafaa05b20990d2dbdb6488e2a9d405e5bcc4ae32b3c012557fb6c1ef9dd2c8c 
 1
 2 node1 2024-04-03T22:38:25.783955Z [httpworker.1] [validation.cpp:1165] [Finalize] [mempool] replacing tx 41ac814a7e27d942d5f8bd212d83090114dd3d28a2d264eeaa1a53873e727de6 (wtxid=dafaa05b20990d2dbdb6488e2a9d405e5bcc4ae32b3c012557fb6c1ef9dd2c8c) with 190fd4bd5fab876d2d6258952d487a98965d2092810f964b44af2ea02c5512e9 (wtxid=74725b97d0668fc3aea49d3322a9f4ed4daf7809c42cf06740b3ef8a12d7c9fa) for 0.00000706 additional fees, 0 delta bytes 
 3
 4node1 2024-04-03T22:38:25.783969Z [httpworker.1] [validationinterface.cpp:200] [TransactionRemovedFromMempool] [validation] Enqueuing TransactionRemovedFromMempool: txid=41ac814a7e27d942d5f8bd212d83090114dd3d28a2d264eeaa1a53873e727de6 wtxid=dafaa05b20990d2dbdb6488e2a9d405e5bcc4ae32b3c012557fb6c1ef9dd2c8c reason=replaced 
 5
 6node1 2024-04-03T22:38:25.785044Z [httpworker.2] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=abandontransaction user=__cookie__ 
 7
 8node1 2024-04-03T22:38:25.785369Z [scheduler] [validationinterface.cpp:191] [operator()] [validation] TransactionAddedToMempool: txid=41ac814a7e27d942d5f8bd212d83090114dd3d28a2d264eeaa1a53873e727de6 wtxid=dafaa05b20990d2dbdb6488e2a9d405e5bcc4ae32b3c012557fb6c1ef9dd2c8c 
 9
10node1 2024-04-03T22:38:25.794933Z [scheduler] [wallet/wallet.h:933] [WalletLogPrintf] [w1] AddToWallet 41ac814a7e27d942d5f8bd212d83090114dd3d28a2d264eeaa1a53873e727de6  update InMempool
11
12node1 2024-04-03T22:38:25.795430Z [scheduler] [validationinterface.cpp:200] [operator()] [validation] TransactionRemovedFromMempool: txid=41ac814a7e27d942d5f8bd212d83090114dd3d28a2d264eeaa1a53873e727de6 wtxid=dafaa05b20990d2dbdb6488e2a9d405e5bcc4ae32b3c012557fb6c1ef9dd2c8c reason=replaced

This can be fixed by calling self.sync_mempools() before node_master.abandontransaction(tx3_id), but I wanted to confirm whether overriding the abandoned status of the wallet transaction is expected behavior before tackling this.

The failure can be reproduced locally by wrapping callbacks.TransactionAddedToMempool and callbacks.TransactionRemovedFromMempool (in validationinterface.cpp) with a lambda introducing an UninterruptibleSleep(40ms), and calling self.sync_mempools() after node_master.abandontransaction(tx3_id) in wallet_backwards_compatibility.py

maflcko commented at 3:01 pm on April 27, 2024: member

If the transaction is eventually considered abandoned in all cases, then adding the sync_mempools (or I guess syncwithvalidationinterface would be enough) seems fine.

Randy808 commented at 4:17 am on April 28, 2024: contributor

Sounds good, I’ll add sync_mempools() to mitigate the immediate inconsistency observed with the abandontransaction call. I’ll mention the potential race conditions between the signals and wallet operations, but I’m thinking that could be treated as a separate issue.

maflcko commented at 9:30 am on April 29, 2024: member

The failure can be reproduced locally by wrapping callbacks.TransactionAddedToMempool and callbacks.TransactionRemovedFromMempool (in validationinterface.cpp) with a lambda introducing an UninterruptibleSleep(40ms), and calling self.sync_mempools() after node_master.abandontransaction(tx3_id) in wallet_backwards_compatibility.py

Can you produce a diff for this please, so that it can be applied locally by reviewers?

Randy808 commented at 11:31 pm on April 29, 2024: contributor

Here’s a commit with the referenced changes applied: https://github.com/Randy808/bitcoin/commit/f39144d808975c016c1a94022a2c4251950afb7d

Repro instructions after branch is built:

0# Pick a directory to put the previous releases in
1export PREVIOUS_RELEASES_DIR=<prev_releases_dir>
2test/get_previous_releases.py -b -t "$PREVIOUS_RELEASES_DIR"
3test/functional/wallet_backwards_compatibility.py

maflcko commented at 2:29 pm on July 19, 2024: member

https://cirrus-ci.com/task/5052912852795392?logs=ci#L3260

achow101 closed this on Dec 10, 2024

maflcko removed the label Tests on Dec 10, 2024

maflcko removed the label CI failed on Dec 10, 2024

maflcko commented at 9:40 pm on December 10, 2024: member

While the wallet bug is worked around in the test, it can still happen for real users. See #29982 (comment)

maflcko reopened this on Dec 10, 2024

pull[bot] referenced this in commit a582ee681c on Dec 10, 2024

intermittent issue in wallet_backwards_compatibility.py: line 245, in run_test assert txs[3][“abandoned”] AssertionError #29806