test: failure in wallet_resendwallettransactions.py #26071

https://cirrus-ci.com/task/5603470202896384?logs=ci#L2681

 test  2022-09-12T11:34:40.885000Z TestFramework (ERROR): JSONRPC error 
                                   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_resendwallettransactions.py", line 91, in run_test
                                       bumped = node.bumpfee(child_txid)
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/coverage.py", line 49, in __call__
                                       return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/authproxy.py", line 144, in __call__
                                       raise JSONRPCException(response['error'], status)
                                   test_framework.authproxy.JSONRPCException: Unable to create transaction. Fee exceeds maximum configured by user (e.g. -maxtxfee, maxfeerate) (-4)

I can reproduce locally and the actual issue is that the list of txs is of length 3, so it can never be equal to a list of length 2, regardless of its content.

To reproduce:

while ./test/functional/test_runner.py --tracerpc  -j 40  wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py wallet_resendwallettransactions.py ; do true ;done

Current diff to reproduce fastest:

diff --git a/test/functional/wallet_resendwallettransactions.py b/test/functional/wallet_resendwallettransactions.py
index 26df0841d8..0b8f4bf317 100755
--- a/test/functional/wallet_resendwallettransactions.py
+++ b/test/functional/wallet_resendwallettransactions.py
@@ -86,6 +86,7 @@ class ResendWalletTransactionsTest(BitcoinTestFramework):
         child_txid = node.send(outputs=[{addr: 0.5}], options={"inputs": [{"txid":txid, "vout":0}]})["txid"]
         while True:
             txids = node.listreceivedbyaddress(minconf=0, address_filter=addr)[0]["txids"]
+            assert_equal(len(txids), 2)
             if txids == [child_txid, txid]:
                 break
             bumped = node.bumpfee(child_txid)

Log:

2022-09-14T14:15:56.480000Z TestFramework (INFO): Chain of unconfirmed not-in-mempool txs are rebroadcast
-29-> send {"outputs": [{"bcrt1qv5q43yunpc7mjw73nje7nd0g66lpjts2xazdj0": 0.5}], "options": {"inputs": [{"txid": "8d6c948eec2b1fbe8362df36cefd5ca803e5e42ebf7f52538ef26331b831ffeb", "vout": 0}]}}
<-29- [0.000320] {"txid": "97d516151b92011f82a612bfea0b70149c617d5ea516196e76c1f599afc1a785", "complete": true}
-30-> listreceivedbyaddress {"minconf": 0, "address_filter": "bcrt1qv5q43yunpc7mjw73nje7nd0g66lpjts2xazdj0"}
<-30- [0.000386] [{"address": "bcrt1qv5q43yunpc7mjw73nje7nd0g66lpjts2xazdj0", "amount": "1.50000000", "confirmations": 0, "label": "", "txids": ["8d6c948eec2b1fbe8362df36cefd5ca803e5e42ebf7f52538ef26331b831ffeb", "97d516151b92011f82a612bfea0b70149c617d5ea516196e76c1f599afc1a785"]}]
-31-> bumpfee ["97d516151b92011f82a612bfea0b70149c617d5ea516196e76c1f599afc1a785"]
<-31- [0.000279] {"txid": "ca38cf9d48be32f7576155d796192ba635b46daf6ac077879ad6d21296d357b8", "origfee": "0.00002820", "fee": "0.00003526", "errors": []}
-32-> removeprunedfunds ["97d516151b92011f82a612bfea0b70149c617d5ea516196e76c1f599afc1a785"]
<-32- [0.000256] null
-33-> listreceivedbyaddress {"minconf": 0, "address_filter": "bcrt1qv5q43yunpc7mjw73nje7nd0g66lpjts2xazdj0"}
<-33- [0.000236] [{"address": "bcrt1qv5q43yunpc7mjw73nje7nd0g66lpjts2xazdj0", "amount": "1.50000000", "confirmations": 0, "label": "", "txids": ["8d6c948eec2b1fbe8362df36cefd5ca803e5e42ebf7f52538ef26331b831ffeb", "ca38cf9d48be32f7576155d796192ba635b46daf6ac077879ad6d21296d357b8"]}]
-34-> bumpfee ["ca38cf9d48be32f7576155d796192ba635b46daf6ac077879ad6d21296d357b8"]
<-34- [0.000250] {"txid": "7436a7a7ccc63bb79e19ba212bb768de1261523fd4481343234430e1de5916af", "origfee": "0.00003526", "fee": "0.00004232", "errors": []}
-35-> removeprunedfunds ["ca38cf9d48be32f7576155d796192ba635b46daf6ac077879ad6d21296d357b8"]
<-35- [0.000240] null
-36-> listreceivedbyaddress {"minconf": 0, "address_filter": "bcrt1qv5q43yunpc7mjw73nje7nd0g66lpjts2xazdj0"}
<-36- [0.000229] [{"address": "bcrt1qv5q43yunpc7mjw73nje7nd0g66lpjts2xazdj0", "amount": "2.00000000", "confirmations": 0, "label": "", "txids": ["7436a7a7ccc63bb79e19ba212bb768de1261523fd4481343234430e1de5916af", "8d6c948eec2b1fbe8362df36cefd5ca803e5e42ebf7f52538ef26331b831ffeb", "97d516151b92011f82a612bfea0b70149c617d5ea516196e76c1f599afc1a785"]}]
2022-09-14T14:15:56.500000Z TestFramework (ERROR): Assertion failed
    assert_equal(len(txids), 2)
AssertionError: not(3 == 2)

Nice, @MarcoFalke. Could reproduce it as well.

Ah nice! Why are there 3 transactions?

There shouldn't be 3 transactions. It looks like one of the child transactions that should have been removed was rebroadcast to the wallet?

The scheduler creates a copy of the transactions an re-submits it at any later point in time. See #https://github.com/bitcoin/bitcoin/pull/26091

See also https://github.com/bitcoin/bitcoin/pull/18840

The scheduler creates a copy of the transactions an re-submits it at any later point in time.

I'm trying to understand what this means, I thought that:

• at the end of bumpfee, the original tx is MarkReplaced(), making wtx.isUnconfirmed() false.
• when the scheduler calls MaybeResendWalletTxs(), it calls ResubmitWalletTransactions() which filters for isUnconfirmed()
• syncing with validation interface queue has wallet handle transactionRemovedFromMempool(), updating the original tx status as well. but this is also done in MarkReplaced()

Which part is incorrect? Is the filtering applied at a different time, e.g. when scheduled?

No, MarkReplaced does not wait for transactionRemovedFromMempool:

bool CWallet::MarkReplaced(const uint256& originalHash, const uint256& newHash)
{   
...
    // Refresh mempool status without waiting for transactionRemovedFromMempool
    RefreshMempoolStatus(wtx, chain());
...

So if the transactionRemovedFromMempool arrives at any future time (unknown), the copy of the transaction is re-added to the wallet.

~Ok I see my assumption of "the original tx is MarkReplaced(), making wtx.isUnconfirmed() false" is incorrect. When MarkReplaced() calls RefreshMempoolStatus(), it asks chain.isInMempool(wtx) which could still be true (?? not sure if this is right?), so the status remains unconfirmed and should be rebroadcast. The state is not correctly updated until RefreshMempoolStatus() is called for transactionRemovedFromMempool() (?).~ Edit: don't know chain.isInMempool() would return false

So if the transactionRemovedFromMempool arrives at any future time (unknown), the copy of the transaction is re-added to the wallet.

Sorry, I still don't understand how it can be "re-added to the wallet" this way? I thought it just calls RefreshMempoolStatus. Is that changing the state back to active somehow? https://github.com/bitcoin/bitcoin/blob/f523df1ee8661e0c4738694b9054952769bfff65/src/wallet/wallet.cpp#L1302-L1337

The only way that transactionRemovedFromMempool can add a transaction back into the wallet is if the removal reason is CONFLICT. Otherwise the transaction does not even exist in the wallet anymore as removeprunedfunds will delete it. It will not exist in mapWallet after removeprunedfunds.

Oh apologies, I meant transactionAddedToMempool. But the fix works in any case.

Ahhh okay, so it's re-added to the wallet when transactionAddedToMempool() for the original tx fires, calling AddToWalletIfInvolvingMe() and undoing the removeprunedfunds? That makes sense to me.

Unrelated to the test fix, the real question is if this is also considered a user-facing bug that should be fixed

Unrelated to the test fix, the real question is if this is also considered a user-facing bug that should be fixed

Unsure, I don't think a user would submit and then conflict a tx so quickly, but maybe?

Just wondering, is there a reason the wallet doesn't wait for validation interface to sync after bumpfee?

I don't see a reason, but Ryan may have reasons: #18840 (comment)