test: Fix intermittent sync_blocks failures

Author: MarcoFalke

test/functional/feature_loadblock.py

@@ -16,10 +16,8 @@
 import tempfile
 import urllib
 
-from test_framework.test_framework import (
-    BitcoinTestFramework,
-)
-from test_framework.util import assert_equal, wait_until
+from test_framework.test_framework import BitcoinTestFramework
+from test_framework.util import assert_equal
 
 
 class LoadblockTest(BitcoinTestFramework):
@@ -75,7 +73,7 @@ def run_test(self):
         self.log.info("Restart second, unsynced node with bootstrap file")
         self.stop_node(1)
         self.start_node(1, ["-loadblock=" + bootstrap_file])
-        wait_until(lambda: self.nodes[1].getblockcount() == 100)
+        assert_equal(self.nodes[1].getblockcount(), 100)  # start_node is blocking on all block files being imported
 
         assert_equal(self.nodes[1].getblockchaininfo()['blocks'], 100)
         assert_equal(self.nodes[0].getbestblockhash(), self.nodes[1].getbestblockhash())

test/functional/feature_reindex.py

@@ -10,10 +10,10 @@
 """
 
 from test_framework.test_framework import BitcoinTestFramework
-from test_framework.util import wait_until
+from test_framework.util import assert_equal
 
-class ReindexTest(BitcoinTestFramework):
 
+class ReindexTest(BitcoinTestFramework):
     def set_test_params(self):
         self.setup_clean_chain = True
         self.num_nodes = 1
@@ -24,7 +24,7 @@ def reindex(self, justchainstate=False):
         self.stop_nodes()
         extra_args = [["-reindex-chainstate" if justchainstate else "-reindex"]]
         self.start_nodes(extra_args)
-        wait_until(lambda: self.nodes[0].getblockcount() == blockcount)
+        assert_equal(self.nodes[0].getblockcount(), blockcount)  # start_node is blocking on reindex
         self.log.info("Success")
 
     def run_test(self):

test/functional/mempool_persist.py

@@ -95,8 +95,8 @@ def run_test(self):
         self.start_node(1, extra_args=["-persistmempool=0"])
         self.start_node(0)
         self.start_node(2)
-        wait_until(lambda: self.nodes[0].getmempoolinfo()["loaded"], timeout=1)
-        wait_until(lambda: self.nodes[2].getmempoolinfo()["loaded"], timeout=1)
+        assert self.nodes[0].getmempoolinfo()["loaded"]  # start_node is blocking on the mempool being loaded
+        assert self.nodes[2].getmempoolinfo()["loaded"]
         assert_equal(len(self.nodes[0].getrawmempool()), 6)
         assert_equal(len(self.nodes[2].getrawmempool()), 5)
         # The others have loaded their mempool. If node_1 loaded anything, we'd probably notice by now:
@@ -117,13 +117,13 @@ def run_test(self):
         self.log.debug("Stop-start node0 with -persistmempool=0. Verify that it doesn't load its mempool.dat file.")
         self.stop_nodes()
         self.start_node(0, extra_args=["-persistmempool=0", "-disablewallet"])
-        wait_until(lambda: self.nodes[0].getmempoolinfo()["loaded"])
+        assert self.nodes[0].getmempoolinfo()["loaded"]
         assert_equal(len(self.nodes[0].getrawmempool()), 0)
 
         self.log.debug("Stop-start node0. Verify that it has the transactions in its mempool.")
         self.stop_nodes()
         self.start_node(0)
-        wait_until(lambda: self.nodes[0].getmempoolinfo()["loaded"])
+        assert self.nodes[0].getmempoolinfo()["loaded"]
         assert_equal(len(self.nodes[0].getrawmempool()), 6)
 
         mempooldat0 = os.path.join(self.nodes[0].datadir, self.chain, 'mempool.dat')
@@ -137,7 +137,7 @@ def run_test(self):
         os.rename(mempooldat0, mempooldat1)
         self.stop_nodes()
         self.start_node(1, extra_args=[])
-        wait_until(lambda: self.nodes[1].getmempoolinfo()["loaded"])
+        assert self.nodes[1].getmempoolinfo()["loaded"]
         assert_equal(len(self.nodes[1].getrawmempool()), 6)
 
         self.log.debug("Prevent bitcoind from writing mempool.dat to disk. Verify that `savemempool` fails")

test/functional/test_framework/test_node.py

@@ -110,7 +110,7 @@ def __init__(self, i, datadir, *, chain, rpchost, timewait, factor, bitcoind, bi
                          "--gen-suppressions=all", "--exit-on-first-error=yes",
                          "--error-exitcode=1", "--quiet"] + self.args
 
-        if self.version is None or self.version >= 190000:
+        if self.version_is_at_least(190000):
             self.args.append("-logthreadnames")
 
         self.cli = TestNodeCLI(bitcoin_cli, self.datadir)
@@ -222,6 +222,27 @@ def wait_for_rpc_connection(self):
                 rpc = get_rpc_proxy(rpc_url(self.datadir, self.index, self.chain, self.rpchost), self.index, timeout=self.rpc_timeout, coveragedir=self.coverage_dir)
                 rpc.getblockcount()
                 # If the call to getblockcount() succeeds then the RPC connection is up
+                if self.version_is_at_least(190000):
+                    # getmempoolinfo.loaded is available since commit
+                    # bb8ae2c (version 0.19.0)
+                    wait_until(lambda: rpc.getmempoolinfo()['loaded'])
+                    # Wait for the node to finish reindex, block import, and
+                    # loading the mempool. Usually importing happens fast or
+                    # even "immediate" when the node is started. However, there
+                    # is no guarantee and sometimes ThreadImport might finish
+                    # later. This is going to cause intermittent test failures,
+                    # because generally the tests assume the node is fully
+                    # ready after being started.
+                    #
+                    # For example, the node will reject block messages from p2p
+                    # when it is still importing with the error "Unexpected
+                    # block message received"
+                    #
+                    # The wait is done here to make tests as robust as possible
+                    # and prevent racy tests and intermittent failures as much
+                    # as possible. Some tests might not need this, but the
+                    # overhead is trivial, and the added gurantees are worth
+                    # the minimal performance cost.
                 self.log.debug("RPC successfully started")
                 if self.use_cli:
                     return
@@ -274,14 +295,17 @@ def get_wallet_rpc(self, wallet_name):
             wallet_path = "wallet/{}".format(urllib.parse.quote(wallet_name))
             return RPCOverloadWrapper(self.rpc / wallet_path, descriptors=self.descriptors)
 
+    def version_is_at_least(self, ver):
+        return self.version is None or self.version >= ver
+
     def stop_node(self, expected_stderr='', wait=0):
         """Stop the node."""
         if not self.running:
             return
         self.log.debug("Stopping node")
         try:
             # Do not use wait argument when testing older nodes, e.g. in feature_backwards_compatibility.py
-            if self.version is None or self.version >= 180000:
+            if self.version_is_at_least(180000):
                 self.stop(wait=wait)
             else:
                 self.stop()

test/functional/wallet_abandonconflict.py

@@ -18,7 +18,6 @@
     assert_raises_rpc_error,
     connect_nodes,
     disconnect_nodes,
-    wait_until,
 )
 
 
@@ -98,7 +97,7 @@ def run_test(self):
         # TODO: redo with eviction
         self.stop_node(0)
         self.start_node(0, extra_args=["-minrelaytxfee=0.0001"])
-        wait_until(lambda: self.nodes[0].getmempoolinfo()['loaded'])
+        assert self.nodes[0].getmempoolinfo()['loaded']
 
         # Verify txs no longer in either node's mempool
         assert_equal(len(self.nodes[0].getrawmempool()), 0)
@@ -126,7 +125,7 @@ def run_test(self):
         # Verify that even with a low min relay fee, the tx is not reaccepted from wallet on startup once abandoned
         self.stop_node(0)
         self.start_node(0, extra_args=["-minrelaytxfee=0.00001"])
-        wait_until(lambda: self.nodes[0].getmempoolinfo()['loaded'])
+        assert self.nodes[0].getmempoolinfo()['loaded']
 
         assert_equal(len(self.nodes[0].getrawmempool()), 0)
         assert_equal(self.nodes[0].getbalance(), balance)
@@ -148,7 +147,7 @@ def run_test(self):
         # Remove using high relay fee again
         self.stop_node(0)
         self.start_node(0, extra_args=["-minrelaytxfee=0.0001"])
-        wait_until(lambda: self.nodes[0].getmempoolinfo()['loaded'])
+        assert self.nodes[0].getmempoolinfo()['loaded']
         assert_equal(len(self.nodes[0].getrawmempool()), 0)
         newbalance = self.nodes[0].getbalance()
         assert_equal(newbalance, balance - Decimal("24.9996"))

test/functional/wallet_basic.py

@@ -4,7 +4,6 @@
 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
 """Test the wallet."""
 from decimal import Decimal
-import time
 
 from test_framework.test_framework import BitcoinTestFramework
 from test_framework.util import (
@@ -466,12 +465,8 @@ def run_test(self):
         extra_args = ["-walletrejectlongchains", "-limitancestorcount=" + str(2 * chainlimit)]
         self.start_node(0, extra_args=extra_args)
 
-        # wait for loadmempool
-        timeout = 10
-        while (timeout > 0 and len(self.nodes[0].getrawmempool()) < chainlimit * 2):
-            time.sleep(0.5)
-            timeout -= 0.5
-        assert_equal(len(self.nodes[0].getrawmempool()), chainlimit * 2)
+        # wait until the wallet has submitted all transactions to the mempool
+        wait_until(lambda: len(self.nodes[0].getrawmempool()) == chainlimit * 2)
 
         node0_balance = self.nodes[0].getbalance()
         # With walletrejectlongchains we will not create the tx and store it in our wallet.