Adds log4js. Updates wait for port attempts.

lib/2wp-utils.js

@@ -15,18 +15,16 @@ const btcEthUnitConverter = require('@rsksmart/btc-eth-unit-converter');
 
 const peginVerifier = require('pegin-address-verificator');
 const { getRskTransactionHelpers } = require('../lib/rsk-tx-helper-provider');
-const { WHITELIST_CHANGE_PK, WHITELIST_CHANGE_ADDR} = require('../lib/assertions/whitelisting')
-
-const ADDRESS_TYPES_CODES = {
-    p2pkh: '01',
-    p2sh: '02'
-};
+const { WHITELIST_CHANGE_PK, WHITELIST_CHANGE_ADDR} = require('../lib/assertions/whitelisting');
+const { getLogger } = require('../logger');
 
 const BTC_TO_RSK_MINIMUM_CONFIRMATIONS = 3;
 const TO_BRIDGE_GAS_PRICE = 2;
 const BRIDGE_ADDRESS = '0x0000000000000000000000000000000001000006';
 const MIN_PEGOUT_VALUE_IN_RBTC = 0.0025;
 
+const logger = getLogger();
+
 /**
  * 
  * @param {RskTransactionHelper} rskTxHelper 
@@ -174,7 +172,7 @@ const ensurePeginIsRegistered = async (rskTxHelper, peginBtcTxHash, expectedUtxo
     };
 
     const check = async (utxoIsRegistered, currentAttempts) => {
-        console.debug(`Attempting to find the pegin ${peginBtcTxHash} in the bridge. Attempt ${currentAttempts} out of ${MAX_ATTEMPTS}`);
+        logger.debug(`[${ensurePeginIsRegistered.name}::${check.name}] Attempting to find the pegin ${peginBtcTxHash} in the bridge. Attempt ${currentAttempts} out of ${MAX_ATTEMPTS}`);
         if(!utxoIsRegistered) {
             await waitAndUpdateBridge(rskTxHelper, 1000);
         }
@@ -184,7 +182,7 @@ const ensurePeginIsRegistered = async (rskTxHelper, peginBtcTxHash, expectedUtxo
     const { result: utxoIsRegisteredInTheBridge } = await retryWithCheck(method, check, MAX_ATTEMPTS, CHECK_EVERY_MILLISECONDS);
 
     if(utxoIsRegisteredInTheBridge) {
-        console.debug(`Found pegin ${peginBtcTxHash} registered in the bridge.`);
+        logger.debug(`[${ensurePeginIsRegistered.name}] Found pegin ${peginBtcTxHash} registered in the bridge.`);
         // The pegin is already registered in the bridge, but the balance may still not be reflected on the user's rsk address
         // So we need to update the bridge and mine one more block so the balance is reflected on the user's rsk address
         await waitAndUpdateBridge(rskTxHelper);

lib/bitcoin-runner.js

@@ -85,7 +85,11 @@ BitcoinRunner.prototype.start = function() {
     }, {
       host: '127.0.0.1',
       port: this.ports.rpc
-    }]).then((r) => {
+    }],
+    {
+      numRetries: 100,
+      retryInterval: 1000
+    }).then((r) => {
       this.running = true;
       return r;
     });

lib/btc-utils.js

@@ -2,6 +2,9 @@ const bitcoinJs = require('bitcoinjs-lib');
 const merkleLib = require('merkle-lib');
 const pmtBuilder = require('@rsksmart/pmt-builder');
 const { retryWithCheck } = require('./utils');
+const { getLogger } = require('../logger');
+
+const logger = getLogger();
 
 const publicKeyToCompressed = (publicKey) => {
     return bitcoinJs.ECPair.fromPublicKey(Buffer.from(publicKey, 'hex'), { compressed: true })
@@ -101,10 +104,10 @@ const waitForBitcoinTxToBeInMempool = async (btcTxHelper, btcTxHash, maxAttempts
       const bitcoinMempool = await getBitcoinTransactionsInMempool(btcTxHelper);
       const isTxInMempool = bitcoinMempool.includes(btcTxHash);
       if(!isTxInMempool) {
-        console.debug(`Attempting to check if the btc tx (${btcTxHash}) was already mined since it's not in the mempool yet.`);
+        logger.debug(`[${waitForBitcoinTxToBeInMempool.name}::${bitcoinMempoolHasTx.name}] Attempting to check if the btc tx (${btcTxHash}) was already mined since it's not in the mempool yet.`);
         const tx = await btcTransactionHelper.getTransaction(btcTxHash);
         if(tx) {
-          console.debug(`The btc tx (${btcTxHash}) was already mined.`);
+          logger.debug(`[${waitForBitcoinTxToBeInMempool.name}::${bitcoinMempoolHasTx.name}] The btc tx (${btcTxHash}) was already mined.`);
           return true;
         }
         return false;
@@ -114,19 +117,19 @@ const waitForBitcoinTxToBeInMempool = async (btcTxHelper, btcTxHash, maxAttempts
 
     const checkBitcoinMempoolHasTx = async (btcTxAlreadyFound, currentAttempts) => {
       if(btcTxAlreadyFound) {
-        console.debug(`The btc tx ${btcTxHash} was found in the mempool at attempt ${currentAttempts}.`);
+        logger.debug(`[${waitForBitcoinTxToBeInMempool.name}::${checkBitcoinMempoolHasTx.name}] The btc tx ${btcTxHash} was found in the mempool at attempt ${currentAttempts}.`);
       } else {
-        console.log(`Attempting to get the btc tx ${btcTxHash} in the mempool. Attempt: ${currentAttempts}.`);
+        logger.debug(`[${waitForBitcoinTxToBeInMempool.name}::${checkBitcoinMempoolHasTx.name}] Attempting to get the btc tx ${btcTxHash} in the mempool. Attempt: ${currentAttempts}.`);
       }
       return btcTxAlreadyFound;
     };
 
     const onError = async (e) => {
       if(e.message.includes('No such mempool or blockchain transaction')) {
-        console.debug(`The btc tx ${btcTxHash} is not in the mempool nor mined yet. Let's allow some more time before retrying to get it.`);
+        logger.debug(`[${waitForBitcoinTxToBeInMempool.name}::${onError.name}] The btc tx ${btcTxHash} is not in the mempool nor mined yet. Let's allow some more time before retrying to get it.`);
         return true;
       }
-      console.error(`Un expected error while trying to get the btc tx ${btcTxHash} in the mempool.`, e);
+      logger.debug(`[${waitForBitcoinTxToBeInMempool.name}::${onError.name}] Un expected error while trying to get the btc tx ${btcTxHash} in the mempool.`, e);
       throw e;
     };
 
@@ -150,8 +153,8 @@ const waitForBitcoinTxToBeInMempool = async (btcTxHelper, btcTxHash, maxAttempts
  */
 const waitForBitcoinMempoolToGetTxs = async (btcTxHelper, maxAttempts = 3, checkEveryMilliseconds = 500) => {
     const initialBitcoinMempoolSize = (await getBitcoinTransactionsInMempool(btcTxHelper)).length;
-    console.debug(`[waitForBitcoinMempoolToGetTxs] The initial bitcoin mempool size is ${initialBitcoinMempoolSize}.`);
-    console.debug(`Will wait and attempt to check if the bitcoin mempool has received any new transactions ${maxAttempts} times.`);
+    logger.debug(`[${waitForBitcoinMempoolToGetTxs.name}] The initial bitcoin mempool size is ${initialBitcoinMempoolSize}.`);
+    logger.debug(`[${waitForBitcoinMempoolToGetTxs.name}] Will wait and attempt to check if the bitcoin mempool has received any new transactions ${maxAttempts} times.`);
 
     const getCountOfTransactionsInMempool = async () => {
       const bitcoinMempool = await getBitcoinTransactionsInMempool(btcTxHelper);
@@ -173,7 +176,7 @@ const waitForBitcoinMempoolToGetTxs = async (btcTxHelper, maxAttempts = 3, check
     const txsInMempool = await getBitcoinTransactionsInMempool(btcTxHelper);
     const finalBitcoinMempoolSize = txsInMempool.length;
 
-    console.debug(`[waitForBitcoinMempoolToGetTxs] The final bitcoin mempool size is ${finalBitcoinMempoolSize}, after ${attempts} attempts. Difference with initial mempool size: ${finalBitcoinMempoolSize - initialBitcoinMempoolSize}.`);
+    logger.debug(`[${waitForBitcoinMempoolToGetTxs.name}] The final bitcoin mempool size is ${finalBitcoinMempoolSize}, after ${attempts} attempts. Difference with initial mempool size: ${finalBitcoinMempoolSize - initialBitcoinMempoolSize}.`);
 
     return bitcoinMempoolHasTx;
   }

lib/federate-runner.js

@@ -158,8 +158,8 @@ FederateRunner.prototype.start = function() {
       host: '127.0.0.1',
       port: this.ports.rpc
     }], {
-      numRetries: 300,
-      retryInterval: 100
+      numRetries: 100,
+      retryInterval: 1000
     }).then((r) => {
       this.running = true;
       return r;

lib/rsk-utils.js

@@ -6,10 +6,13 @@ const fingerrootBridgeTxParser = require('bridge-transaction-parser-fingerroot50
 const { getRskTransactionHelpers } = require('../lib/rsk-tx-helper-provider');
 const { wait, retryWithCheck, removePrefix0x } = require('./utils');
 const { waitForBitcoinMempoolToGetTxs } = require('./btc-utils');
+const { getLogger } = require('../logger');
 
 const BTC_TO_RSK_MINIMUM_ACCEPTABLE_CONFIRMATIONS = 3;
 const RSK_TO_BTC_MINIMUM_ACCEPTABLE_CONFIRMATIONS = 3;
 
+const logger = getLogger();
+
 /**
  * 
  * @param {Array<RskTransactionHelper>} rskTransactionHelpers to check which one has the latest block number
@@ -183,31 +186,31 @@ const waitForRskTxToBeInTheMempool = async (rskTxHelper, txHash, maxAttempts = 3
     const isTxInTheMempool = tx && !tx.blockNumber;
 
     if(isTxInTheMempool) {
-      console.debug(`The tx (${txHash}) is in the mempool`);
+      logger.debug(`[${waitForRskTxToBeInTheMempool.name}::${method.anme}] 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`);
+      logger.debug(`[${waitForRskTxToBeInTheMempool.name}::${method.anme}] 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`);
+    logger.debug(`[${waitForRskTxToBeInTheMempool.name}::${method.anme}] 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}`);
+    logger.debug(`[${waitForRskTxToBeInTheMempool.name}::${check.name}] 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.`);
+  logger.debug(`[${waitForRskTxToBeInTheMempool.name}] Tx ${txHash} was found in the rsk mempool or mined: ${isTxInTheMempool}, after ${attempts} attempts.`);
 
   return isTxInTheMempool;
 
@@ -224,13 +227,13 @@ const waitForRskMempoolToGetNewTxs = async (rskTxHelper, maxAttempts = 3, checkE
 
     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.`);
+    logger.debug(`[${waitForRskMempoolToGetNewTxs.name}] initial rsk mempool size: ${initialRskMempoolTxHashes.length}`);
+    logger.debug(`[${waitForRskMempoolToGetNewTxs.name}] 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`);
+        logger.debug(`[${waitForRskMempoolToGetNewTxs.name}] The mempool got ${mempoolTxHashes.length - initialRskMempoolTxHashes.length} new transactions`);
         return true;
       }
       return false;
@@ -244,7 +247,7 @@ const waitForRskMempoolToGetNewTxs = async (rskTxHelper, maxAttempts = 3, checkE
 
     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}`);
+    logger.debug(`[${waitForRskMempoolToGetNewTxs.name}] final rsk mempool size: ${finalRskMempoolTxHashes.length}, after ${attempts} attempts. Difference with initial mempool size: ${finalRskMempoolTxHashes.length - initialRskMempoolTxHashes.length}`);
 
     return newTxsWhereFoundInTheRskMempool;
 
@@ -291,7 +294,7 @@ const triggerRelease = async (rskTransactionHelpers, btcClient, callbacks = {})
   // and when the pegout is no longer in the `pegoutsWaitingForSignatures`, it means it has been already broadcasted to the btc network.
   // Usually this happens after the first or second attempts. This part is the only uncertainty because the fed nodes have to call `addSignature` on their own
   // and we can not make them call `addSignature` on demand.
-  console.debug(`Waiting and retrying until pegout is broadcasted with a maximum attempt of: ${MAX_ATTEMPTS} and checking every: ${CHECK_EVERY_MILLISECONDS} milliseconds.`);
+  logger.debug(`[${triggerRelease.name}] Waiting and retrying until pegout is broadcasted with a maximum attempt of: ${MAX_ATTEMPTS} and checking every: ${CHECK_EVERY_MILLISECONDS} milliseconds.`);
 
   const method = async () => {
     const currentBridgeState = await getBridgeState(rskTxHelper.getClient());
@@ -305,7 +308,7 @@ const triggerRelease = async (rskTransactionHelpers, btcClient, callbacks = {})
 
   const { result: wasPegoutBroadcasted, attempts } = await retryWithCheck(method, pegoutIsBroadcasted => pegoutIsBroadcasted, MAX_ATTEMPTS, CHECK_EVERY_MILLISECONDS);
 
-  console.debug(`Pegout broadcasted: ${wasPegoutBroadcasted}, after ${attempts} attempts.`);
+  logger.debug(`[${triggerRelease.name}] 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) {

log4js.json

@@ -0,0 +1,14 @@
+{
+    "appenders": {
+      "console": {
+        "type": "console"
+      }
+    },
+    "categories": {
+      "default": {
+        "appenders": ["console"],
+        "level": "info"
+      }
+    }
+}
+

logger.js

@@ -0,0 +1,21 @@
+const log4js = require('log4js');
+const logLevel = process.env.LOG_LEVEL || 'info';
+
+log4js.configure({
+  appenders: { console: { type: 'console' } },
+  categories: { default: { appenders: ['console'], level: logLevel } }
+});
+
+let logger = null;
+
+const getLogger = () => {
+    if(!logger) {
+        logger = log4js.getLogger();
+    }
+    return logger;
+};
+
+module.exports = {
+    getLogger
+};
+

package.json

@@ -7,7 +7,10 @@
     "test": "mocha --timeout 600000",
     "test-fail-fast": "mocha -b --timeout 600000",
     "run-tests-multiple-times": "node multipleTestExecutionsRunner.js",
-    "run-single-test-file": "node singleTestFileRunner.js"
+    "run-single-test-file": "node singleTestFileRunner.js",
+    "test-fail-fast:info": "LOG_LEVEL=info mocha -b --timeout 600000",
+    "test-fail-fast:debug": "LOG_LEVEL=debug mocha -b --timeout 600000",
+    "test-fail-fast:trace": "LOG_LEVEL=trace mocha -b --timeout 600000"
   },
   "author": "",
   "license": "GPL3",
@@ -30,6 +33,7 @@
     "fs-extra": "^4.0.2",
     "glob": "^7.1.2",
     "lodash": "^4.17.5",
+    "log4js": "^6.9.1",
     "mocha": "^10.1.0",
     "mocha-junit-reporter": "^1.17.0",
     "pegin-address-verificator": "git+https://[email protected]/rsksmart/pegin-address-verifier#v0.4.0",

tests/01_03_54-post-papyrus_coinbase_information.js

@@ -8,12 +8,14 @@ const { getBtcClient } = require('../lib//btc-client-provider');
 const btcEthUnitConverter = require('@rsksmart/btc-eth-unit-converter');
 const { getRskTransactionHelpers } = require('../lib/rsk-tx-helper-provider');
 
-let rskTxHelpers;
+const { getLogger } = require('../logger');
 
 describe('Calling coinbase information methods after papyrus', () => {
 
+    const logger = getLogger();
     let btcClient;
     let rskTxHelper;
+    let rskTxHelpers;
 
     before(() => {
       btcClient = getBtcClient();