diff --git a/framework-plugins/lisk-framework-chain-connector-plugin/src/block_event_handler.ts b/framework-plugins/lisk-framework-chain-connector-plugin/src/block_event_handler.ts index 46442f7294..33a3dd3a0d 100644 --- a/framework-plugins/lisk-framework-chain-connector-plugin/src/block_event_handler.ts +++ b/framework-plugins/lisk-framework-chain-connector-plugin/src/block_event_handler.ts @@ -113,12 +113,24 @@ export class BlockEventHandler { // On a new block start with CCU creation process this._sendingChainAPIClient.subscribe( 'chain_newBlock', - async (data?: Record) => this._handleNewBlock(data), + async (data?: Record) => { + try { + await this._handleNewBlock(data); + } catch (error) { + this._logger.error({ err: error as Error }, 'Failed to handle new block.'); + } + }, ); this._sendingChainAPIClient.subscribe( 'chain_deleteBlock', - async (data?: Record) => this._deleteBlockHandler(data), + async (data?: Record) => { + try { + await this._deleteBlockHandler(data); + } catch (error) { + this._logger.error({ err: error as Error }, 'Failed to handle delete block.'); + } + }, ); // Initialize the receiving chain client in the end of load so not to miss the initial new blocks @@ -129,12 +141,8 @@ export class BlockEventHandler { const { blockHeader: receivedBlock } = data as unknown as Data; const newBlockHeader = chain.BlockHeader.fromJSON(receivedBlock).toObject(); - try { - await this._saveOnNewBlock(newBlockHeader); - } catch (error) { - this._logger.error({ err: error as Error }, 'Error occurred while saving data on new block.'); - return; - } + await this._saveOnNewBlock(newBlockHeader); + const nodeInfo = await this._sendingChainAPIClient.getNodeInfo(); if (nodeInfo.syncing) { @@ -148,6 +156,7 @@ export class BlockEventHandler { chainAccount = await this._receivingChainAPIClient.getChainAccount(this._ownChainID); } catch (error) { // If receivingChainAPIClient is not ready then still save data on new block + // Error is handled within this function so need to have try/catch await this._initializeReceivingChainClient(); this._logger.error( { err: error as Error }, @@ -166,13 +175,13 @@ export class BlockEventHandler { } this._lastCertificate = chainAccount.lastCertificate; - this._logger.debug( + this._logger.info( `Last certificate value has been set with height ${this._lastCertificate.height}`, ); const numOfBlocksSinceLastCertificate = newBlockHeader.height - this._lastCertificate.height; if (this._ccuFrequency > numOfBlocksSinceLastCertificate) { - this._logger.debug( + this._logger.info( { ccuFrequency: this._ccuFrequency, nextPossibleCCUHeight: this._ccuFrequency - numOfBlocksSinceLastCertificate, @@ -196,59 +205,53 @@ export class BlockEventHandler { } this._isReceivingChainRegistered = true; } + let computedCCUParams; - try { - // Compute CCU when there is no pending CCU that was sent earlier - if (this._lastSentCCUTxID === '') { - computedCCUParams = await this._ccuHandler.computeCCU( - this._lastCertificate, - this._lastIncludedCCMOnReceivingChain, - ); - } else { - this._logger.info( - `Still pending CCU on the receiving CCU with tx ID ${this._lastSentCCUTxID}`, - ); - return; - } - } catch (error) { - this._logger.error( - { err: error }, - `Error occurred while computing CCU for the blockHeader at height: ${newBlockHeader.height}`, + // Compute CCU when there is no pending CCU that was sent earlier + if (this._lastSentCCUTxID === '') { + computedCCUParams = await this._ccuHandler.computeCCU( + this._lastCertificate, + this._lastIncludedCCMOnReceivingChain, + ); + } else { + this._logger.info( + `Still pending CCU on the receiving CCU with tx ID ${this._lastSentCCUTxID}`, ); return; } - if (computedCCUParams) { - try { - const ccuSubmitResult = await this._ccuHandler.submitCCU( - computedCCUParams.ccuParams, - this._lastSentCCUTxID, - ); - if (ccuSubmitResult) { - this._lastSentCCUTxID = ccuSubmitResult; - // Wait until 1 hour - this._sentCCUTxTimeout = setTimeout(() => { - this._lastSentCCUTxID = ''; - clearTimeout(this._sentCCUTxTimeout); - }, DEFAULT_SENT_CCU_TIMEOUT); - // If CCU was sent successfully then save the lastSentCCM if any - if (computedCCUParams.lastCCMToBeSent) { - this._lastSentCCM = computedCCUParams.lastCCMToBeSent; - } - return; - } - this._logger.debug( - `Last sent CCU tx with ID ${this._lastSentCCUTxID} was not yet included in the receiving chain.`, - ); - } catch (error) { - this._logger.error( - { err: error }, - `Error occured while submitting CCU for the blockHeader at height: ${newBlockHeader.height}`, + if (!computedCCUParams) { + this._logger.info(`No CCU params were generated for block height ${newBlockHeader.height}`); + + return; + } + + const ccuSubmitResult = await this._ccuHandler.submitCCU( + computedCCUParams.ccuParams, + this._lastSentCCUTxID, + ); + if (ccuSubmitResult) { + this._lastSentCCUTxID = ccuSubmitResult; + // Wait until 1 hour + this._sentCCUTxTimeout = setTimeout(() => { + this._lastSentCCUTxID = ''; + clearTimeout(this._sentCCUTxTimeout); + }, DEFAULT_SENT_CCU_TIMEOUT); + // If CCU was sent successfully then save the lastSentCCM if any + if (computedCCUParams.lastCCMToBeSent) { + this._lastSentCCM = computedCCUParams.lastCCMToBeSent; + this._logger.info( + `Last sent CCM with nonce ${this._lastSentCCM.nonce.toString()} is saved.`, ); } + this._logger.info(`CCU transaction was successfully sent with Tx ID ${ccuSubmitResult}.`); + return; } + this._logger.info( + `Last sent CCU tx with ID ${this._lastSentCCUTxID} was not yet included in the receiving chain.`, + ); } private async _saveOnNewBlock(newBlockHeader: BlockHeader) { diff --git a/framework-plugins/lisk-framework-chain-connector-plugin/src/ccu_handler.ts b/framework-plugins/lisk-framework-chain-connector-plugin/src/ccu_handler.ts index 4c036c2bc6..d1849aae3d 100644 --- a/framework-plugins/lisk-framework-chain-connector-plugin/src/ccu_handler.ts +++ b/framework-plugins/lisk-framework-chain-connector-plugin/src/ccu_handler.ts @@ -319,8 +319,6 @@ export class CCUHandler { } // Save the sent CCU await this._db.setCCUTransaction(tx.toObject()); - // Update logs - this._logger.info({ transactionID: result.transactionId }, 'Sent CCU transaction'); return result.transactionId; } diff --git a/framework-plugins/lisk-framework-chain-connector-plugin/test/unit/block_event_handler.spec.ts b/framework-plugins/lisk-framework-chain-connector-plugin/test/unit/block_event_handler.spec.ts index 345b4a51e2..141cea6590 100644 --- a/framework-plugins/lisk-framework-chain-connector-plugin/test/unit/block_event_handler.spec.ts +++ b/framework-plugins/lisk-framework-chain-connector-plugin/test/unit/block_event_handler.spec.ts @@ -225,17 +225,14 @@ describe('BlockEventHandler', () => { clearTimeout(blockEventHandler['_sentCCUTxTimeout']); }); - it('should log error and return when _saveOnNewBlock fails', async () => { + it('should throw when _saveOnNewBlock fails', async () => { const fakeError = new Error('Error occurred while save on new block'); saveOnNewBlockMock.mockRejectedValue(fakeError); jest.spyOn(initArgs.logger as Logger, 'error'); - await blockEventHandler['_handleNewBlock']({ blockHeader: sampleBlockHeader }); - - expect((initArgs.logger as Logger).error).toHaveBeenCalledWith( - { err: fakeError }, - 'Error occurred while saving data on new block.', - ); + await expect( + blockEventHandler['_handleNewBlock']({ blockHeader: sampleBlockHeader }), + ).rejects.toThrow(fakeError); }); it('should return after getNodeInfo when the node is syncing', async () => { @@ -283,14 +280,14 @@ describe('BlockEventHandler', () => { saveOnNewBlockMock.mockResolvedValue({}); receivingChainAPIClientMock.getChainAccount.mockResolvedValue(sidechainChainAccount); sendingChainAPIClientMock.getNodeInfo.mockResolvedValue({ syncing: false }); - jest.spyOn(initArgs.logger as Logger, 'debug'); + jest.spyOn(initArgs.logger as Logger, 'info'); (blockEventHandler as any)['_ccuFrequency'] = 100; await blockEventHandler['_handleNewBlock']({ blockHeader: sampleBlockHeader }); - expect((initArgs.logger as Logger).debug).toHaveBeenCalledWith( + expect((initArgs.logger as Logger).info).toHaveBeenCalledWith( `Last certificate value has been set with height ${sidechainLastCertificate.height}`, ); - expect((initArgs.logger as Logger).debug).toHaveBeenCalledWith( + expect((initArgs.logger as Logger).info).toHaveBeenCalledWith( { ccuFrequency: 100, nextPossibleCCUHeight: @@ -300,6 +297,19 @@ describe('BlockEventHandler', () => { ); }); + it('should throw error when getChainAccount fails on sending chain client', async () => { + const fakeError = new Error('Failed to get chain account'); + saveOnNewBlockMock.mockResolvedValue({}); + receivingChainAPIClientMock.getChainAccount.mockResolvedValue(sidechainChainAccount); + sendingChainAPIClientMock.getNodeInfo.mockResolvedValue({ syncing: false }); + sendingChainAPIClientMock.getChainAccount.mockRejectedValue(fakeError); + jest.spyOn(initArgs.logger as Logger, 'error'); + + await expect( + blockEventHandler['_handleNewBlock']({ blockHeader: sampleBlockHeader }), + ).rejects.toThrow(fakeError); + }); + it('should log message and return when receiving chain is not registered yet', async () => { saveOnNewBlockMock.mockResolvedValue({}); receivingChainAPIClientMock.getChainAccount.mockResolvedValue(sidechainChainAccount); @@ -340,15 +350,11 @@ describe('BlockEventHandler', () => { blockEventHandler['_isReceivingChainRegistered'] = true; blockEventHandler['_lastSentCCUTxID'] = lastSentCCUTxID; - await blockEventHandler['_handleNewBlock']({ blockHeader: sampleBlockHeader }); - - expect((initArgs.logger as Logger).error).toHaveBeenCalledWith( - { err: fakeError }, - `Error occurred while computing CCU for the blockHeader at height: ${ - sampleBlockHeader.height as number - }`, - ); + await expect( + blockEventHandler['_handleNewBlock']({ blockHeader: sampleBlockHeader }), + ).rejects.toThrow(fakeError); }); + it('should log error when submitCCU fails', async () => { const lastSentCCUTxID = ''; const fakeError = new Error('Failed at computeCCU'); @@ -365,21 +371,17 @@ describe('BlockEventHandler', () => { blockEventHandler['_isReceivingChainRegistered'] = true; blockEventHandler['_lastSentCCUTxID'] = lastSentCCUTxID; - await blockEventHandler['_handleNewBlock']({ blockHeader: sampleBlockHeader }); - - expect((initArgs.logger as Logger).error).toHaveBeenCalledWith( - { err: fakeError }, - `Error occured while submitting CCU for the blockHeader at height: ${ - sampleBlockHeader.height as number - }`, - ); + await expect( + blockEventHandler['_handleNewBlock']({ blockHeader: sampleBlockHeader }), + ).rejects.toThrow(fakeError); }); + it('should log message when submitCCU returns undefined', async () => { const lastSentCCUTxID = ''; saveOnNewBlockMock.mockResolvedValue({}); receivingChainAPIClientMock.getChainAccount.mockResolvedValue(sidechainChainAccount); sendingChainAPIClientMock.getNodeInfo.mockResolvedValue({ syncing: false }); - jest.spyOn(initArgs.logger as Logger, 'debug'); + jest.spyOn(initArgs.logger as Logger, 'info'); jest.spyOn(blockEventHandler['_ccuHandler'], 'computeCCU').mockResolvedValue({ ccuParams: {} as any, lastCCMToBeSent: {} as any, @@ -391,7 +393,7 @@ describe('BlockEventHandler', () => { await blockEventHandler['_handleNewBlock']({ blockHeader: sampleBlockHeader }); - expect((initArgs.logger as Logger).debug).toHaveBeenCalledWith( + expect((initArgs.logger as Logger).info).toHaveBeenCalledWith( `Last sent CCU tx with ID ${lastSentCCUTxID} was not yet included in the receiving chain.`, ); }); @@ -401,10 +403,12 @@ describe('BlockEventHandler', () => { saveOnNewBlockMock.mockResolvedValue({}); receivingChainAPIClientMock.getChainAccount.mockResolvedValue(sidechainChainAccount); sendingChainAPIClientMock.getNodeInfo.mockResolvedValue({ syncing: false }); - jest.spyOn(initArgs.logger as Logger, 'debug'); + jest.spyOn(initArgs.logger as Logger, 'info'); jest.spyOn(blockEventHandler['_ccuHandler'], 'computeCCU').mockResolvedValue({ ccuParams: {} as any, - lastCCMToBeSent: {} as any, + lastCCMToBeSent: { + nonce: BigInt(1), + } as any, }); jest.spyOn(blockEventHandler['_ccuHandler'], 'submitCCU').mockResolvedValue('txID'); @@ -413,7 +417,9 @@ describe('BlockEventHandler', () => { await blockEventHandler['_handleNewBlock']({ blockHeader: sampleBlockHeader }); expect(blockEventHandler['_lastSentCCUTxID']).toBe('txID'); - expect(blockEventHandler['_lastSentCCM']).toEqual({}); + expect(blockEventHandler['_lastSentCCM']).toEqual({ + nonce: BigInt(1), + }); }); }); diff --git a/framework-plugins/lisk-framework-chain-connector-plugin/test/unit/ccu_handler.spec.ts b/framework-plugins/lisk-framework-chain-connector-plugin/test/unit/ccu_handler.spec.ts index d3036faeb5..1fd65d4d73 100644 --- a/framework-plugins/lisk-framework-chain-connector-plugin/test/unit/ccu_handler.spec.ts +++ b/framework-plugins/lisk-framework-chain-connector-plugin/test/unit/ccu_handler.spec.ts @@ -837,10 +837,6 @@ describe('CCUHandler', () => { expect(result).toEqual(ccuTx.id.toString('hex')); expect(chainConnectorDBMock.setCCUTransaction).toHaveBeenCalledWith(ccuTx.toObject()); - expect((initArgs.logger as Logger).info).toHaveBeenCalledWith( - { transactionID: result }, - 'Sent CCU transaction', - ); }); });