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

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

   https://cirrus-ci.com/task/5524545770094592?logs=ci#L3290
2. maflcko added the label Tests on Apr 15, 2024
3. maflcko added the label CI failed on Apr 15, 2024
4. 
   stratospher commented at 4:56 pm on April 17, 2024: contributor

   seen in #29898 too - https://cirrus-ci.com/task/5457627730149376?logs=ci#L3718
5. maflcko added the label Wallet on Apr 17, 2024
6. 
   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

7. 
   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.
8. 
   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.
9. 
   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?

10. 
    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
    

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

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

Contributors
maflcko stratospher Randy808

Labels
Wallet Tests CI failed