improve logging

Author: mwtian

consensus/core/src/commit_observer.rs

@@ -215,7 +215,7 @@ impl CommitObserver {
                 .recover_commits_to_write(unsent_commits.clone());
 
             info!(
-                "Recovered {} unsent commits in range [{start_index}..={end_index}]",
+                "Recovering {} unsent commits in range [{start_index}..={end_index}]",
                 unsent_commits.len()
             );
 
@@ -246,9 +246,15 @@ impl CommitObserver {
                 );
 
                 if !committed_sub_dag.recovered_rejected_transactions {
-                    // When the commit has no associated storage entry for rejected transactions,
-                    // even if an empty set, the commit is unfinalized.
-                    seen_unfinalized_commit = true;
+                    if !seen_unfinalized_commit {
+                        info!(
+                            "Starting to recover unfinalized commit from {}",
+                            committed_sub_dag.commit_ref
+                        );
+                        // When the commit has no associated storage entry for rejected transactions,
+                        // not even an empty set, the commit is unfinalized.
+                        seen_unfinalized_commit = true;
+                    }
                 }
 
                 if seen_unfinalized_commit {

crates/sui-core/src/checkpoints/mod.rs

@@ -22,6 +22,7 @@ use crate::execution_cache::TransactionCacheRead;
 use crate::execution_scheduler::balance_withdraw_scheduler::BalanceSettlement;
 use crate::global_state_hasher::GlobalStateHasher;
 use crate::stake_aggregator::{InsertResult, MultiStakeAggregator};
+use consensus_core::CommitRef;
 use diffy::create_patch;
 use itertools::Itertools;
 use mysten_common::random::get_rng;
@@ -61,7 +62,9 @@ use sui_protocol_config::ProtocolVersion;
 use sui_types::base_types::{AuthorityName, EpochId, TransactionDigest};
 use sui_types::committee::StakeUnit;
 use sui_types::crypto::AuthorityStrongQuorumSignInfo;
-use sui_types::digests::{CheckpointContentsDigest, CheckpointDigest, TransactionEffectsDigest};
+use sui_types::digests::{
+    CheckpointContentsDigest, CheckpointDigest, Digest, TransactionEffectsDigest,
+};
 use sui_types::effects::{TransactionEffects, TransactionEffectsAPI};
 use sui_types::error::{SuiErrorKind, SuiResult};
 use sui_types::gas::GasCostSummary;
@@ -105,6 +108,9 @@ pub struct PendingCheckpointInfo {
     // Computed in calculate_pending_checkpoint_height() from consensus round,
     // there is no guarantee that this is increasing per checkpoint, because of checkpoint splitting.
     pub checkpoint_height: CheckpointHeight,
+    // Consensus commit ref and rejected transactions digest which corresponds to this checkpoint.
+    pub consensus_commit_ref: CommitRef,
+    pub rejected_transactions_digest: Digest,
 }
 
 #[derive(Clone, Debug)]
@@ -1392,6 +1398,18 @@ impl CheckpointBuilder {
         pendings: Vec<PendingCheckpoint>,
     ) -> CheckpointBuilderResult<CheckpointSequenceNumber> {
         let _scope = monitored_scope("CheckpointBuilder::make_checkpoint");
+
+        let pending_ckpt_str = pendings
+            .iter()
+            .map(|p| {
+                format!(
+                    "height={}, commit={}",
+                    p.details().checkpoint_height,
+                    p.details().consensus_commit_ref
+                )
+            })
+            .join("; ");
+
         let last_details = pendings.last().unwrap().details().clone();
 
         // Stores the transactions that should be included in the checkpoint. Transactions will be recorded in the checkpoint
@@ -1419,8 +1437,18 @@ impl CheckpointBuilder {
             );
         }
 
+        let new_ckpt_str = new_checkpoints
+            .iter()
+            .map(|(ckpt, _)| format!("seq={}, digest={}", ckpt.sequence_number(), ckpt.digest()))
+            .join("; ");
+
         self.write_checkpoints(last_details.checkpoint_height, new_checkpoints)
             .await?;
+        info!(
+            "Made new checkpoint {} from pending checkpoint {}",
+            new_ckpt_str, pending_ckpt_str
+        );
+
         Ok(highest_sequence)
     }
 
@@ -3795,6 +3823,8 @@ mod tests {
                 timestamp_ms,
                 last_of_epoch: false,
                 checkpoint_height: i,
+                consensus_commit_ref: CommitRef::default(),
+                rejected_transactions_digest: Digest::default(),
             },
         }
     }

crates/sui-core/src/consensus_handler.rs

@@ -169,8 +169,9 @@ impl ConsensusHandlerInitializer {
 mod additional_consensus_state {
     use std::marker::PhantomData;
 
+    use consensus_core::CommitRef;
     use fastcrypto::hash::HashFunction as _;
-    use sui_types::crypto::DefaultHash;
+    use sui_types::{crypto::DefaultHash, digests::Digest};
 
     use super::*;
     /// AdditionalConsensusState tracks any in-memory state that is retained by ConsensusHandler
@@ -216,7 +217,6 @@ mod additional_consensus_state {
 
             self.commit_info_impl(
                 epoch_start_time,
-                protocol_config,
                 consensus_commit,
                 Some(estimated_commit_period),
             )
@@ -225,7 +225,6 @@ mod additional_consensus_state {
         fn commit_info_impl(
             &self,
             epoch_start_time: u64,
-            protocol_config: &ProtocolConfig,
             consensus_commit: &impl ConsensusCommitAPI,
             estimated_commit_period: Option<Duration>,
         ) -> ConsensusCommitInfo {
@@ -246,8 +245,8 @@ mod additional_consensus_state {
                 round: consensus_commit.leader_round(),
                 timestamp,
                 leader_author,
-                sub_dag_index: consensus_commit.commit_sub_dag_index(),
-                consensus_commit_digest: consensus_commit.consensus_digest(protocol_config),
+                consensus_commit_ref: consensus_commit.commit_ref(),
+                rejected_transactions_digest: consensus_commit.rejected_transactions_digest(),
                 additional_state_digest: Some(self.digest()),
                 estimated_commit_period,
                 skip_consensus_commit_prologue_in_test: false,
@@ -269,8 +268,8 @@ mod additional_consensus_state {
         pub round: u64,
         pub timestamp: u64,
         pub leader_author: AuthorityIndex,
-        pub sub_dag_index: u64,
-        pub consensus_commit_digest: ConsensusCommitDigest,
+        pub consensus_commit_ref: CommitRef,
+        pub rejected_transactions_digest: Digest,
 
         additional_state_digest: Option<AdditionalConsensusStateDigest>,
         estimated_commit_period: Option<Duration>,
@@ -290,8 +289,8 @@ mod additional_consensus_state {
                 round: commit_round,
                 timestamp: commit_timestamp,
                 leader_author: 0,
-                sub_dag_index: 0,
-                consensus_commit_digest: ConsensusCommitDigest::default(),
+                consensus_commit_ref: CommitRef::default(),
+                rejected_transactions_digest: Digest::default(),
                 additional_state_digest: Some(AdditionalConsensusStateDigest::ZERO),
                 estimated_commit_period,
                 skip_consensus_commit_prologue_in_test,
@@ -323,6 +322,10 @@ mod additional_consensus_state {
                 .expect("estimated commit period is not available")
         }
 
+        fn consensus_commit_digest(&self) -> ConsensusCommitDigest {
+            ConsensusCommitDigest::new(self.consensus_commit_ref.digest.into_inner())
+        }
+
         fn consensus_commit_prologue_transaction(
             &self,
             epoch: u64,
@@ -343,7 +346,7 @@ mod additional_consensus_state {
                 epoch,
                 self.round,
                 self.timestamp,
-                self.consensus_commit_digest,
+                self.consensus_commit_digest(),
             );
             VerifiedExecutableTransaction::new_system(transaction, epoch)
         }
@@ -357,7 +360,7 @@ mod additional_consensus_state {
                 epoch,
                 self.round,
                 self.timestamp,
-                self.consensus_commit_digest,
+                self.consensus_commit_digest(),
                 consensus_determined_version_assignments,
             );
             VerifiedExecutableTransaction::new_system(transaction, epoch)
@@ -373,7 +376,7 @@ mod additional_consensus_state {
                 epoch,
                 self.round,
                 self.timestamp,
-                self.consensus_commit_digest,
+                self.consensus_commit_digest(),
                 consensus_determined_version_assignments,
                 additional_state_digest,
             );
@@ -801,7 +804,8 @@ impl<C: CheckpointServiceNotify + Send + Sync> ConsensusHandler<C> {
 
         info!(
             %consensus_commit,
-            "Received consensus output"
+            "Received consensus output. Rejected transactions: {}",
+            consensus_commit.rejected_transactions_debug_string(),
         );
 
         self.last_consensus_stats.index = ExecutionIndices {
@@ -1049,19 +1053,28 @@ impl<C: CheckpointServiceNotify + Send + Sync> ConsensusHandler<C> {
                 timestamp_ms: commit_info.timestamp,
                 last_of_epoch: final_round && !should_write_random_checkpoint,
                 checkpoint_height,
+                consensus_commit_ref: commit_info.consensus_commit_ref,
+                rejected_transactions_digest: commit_info.rejected_transactions_digest,
             },
         };
         self.epoch_store
             .write_pending_checkpoint(&mut state.output, &pending_checkpoint)
             .expect("failed to write pending checkpoint");
 
+        info!(
+            "Written pending checkpoint: {:?}",
+            pending_checkpoint.details,
+        );
+
         if should_write_random_checkpoint {
             let pending_checkpoint = PendingCheckpoint {
                 roots: randomness_schedulables.iter().map(|s| s.key()).collect(),
                 details: PendingCheckpointInfo {
                     timestamp_ms: commit_info.timestamp,
                     last_of_epoch: final_round,
                     checkpoint_height: checkpoint_height + 1,
+                    consensus_commit_ref: commit_info.consensus_commit_ref,
+                    rejected_transactions_digest: commit_info.rejected_transactions_digest,
                 },
             };
             self.epoch_store
@@ -2147,7 +2160,7 @@ impl<C: CheckpointServiceNotify + Send + Sync> ConsensusHandler<C> {
             // Therefore, the transaction sequence number starts from 1 here.
             let current_tx_index = ExecutionIndices {
                 last_committed_round: commit_info.round,
-                sub_dag_index: commit_info.sub_dag_index,
+                sub_dag_index: commit_info.consensus_commit_ref.index.into(),
                 transaction_index: (seq + 1) as u64,
             };
 

crates/sui-core/src/consensus_types/consensus_output_api.rs

@@ -1,12 +1,14 @@
 // Copyright (c) Mysten Labs, Inc.
 // SPDX-License-Identifier: Apache-2.0
+
 use std::{cmp::Ordering, fmt::Display};
 
-use consensus_core::{BlockAPI, CommitDigest, VerifiedBlock};
+use consensus_core::{BlockAPI, CommitRef, VerifiedBlock};
 use consensus_types::block::{BlockRef, TransactionIndex};
-use sui_protocol_config::ProtocolConfig;
+use fastcrypto::hash::HashFunction as _;
+use itertools::Itertools as _;
 use sui_types::{
-    digests::ConsensusCommitDigest,
+    digests::Digest,
     messages_consensus::{AuthorityIndex, ConsensusTransaction},
 };
 
@@ -20,6 +22,9 @@ pub(crate) struct ParsedTransaction {
 }
 
 pub(crate) trait ConsensusCommitAPI: Display {
+    /// Returns the ref of consensus output.
+    fn commit_ref(&self) -> CommitRef;
+
     fn reputation_score_sorted_desc(&self) -> Option<Vec<(AuthorityIndex, u64)>>;
     fn leader_round(&self) -> u64;
     fn leader_author_index(&self) -> AuthorityIndex;
@@ -33,11 +38,16 @@ pub(crate) trait ConsensusCommitAPI: Display {
     /// Returns all accepted and rejected transactions per block in the commit in deterministic order.
     fn transactions(&self) -> Vec<(BlockRef, Vec<ParsedTransaction>)>;
 
-    /// Returns the digest of consensus output.
-    fn consensus_digest(&self, protocol_config: &ProtocolConfig) -> ConsensusCommitDigest;
+    /// Returns a debug string of all rejected transactions.
+    fn rejected_transactions_digest(&self) -> Digest;
+    fn rejected_transactions_debug_string(&self) -> String;
 }
 
 impl ConsensusCommitAPI for consensus_core::CommittedSubDag {
+    fn commit_ref(&self) -> CommitRef {
+        self.commit_ref
+    }
+
     fn reputation_score_sorted_desc(&self) -> Option<Vec<(AuthorityIndex, u64)>> {
         if !self.reputation_scores_desc.is_empty() {
             Some(
@@ -85,15 +95,29 @@ impl ConsensusCommitAPI for consensus_core::CommittedSubDag {
             .collect()
     }
 
-    fn consensus_digest(&self, protocol_config: &ProtocolConfig) -> ConsensusCommitDigest {
-        if protocol_config.mysticeti_use_committed_subdag_digest() {
-            // We port CommitDigest, a consensus space object, into ConsensusCommitDigest, a sui-core space object.
-            // We assume they always have the same format.
-            static_assertions::assert_eq_size!(ConsensusCommitDigest, CommitDigest);
-            ConsensusCommitDigest::new(self.commit_ref.digest.into_inner())
-        } else {
-            ConsensusCommitDigest::default()
-        }
+    fn rejected_transactions_digest(&self) -> Digest {
+        let bytes = bcs::to_bytes(&self.rejected_transactions_by_block).unwrap();
+        let mut hasher = sui_types::crypto::DefaultHash::new();
+        hasher.update(bytes);
+        hasher.finalize().digest.into()
+    }
+
+    fn rejected_transactions_debug_string(&self) -> String {
+        let str = self
+            .rejected_transactions_by_block
+            .iter()
+            .map(|(block_ref, rejected_transactions)| {
+                format!(
+                    "{block_ref}: [{}]",
+                    rejected_transactions
+                        .iter()
+                        .map(|tx| tx.to_string())
+                        .join(",")
+                )
+            })
+            .join(", ");
+        let digest = self.rejected_transactions_digest();
+        format!("{str}; digest: {digest}")
     }
 }