Merge #7241: test: fix intermittent IS lock timeouts by syncing mempools before waiting

d8ac781 test: fix additional IS lock sync sites that passed nodes=[self.nodes[0]] (UdjinM6)
c79c2d9 refactor: improve is-waiting helper by including mempool sync bump of mocktime (Konstantin Akimov)
a0e4260 test: address review — fix additional IS lock sync sites and remove dead code (UdjinM6)
62d47f7 test: fix intermittent IS lock timeouts by syncing mempools before waiting (UdjinM6)

Pull request description:

  ## Issue being fixed or feature implemented
  When mocktime is set, `NodeClock::now()` returns a frozen value. After `bump_mocktime()`, the trickle relay timer fires once, then `m_next_inv_send_time` is set ahead of the frozen clock and never fires again. If a TX inv misses that single relay window, it stays stuck in the sender's mempool indefinitely — regardless of real-time elapsed.

  ## What was done?
  Add `sync_mempools()` after `bump_mocktime()` in all test paths that send a TX and immediately wait for an IS lock. This ensures all nodes (especially MNs that need to sign) have the TX before polling begins.

  ## How Has This Been Tested?
  Run tests, should no longer fail in these parts

  ## Breaking Changes
  n/a

  ## Checklist:
  - [ ] I have performed a self-review of my own code
  - [ ] I have commented my code, particularly in hard-to-understand areas
  - [ ] I have added or updated relevant unit/integration/functional/e2e tests
  - [ ] I have made corresponding changes to the documentation
  - [ ] I have assigned this pull request to a milestone _(for repository code-owners and collaborators only)_

ACKs for top commit:
  PastaPastaPasta:
    utACK d8ac781
  knst:
    utACK d8ac781

Tree-SHA512: 44201c2afcbea4c0a61e96ad2217c8beae9bc54c80c5c240c74a47af4d533ccf87ec0e2447cc45d9470ec818dcd56595884c686c28f2751ff0ac24c5ca926081

Author: PastaPastaPasta

test/functional/feature_asset_locks.py

@@ -391,9 +391,7 @@ def test_asset_unlocks(self, node_wallet, node, pubkey):
 
         assert_equal(node.getmempoolentry(txid)['fees']['base'], Decimal("0.0007"))
         is_id = node_wallet.sendtoaddress(node_wallet.getnewaddress(), 1)
-        self.bump_mocktime(30)
-        for node in self.nodes:
-            self.wait_for_instantlock(is_id, node)
+        self.wait_for_instantlock(is_id)
 
         rawtx = node.getrawtransaction(txid, 1)
         rawtx_is = node.getrawtransaction(is_id, 1)

test/functional/feature_llmq_is_cl_conflicts.py

@@ -99,11 +99,7 @@ def test_chainlock_overrides_islock(self, test_block_conflict, mine_confllicting
         rawtx4_txid = self.nodes[0].sendrawtransaction(rawtx4)
 
         # wait for transactions to propagate
-        self.bump_mocktime(30)
-        self.sync_mempools()
-        for node in self.nodes:
-            self.wait_for_instantlock(rawtx1_txid, node)
-            self.wait_for_instantlock(rawtx4_txid, node)
+        self.wait_for_instantlock(rawtx1_txid, rawtx4_txid)
 
         block = create_block_with_mnpayments(self.mninfo, self.nodes[0], [rawtx2_obj])
         if test_block_conflict:
@@ -160,10 +156,7 @@ def test_chainlock_overrides_islock(self, test_block_conflict, mine_confllicting
         rawtx5 = self.nodes[0].signrawtransactionwithwallet(rawtx5)['hex']
         rawtx5_txid = self.nodes[0].sendrawtransaction(rawtx5)
         # wait for the transaction to propagate
-        self.bump_mocktime(30)
-        self.sync_mempools()
-        for node in self.nodes:
-            self.wait_for_instantlock(rawtx5_txid, node)
+        self.wait_for_instantlock(rawtx5_txid)
 
         if mine_confllicting:
             # Lets verify that the ISLOCKs got pruned and conflicting txes were mined but never confirmed
@@ -243,17 +236,15 @@ def test_chainlock_overrides_islock_overrides_nonchainlock(self):
         # Should drop tx1 and accept tx2 because there is an isdlock waiting for it
         self.nodes[0].sendrawtransaction(rawtx2)
         # bump mocktime to force tx relay
-        self.bump_mocktime(60)
-        for node in self.nodes:
-            self.wait_for_instantlock(rawtx2_txid, node)
+        self.wait_for_instantlock(rawtx2_txid)
 
         # Should not allow competing txes now
         assert_raises_rpc_error(-26, "tx-txlock-conflict", self.nodes[0].sendrawtransaction, rawtx1)
 
         islock_tip = self.generate(self.nodes[0], 1)[0]
 
+        self.wait_for_instantlock(rawtx2_txid, skip_sync=True)
         for node in self.nodes:
-            self.wait_for_instantlock(rawtx2_txid, node)
             assert_equal(node.getrawtransaction(rawtx2_txid, True)['confirmations'], 1)
             assert_equal(node.getbestblockhash(), islock_tip)
 

test/functional/feature_llmq_is_retroactive.py

@@ -35,16 +35,6 @@ def sleep_and_assert_no_instantlock(self, txid, node, sleep=5):
         time.sleep(sleep)
         self.assert_no_instantlock(txid, node)
 
-    # random delay before tx is actually send by network could take up to 30 seconds
-    def wait_for_tx(self, txid, node, expected=True, timeout=60):
-        def check_tx():
-            try:
-                return node.getrawtransaction(txid)
-            except Exception:
-                return False
-        if self.wait_until(check_tx, timeout=timeout, do_assert=expected) and not expected:
-            raise AssertionError("waiting unexpectedly succeeded")
-
     def create_fund_sign_tx(self):
         rawtx = self.nodes[0].createrawtransaction([], {self.nodes[0].getnewaddress(): 1})
         rawtx = self.nodes[0].fundrawtransaction(rawtx)['hex']
@@ -67,14 +57,15 @@ def run_test(self):
         # 3 nodes should be enough to create an IS lock even if nodes 4 and 5 (which have no tx itself)
         # are the only "neighbours" in intra-quorum connections for one of them.
         self.bump_mocktime(30)
+        self.sync_mempools(self.nodes[:3])
         self.sleep_and_assert_no_instantlock(txid, self.nodes[0])
         # Have to disable ChainLocks to avoid signing a block with a "safe" tx too early
         self.nodes[0].sporkupdate("SPORK_19_CHAINLOCKS_ENABLED", 4000000000)
         self.wait_for_sporks_same()
         # We have to wait in order to include tx in block
         self.bump_mocktime(10 * 60 + 1)
         block = self.generate(self.nodes[0], 1, sync_fun=self.no_op)[0]
-        self.wait_for_instantlock(txid, self.nodes[0])
+        self.wait_for_instantlock(txid, nodes=[self.nodes[0]], skip_sync=True)
         self.nodes[0].sporkupdate("SPORK_19_CHAINLOCKS_ENABLED", 0)
         self.wait_for_sporks_same()
         self.wait_for_chainlocked_block_all_nodes(block)
@@ -87,19 +78,17 @@ def run_test(self):
         txid = self.nodes[0].sendtoaddress(self.nodes[0].getnewaddress(), 1)
         # 3 nodes should be enough to create an IS lock even if nodes 4 and 5 (which have no tx itself)
         # are the only "neighbours" in intra-quorum connections for one of them.
-        self.bump_mocktime(30)
-        self.wait_for_instantlock(txid, self.nodes[0])
+        self.wait_for_instantlock(txid, nodes=self.nodes[:3])
         block = self.generate(self.nodes[0], 1, sync_fun=self.no_op)[0]
         self.wait_for_chainlocked_block_all_nodes(block)
 
         self.log.info("testing normal signing with partially known TX")
         self.isolate_node(3)
         txid = self.nodes[0].sendtoaddress(self.nodes[0].getnewaddress(), 1)
-        # Make sure nodes 1 and 2 received the TX before we continue,
+        # Make sure connected nodes received the TX before we continue,
         # otherwise it might announce the TX to node 3 when reconnecting
         self.bump_mocktime(30)
-        self.wait_for_tx(txid, self.nodes[1])
-        self.wait_for_tx(txid, self.nodes[2])
+        self.sync_mempools(self.nodes[:3])
         self.reconnect_isolated_node(3, 0)
         # Make sure nodes actually try re-connecting quorum connections
         self.bump_mocktime(30)
@@ -110,7 +99,7 @@ def run_test(self):
         self.nodes[3].sendrawtransaction(self.nodes[0].getrawtransaction(txid))
         # node 3 should vote on a tx now since it became aware of it via sendrawtransaction
         # and this should be enough to complete an IS lock
-        self.wait_for_instantlock(txid, self.nodes[0])
+        self.wait_for_instantlock(txid, nodes=[self.nodes[0]], skip_sync=True)
 
         self.log.info("testing retroactive signing with unknown TX")
         self.isolate_node(3)
@@ -126,11 +115,10 @@ def run_test(self):
         self.log.info("testing retroactive signing with partially known TX")
         self.isolate_node(3)
         txid = self.nodes[0].sendtoaddress(self.nodes[0].getnewaddress(), 1)
-        # Make sure nodes 1 and 2 received the TX before we continue,
+        # Make sure connected nodes received the TX before we continue,
         # otherwise it might announce the TX to node 3 when reconnecting
         self.bump_mocktime(30)
-        self.wait_for_tx(txid, self.nodes[1])
-        self.wait_for_tx(txid, self.nodes[2])
+        self.sync_mempools(self.nodes[:3])
         self.reconnect_isolated_node(3, 0)
         # Make sure nodes actually try re-connecting quorum connections
         self.bump_mocktime(30)
@@ -159,10 +147,9 @@ def test_session_timeout(self, do_cycle_llmqs):
         rawtx_1 = self.create_fund_sign_tx()
         txid_single_node = self.nodes[3].sendrawtransaction(rawtx_1)
 
-        # Make sure nodes 1 and 2 received the TX before we continue
+        # Make sure connected nodes received the TX before we continue
         self.bump_mocktime(30)
-        self.wait_for_tx(txid_all_nodes, self.nodes[1])
-        self.wait_for_tx(txid_all_nodes, self.nodes[2])
+        self.sync_mempools(self.nodes[:3])
         # Make sure signing is done on nodes 1 and 2 (it's async)
         time.sleep(5)
         # Make the signing session for the IS lock timeout on nodes 1-3
@@ -174,10 +161,9 @@ def test_session_timeout(self, do_cycle_llmqs):
         self.wait_for_mnauth(self.nodes[3], 2)
 
         self.nodes[0].sendrawtransaction(rawtx_1)
-        # Make sure nodes 1 and 2 received the TX
+        # Make sure connected nodes received the TX
         self.bump_mocktime(30)
-        self.wait_for_tx(txid_single_node, self.nodes[1])
-        self.wait_for_tx(txid_single_node, self.nodes[2])
+        self.sync_mempools(self.nodes[:3])
         self.bump_mocktime(30)
 
         # Make sure signing is done on nodes 1 and 2 (it's async)

test/functional/feature_llmq_singlenode.py

@@ -106,8 +106,7 @@ def run_test(self):
 
         self.log.info("Send funds and wait InstantSend lock")
         txid = self.nodes[0].sendtoaddress(self.nodes[0].getnewaddress(), 1)
-        self.bump_mocktime(30)
-        self.wait_for_instantlock(txid, self.nodes[0])
+        self.wait_for_instantlock(txid)
 
         self.log.info("Test various options to sign messages with nodes")
         recsig_time = self.mocktime
@@ -184,9 +183,8 @@ def run_test(self):
         self.log.info(f"Chainlock on block: {block_hash} is expecting")
         self.wait_for_best_chainlock(self.nodes[0], block_hash)
         txid = self.nodes[0].sendtoaddress(self.nodes[0].getnewaddress(), 1)
-        self.bump_mocktime(30)
         self.log.info(f"InstantSend lock on tx: {txid} is expecting")
-        self.wait_for_instantlock(txid, self.nodes[0])
+        self.wait_for_instantlock(txid)
 
 
 if __name__ == '__main__':

test/functional/feature_notifications.py

@@ -139,8 +139,7 @@ def run_test(self):
             tx_count = 10
             for _ in range(tx_count):
                 txid = self.nodes[0].sendtoaddress(self.nodes[1].getnewaddress(), 1)
-                self.bump_mocktime(30)
-                self.wait_for_instantlock(txid, self.nodes[0])
+                self.wait_for_instantlock(txid)
 
             # wait at most 10 seconds for expected number of files before reading the content
             self.bump_mocktime(30)

test/functional/interface_zmq_dash.py

@@ -296,8 +296,7 @@ def test_instantsend_publishers(self):
         assert_equal(['None'], self.nodes[0].getislocks([rpc_raw_tx_1['txid']]))
         # Send the first transaction and wait for the InstantLock
         rpc_raw_tx_1_hash = self.nodes[0].sendrawtransaction(rpc_raw_tx_1['hex'])
-        self.bump_mocktime(30)
-        self.wait_for_instantlock(rpc_raw_tx_1_hash, self.nodes[0])
+        self.wait_for_instantlock(rpc_raw_tx_1_hash)
         # Validate hashtxlock
         zmq_tx_lock_hash = self.subscribers[ZMQPublisher.hash_tx_lock].receive().read(32).hex()
         assert_equal(zmq_tx_lock_hash, rpc_raw_tx_1['txid'])
@@ -349,8 +348,7 @@ def test_instantsend_publishers(self):
             pass
         # Now send the tx itself
         self.test_node.send_tx(from_hex(msg_tx(),rpc_raw_tx_3['hex']))
-        self.bump_mocktime(30)
-        self.wait_for_instantlock(rpc_raw_tx_3['txid'], self.nodes[0])
+        self.wait_for_instantlock(rpc_raw_tx_3['txid'])
         # Validate hashtxlock
         zmq_tx_lock_hash = self.subscribers[ZMQPublisher.hash_tx_lock].receive().read(32).hex()
         assert_equal(zmq_tx_lock_hash, rpc_raw_tx_3['txid'])
@@ -383,8 +381,7 @@ def test_governance_publishers(self):
         }
         proposal_hex = ''.join(format(x, '02x') for x in json.dumps(proposal_data).encode())
         collateral = self.nodes[0].gobject("prepare", "0", proposal_rev, proposal_time, proposal_hex)
-        self.bump_mocktime(30)
-        self.wait_for_instantlock(collateral, self.nodes[0])
+        self.wait_for_instantlock(collateral)
         self.generate(self.nodes[0], 6, sync_fun=lambda: self.sync_blocks())
         rpc_proposal_hash = self.nodes[0].gobject("submit", "0", proposal_rev, proposal_time, proposal_hex, collateral)
         # Validate hashgovernanceobject

test/functional/p2p_instantsend.py

@@ -46,9 +46,7 @@ def test_block_doublespend(self):
         # feed the sender with some balance
         sender_addr = sender.getnewaddress()
         is_id = self.nodes[0].sendtoaddress(sender_addr, 1)
-        self.bump_mocktime(30)
-        for node in self.nodes:
-            self.wait_for_instantlock(is_id, node)
+        self.wait_for_instantlock(is_id)
         self.generate(self.nodes[0], 2)
 
         # create doublespending transaction, but don't relay it
@@ -61,10 +59,7 @@ def test_block_doublespend(self):
         # wait for the transaction to propagate
         connected_nodes = self.nodes.copy()
         del connected_nodes[self.isolated_idx]
-        self.sync_mempools(connected_nodes)
-        self.bump_mocktime(30)
-        for node in connected_nodes:
-            self.wait_for_instantlock(is_id, node)
+        self.wait_for_instantlock(is_id, nodes=connected_nodes)
         # send doublespend transaction to isolated node
         dblspnd_txid = isolated.sendrawtransaction(dblspnd_tx['hex'])
         # generate block on isolated node with doublespend transaction
@@ -106,9 +101,7 @@ def test_mempool_doublespend(self):
         # feed the sender with some balance
         sender_addr = sender.getnewaddress()
         is_id = self.nodes[0].sendtoaddress(sender_addr, 1)
-        self.bump_mocktime(30)
-        for node in self.nodes:
-            self.wait_for_instantlock(is_id, node)
+        self.wait_for_instantlock(is_id)
         self.generate(self.nodes[0], 2)
 
         # create doublespending transaction, but don't relay it
@@ -129,17 +122,11 @@ def test_mempool_doublespend(self):
         receiver_addr = receiver.getnewaddress()
         is_id = sender.sendtoaddress(receiver_addr, 0.9)
         # wait for the transaction to propagate
-        self.bump_mocktime(30)
-        self.sync_mempools()
-        for node in self.nodes:
-            self.wait_for_instantlock(is_id, node)
+        self.wait_for_instantlock(is_id)
         assert dblspnd_txid not in set(isolated.getrawmempool())
         # send coins back to the controller node without waiting for confirmations
         sentback_id = receiver.sendtoaddress(self.nodes[0].getnewaddress(), 0.9, "", "", True)
-        self.bump_mocktime(30)
-        self.sync_mempools()
-        for node in self.nodes:
-            self.wait_for_instantlock(sentback_id, node)
+        self.wait_for_instantlock(sentback_id)
         assert_equal(receiver.getwalletinfo()["balance"], 0)
         # mine more blocks
         self.generate(self.nodes[0], 2)

test/functional/rpc_verifyislock.py

@@ -41,8 +41,7 @@ def run_test(self):
         self.generate(self.nodes[0], 8, sync_fun=self.sync_blocks())
 
         txid = node.sendtoaddress(node.getnewaddress(), 1)
-        self.bump_mocktime(30)
-        self.wait_for_instantlock(txid, node)
+        self.wait_for_instantlock(txid, nodes=[node])
 
         request_id = self.get_request_id(self.nodes[0].getrawtransaction(txid))
         request_id_rpc = self.nodes[0].getislocks([txid])[0]["id"]

test/functional/test_framework/test_framework.py

@@ -1945,17 +1945,26 @@ def create_isdlock(self, hextx):
         return isdlock
 
     # due to privacy reasons random delay is used before sending transaction by network
-    # most times is just 2-5 seconds, but once in 1000 it's up to 1000 seconds.
-    # it's recommended to bump mocktime for 30 seconds before wait_for_instantlock
-    def wait_for_instantlock(self, txid, node, timeout=60):
+    # most times it's just 2-5 seconds, but once in 1000 times it's up to 10 seconds and has no bound from the top.
+    def wait_for_instantlock(self, *txids, nodes=None, timeout=60, skip_sync=False):
+        nodes = nodes or self.nodes
+
+        if not skip_sync:
+            self.bump_mocktime(30)
+            self.sync_mempools(nodes)
+
+        self.log.info(f"Expecting InstantLock for {list(txids)}")
 
         def check_instantlock():
             try:
-                return node.getrawtransaction(txid, True)["instantlock"]
+                return all(
+                    node.getrawtransaction(txid, True)["instantlock"]
+                    for txid in txids
+                    for node in nodes
+                )
             except Exception:
                 return False
 
-        self.log.info(f"Expecting InstantLock for {txid}")
         self.wait_until(check_instantlock, timeout=timeout)
 
     def wait_for_chainlocked_block(self, node, block_hash, expected=True, timeout=15):