Merge #6751: test: wait delays for IS, CL just 0.05s

1a5cee6 test: instead bumping time per 1 second bump straightly 30 seconds in feature_llmq_is_retroactive (Konstantin Akimov)
0e9f7fb test: move helper wait_for_tx from test_framework to feature_llmq_is_retroactive (Konstantin Akimov)
71ef10a test: fix intermittent failures in p2p_instantsend.py and others (Konstantin Akimov)
067aa25 test: use default delay 0.05 for waiter of chainlock and chainlocked blocks (Konstantin Akimov)

Pull request description:

  ## Issue being fixed or feature implemented
  Dash Core sends transactions after random delay for privacy reason.

       tx_relay->m_next_inv_send_time = GetExponentialRand(current_time, OUTBOUND_INVENTORY_BROADCAST_INTERVAL)

  This expential random delay could be long as  2s * 10 = 20 seconds or even longer sometimes.

  ## What was done?
  Prior work: #6631

  To be sure that helper wait_for_instantsend is reliable need to bump mocktime for 20+ second, or even better 30 seconds.

  It fixes potential instability in functional tests and make them more deterministic and faster to run.
  Decreased delay for ChainLocks also.

  ## How Has This Been Tested?
  Run functional tests several times; no new failures are noticed.

  Minor performance improvement for functional tests that use `wait_for_instantlock`:
  ```
  TEST                                  | STATUS    | DURATION

  feature_asset_locks.py                | ✓ Passed  | 114 s
  feature_llmq_is_cl_conflicts.py       | ✓ Passed  | 47 s
  feature_llmq_is_retroactive.py        | ✓ Passed  | 135 s
  feature_llmq_singlenode.py            | ✓ Passed  | 56 s
  feature_notifications.py              | ✓ Passed  | 74 s
  interface_zmq_dash.py --legacy-wallet | ✓ Passed  | 45 s
  p2p_instantsend.py                    | ✓ Passed  | 49 s
  rpc_verifyislock.py                   | ✓ Passed  | 39 s

  ALL                                   | ✓ Passed  | 559 s (accumulated)
  Runtime: 135 s

  --->

  TEST                                  | STATUS    | DURATION

  feature_asset_locks.py                | ✓ Passed  | 113 s
  feature_llmq_is_cl_conflicts.py       | ✓ Passed  | 33 s
  feature_llmq_is_retroactive.py        | ✓ Passed  | 126 s
  feature_llmq_singlenode.py            | ✓ Passed  | 37 s
  feature_notifications.py              | ✓ Passed  | 29 s
  interface_zmq_dash.py --legacy-wallet | ✓ Passed  | 41 s
  p2p_instantsend.py                    | ✓ Passed  | 44 s
  rpc_verifyislock.py                   | ✓ Passed  | 37 s

  ALL                                   | ✓ Passed  | 460 s (accumulated)
  Runtime: 126 s
  ```

  ## Breaking Changes
  N/A

  ## Checklist:
  - [x] 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
  - [x] I have assigned this pull request to a milestone

ACKs for top commit:
  UdjinM6:
    utACK 1a5cee6
  PastaPastaPasta:
    utACK 1a5cee6

Tree-SHA512: c8b2066513f5496eac6ad98a8c6891acd4ad05820ad7339f657d695be114370cf0b4b7250f5d5077f1ec88b1baac658f01386c48190115163dd9f0e49941fd9f

Author: PastaPastaPasta

test/functional/feature_asset_locks.py

@@ -378,6 +378,7 @@ def test_asset_unlocks(self, node_wallet, node, pubkey):
         txid = self.send_tx(asset_unlock_tx)
         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)
 

test/functional/feature_llmq_is_cl_conflicts.py

@@ -96,6 +96,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)
@@ -156,6 +157,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)

test/functional/feature_llmq_is_retroactive.py

@@ -24,6 +24,16 @@ def set_test_params(self):
         # -whitelist is needed to avoid the trickling logic on node0
         self.set_dash_test_params(5, 4, [["-whitelist=127.0.0.1"], [], [], [], ["-minrelaytxfee=0.001"]])
 
+    # 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:
+                return False
+        if self.wait_until(check_tx, timeout=timeout, do_assert=expected) and not expected:
+            raise AssertionError("waiting unexpectedly succeeded")
+
     def run_test(self):
         self.nodes[0].sporkupdate("SPORK_17_QUORUM_DKG_ENABLED", 0)
         # Turn mempool IS signing off
@@ -39,6 +49,7 @@ 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], False, 5)
         # Have to disable ChainLocks to avoid signing a block with a "safe" tx too early
         self.nodes[0].sporkupdate("SPORK_19_CHAINLOCKS_ENABLED", 4000000000)
@@ -59,8 +70,8 @@ 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.bump_mocktime(1)
         block = self.generate(self.nodes[0], 1, sync_fun=self.no_op)[0]
         self.wait_for_chainlocked_block_all_nodes(block)
 
@@ -69,6 +80,7 @@ def run_test(self):
         txid = self.nodes[0].sendtoaddress(self.nodes[0].getnewaddress(), 1)
         # Make sure nodes 1 and 2 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.reconnect_isolated_node(3, 0)
@@ -101,6 +113,7 @@ def run_test(self):
         txid = self.nodes[0].sendtoaddress(self.nodes[0].getnewaddress(), 1)
         # Make sure nodes 1 and 2 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.reconnect_isolated_node(3, 0)
@@ -139,6 +152,7 @@ def test_all_nodes_session_timeout(self, do_cycle_llmqs):
         txid = self.nodes[0].sendrawtransaction(rawtx)
         txid = self.nodes[3].sendrawtransaction(rawtx)
         # Make sure nodes 1 and 2 received the TX before we continue
+        self.bump_mocktime(30)
         self.wait_for_tx(txid, self.nodes[1])
         self.wait_for_tx(txid, self.nodes[2])
         # Make sure signing is done on nodes 1 and 2 (it's async)
@@ -178,12 +192,13 @@ def test_single_node_session_timeout(self, do_cycle_llmqs):
         self.wait_for_mnauth(self.nodes[3], 2)
         self.nodes[0].sendrawtransaction(rawtx)
         # Make sure nodes 1 and 2 received the TX
+        self.bump_mocktime(30)
         self.wait_for_tx(txid, self.nodes[1])
         self.wait_for_tx(txid, self.nodes[2])
+        self.bump_mocktime(30)
         # Make sure signing is done on nodes 1 and 2 (it's async)
-        time.sleep(5)
         # node 3 fully reconnected but the signing session is already timed out on it, so no IS lock
-        self.wait_for_instantlock(txid, self.nodes[0], False, 1)
+        self.wait_for_instantlock(txid, self.nodes[0], False, 5)
         if do_cycle_llmqs:
             self.cycle_llmqs()
             self.wait_for_instantlock(txid, self.nodes[0], False, 5)

test/functional/feature_llmq_singlenode.py

@@ -104,6 +104,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.log.info("Test various options to sign messages with nodes")
@@ -181,6 +182,7 @@ 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])
 

test/functional/feature_notifications.py

@@ -132,9 +132,11 @@ def run_test(self):
             tx_count = 10
             for _ in range(tx_count):
                 txid = self.nodes[0].sendtoaddress(self.nodes[1].getnewaddress(), 1)
-                self.wait_for_instantlock(txid, self.nodes[1])
+                self.bump_mocktime(30)
+                self.wait_for_instantlock(txid, self.nodes[0])
 
             # wait at most 10 seconds for expected number of files before reading the content
+            self.bump_mocktime(30)
             self.wait_until(lambda: len(os.listdir(self.instantsendnotify_dir)) == tx_count, timeout=10)
 
             # directory content should equal the generated transaction hashes

test/functional/interface_zmq_dash.py

@@ -293,6 +293,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])
         # Validate hashtxlock
         zmq_tx_lock_hash = self.subscribers[ZMQPublisher.hash_tx_lock].receive().read(32).hex()
@@ -345,6 +346,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])
         # Validate hashtxlock
         zmq_tx_lock_hash = self.subscribers[ZMQPublisher.hash_tx_lock].receive().read(32).hex()
@@ -378,6 +380,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.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)

test/functional/p2p_instantsend.py

@@ -42,9 +42,9 @@ 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.bump_mocktime(1)
         self.generate(self.nodes[0], 2)
 
         # create doublespending transaction, but don't relay it
@@ -58,6 +58,7 @@ def test_block_doublespend(self):
         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)
         # send doublespend transaction to isolated node
@@ -101,9 +102,9 @@ 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.bump_mocktime(1)
         self.generate(self.nodes[0], 2)
 
         # create doublespending transaction, but don't relay it
@@ -124,18 +125,19 @@ 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)
         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)
         assert_equal(receiver.getwalletinfo()["balance"], 0)
         # mine more blocks
-        self.bump_mocktime(1)
         self.generate(self.nodes[0], 2)
 
 if __name__ == '__main__':

test/functional/rpc_verifyislock.py

@@ -38,6 +38,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)
 
         request_id = self.get_request_id(self.nodes[0].getrawtransaction(txid))

test/functional/test_framework/test_framework.py

@@ -1898,16 +1898,6 @@ def make_change(from_node, amount_in, amount_out, fee):
         ret = {**decoded, **ret}
         return ret
 
-    def wait_for_tx(self, txid, node, expected=True, timeout=60):
-        def check_tx():
-            try:
-                self.bump_mocktime(1)
-                return node.getrawtransaction(txid)
-            except:
-                return False
-        if self.wait_until(check_tx, timeout=timeout, sleep=1, do_assert=expected) and not expected:
-            raise AssertionError("waiting unexpectedly succeeded")
-
     def create_isdlock(self, hextx):
         tx = tx_from_hex(hextx)
         tx.rehash()
@@ -1930,15 +1920,19 @@ 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, expected=True, timeout=60):
+
         def check_instantlock():
-            self.bump_mocktime(1)
             try:
                 return node.getrawtransaction(txid, True)["instantlock"]
             except:
                 return False
+
         self.log.info(f"Expecting InstantLock for {txid}")
-        if self.wait_until(check_instantlock, timeout=timeout, sleep=1, do_assert=expected) and not expected:
+        if self.wait_until(check_instantlock, timeout=timeout, do_assert=expected) and not expected:
             raise AssertionError("waiting unexpectedly succeeded")
 
     def wait_for_chainlocked_block(self, node, block_hash, expected=True, timeout=15):
@@ -1949,15 +1943,15 @@ def check_chainlocked_block():
             except:
                 return False
         self.log.info(f"Expecting ChainLock for {block_hash}")
-        if self.wait_until(check_chainlocked_block, timeout=timeout, sleep=0.1, do_assert=expected) and not expected:
+        if self.wait_until(check_chainlocked_block, timeout=timeout, do_assert=expected) and not expected:
             raise AssertionError("waiting unexpectedly succeeded")
 
     def wait_for_chainlocked_block_all_nodes(self, block_hash, timeout=15, expected=True):
         for node in self.nodes:
             self.wait_for_chainlocked_block(node, block_hash, expected=expected, timeout=timeout)
 
     def wait_for_best_chainlock(self, node, block_hash, timeout=15):
-        self.wait_until(lambda: node.getbestchainlock()["blockhash"] == block_hash, timeout=timeout, sleep=0.1)
+        self.wait_until(lambda: node.getbestchainlock()["blockhash"] == block_hash, timeout=timeout)
 
     def wait_for_sporks_same(self, timeout=30):
         def check_sporks_same():