chore: various logging improvements (#1666)

Co-authored-by: QuantumExplorer <[email protected]>

packages/dapi/lib/grpcServer/handlers/platform/broadcastStateTransitionHandlerFactory.js

@@ -13,6 +13,7 @@ const {
     BroadcastStateTransitionResponse,
   },
 } = require('@dashevo/dapi-grpc');
+const logger = require('../../../logger');
 
 /**
  * @param {jaysonClient} rpcClient
@@ -38,7 +39,17 @@ function broadcastStateTransitionHandlerFactory(rpcClient, createGrpcErrorFromDr
 
     const tx = Buffer.from(stByteArray).toString('base64');
 
-    const { result, error: jsonRpcError } = await rpcClient.request('broadcast_tx_sync', { tx });
+    let response;
+
+    try {
+      response = await rpcClient.request('broadcast_tx_sync', { tx });
+    } catch (e) {
+      logger.error(e, 'Failed broadcasting state transition');
+
+      throw e;
+    }
+
+    const { result, error: jsonRpcError } = response;
 
     if (jsonRpcError) {
       if (typeof jsonRpcError.data === 'string') {
@@ -59,6 +70,8 @@ function broadcastStateTransitionHandlerFactory(rpcClient, createGrpcErrorFromDr
       const error = new Error();
       Object.assign(error, jsonRpcError);
 
+      logger.error(error, 'Unexpected JSON RPC error during broadcasting state transition');
+
       throw error;
     }
 

packages/rs-drive-abci/src/abci/handler/mod.rs

@@ -109,15 +109,14 @@ where
             last_block_app_hash: state_app_hash.clone(),
         };
 
-        tracing::info!(
+        tracing::debug!(
             protocol_version = latest_platform_version.protocol_version,
             software_version = env!("CARGO_PKG_VERSION"),
             block_version = request.block_version,
             p2p_version = request.p2p_version,
             app_hash = hex::encode(state_app_hash),
             height = state_guard.last_block_height(),
-            "Consensus engine is started from block {}",
-            state_guard.last_block_height(),
+            "Handshake with consensus engine",
         );
 
         if tracing::enabled!(tracing::Level::TRACE) {
@@ -163,7 +162,7 @@ where
         tracing::info!(
             app_hash,
             chain_id,
-            "platform chain initialized, initial state is created"
+            "Platform chain initialized, initial state is created"
         );
 
         Ok(response)
@@ -173,7 +172,7 @@ where
         &self,
         mut request: RequestPrepareProposal,
     ) -> Result<ResponsePrepareProposal, proto::ResponseException> {
-        let _timer = crate::metrics::abci_request_duration("prepare_proposal");
+        let timer = crate::metrics::abci_request_duration("prepare_proposal");
 
         // We should get the latest CoreChainLock from core
         // It is possible that we will not get a chain lock from core, in this case, just don't
@@ -265,9 +264,11 @@ where
 
         // We need to let Tenderdash know about the transactions we should remove from execution
         let valid_tx_count = state_transitions_result.valid_count();
-        let invalid_tx_count = state_transitions_result.invalid_count();
+        let invalid_all_tx_count = state_transitions_result.invalid_count();
         let failed_tx_count = state_transitions_result.failed_count();
         let delayed_tx_count = transactions_exceeding_max_block_size.len();
+        let mut invalid_paid_tx_count = state_transitions_result.invalid_count();
+        let mut invalid_unpaid_tx_count = state_transitions_result.invalid_count();
 
         let mut tx_results = Vec::new();
         let mut tx_records = Vec::new();
@@ -280,13 +281,21 @@ where
             let tx_action = match &state_transition_execution_result {
                 StateTransitionExecutionResult::SuccessfulExecution(_, _) => TxAction::Unmodified,
                 // We have identity to pay for the state transition, so we keep it in the block
-                StateTransitionExecutionResult::PaidConsensusError(_) => TxAction::Unmodified,
+                StateTransitionExecutionResult::PaidConsensusError(_) => {
+                    invalid_paid_tx_count += 1;
+
+                    TxAction::Unmodified
+                }
                 // We don't have any associated identity to pay for the state transition,
                 // so we remove it from the block to prevent spam attacks.
                 // Such state transitions must be invalidated by check tx, but they might
                 // still be added to mempool due to inconsistency between check tx and tx processing
                 // (fees calculation) or malicious proposer.
-                StateTransitionExecutionResult::UnpaidConsensusError(_) => TxAction::Removed,
+                StateTransitionExecutionResult::UnpaidConsensusError(_) => {
+                    invalid_unpaid_tx_count += 1;
+
+                    TxAction::Removed
+                }
                 // We shouldn't include in the block any state transitions that produced an internal error
                 // during execution
                 StateTransitionExecutionResult::DriveAbciError(_) => TxAction::Removed,
@@ -333,15 +342,20 @@ where
             .expect("expected that a block execution context was set");
         block_execution_context.set_proposer_results(Some(response.clone()));
 
+        let elapsed_time_ms = timer.elapsed().as_millis();
+
         tracing::info!(
-            invalid_tx_count,
+            invalid_paid_tx_count,
+            invalid_unpaid_tx_count,
             valid_tx_count,
             delayed_tx_count,
             failed_tx_count,
-            "Prepared proposal with {} transitions for height: {}, round: {}",
-            valid_tx_count,
+            invalid_unpaid_tx_count,
+            "Prepared proposal with {} transitions for height: {}, round: {} in {} ms",
+            valid_tx_count + invalid_paid_tx_count,
             request.height,
             request.round,
+            elapsed_time_ms,
         );
 
         Ok(response)
@@ -351,7 +365,7 @@ where
         &self,
         mut request: RequestProcessProposal,
     ) -> Result<ResponseProcessProposal, proto::ResponseException> {
-        let _timer = crate::metrics::abci_request_duration("process_proposal");
+        let timer = crate::metrics::abci_request_duration("process_proposal");
 
         let mut block_execution_context_guard =
             self.platform.block_execution_context.write().unwrap();
@@ -561,13 +575,17 @@ where
                 consensus_param_updates: None,
             };
 
+            let elapsed_time_ms = timer.elapsed().as_millis();
+
             tracing::info!(
                 invalid_tx_count,
                 valid_tx_count,
-                "Processed proposal with {} transactions for height: {}, round: {}",
-                valid_tx_count,
+                elapsed_time_ms,
+                "Processed proposal with {} transactions for height: {}, round: {} in {} ms",
+                valid_tx_count + invalid_tx_count,
                 request.height,
                 request.round,
+                elapsed_time_ms,
             );
 
             Ok(response)

packages/rs-drive-abci/src/metrics.rs

@@ -56,6 +56,11 @@ impl HistogramTiming {
             start: Instant::now(),
         }
     }
+
+    /// Returns the elapsed time since the metric was started.
+    pub fn elapsed(&self) -> std::time::Duration {
+        self.start.elapsed()
+    }
 }
 
 impl Drop for HistogramTiming {