Reduce logging verbosity (#20918)

This PR - Reduces logging vebosity in general - this was an ad hoc change based on taking high-volume debug logs and changing them to trace if I didn't personally recall looking at them while debugging. - Reduce log levels for antithesis tests - Attempts to remove a lot of unnecessary logs in antithesis runs.
MystenLabs · Jan 21, 2025 · c29efa3 · c29efa3
1 parent 688d284
commit c29efa3
Show file tree

Hide file tree

Showing 5 changed files with 25 additions and 16 deletions.
diff --git a/crates/sui-core/src/authority.rs b/crates/sui-core/src/authority.rs
@@ -61,6 +61,7 @@ use tap::TapFallible;
 use tokio::sync::mpsc::unbounded_channel;
 use tokio::sync::{mpsc, oneshot, RwLock};
 use tokio::task::JoinHandle;
+use tracing::trace;
 use tracing::{debug, error, info, instrument, warn};
 
 use self::authority_store::ExecutionLockWriteGuard;
@@ -1150,7 +1151,7 @@ impl AuthorityState {
                 .execute_certificate_latency_single_writer
                 .start_timer()
         };
-        debug!("execute_certificate");
+        trace!("execute_certificate");
 
         self.metrics.total_cert_attempts.inc();
 
@@ -1213,7 +1214,6 @@ impl AuthorityState {
     ) -> SuiResult<(TransactionEffects, Option<ExecutionError>)> {
         let _scope = monitored_scope("Execution::try_execute_immediately");
         let _metrics_guard = self.metrics.internal_execution_latency.start_timer();
-        debug!("execute_certificate_internal");
 
         let tx_digest = certificate.digest();
 
@@ -1249,7 +1249,8 @@ impl AuthorityState {
             epoch_store,
         )
         .await
-        .tap_err(|e| info!(?tx_digest, "process_certificate failed: {e}"))
+        .tap_err(|e| info!("process_certificate failed: {e}"))
+        .tap_ok(|_| debug!("process_certificate succeeded"))
     }
 
     pub fn read_objects_for_execution(

diff --git a/crates/sui-core/src/authority/authority_per_epoch_store.rs b/crates/sui-core/src/authority/authority_per_epoch_store.rs
@@ -723,7 +723,7 @@ impl AuthorityEpochTables {
         impl Iterator<Item = ((CheckpointSequenceNumber, u64), CheckpointSignatureMessage)> + '_,
     > {
         let key = (checkpoint_seq, starting_index);
-        debug!("Scanning pending checkpoint signatures from {:?}", key);
+        trace!("Scanning pending checkpoint signatures from {:?}", key);
         let iter = self
             .pending_checkpoint_signatures
             .unbounded_iter()
@@ -2658,7 +2658,7 @@ impl AuthorityPerEpochStore {
             .is_consensus_message_processed(&transaction.transaction.key())
             .expect("Storage error")
         {
-            debug!(
+            trace!(
                 consensus_index=?transaction.consensus_index.transaction_index,
                 tracking_id=?transaction.transaction.get_tracking_id(),
                 "handle_consensus_transaction UserTransaction [skip]",

diff --git a/crates/sui-core/src/checkpoints/mod.rs b/crates/sui-core/src/checkpoints/mod.rs
@@ -61,7 +61,7 @@ use sui_types::signature::GenericSignature;
 use sui_types::sui_system_state::{SuiSystemState, SuiSystemStateTrait};
 use sui_types::transaction::{TransactionDataAPI, TransactionKey, TransactionKind};
 use tokio::{sync::Notify, task::JoinSet, time::timeout};
-use tracing::{debug, error, info, instrument, warn};
+use tracing::{debug, error, info, instrument, trace, warn};
 use typed_store::traits::{TableSummary, TypedStoreDebug};
 use typed_store::DBMapUtils;
 use typed_store::Map;
@@ -1837,14 +1837,14 @@ impl CheckpointAggregator {
             )?;
             for ((seq, index), data) in iter {
                 if seq != current.summary.sequence_number {
-                    debug!(
+                    trace!(
                         checkpoint_seq =? current.summary.sequence_number,
                         "Not enough checkpoint signatures",
                     );
                     // No more signatures (yet) for this checkpoint
                     return Ok(result);
                 }
-                debug!(
+                trace!(
                     checkpoint_seq = current.summary.sequence_number,
                     "Processing signature for checkpoint (digest: {:?}) from {:?}",
                     current.summary.digest(),
@@ -1858,6 +1858,11 @@ impl CheckpointAggregator {
                     )])
                     .inc();
                 if let Ok(auth_signature) = current.try_aggregate(data) {
+                    debug!(
+                        checkpoint_seq = current.summary.sequence_number,
+                        "Successfully aggregated signatures for checkpoint (digest: {:?})",
+                        current.summary.digest(),
+                    );
                     let summary = VerifiedCheckpoint::new_unchecked(
                         CertifiedCheckpointSummary::new_from_data_and_sig(
                             current.summary.clone(),
@@ -2291,17 +2296,18 @@ impl CheckpointServiceNotify for CheckpointService {
             .map(|x| *x.sequence_number())
         {
             if sequence <= highest_verified_checkpoint {
-                debug!(
+                trace!(
                     checkpoint_seq = sequence,
-                    "Ignore checkpoint signature from {} - already certified", signer,
+                    "Ignore checkpoint signature from {} - already certified",
+                    signer,
                 );
                 self.metrics
                     .last_ignored_checkpoint_signature_received
                     .set(sequence as i64);
                 return Ok(());
             }
         }
-        debug!(
+        trace!(
             checkpoint_seq = sequence,
             "Received checkpoint signature, digest {} from {}",
             info.summary.digest(),

diff --git a/docker/sui-antithesis/Dockerfile b/docker/sui-antithesis/Dockerfile
@@ -13,12 +13,14 @@ WORKDIR /
 
 ARG SUI_NODE_A_TAG
 ARG SUI_NODE_B_TAG
+ARG SUI_RUST_LOG
 ENV SUI_NODE_A_TAG=$SUI_NODE_A_TAG
 ENV SUI_NODE_B_TAG=$SUI_NODE_B_TAG
 
 RUN ./new-genesis.sh
 RUN echo "SUI_NODE_A_TAG=$SUI_NODE_A_TAG" >> /.env
 RUN echo "SUI_NODE_B_TAG=$SUI_NODE_B_TAG" >> /.env
+RUN echo "SUI_RUST_LOG=$SUI_RUST_LOG" >> /.env
 
 COPY ./docker-compose-antithesis.yaml /docker-compose.yaml
 

diff --git a/docker/sui-antithesis/docker-compose-antithesis.yaml b/docker/sui-antithesis/docker-compose-antithesis.yaml
@@ -11,7 +11,7 @@ services:
     environment:
       - ENABLE_WRITEBACK_CACHE=1
       - RUST_BACKTRACE=1
-      - RUST_LOG=info,sui_core=debug,consensus=debug,jsonrpsee=error
+      - RUST_LOG=${SUI_RUST_LOG:-info}
       - RPC_WORKER_THREAD=12
       - NEW_CHECKPOINT_WARNING_TIMEOUT_MS=30000
       - NEW_CHECKPOINT_PANIC_TIMEOUT_MS=60000
@@ -39,7 +39,7 @@ services:
     environment:
       - ENABLE_WRITEBACK_CACHE=1
       - RUST_BACKTRACE=1
-      - RUST_LOG=info,sui_core=debug,sui_network=debug,sui_node=debug,consensus=debug,jsonrpsee=error
+      - RUST_LOG=${SUI_RUST_LOG:-info}
       - RPC_WORKER_THREAD=12
       - NEW_CHECKPOINT_WARNING_TIMEOUT_MS=30000
       - NEW_CHECKPOINT_PANIC_TIMEOUT_MS=60000
@@ -67,7 +67,7 @@ services:
     environment:
       - DISABLE_WRITEBACK_CACHE=1
       - RUST_BACKTRACE=1
-      - RUST_LOG=info,sui_core=debug,sui_network=debug,sui_node=debug,consensus=debug,jsonrpsee=error
+      - RUST_LOG=${SUI_RUST_LOG:-info}
       - RPC_WORKER_THREAD=12
       - NEW_CHECKPOINT_WARNING_TIMEOUT_MS=30000
       - NEW_CHECKPOINT_PANIC_TIMEOUT_MS=60000
@@ -95,7 +95,7 @@ services:
     environment:
       - DISABLE_WRITEBACK_CACHE=1
       - RUST_BACKTRACE=1
-      - RUST_LOG=info,sui_core=debug,sui_network=debug,sui_node=debug,consensus=debug,jsonrpsee=error
+      - RUST_LOG=${SUI_RUST_LOG:-info}
       - RPC_WORKER_THREAD=12
       - NEW_CHECKPOINT_WARNING_TIMEOUT_MS=30000
       - NEW_CHECKPOINT_PANIC_TIMEOUT_MS=60000
@@ -123,7 +123,7 @@ services:
     environment:
       - ENABLE_WRITEBACK_CACHE=1
       - RUST_BACKTRACE=1
-      - RUST_LOG=info,jsonrpsee=error
+      - RUST_LOG=${SUI_RUST_LOG:-info}
       - RPC_WORKER_THREAD=12
       - NEW_CHECKPOINT_WARNING_TIMEOUT_MS=30000
       - NEW_CHECKPOINT_PANIC_TIMEOUT_MS=60000