Debug failures

lib/2wp-utils-legacy.js

@@ -153,7 +153,7 @@ const ensurePeginIsRegistered = async (rskClient, peginBtcTxHash, expectedUxtosC
         return utxoIsRegistered;
     };
 
-    const utxoIsRegisteredInTheBridge = await retryWithCheck(method, check, MAX_ATTEMPTS, CHECK_EVERY_MILLISECONDS);
+    const { result: utxoIsRegisteredInTheBridge } = await retryWithCheck(method, check, MAX_ATTEMPTS, CHECK_EVERY_MILLISECONDS);
 
     if(utxoIsRegisteredInTheBridge) {
         console.debug(`Found pegin ${peginBtcTxHash} registered in the bridge.`);

lib/2wp-utils.js

@@ -1,6 +1,6 @@
 const expect = require('chai').expect;
-const { sendFromCow, mineAndSync, sendTxWithCheck, getUnlockedAddress } = require('./rsk-utils');
-const { wait, retryWithCheck } = require('./utils');
+const { sendFromCow, mineAndSync, sendTxWithCheck, getUnlockedAddress, waitForRskMempoolToGetNewTxs, waitAndUpdateBridge } = require('./rsk-utils');
+const { retryWithCheck, waitForBitcoinTxToBeInMempool, waitForBitcoinMempoolToGetTxs } = require('./utils');
 const { getBridge, getLatestActiveForkName } = require('./precompiled-abi-forks-util');
 const { getBridgeState } = require('@rsksmart/bridge-state-data-parser');
 const btcEthUnitConverter = require('@rsksmart/btc-eth-unit-converter');
@@ -62,7 +62,10 @@ const sendTxToBridge = async (rskTxHelper, amountInRbtc, rskFromAddress, mine =
     if(!mine) {
         return;
     }
-    await wait(1000);
+
+    // Wait for the rsk tx to be in the rsk mempool before mining
+    await waitForRskMempoolToGetNewTxs(rskTxHelper);
+
     await mineAndSync(getRskTransactionHelpers());
     const result = await txPromise;
     return result;
@@ -103,9 +106,13 @@ const isUtxoRegisteredInBridge = async (rskTxHelper, peginTxHash, expectedUxtosC
 
 const mineForPeginRegistration = async (rskTxHelper, btcTxHelper) => {
     // Enough confirmations to register the coinbase but not the pegin.
+    // Wait for the pegin to be in the bitcoin mempool before mining
+    await waitForBitcoinMempoolToGetTxs(btcTxHelper);
     await btcTxHelper.mine(BTC_TO_RSK_MINIMUM_CONFIRMATIONS - 1);
     await waitAndUpdateBridge(rskTxHelper, 500);
     // One more confirmation to register the pegin.
+    // Wait for the pegin to be in the bitcoin mempool before mining
+    await waitForBitcoinMempoolToGetTxs(btcTxHelper);
     await btcTxHelper.mine(1);
     await waitAndUpdateBridge(rskTxHelper, 500);
 };
@@ -132,6 +139,9 @@ const sendPegin = async (rskTxHelper, btcTxHelper, btcSenderAddressInformation,
 
     const peginBtcTxHash = await btcTxHelper.transferBtc(btcSenderAddressInformation, recipientsTransferInformation, data);
 
+    // Wait for the pegin to be in the bitcoin mempool before mining
+    await waitForBitcoinTxToBeInMempool(btcTxHelper, peginBtcTxHash);
+
     await mineForPeginRegistration(rskTxHelper, btcTxHelper);
 
     return peginBtcTxHash;
@@ -163,7 +173,7 @@ const ensurePeginIsRegistered = async (rskTxHelper, peginBtcTxHash, expectedUtxo
         return utxoIsRegistered;
     };
 
-    const utxoIsRegisteredInTheBridge = await retryWithCheck(method, check, MAX_ATTEMPTS, CHECK_EVERY_MILLISECONDS);
+    const { result: utxoIsRegisteredInTheBridge } = await retryWithCheck(method, check, MAX_ATTEMPTS, CHECK_EVERY_MILLISECONDS);
 
     if(utxoIsRegisteredInTheBridge) {
         console.debug(`Found pegin ${peginBtcTxHash} registered in the bridge.`);
@@ -177,18 +187,6 @@ const ensurePeginIsRegistered = async (rskTxHelper, peginBtcTxHash, expectedUtxo
 
 };
 
-/**
- * Waits for the specified time, updates the bridge and mines 1 rsk block
- * @param {RskTransactionHelper} rskTxHelper 
- * @param {number} timeInMilliseconds defaults to 1000
- * @returns {Promise<void>}
- */
-const waitAndUpdateBridge = async (rskTxHelper, timeInMilliseconds = 1000) => {
-    await wait(timeInMilliseconds);
-    await rskTxHelper.updateBridge();
-    await mineAndSync(getRskTransactionHelpers());
-};
-
 /**
  * Creates a pegin v1 data for a user to indicate to which rsk address to receive their pegin funds.
  * @param {string} rskDestinationAddress 
@@ -273,5 +271,5 @@ module.exports = {
     createPeginV1TxData,
     mineForPeginRegistration,
     MIN_PEGOUT_VALUE_IN_RBTC,
-    disableWhitelisting
+    disableWhitelisting,
 };

lib/rsk-utils.js

@@ -5,7 +5,7 @@ const { getBridge, getLatestActiveForkName } = require('./precompiled-abi-forks-
 const hopBridgeTxParser = require('bridge-transaction-parser-hop400');
 const fingerrootBridgeTxParser = require('bridge-transaction-parser-fingerroot500');
 const { getRskTransactionHelpers } = require('../lib/rsk-tx-helper-provider');
-const { removePrefix0x } = require('./utils');
+const { removePrefix0x, waitForBitcoinMempoolToGetTxs } = require('./utils');
 
 const BTC_TO_RSK_MINIMUM_ACCEPTABLE_CONFIRMATIONS = 3;
 const RSK_TO_BTC_MINIMUM_ACCEPTABLE_CONFIRMATIONS = 3;
@@ -127,6 +127,116 @@ const increaseBlockToNextPegoutHeight = async (rskTransactionHelpers) => {
   }
 };
 
+/**
+ * Waits for the specified time, updates the bridge and mines 1 rsk block
+ * @param {RskTransactionHelper} rskTxHelper 
+ * @param {number} timeInMilliseconds defaults to 1000
+ * @returns {Promise<void>}
+ */
+const waitAndUpdateBridge = async (rskTxHelper, timeInMilliseconds = 1000) => {
+  await wait(timeInMilliseconds);
+  await rskTxHelper.updateBridge();
+
+  // Wait for the rsk `updateBridge` tx to be in the rsk mempool before mining
+  await waitForRskMempoolToGetNewTxs(rskTxHelper);
+
+  await mineAndSync(getRskTransactionHelpers());
+};
+
+/**
+ * 
+ * @param {RskTransactionHelper} rskTxHelper 
+ * @returns {Promise<string[]>} array of tx hashes in the mempool
+ */
+const getRskMempoolTransactionHashes = async (rskTxHelper) => {
+  const mempoolBlock = await rskTxHelper.getClient().eth.getBlock('pending');
+  return mempoolBlock.transactions;
+};
+
+/**
+ * 
+ * @param {RskTransactionHelper} rskTxHelper 
+ * @param {string} txHash 
+ * @param {number} maxAttempts Defaults to 3
+ * @param {number} checkEveryMilliseconds Defaults to 500 milliseconds
+ * @returns {Promise<boolean>} whether the tx is in the mempool or not
+ */
+const waitForRskTxToBeInTheMempool = async (rskTxHelper, txHash, maxAttempts = 3, checkEveryMilliseconds = 500) => {
+
+  const method = async () => {
+
+    const tx = await rskTxHelper.getClient().eth.getTransaction(txHash);
+
+    const isTxInTheMempool = tx && !tx.blockNumber;
+
+    if(isTxInTheMempool) {
+      console.debug(`The tx (${txHash}) is in the mempool`);
+      return true;
+    }
+
+    const isTxAlreadyMined = tx && tx.blockNumber;
+
+    if(isTxAlreadyMined) {
+      console.debug(`The tx (${txHash}) is already mined in a block`);
+      return true;
+    }
+
+    console.debug(`The tx (${txHash}) is not in the mempool nor in a block yet. Will keep retrying until it is in the mempool, block, or it reaches the max attempts to find it`);
+
+    return false;
+
+  };
+
+  const check = async (txIsInTheMempool, currentAttempts) => {
+    console.debug(`Attempting to find the tx ${txHash} in the mempool. Attempt ${currentAttempts} out of ${maxAttempts}`);
+    return txIsInTheMempool;
+  };
+
+  const { result: isTxInTheMempool, attempts } = await retryWithCheck(method, check, maxAttempts, checkEveryMilliseconds);
+
+  console.debug(`Tx ${txHash} was found in the rsk mempool or mined: ${isTxInTheMempool}, after ${attempts} attempts.`);
+
+  return isTxInTheMempool;
+
+};
+
+/**
+ * 
+ * @param {RskTransactionHelper} rskTxHelper 
+ * @param {number} maxAttempts Defaults to 3
+ * @param {number} checkEveryMilliseconds Defaults to 500 milliseconds
+ * @returns {Promise<boolean>} whether the mempool has new txs or not
+ */
+const waitForRskMempoolToGetNewTxs = async (rskTxHelper, maxAttempts = 3, checkEveryMilliseconds = 500) => {
+
+    const initialRskMempoolTxHashes = await getRskMempoolTransactionHashes(rskTxHelper);
+
+    console.debug(`[waitForRskMempoolToGetNewTxs] initial rsk mempool size: ${initialRskMempoolTxHashes.length}`);
+    console.debug(`Will wait and attempt to check if the rsk mempool has received any new transactions ${maxAttempts} times.`);
+
+    const areThereNewTxsInTheMempool = async () => {
+      const mempoolTxHashes = await getRskMempoolTransactionHashes(rskTxHelper);
+      if(mempoolTxHashes.length > initialRskMempoolTxHashes.length) {
+        console.debug(`The mempool got ${mempoolTxHashes.length - initialRskMempoolTxHashes.length} new transactions`);
+        return true;
+      }
+      return false;
+    };
+
+    const check = async (mempoolHasTxs) => {
+      return mempoolHasTxs;
+    };
+
+    const { result: newTxsWhereFoundInTheRskMempool, attempts } = await retryWithCheck(areThereNewTxsInTheMempool, check, maxAttempts, checkEveryMilliseconds);
+
+    const finalRskMempoolTxHashes = await getRskMempoolTransactionHashes(rskTxHelper);
+
+    console.debug(`[waitForRskMempoolToGetNewTxs] final rsk mempool size: ${finalRskMempoolTxHashes.length}, after ${attempts} attempts. Difference with initial mempool size: ${finalRskMempoolTxHashes.length - initialRskMempoolTxHashes.length}`);
+
+    return newTxsWhereFoundInTheRskMempool;
+
+  };
+
 /**
  * 
  * @param {Array<RskTransactionHelper>} rskTransactionHelpers RskTransactionHelper instances each belonging to one federator node to make calls to the rsk network
@@ -141,12 +251,9 @@ const triggerRelease = async (rskTransactionHelpers, btcClient, callbacks = {})
     await increaseBlockToNextPegoutHeight(rskTransactionHelpers);
   }
 
-  // Sync all nodes
-  await waitForSync(rskTransactionHelpers);
-
   // Adds the pegout to the pegoutsWaitingForConfirmations structure with this 1 confirmation
-  await rskTxHelper.updateBridge(); 
-  await mineAndSync(rskTransactionHelpers); // release_request_received and batch_pegout_created triggered here (if appropriate fork, RSKIP185 and RSKIP271, is/are active)
+  // release_request_received and batch_pegout_created triggered here (if appropriate fork, RSKIP185 and RSKIP271, is/are active)
+  await waitAndUpdateBridge(rskTxHelper);
 
   if(callbacks.pegoutCreatedCallback) {
     await callbacks.pegoutCreatedCallback(rskTxHelper);
@@ -156,8 +263,8 @@ const triggerRelease = async (rskTransactionHelpers, btcClient, callbacks = {})
   await mineAndSync(rskTransactionHelpers, BTC_TO_RSK_MINIMUM_ACCEPTABLE_CONFIRMATIONS - 1);
 
   // Moves the pegout from pegoutsWaitingForConfirmations to pegoutsWaitingForSignatures
-  await rskTxHelper.updateBridge(); // Makes an updateCollections call which is the tx that will move the pegout to pegoutsWaitingForSignatures
-  await mineAndSync(rskTransactionHelpers);  // pegout_confirmed event triggered here (if appropriate fork, RSKIP326, is active)
+  // pegout_confirmed event triggered here (if appropriate fork, RSKIP326, is active)
+  await waitAndUpdateBridge(rskTxHelper);
 
   if(callbacks.pegoutConfirmedCallback) {
     await callbacks.pegoutConfirmedCallback(rskTxHelper);
@@ -183,22 +290,25 @@ const triggerRelease = async (rskTransactionHelpers, btcClient, callbacks = {})
     return false; // Returning false to make the retryWithCheck loop continue until this check returns true or it reaches the max attempts
   };
 
-  const wasPegoutBroadcasted = await retryWithCheck(method, pegoutIsBroadcasted => pegoutIsBroadcasted, MAX_ATTEMPTS, CHECK_EVERY_MILLISECONDS);
+  const { result: wasPegoutBroadcasted, attempts } = await retryWithCheck(method, pegoutIsBroadcasted => pegoutIsBroadcasted, MAX_ATTEMPTS, CHECK_EVERY_MILLISECONDS);
 
-  console.debug(`Pegout broadcasted: ${wasPegoutBroadcasted}`);
+  console.debug(`Pegout broadcasted: ${wasPegoutBroadcasted}, after ${attempts} attempts.`);
 
   // Last add_signature and release_btc events emitted here at the block that just broadcasted the pegout to the btc network.
   if(callbacks.releaseBtcCallback) {
     await callbacks.releaseBtcCallback(rskTxHelper);
   }
 
+  // Waiting to make sure that the pegout tx is in the bitcoin mempool before mining the required blocks for confirmation.
+  await waitForBitcoinMempoolToGetTxs(btcClient);
+
   // From the btc network side, mine `RSK_TO_BTC_MINIMUM_ACCEPTABLE_CONFIRMATIONS + 1` blocks, 1 for the pegout funds to be mined and reflected in the recipient address,
   // and `RSK_TO_BTC_MINIMUM_ACCEPTABLE_CONFIRMATIONS` more to have enough confirmation for the change balance to be reflected back in the bridge (like a pegin)
   await btcClient.mine(RSK_TO_BTC_MINIMUM_ACCEPTABLE_CONFIRMATIONS + 1);
 
   // Make pegnatories register the change utxo back in the bridge
-  await rskTxHelper.updateBridge();
-  await mineAndSync(rskTransactionHelpers); // At this point the bridge should already have the change uxto registered
+ // After this point the bridge should already have the change uxto registered
+  await waitAndUpdateBridge(rskTxHelper);
 
 };
 
@@ -221,7 +331,7 @@ const sendTxWithCheck = async (rskTxHelper, method, from, checkCallback) => {
   const estimatedGas = await method.estimateGas({ from });
   const txReceiptPromise = method.send({ from, value: 0, gasPrice: 0, gas: estimatedGas });
 
-  await wait(1000);
+  await waitForRskMempoolToGetNewTxs(rskTxHelper);
   await mineAndSync(getRskTransactionHelpers());
 
   return await txReceiptPromise;
@@ -344,5 +454,9 @@ module.exports = {
   getUnlockedAddress,
   getFedsPubKeys,
   activateFork,
-  getLatestForkName
+  getLatestForkName,
+  getRskMempoolTransactionHashes,
+  waitForRskTxToBeInTheMempool,
+  waitForRskMempoolToGetNewTxs,
+  waitAndUpdateBridge,
 };

lib/tests/2wp.js

@@ -9,6 +9,7 @@ const { getRskTransactionHelpers, getRskTransactionHelper } = require('../rsk-tx
 const { getDerivedRSKAddressInformation } = require('@rsksmart/btc-rsk-derivation');
 const btcEthUnitConverter = require('@rsksmart/btc-eth-unit-converter');
 const { sendTxToBridge, sendPegin, ensurePeginIsRegistered, donateToBridge } = require('../2wp-utils');
+const { waitAndUpdateBridge } = require('../rsk-utils');
 
 const DONATION_AMOUNT = 250;
 const REJECTED_REASON = 1;
@@ -50,8 +51,7 @@ const execute = (description, getRskHost) => {
       rskTxHelpers = getRskTransactionHelpers();
 
       // Update the bridge to sync btc blockchains
-      await rskTxHelper.updateBridge();
-      await rskUtils.mineAndSync(rskTxHelpers);
+      await waitAndUpdateBridge(rskTxHelper);
 
       // At the moment there are a lot of pegout tests that depend on the bridge to have enough balance.
       // Those tests are not doing a pegin if needed, so we need to donate to the bridge to ensure it has enough balance.