wallet_backup.py fails with AssertionError: not(50 == 0) [assert_equal(self.nodes[2].getbalance(), 0)]

[maflcko]

From https://cirrus-ci.com/task/5098379825905664?logs=ci#L3267

 node2 2022-07-20T16:54:37.082831Z [httpworker.0] [wallet/wallet.h:818] [WalletLogPrintf] [default wallet] Wallet file version = 10500, last client version = 239900 
 node2 2022-07-20T16:54:37.082858Z [httpworker.0] [wallet/wallet.h:818] [WalletLogPrintf] [default wallet] Keys: 0 plaintext, 0 encrypted, 0 w/ metadata, 0 total. Unknown wallet records: 0 
 node2 2022-07-20T16:54:37.363230Z [httpworker.0] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] keypool added 200 keys (100 internal), size=200 (100 internal) 
 node2 2022-07-20T16:54:37.372743Z [httpworker.0] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] LegacyScriptPubKeyMan::NewKeyPool rewrote keypool 
 node2 2022-07-20T16:54:37.374228Z [httpworker.0] [wallet/wallet.h:818] [WalletLogPrintf] [default wallet] Wallet completed loading in             301ms 
 node2 2022-07-20T16:54:37.374283Z [httpworker.0] [wallet/wallet.h:818] [WalletLogPrintf] [default wallet] setKeyPool.size() = 200 
 node2 2022-07-20T16:54:37.374293Z [httpworker.0] [wallet/wallet.h:818] [WalletLogPrintf] [default wallet] mapWallet.size() = 0 
 node2 2022-07-20T16:54:37.374302Z [httpworker.0] [wallet/wallet.h:818] [WalletLogPrintf] [default wallet] m_address_book.size() = 0 
 node2 2022-07-20T16:54:37.375129Z [http] [httpserver.cpp:241] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43832 
 node2 2022-07-20T16:54:37.375178Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getwalletinfo user=__cookie__ 
 node2 2022-07-20T16:54:37.375852Z [http] [httpserver.cpp:241] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43832 
 node2 2022-07-20T16:54:37.375896Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=importprivkey user=__cookie__ 
 node2 2022-07-20T16:54:37.384691Z [httpworker.3] [wallet/scriptpubkeyman.h:248] [WalletLogPrintf] [default wallet] Already have script 00144ff785b8221dc206314ca12e65773a876dff30ff, skipping 
 node2 2022-07-20T16:54:37.385674Z [httpworker.3] [wallet/wallet.h:818] [WalletLogPrintf] [default wallet] RescanFromTime: Rescanning last 215 blocks 
 node2 2022-07-20T16:54:37.385688Z [httpworker.3] [wallet/wallet.h:818] [WalletLogPrintf] [default wallet] Rescan started from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206... 
 node2 2022-07-20T16:54:37.386000Z [httpworker.3] [wallet/wallet.h:818] [WalletLogPrintf] [default wallet] AddToWallet 4cddeee95a635bbf1efa02cd90f11f3385981ba1461309d7e4787e8f3c95d2df  new 
 node2 2022-07-20T16:54:37.391170Z [httpworker.3] [wallet/wallet.h:818] [WalletLogPrintf] [default wallet] Scanning current mempool transactions. 
 node2 2022-07-20T16:54:37.391187Z [httpworker.3] [wallet/wallet.h:818] [WalletLogPrintf] [default wallet] Rescan completed in               5ms 
 node0 2022-07-20T16:54:37.391944Z [http] [httpserver.cpp:241] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:42220 
 node0 2022-07-20T16:54:37.391992Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbalance user=__cookie__ 
 node1 2022-07-20T16:54:37.392518Z [http] [httpserver.cpp:241] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:34582 
 node1 2022-07-20T16:54:37.392564Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbalance user=__cookie__ 
 test  2022-07-20T16:54:37.393000Z 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_backup.py", line 234, in run_test
                                       assert_equal(self.nodes[2].getbalance(), 0)
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/util.py", line 51, in assert_equal
                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
                                   AssertionError: not(50.00000000 == 0)

[achow101]

Is this still an issue?

[maflcko]

https://cirrus-ci.com/task/4706454958505984?logs=ci#L3277

[maflcko]

https://cirrus-ci.com/task/5585512359002112?logs=ci#L3353

[maflcko]

https://cirrus-ci.com/task/5620574878171136?logs=ci#L3154

[fanquake]

https://cirrus-ci.com/task/6032521255714816?logs=ci#L3307

[theStack]

https://cirrus-ci.com/task/6546470984220672?logs=ci#L3298

[furszy]

The issue is inside the init_three() function, where we call the framework init_wallet().
The test expects the newly created wallets to be empty. But they might not be empty because init_wallet() by default imports the coinbase privkey (which is not what we want on this test, because we are testing the wallet's importwallet..).
So, the race arises when other peers provide the chain prior to the wallet initialization.

will cook a quick PR for it.

[furszy]

#28325 should hopefully fix this.