chore(drive): comprehensive logging for same block execution

packages/js-drive/lib/abci/handlers/extendVoteHandlerFactory.js

@@ -17,11 +17,16 @@ const {
 function extendVoteHandlerFactory(proposalBlockExecutionContext) {
   /**
    * @typedef extendVoteHandler
-   * @param {Object} request
-   * @param {number} request.round
    * @return {Promise<abci.ResponseExtendVote>}
    */
   async function extendVoteHandler() {
+    const consensusLogger = proposalBlockExecutionContext.getConsensusLogger()
+      .child({
+        abciMethod: 'extendVote',
+      });
+
+    consensusLogger.debug('ExtendVote ABCI method requested');
+
     const unsignedWithdrawalTransactionsMap = proposalBlockExecutionContext
       .getWithdrawalTransactionsMap();
 
@@ -32,6 +37,25 @@ function extendVoteHandlerFactory(proposalBlockExecutionContext) {
         extension: Buffer.from(txHashHex, 'hex'),
       }));
 
+    const voteExtensionTypeName = {
+      [VoteExtensionType.DEFAULT]: 'default',
+      [VoteExtensionType.THRESHOLD_RECOVER]: 'threshold recovery',
+    };
+
+    voteExtensions.forEach(({ extension, type }) => {
+      const extensionString = extension.toString('hex');
+
+      const extensionTruncatedString = extensionString.substring(
+        0,
+        Math.min(30, extensionString.length),
+      );
+
+      consensusLogger.debug({
+        type,
+        extension: extensionString,
+      }, `Vote extended to obtain ${voteExtensionTypeName} signature for ${extensionTruncatedString}... payload`);
+    });
+
     return new ResponseExtendVote({
       voteExtensions,
     });

packages/js-drive/lib/abci/handlers/finalizeBlockHandlerFactory.js

@@ -2,6 +2,7 @@ const {
   tendermint: {
     abci: {
       ResponseFinalizeBlock,
+      RequestProcessProposal,
     },
   },
 } = require('@dashevo/abci/types');
@@ -11,13 +12,12 @@ const {
  * @return {finalizeBlockHandler}
  * @param {GroveDBStore} groveDBStore
  * @param {BlockExecutionContextRepository} blockExecutionContextRepository
- * @param {LRUCache} dataContractCache
  * @param {CoreRpcClient} coreRpcClient
  * @param {BaseLogger} logger
  * @param {ExecutionTimer} executionTimer
  * @param {BlockExecutionContext} latestBlockExecutionContext
  * @param {BlockExecutionContext} proposalBlockExecutionContext
- * @param {processProposalHandler} processProposalHandler
+ * @param {processProposal} processProposal
  */
 function finalizeBlockHandlerFactory(
   groveDBStore,
@@ -27,7 +27,7 @@ function finalizeBlockHandlerFactory(
   executionTimer,
   latestBlockExecutionContext,
   proposalBlockExecutionContext,
-  processProposalHandler,
+  processProposal,
 ) {
   /**
    * @typedef finalizeBlockHandler
@@ -44,16 +44,20 @@ function finalizeBlockHandlerFactory(
 
     const consensusLogger = logger.child({
       height: height.toString(),
+      round,
       abciMethod: 'finalizeBlock',
     });
 
     consensusLogger.debug('FinalizeBlock ABCI method requested');
     consensusLogger.trace({ abciRequest: request });
 
-    if (proposalBlockExecutionContext.getRound() !== round) {
-      consensusLogger.warn(
-        `Finalizing previously executed round ${round} instead of the last known ${proposalBlockExecutionContext.getRound()}`,
-      );
+    const lastProcessedRound = proposalBlockExecutionContext.getRound();
+
+    if (lastProcessedRound !== round) {
+      consensusLogger.warn({
+        lastProcessedRound,
+        round,
+      }, `Finalizing previously executed round ${round} instead of the last known ${lastProcessedRound}`);
 
       const {
         block: {
@@ -69,7 +73,7 @@ function finalizeBlockHandlerFactory(
         },
       } = request;
 
-      await processProposalHandler({
+      const processProposalRequest = new RequestProcessProposal({
         height,
         txs,
         coreChainLockedHeight,
@@ -79,21 +83,27 @@ function finalizeBlockHandlerFactory(
         proposerProTxHash,
         round,
       });
+
+      await processProposal(processProposalRequest, consensusLogger);
+
+      // Revert consensus logger
+      proposalBlockExecutionContext.setConsensusLogger(consensusLogger);
     }
 
     proposalBlockExecutionContext.setLastCommitInfo(commitInfo);
 
-    // Store block execution context
+    // Store proposal block execution context
     await blockExecutionContextRepository.store(
       proposalBlockExecutionContext,
       {
         useTransaction: true,
       },
     );
 
-    // Commit the current block db transactions
+    // Commit the current block db transactions into storage
     await groveDBStore.commitTransaction();
 
+    // Update last block execution context with proposal data
     latestBlockExecutionContext.populate(proposalBlockExecutionContext);
 
     // Send withdrawal transactions to Core
@@ -124,11 +134,11 @@ function finalizeBlockHandlerFactory(
 
     const blockExecutionTimings = executionTimer.stopTimer('blockExecution');
 
-    consensusLogger.trace(
+    consensusLogger.info(
       {
         timings: blockExecutionTimings,
       },
-      `Block #${height} execution took ${blockExecutionTimings} seconds`,
+      `Block #${height} finalized in ${round + 1} round(s) and ${blockExecutionTimings} seconds`,
     );
 
     return new ResponseFinalizeBlock();

packages/js-drive/lib/abci/handlers/prepareProposalHandlerFactory.js

@@ -22,6 +22,7 @@ const txAction = {
  * @param {beginBlock} beginBlock
  * @param {endBlock} endBlock
  * @param {createCoreChainLockUpdate} createCoreChainLockUpdate
+ * @param {ExecutionTimer} executionTimer
  * @return {prepareProposalHandler}
  */
 function prepareProposalHandlerFactory(
@@ -31,6 +32,7 @@ function prepareProposalHandlerFactory(
   beginBlock,
   endBlock,
   createCoreChainLockUpdate,
+  executionTimer,
 ) {
   /**
    * @typedef prepareProposalHandler
@@ -49,20 +51,18 @@ function prepareProposalHandlerFactory(
       proposerProTxHash,
       round,
     } = request;
+
     const consensusLogger = logger.child({
       height: height.toString(),
+      round,
       abciMethod: 'prepareProposal',
     });
 
-    consensusLogger.info(
-      {
-        height,
-      },
-      `Prepare proposal #${height}`,
-    );
     consensusLogger.debug('PrepareProposal ABCI method requested');
     consensusLogger.trace({ abciRequest: request });
 
+    consensusLogger.info(`Preparing a block proposal for height #${height} round #${round}`);
+
     await beginBlock(
       {
         lastCommitInfo,
@@ -119,6 +119,7 @@ function prepareProposalHandlerFactory(
       txResults.push(txResult);
     }
 
+    // Revert consensus logger after deliverTx
     proposalBlockExecutionContext.setConsensusLogger(consensusLogger);
 
     const coreChainLockUpdate = await createCoreChainLockUpdate(round, consensusLogger);
@@ -134,13 +135,19 @@ function prepareProposalHandlerFactory(
       coreChainLockedHeight,
     }, consensusLogger);
 
+    const roundExecutionTime = executionTimer.getTimer('roundExecution', true);
+
+    const mempoolTxCount = txs.length - validTxCount - invalidTxCount;
+
     consensusLogger.info(
       {
+        roundExecutionTime,
         validTxCount,
         invalidTxCount,
+        mempoolTxCount,
       },
-      `Prepare proposal #${height} with appHash ${appHash.toString('hex').toUpperCase()}`
-      + ` (valid txs = ${validTxCount}, invalid txs = ${invalidTxCount})`,
+      `Prepared block proposal for height #${height} with appHash ${appHash.toString('hex').toUpperCase()}`
+      + ` in ${roundExecutionTime} seconds (valid txs = ${validTxCount}, invalid txs = ${invalidTxCount}, mempool txs = ${mempoolTxCount})`,
     );
 
     proposalBlockExecutionContext.setPrepareProposalResult({