tweak: Add new debug! logs before commit batches and user transaction executions

Author: dhedey

core-rust/state-manager/src/committer.rs

@@ -74,6 +74,7 @@ pub struct Committer {
     execution_cache_manager: Arc<ExecutionCacheManager>,
     protocol_manager: Arc<ProtocolManager>,
     ledger_metrics: Arc<LedgerMetrics>,
+    formatter: Arc<Formatter>,
 }
 
 impl Committer {
@@ -86,6 +87,7 @@ impl Committer {
         execution_cache_manager: Arc<ExecutionCacheManager>,
         protocol_manager: Arc<ProtocolManager>,
         ledger_metrics: Arc<LedgerMetrics>,
+        formatter: Arc<Formatter>,
     ) -> Self {
         Self {
             database,
@@ -95,6 +97,7 @@ impl Committer {
             execution_cache_manager,
             protocol_manager,
             ledger_metrics,
+            formatter,
         }
     }
 }
@@ -171,6 +174,12 @@ impl Committer {
             .start_series_execution(database.deref());
         self.verify_pre_commit_invariants(&series_executor, transactions.len(), &proof);
 
+        debug!(
+            "Starting commit of normal transaction batch on top of existing state version {} until state version {}",
+            series_executor.latest_state_version(),
+            commit_state_version,
+        );
+
         // Naively, the below could be a part of pre-commit invariants (see above); however, we do
         // not want to panic, but rather return an `Err` for the consensus layer, since a
         // transaction root mismatch may mean a malicious peer (and not our inconsistent state).
@@ -221,6 +230,16 @@ impl Committer {
             let hashes = validated.create_hashes();
             let executable = validated.create_ledger_executable();
 
+            if let Some(user_hashes) = hashes.as_user() {
+                debug!(
+                    "Starting commit execution of {} for {:?}",
+                    user_hashes
+                        .transaction_intent_hash
+                        .display(&*self.formatter),
+                    series_executor.latest_state_version().next().unwrap(),
+                );
+            }
+
             let commit = series_executor
                 .execute_and_update_state(&executable, &hashes, "prepared")
                 .expect("cannot execute transaction to be committed");
@@ -304,6 +323,12 @@ impl Committer {
             .start_series_execution(database.deref());
         self.verify_pre_commit_invariants(&series_executor, transactions.len(), &proof);
 
+        debug!(
+            "Starting commit of system transaction batch on top of existing state version {} until state version {}",
+            series_executor.latest_state_version(),
+            proof.ledger_header.state_version,
+        );
+
         let mut commit_bundle_builder = series_executor.start_commit_builder();
         let mut transactions_metrics_data = Vec::new();
         for ProcessedLedgerTransaction {
@@ -312,6 +337,15 @@ impl Committer {
             hashes,
         } in transactions
         {
+            if let Some(user_hashes) = hashes.as_user() {
+                debug!(
+                    "Starting commit execution of {} for {:?}",
+                    user_hashes
+                        .transaction_intent_hash
+                        .display(&*self.formatter),
+                    series_executor.latest_state_version().next().unwrap(),
+                );
+            }
             let mut commit = series_executor
                 .execute_and_update_state(&executable, &hashes, "system transaction")
                 .expect("cannot execute system transaction");

core-rust/state-manager/src/formatter.rs

@@ -0,0 +1,46 @@
+use crate::prelude::*;
+
+pub struct Formatter {
+    address_encoder: AddressBech32Encoder,
+    transaction_hash_encoder: TransactionHashBech32Encoder,
+}
+
+impl Formatter {
+    pub fn new(network_definition: &NetworkDefinition) -> Self {
+        let address_encoder = AddressBech32Encoder::new(network_definition);
+        let hash_encoder = TransactionHashBech32Encoder::new(network_definition);
+
+        Self {
+            address_encoder,
+            transaction_hash_encoder: hash_encoder,
+        }
+    }
+
+    pub fn address_encoder(&self) -> &AddressBech32Encoder {
+        &self.address_encoder
+    }
+}
+
+impl<'a> From<&'a Formatter> for ScryptoValueDisplayContext<'a> {
+    fn from(formatter: &'a Formatter) -> Self {
+        ScryptoValueDisplayContext {
+            address_bech32_encoder: Some(&formatter.address_encoder),
+        }
+    }
+}
+
+impl<'a> From<&'a Formatter> for AddressDisplayContext<'a> {
+    fn from(formatter: &'a Formatter) -> Self {
+        AddressDisplayContext {
+            encoder: Some(&formatter.address_encoder),
+        }
+    }
+}
+
+impl<'a> From<&'a Formatter> for TransactionHashDisplayContext<'a> {
+    fn from(formatter: &'a Formatter) -> Self {
+        TransactionHashDisplayContext {
+            encoder: Some(&formatter.transaction_hash_encoder),
+        }
+    }
+}

core-rust/state-manager/src/jni/mempool.rs

@@ -84,9 +84,8 @@ extern "system" fn Java_com_radixdlt_mempool_RustMempool_add(
             JNINodeRustEnvironment::get_mempool_manager(&env, j_node_rust_env)
                 .add_if_committable(MempoolAddSource::MempoolSync, transaction, false)
                 .map_err(|err| {
-                    let encoder =
-                        JNINodeRustEnvironment::get_address_encoder(&env, j_node_rust_env);
-                    MempoolAddErrorJava::new_from(err, (&encoder).into())
+                    let formatter = JNINodeRustEnvironment::get_formatter(&env, j_node_rust_env);
+                    MempoolAddErrorJava::new_from(err, &formatter)
                 })?;
             Ok(())
         },
@@ -203,7 +202,7 @@ enum MempoolAddErrorJava {
 }
 
 impl MempoolAddErrorJava {
-    fn new_from(err: MempoolAddError, display_context: ScryptoValueDisplayContext) -> Self {
+    fn new_from(err: MempoolAddError, formatter: &Formatter) -> Self {
         match err {
             MempoolAddError::PriorityThresholdNotMet {
                 min_tip_basis_points_required: min_tip_percentage_required,
@@ -214,7 +213,7 @@ impl MempoolAddErrorJava {
             },
             MempoolAddError::Duplicate(hash) => MempoolAddErrorJava::Duplicate(hash),
             MempoolAddError::Rejected(rejection, _) => {
-                MempoolAddErrorJava::Rejected(rejection.reason.to_string(display_context))
+                MempoolAddErrorJava::Rejected(rejection.reason.to_string(formatter))
             }
         }
     }

core-rust/state-manager/src/jni/node_rust_environment.rs

@@ -214,9 +214,9 @@ impl JNINodeRustEnvironment {
             .clone()
     }
 
-    pub fn get_address_encoder(env: &JNIEnv, j_node_rust_env: JObject) -> AddressBech32Encoder {
+    pub fn get_formatter(env: &JNIEnv, j_node_rust_env: JObject) -> Arc<Formatter> {
         let env = Self::get(env, j_node_rust_env);
-        AddressBech32Encoder::new(&env.state_manager.network_definition)
+        env.state_manager.formatter.clone()
     }
 
     pub fn get_database(

core-rust/state-manager/src/jni/test_state_reader.rs

@@ -117,7 +117,7 @@ extern "system" fn Java_com_radixdlt_testutil_TestStateReader_getTransactionAtSt
             let local_transaction_execution =
                 database.get_committed_local_transaction_execution(state_version)?;
 
-            let encoder = JNINodeRustEnvironment::get_address_encoder(&env, j_rust_global_context);
+            let formatter = JNINodeRustEnvironment::get_formatter(&env, j_rust_global_context);
 
             Some(ExecutedTransaction {
                 ledger_transaction_hash: committed_identifiers
@@ -129,7 +129,9 @@ extern "system" fn Java_com_radixdlt_testutil_TestStateReader_getTransactionAtSt
                 },
                 error_message: match local_transaction_execution.outcome {
                     DetailedTransactionOutcome::Success(_) => None,
-                    DetailedTransactionOutcome::Failure(error) => Some(error.to_string(&encoder)),
+                    DetailedTransactionOutcome::Failure(error) => {
+                        Some(error.to_string(&*formatter))
+                    }
                 },
                 consensus_receipt_bytes: scrypto_encode(
                     &committed_ledger_transaction_receipt.get_consensus_receipt(),

core-rust/state-manager/src/lib.rs

@@ -67,6 +67,7 @@ extern crate core;
 mod accumulator_tree;
 mod commit_bundle;
 mod committer;
+mod formatter;
 pub mod jni;
 mod limits;
 mod mempool;
@@ -91,6 +92,7 @@ pub mod prelude {
     pub(crate) use node_common::prelude::*;
 
     // Public prelude
+    pub use crate::formatter::*;
     pub use crate::mempool::*;
     pub use crate::protocol::*;
     pub use crate::query::*;

core-rust/state-manager/src/state_manager.rs

@@ -180,6 +180,7 @@ pub struct StateManager {
     pub protocol_manager: Arc<ProtocolManager>,
     pub protocol_update_executor: Arc<NodeProtocolUpdateExecutor>,
     pub ledger_metrics: Arc<LedgerMetrics>,
+    pub formatter: Arc<Formatter>,
 }
 
 impl StateManager {
@@ -222,6 +223,8 @@ impl StateManager {
 
         let database = Arc::new(lock_factory.named("database").new_db_lock(raw_db));
 
+        let formatter = Arc::new(Formatter::new(&network_definition));
+
         let transaction_validator = Arc::new(lock_factory.named("validator").new_rwlock(
             TransactionValidator::new(database.access_direct().deref(), &network_definition),
         ));
@@ -266,6 +269,7 @@ impl StateManager {
                     database.clone(),
                     execution_configurator.clone(),
                     transaction_validator.clone(),
+                    formatter.clone(),
                 ),
             ));
         let cached_committability_validator = CachedCommittabilityValidator::new(
@@ -307,6 +311,7 @@ impl StateManager {
             transaction_validator.clone(),
             vertex_limits_config.unwrap_or_default(),
             metrics_registry,
+            formatter.clone(),
         ));
 
         let ledger_metrics = Arc::new(LedgerMetrics::new(
@@ -325,6 +330,7 @@ impl StateManager {
             execution_cache_manager.clone(),
             protocol_manager.clone(),
             ledger_metrics.clone(),
+            formatter.clone(),
         ));
 
         let system_executor = Arc::new(SystemExecutor::new(
@@ -387,6 +393,7 @@ impl StateManager {
             protocol_manager,
             protocol_update_executor,
             ledger_metrics,
+            formatter,
         };
 
         state_manager.resume_protocol_updates_if_any();

core-rust/state-manager/src/transaction/preparation.rs

@@ -71,6 +71,7 @@ pub struct Preparator {
     transaction_validator: Arc<RwLock<TransactionValidator>>,
     vertex_prepare_metrics: VertexPrepareMetrics,
     vertex_limits_config: VertexLimitsConfig,
+    formatter: Arc<Formatter>,
 }
 
 impl Preparator {
@@ -81,6 +82,7 @@ impl Preparator {
         transaction_validator: Arc<RwLock<TransactionValidator>>,
         vertex_limits_config: VertexLimitsConfig,
         metrics_registry: &MetricRegistry,
+        formatter: Arc<Formatter>,
     ) -> Self {
         Self {
             database,
@@ -89,6 +91,7 @@ impl Preparator {
             transaction_validator,
             vertex_prepare_metrics: VertexPrepareMetrics::new(metrics_registry),
             vertex_limits_config,
+            formatter,
         }
     }
 
@@ -454,6 +457,14 @@ impl Preparator {
             let ledger_transaction_hash = prepared_details.hashes.ledger_transaction_hash;
             let invalid_at_epoch = prepared_details.end_epoch_exclusive;
 
+            debug!(
+                "Starting prepare execution of {} for {:?}",
+                user_hashes
+                    .transaction_intent_hash
+                    .display(&*self.formatter),
+                series_executor.latest_state_version().next().unwrap(),
+            );
+
             // Note that we're using a "_no_state_update" variant here, because
             // we may still reject some *committable* transactions if they exceed
             // the limit, which would otherwise spoil the internal StateTracker.

core-rust/state-manager/src/transaction/validation.rs

@@ -26,18 +26,21 @@ pub struct CommittabilityValidator {
     database: Arc<DbLock<ActualStateManagerDatabase>>,
     execution_configurator: Arc<ExecutionConfigurator>,
     transaction_validator: Arc<RwLock<TransactionValidator>>,
+    formatter: Arc<Formatter>,
 }
 
 impl CommittabilityValidator {
     pub fn new(
         database: Arc<DbLock<ActualStateManagerDatabase>>,
         execution_configurator: Arc<ExecutionConfigurator>,
         transaction_validator: Arc<RwLock<TransactionValidator>>,
+        formatter: Arc<Formatter>,
     ) -> Self {
         Self {
             database,
             execution_configurator,
             transaction_validator,
+            formatter,
         }
     }
 
@@ -93,6 +96,13 @@ impl CommittabilityValidator {
             };
         }
 
+        trace!(
+            "Starting mempool execution of {}",
+            user_hashes
+                .transaction_intent_hash
+                .display(&*self.formatter),
+        );
+
         let receipt = self
             .execution_configurator
             .wrap_pending_transaction(executable, user_hashes)