diff --git a/lib/2wp-utils.js b/lib/2wp-utils.js index 2b919e95..0db45a40 100644 --- a/lib/2wp-utils.js +++ b/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); diff --git a/lib/bitcoin-runner.js b/lib/bitcoin-runner.js index 4cc8811f..f998dd48 100644 --- a/lib/bitcoin-runner.js +++ b/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; }); diff --git a/lib/btc-utils.js b/lib/btc-utils.js index eb57d753..19556ea9 100644 --- a/lib/btc-utils.js +++ b/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; } diff --git a/lib/federate-runner.js b/lib/federate-runner.js index 799e4b0e..55720347 100644 --- a/lib/federate-runner.js +++ b/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; diff --git a/lib/rsk-utils.js b/lib/rsk-utils.js index 5f47f91d..5de39e20 100644 --- a/lib/rsk-utils.js +++ b/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} 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) { diff --git a/log4js.json b/log4js.json new file mode 100644 index 00000000..4a47ec5d --- /dev/null +++ b/log4js.json @@ -0,0 +1,14 @@ +{ + "appenders": { + "console": { + "type": "console" + } + }, + "categories": { + "default": { + "appenders": ["console"], + "level": "info" + } + } +} + \ No newline at end of file diff --git a/logger.js b/logger.js new file mode 100644 index 00000000..cbfd8008 --- /dev/null +++ b/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 +}; + diff --git a/package-lock.json b/package-lock.json index eb31f865..1be666c2 100644 --- a/package-lock.json +++ b/package-lock.json @@ -27,6 +27,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://git@github.com/rsksmart/pegin-address-verifier#v0.4.0", @@ -1907,6 +1908,14 @@ "node": ">=0.10" } }, + "node_modules/date-format": { + "version": "4.0.14", + "resolved": "https://registry.npmjs.org/date-format/-/date-format-4.0.14.tgz", + "integrity": "sha512-39BOQLs9ZjKh0/patS9nrT8wc3ioX3/eA/zgbKNopnF2wCqJEoxywwwElATYvRsXdnOxA/OQeQoFZ3rFjVajhg==", + "engines": { + "node": ">=4.0" + } + }, "node_modules/debug": { "version": "4.3.4", "resolved": "https://registry.npmjs.org/debug/-/debug-4.3.4.tgz", @@ -3769,6 +3778,21 @@ "url": "https://github.com/sponsors/sindresorhus" } }, + "node_modules/log4js": { + "version": "6.9.1", + "resolved": "https://registry.npmjs.org/log4js/-/log4js-6.9.1.tgz", + "integrity": "sha512-1somDdy9sChrr9/f4UlzhdaGfDR2c/SaD2a4T7qEkG4jTS57/B3qmnjLYePwQ8cqWnUHZI0iAKxMBpCZICiZ2g==", + "dependencies": { + "date-format": "^4.0.14", + "debug": "^4.3.4", + "flatted": "^3.2.7", + "rfdc": "^1.3.0", + "streamroller": "^3.1.5" + }, + "engines": { + "node": ">=8.0" + } + }, "node_modules/loupe": { "version": "2.3.7", "resolved": "https://registry.npmjs.org/loupe/-/loupe-2.3.7.tgz", @@ -4916,6 +4940,11 @@ "eslint": "^7.32.0" } }, + "node_modules/rfdc": { + "version": "1.3.1", + "resolved": "https://registry.npmjs.org/rfdc/-/rfdc-1.3.1.tgz", + "integrity": "sha512-r5a3l5HzYlIC68TpmYKlxWjmOP6wiPJ1vWv2HeLhNsRZMrCkxeqxiHlQ21oXmQ4F3SiryXBHhAD7JZqvOJjFmg==" + }, "node_modules/rimraf": { "version": "3.0.2", "resolved": "https://registry.npmjs.org/rimraf/-/rimraf-3.0.2.tgz", @@ -5386,6 +5415,32 @@ "async": "~0.2.10" } }, + "node_modules/streamroller": { + "version": "3.1.5", + "resolved": "https://registry.npmjs.org/streamroller/-/streamroller-3.1.5.tgz", + "integrity": "sha512-KFxaM7XT+irxvdqSP1LGLgNWbYN7ay5owZ3r/8t77p+EtSUAfUgtl7be3xtqtOmGUl9K9YPO2ca8133RlTjvKw==", + "dependencies": { + "date-format": "^4.0.14", + "debug": "^4.3.4", + "fs-extra": "^8.1.0" + }, + "engines": { + "node": ">=8.0" + } + }, + "node_modules/streamroller/node_modules/fs-extra": { + "version": "8.1.0", + "resolved": "https://registry.npmjs.org/fs-extra/-/fs-extra-8.1.0.tgz", + "integrity": "sha512-yhlQgA6mnOJUKOsRUFsgJdQCvkKhcz8tlZG5HBQfReYZy46OwLcY+Zia0mtdHsOo9y/hP+CxMN0TU9QxoOtG4g==", + "dependencies": { + "graceful-fs": "^4.2.0", + "jsonfile": "^4.0.0", + "universalify": "^0.1.0" + }, + "engines": { + "node": ">=6 <7 || >=8" + } + }, "node_modules/strict-uri-encode": { "version": "1.1.0", "resolved": "https://registry.npmjs.org/strict-uri-encode/-/strict-uri-encode-1.1.0.tgz", diff --git a/package.json b/package.json index eb4659bc..47afa5c2 100644 --- a/package.json +++ b/package.json @@ -30,6 +30,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://git@github.com/rsksmart/pegin-address-verifier#v0.4.0", diff --git a/tests/01_03_54-post-papyrus_coinbase_information.js b/tests/01_03_54-post-papyrus_coinbase_information.js index 992a7ecb..326d840b 100644 --- a/tests/01_03_54-post-papyrus_coinbase_information.js +++ b/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();