test: Fix wallet_balance intermittent issue #25915

MarcoFalke commented at 11:01 AM on August 24, 2022: member

Diff to reproduce:

index d2ed97ca76..25cc2d5734 100755
--- a/test/functional/wallet_balance.py
+++ b/test/functional/wallet_balance.py
@@ -265,7 +265,7 @@ class WalletTest(BitcoinTestFramework):
         self.nodes[0].invalidateblock(block_reorg)
         self.nodes[1].invalidateblock(block_reorg)
         assert_equal(self.nodes[0].getbalance(minconf=0), 0)  # wallet txs not in the mempool are untrusted
-        self.generatetoaddress(self.nodes[0], 1, ADDRESS_WATCHONLY, sync_fun=self.no_op)
+        self.generatetoaddress(self.nodes[0], 1, ADDRESS_WATCHONLY)
         assert_equal(self.nodes[0].getbalance(minconf=0), 0)  # wallet txs not in the mempool are untrusted
 
         # Now confirm tx_orig

Example in CI:

 test  2022-08-24T10:09:22.486000Z 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_balance.py", line 269, in run_test
                                       assert_equal(self.nodes[0].getbalance(minconf=0), 0)  # wallet txs not in the mempool are untrusted
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/util.py", line 56, in assert_equal
                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
                                   AssertionError: not(98.85983340 == 0)

https://cirrus-ci.com/task/4981266251513856?logs=ci#L3269

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

fanquake added the label Tests on Aug 24, 2022

brunoerg approved

brunoerg commented at 7:10 PM on August 26, 2022: contributor

ACK 69b33dc437c0c34cb057f1b093c1b665e064afc4

I was able to reproduce the bug and checked the fix.

furszy commented at 7:23 PM on August 26, 2022: member

If possible, would be good to add a text explaining why the stop/start calls are fixing the issue. Guessing that has to do with nodes sync.

MarcoFalke force-pushed on Aug 27, 2022

MarcoFalke commented at 10:48 AM on August 27, 2022: member

If possible, would be good to add a text explaining why the stop/start calls are fixing the issue. Guessing that has to do with nodes sync.

The restart (or stop/start) is part of the original test to empty the mempool. The test can be reworked to just use generateblock(tx_orig) instead of the restart, but that can be done in a follow-up. I'll keep the changes here to only fixing the intermittent issue.

I've pushed an alternative fix that simply removes the redundant (and failing) check.

furszy commented at 1:34 PM on August 27, 2022: member

Hmm, under the hood, nodes are syncing data and the tx ends up in the mempool when we are expecting to not have it there (thus why removing the sync_fun=self.no_op makes it fail all the time, you force nodes to sync-up).

Probably, the simplest path to fix the unexpected sync should be something like:

diff --git a/test/functional/wallet_balance.py b/test/functional/wallet_balance.py
--- a/test/functional/wallet_balance.py	(revision a7c7f6d354304521d3a2de04eb57fc74be52b68a)
+++ b/test/functional/wallet_balance.py	(date 1661606543724)
@@ -262,6 +262,7 @@
         assert_equal(self.nodes[0].getbalance(minconf=0), total_amount)
 
         self.log.info('Put txs back into mempool of node 1 (not node 0)')
+        self.disconnect_nodes(0, 1)
         self.nodes[0].invalidateblock(block_reorg)
         self.nodes[1].invalidateblock(block_reorg)
         assert_equal(self.nodes[0].getbalance(minconf=0), 0)  # wallet txs not in the mempool are untrusted

(nodes are, few lines below, re-connected anyway)

note: with this change, cannot remove the sync_fun=self.no_op from the generatetoaddress call as any sync attempt between nodes will fail (they are not longer connected).

test: Fix wallet_balance intermittent issue

Fix it by removing a duplicate balance check on the same node.

fae5bd9200

MarcoFalke force-pushed on Aug 27, 2022

MarcoFalke commented at 3:27 PM on August 27, 2022: member

Probably, the simplest path to fix the unexpected sync should be something like:

Yes, that should also work. Though, the second balance check is redundant and not needed, so I think removing it is better than accommodating it.

w0xlt approved

w0xlt commented at 7:47 PM on August 29, 2022: contributor

ACK https://github.com/bitcoin/bitcoin/pull/25915/commits/fae5bd920007c33de0b794bf2b2d698bfccc12ee

furszy commented at 9:07 PM on August 29, 2022: member

Probably, the simplest path to fix the unexpected sync should be something like:

Yes, that should also work. Though, the second balance check is redundant and not needed, so I think removing it is better than accommodating it.

Yeah but with the removal, we are still doubtful over the intermittency cause.

Up until now, what we know is that the intermittency is related to node1 syncing the mempool with node0. Which means that after generating the block, node0 accepts a tx that was previously rejected (due be "the third descendant of the tx created above" ).

Note, I'm not blocking this, can move forward as is. Just saying that would be nice to describe the intermittency cause in-detail. I think that, sooner or later, the issue can pop-up again in another test case.

fanquake requested review from achow101 on Aug 31, 2022

achow101 commented at 3:19 PM on August 31, 2022: member

ACK fae5bd920007c33de0b794bf2b2d698bfccc12ee

achow101 merged this on Aug 31, 2022

achow101 closed this on Aug 31, 2022

MarcoFalke deleted the branch on Sep 1, 2022

MarcoFalke commented at 8:34 AM on September 1, 2022: member

Probably, the simplest path to fix the unexpected sync should be something like:

Yes, that should also work. Though, the second balance check is redundant and not needed, so I think removing it is better than accommodating it.

Yeah but with the removal, we are still doubtful over the intermittency cause.

Up until now, what we know is that the intermittency is related to node1 syncing the mempool with node0. Which means that after generating the block, node0 accepts a tx that was previously rejected (due be "the third descendant of the tx created above" ).

Note, I'm not blocking this, can move forward as is. Just saying that would be nice to describe the intermittency cause in-detail. I think that, sooner or later, the issue can pop-up again in another test case.

To describe the steps as I understand them:

invalidateblock usually puts the txs in the block back into the mempool, however for node 0 it does not because it has a strict descendant limit of 3.
After generatetoaddress the tx will be put into the mempool again. The reason the test passed most of the time is by pure chance, because apparently the getbalance call was faster than tx-trickle.

The fix in this pull removes the getbalance, because:

It is wrong (only passed most of the time by pure chance)
It is redundant

furszy commented at 8:57 PM on September 1, 2022: member

To describe the steps as I understand them:

invalidateblock usually puts the txs in the block back into the mempool, however for node 0 it does not because it has a strict descendant limit of 3. After generatetoaddress the tx will be put into the mempool again. The reason the test passed most of the time is by pure chance, because apparently the getbalance call was faster than tx-trickle. The fix in this pull removes the getbalance, because:

It is wrong (only passed most of the time by pure chance) It is redundant

Ok thanks Marko, now it make sense. I was missing the strict descendant limit. Then this started happening more often now due #25865 that whitelisted peers by default. All good.

sidhujag referenced this in commit 272c6f74b4 on Sep 1, 2022

bitcoin locked this on Sep 1, 2023