Some debug-span and debug-log changes to help with filtering during tracing analysis

chain/chain-primitives/src/error.rs

@@ -240,7 +240,7 @@ pub trait LogTransientStorageError {
 impl<T> LogTransientStorageError for Result<T, Error> {
     fn log_storage_error(self, message: &str) -> Self {
         if let Err(err) = &self {
-            tracing::error!(target: "client", "Transient storage error: {message}, {err}");
+            tracing::error!(target: "chain", "Transient storage error: {message}, {err}");
         }
         self
     }

chain/chain/src/chain.rs

@@ -1080,7 +1080,7 @@ impl Chain {
         header: &BlockHeader,
         challenges: &mut Vec<ChallengeBody>,
     ) -> Result<(), Error> {
-        debug!(target: "chain", "Process block header: {} at {}", header.hash(), header.height());
+        debug!(target: "chain", block_hash=?header.hash(), height=header.height(), "process_block_header");
 
         check_known(self, header.hash())?.map_err(|e| Error::BlockKnown(e))?;
         self.validate_header(header, &Provenance::NONE, challenges)?;
@@ -1413,12 +1413,12 @@ impl Chain {
         block_processing_artifacts: &mut BlockProcessingArtifact,
         apply_chunks_done_sender: Option<near_async::messaging::Sender<ApplyChunksDoneMessage>>,
     ) -> Result<(), Error> {
+        let block_height = block.header().height();
         let _span =
-            debug_span!(target: "chain", "start_process_block_async", ?provenance).entered();
+            debug_span!(target: "chain", "start_process_block_async", ?provenance, height=block_height).entered();
         let block_received_time = self.clock.now();
         metrics::BLOCK_PROCESSING_ATTEMPTS_TOTAL.inc();
 
-        let block_height = block.header().height();
         let hash = *block.hash();
         let res = self.start_process_block_impl(
             me,
@@ -1627,7 +1627,8 @@ impl Chain {
         block_processing_artifacts: &mut BlockProcessingArtifact,
         apply_chunks_done_sender: Option<near_async::messaging::Sender<ApplyChunksDoneMessage>>,
     ) -> Result<(), Error> {
-        let _span = tracing::debug_span!(target: "sync", "reset_heads_post_state_sync").entered();
+        let _span = tracing::debug_span!(target: "sync", "reset_heads_post_state_sync", ?sync_hash)
+            .entered();
         // Get header we were syncing into.
         let header = self.get_block_header(&sync_hash)?;
         let hash = *header.prev_hash();
@@ -1738,8 +1739,9 @@ impl Chain {
                             .add_block_with_missing_chunks(orphan, missing_chunk_hashes.clone());
                         debug!(
                             target: "chain",
-                            "Process block: missing chunks. Block hash: {:?}. Missing chunks: {:?}",
-                            block_hash, missing_chunk_hashes,
+                            ?block_hash,
+                            chunk_hashes=missing_chunk_hashes.iter().map(|h| format!("{:?}", h)).join(","),
+                            "Process block: missing chunks"
                         );
                     }
                     Error::EpochOutOfBounds(epoch_id) => {
@@ -1750,10 +1752,10 @@ impl Chain {
                     Error::BlockKnown(block_known_error) => {
                         debug!(
                             target: "chain",
-                            "Block {} at {} is known at this time: {:?}",
-                            block.hash(),
-                            block_height,
-                            block_known_error);
+                            block_hash=?block.hash(),
+                            height=block_height,
+                            error=?block_known_error,
+                            "Block known at this time");
                     }
                     _ => {}
                 }
@@ -1920,12 +1922,7 @@ impl Chain {
                     true,
                 )
             };
-            tracing::debug!(
-                target: "chain",
-                "Updating flat storage for shard {} need_flat_storage_update: {}",
-                shard_id,
-                need_flat_storage_update
-            );
+            tracing::debug!(target: "chain", shard_id,need_flat_storage_update, "Updating flat storage");
 
             if need_flat_storage_update {
                 let shard_uid = self.epoch_manager.shard_id_to_uid(shard_id, epoch_id)?;
@@ -2007,7 +2004,7 @@ impl Chain {
         // see if the block is already in processing or if there are too many blocks being processed
         self.blocks_in_processing.add_dry_run(block.hash())?;
 
-        debug!(target: "chain", num_approvals = header.num_approvals(), "Preprocess block");
+        debug!(target: "chain", height=header.height(), num_approvals = header.num_approvals(), "preprocess_block");
 
         // Check that we know the epoch of the block before we try to get the header
         // (so that a block from unknown epoch doesn't get marked as an orphan)
@@ -2525,7 +2522,7 @@ impl Chain {
             "get_state_response_part",
             shard_id,
             part_id,
-            %sync_hash)
+            ?sync_hash)
         .entered();
         // Check cache
         let key = borsh::to_vec(&StatePartKey(sync_hash, shard_id, part_id))?;

chain/chain/src/chain_update.rs

@@ -152,7 +152,7 @@ impl<'a> ChainUpdate<'a> {
         apply_results: Vec<ShardUpdateResult>,
         should_save_state_transition_data: bool,
     ) -> Result<(), Error> {
-        let _span = tracing::debug_span!(target: "chain", "apply_chunk_postprocessing").entered();
+        let _span = tracing::debug_span!(target: "chain", "apply_chunk_postprocessing", height=block.header().height()).entered();
         for result in apply_results {
             self.process_apply_chunk_result(block, result, should_save_state_transition_data)?;
         }
@@ -725,7 +725,7 @@ impl<'a> ChainUpdate<'a> {
         shard_state_header: ShardStateSyncResponseHeader,
     ) -> Result<ShardUId, Error> {
         let _span =
-            tracing::debug_span!(target: "sync", "chain_update_set_state_finalize").entered();
+            tracing::debug_span!(target: "sync", "chain_update_set_state_finalize", shard_id, ?sync_hash).entered();
         let (chunk, incoming_receipts_proofs) = match shard_state_header {
             ShardStateSyncResponseHeader::V1(shard_state_header) => (
                 ShardChunk::V1(shard_state_header.chunk),
@@ -855,7 +855,9 @@ impl<'a> ChainUpdate<'a> {
         shard_id: ShardId,
         sync_hash: CryptoHash,
     ) -> Result<bool, Error> {
-        let _span = tracing::debug_span!(target: "sync", "set_state_finalize_on_height").entered();
+        let _span =
+            tracing::debug_span!(target: "sync", "set_state_finalize_on_height", height, shard_id)
+                .entered();
         let block_header_result =
             self.chain_store_update.get_block_header_on_chain_by_height(&sync_hash, height);
         if let Err(_) = block_header_result {

chain/chain/src/update_shard.rs

@@ -177,7 +177,7 @@ pub fn apply_new_chunk(
     let _span = tracing::debug_span!(
         target: "chain",
         parent: parent_span,
-        "new_chunk",
+        "apply_new_chunk",
         shard_id)
     .entered();
     let gas_limit = chunk_header.gas_limit();
@@ -242,7 +242,7 @@ pub fn apply_old_chunk(
     let _span = tracing::debug_span!(
         target: "chain",
         parent: parent_span,
-        "existing_chunk",
+        "apply_old_chunk",
         shard_id)
     .entered();
 
@@ -302,7 +302,7 @@ fn apply_resharding(
     let _span = tracing::debug_span!(
         target: "chain",
         parent: parent_span,
-        "resharding",
+        "apply_resharding",
         shard_id,
         ?shard_uid)
     .entered();

chain/chunks/src/client.rs

@@ -122,7 +122,7 @@ impl ShardedTransactionPool {
     /// transactions back to the pool with the new shard uids.
     pub fn reshard(&mut self, old_shard_layout: &ShardLayout, new_shard_layout: &ShardLayout) {
         tracing::debug!(
-            target: "client",
+            target: "resharding",
             old_shard_layout_version = old_shard_layout.version(),
             new_shard_layout_version = new_shard_layout.version(),
             "resharding the transaction pool"

chain/client/src/client.rs

@@ -87,7 +87,7 @@ use std::cmp::max;
 use std::collections::{HashMap, HashSet};
 use std::sync::Arc;
 use std::sync::RwLock;
-use tracing::{debug, debug_span, error, info, trace, warn};
+use tracing::{debug, debug_span, error, info, instrument, trace, warn};
 
 #[cfg(feature = "test_features")]
 use crate::client_actor::AdvProduceChunksMode;
@@ -820,21 +820,14 @@ impl Client {
         Ok(Some(block))
     }
 
-    pub fn produce_chunk(
+    pub fn try_produce_chunk(
         &mut self,
         prev_block: &Block,
         epoch_id: &EpochId,
         last_header: ShardChunkHeader,
         next_height: BlockHeight,
         shard_id: ShardId,
     ) -> Result<Option<ProduceChunkResult>, Error> {
-        let timer = Instant::now();
-        let _timer =
-            metrics::PRODUCE_CHUNK_TIME.with_label_values(&[&shard_id.to_string()]).start_timer();
-        let _span = tracing::debug_span!(target: "client", "produce_chunk", next_height, shard_id, ?epoch_id).entered();
-
-        let prev_block_hash = *prev_block.hash();
-
         let validator_signer = self
             .validator_signer
             .as_ref()
@@ -852,6 +845,37 @@ impl Client {
                 "Not producing chunk. Not chunk producer for next chunk.");
             return Ok(None);
         }
+
+        self.produce_chunk(
+            prev_block,
+            epoch_id,
+            last_header,
+            next_height,
+            shard_id,
+            validator_signer,
+        )
+    }
+
+    #[instrument(target = "client", level = "debug", "produce_chunk", skip_all, fields(
+        height = next_height,
+        shard_id,
+        ?epoch_id,
+        chunk_hash = tracing::field::Empty,
+    ))]
+    pub fn produce_chunk(
+        &mut self,
+        prev_block: &Block,
+        epoch_id: &EpochId,
+        last_header: ShardChunkHeader,
+        next_height: BlockHeight,
+        shard_id: ShardId,
+        validator_signer: Arc<dyn ValidatorSigner>,
+    ) -> Result<Option<ProduceChunkResult>, Error> {
+        let span = tracing::Span::current();
+        let timer = Instant::now();
+        let _timer =
+            metrics::PRODUCE_CHUNK_TIME.with_label_values(&[&shard_id.to_string()]).start_timer();
+        let prev_block_hash = *prev_block.hash();
         if self.epoch_manager.is_next_block_epoch_start(&prev_block_hash)? {
             let prev_prev_hash = *self.chain.get_block_header(&prev_block_hash)?.prev_hash();
             if !self.chain.prev_block_is_caught_up(&prev_prev_hash, &prev_block_hash)? {
@@ -914,6 +938,7 @@ impl Client {
             protocol_version,
         )?;
 
+        span.record("chunk_hash", tracing::field::debug(encoded_chunk.chunk_hash()));
         debug!(target: "client",
             me = %validator_signer.validator_id(),
             chunk_hash = ?encoded_chunk.chunk_hash(),
@@ -1759,7 +1784,13 @@ impl Client {
                 .with_label_values(&[&shard_id.to_string()])
                 .start_timer();
             let last_header = Chain::get_prev_chunk_header(epoch_manager, block, shard_id).unwrap();
-            match self.produce_chunk(block, &epoch_id, last_header.clone(), next_height, shard_id) {
+            match self.try_produce_chunk(
+                block,
+                &epoch_id,
+                last_header.clone(),
+                next_height,
+                shard_id,
+            ) {
                 Ok(Some(result)) => {
                     let shard_chunk = self
                         .persist_and_distribute_encoded_chunk(

chain/client/src/stateless_validation/chunk_endorsement_tracker.rs

@@ -58,7 +58,7 @@ impl Client {
                 .chunk_endorsement_tracker
                 .process_chunk_endorsement(&chunk.cloned_header(), endorsement),
             Err(Error::ChunkMissing(_)) => {
-                tracing::debug!(target: "stateless_validation", ?endorsement, "Endorsement arrived before chunk.");
+                tracing::debug!(target: "client", ?endorsement, "Endorsement arrived before chunk.");
                 self.chunk_endorsement_tracker.add_chunk_endorsement_to_pending_cache(endorsement)
             }
             Err(error) => return Err(error),
@@ -87,10 +87,10 @@ impl ChunkEndorsementTracker {
         let Some(chunk_endorsements) = chunk_endorsements else {
             return;
         };
-        tracing::debug!(target: "stateless_validation", ?chunk_hash, "Processing pending chunk endorsements.");
+        tracing::debug!(target: "client", ?chunk_hash, "Processing pending chunk endorsements.");
         for endorsement in chunk_endorsements.values() {
             if let Err(error) = self.process_chunk_endorsement(chunk_header, endorsement.clone()) {
-                tracing::debug!(target: "stateless_validation", ?endorsement, "Error processing pending chunk endorsement: {:?}", error);
+                tracing::debug!(target: "client", ?endorsement, ?error, "Error processing pending chunk endorsement");
             }
         }
     }
@@ -111,6 +111,7 @@ impl ChunkEndorsementTracker {
         chunk_header: &ShardChunkHeader,
         endorsement: ChunkEndorsement,
     ) -> Result<(), Error> {
+        let _span = tracing::debug_span!(target: "client", "process_chunk_endorsement", chunk_hash=?chunk_header.chunk_hash()).entered();
         self.process_chunk_endorsement_impl(endorsement, Some(chunk_header))
     }
 
@@ -135,13 +136,13 @@ impl ChunkEndorsementTracker {
             .get(chunk_hash)
             .is_some_and(|existing_endorsements| existing_endorsements.contains_key(account_id))
         {
-            tracing::debug!(target: "stateless_validation", ?endorsement, "Already received chunk endorsement.");
+            tracing::debug!(target: "client", ?endorsement, "Already received chunk endorsement.");
             return Ok(());
         }
 
         if let Some(chunk_header) = chunk_header {
             if !self.epoch_manager.verify_chunk_endorsement(&chunk_header, &endorsement)? {
-                tracing::error!(target: "stateless_validation", ?endorsement, "Invalid chunk endorsement.");
+                tracing::error!(target: "client", ?endorsement, "Invalid chunk endorsement.");
                 return Err(Error::InvalidChunkEndorsement);
             }
         }
@@ -152,7 +153,7 @@ impl ChunkEndorsementTracker {
         // for 100 unique chunks thus pushing out current valid endorsements from our cache.
         // Maybe add check to ensure we don't accept endorsements from chunks already included in some block?
         // Maybe add check to ensure we don't accept endorsements from chunks that have too old height_created?
-        tracing::debug!(target: "stateless_validation", ?endorsement, "Received and saved chunk endorsement.");
+        tracing::debug!(target: "client", ?endorsement, "Received and saved chunk endorsement.");
         let mut guard = endorsement_cache.lock();
         guard.get_or_insert(chunk_hash.clone(), || HashMap::new());
         let chunk_endorsements = guard.get_mut(chunk_hash).unwrap();

chain/client/src/stateless_validation/chunk_validator/mod.rs

@@ -507,7 +507,7 @@ pub(crate) fn validate_chunk_state_witness(
     let _timer = metrics::CHUNK_STATE_WITNESS_VALIDATION_TIME
         .with_label_values(&[&state_witness.chunk_header.shard_id().to_string()])
         .start_timer();
-    let span = tracing::debug_span!(target: "chain", "validate_chunk_state_witness").entered();
+    let span = tracing::debug_span!(target: "client", "validate_chunk_state_witness").entered();
     let block_hash = pre_validation_output.main_transition_params.block_hash();
     let epoch_id = epoch_manager.get_epoch_id(&block_hash)?;
     let shard_uid = epoch_manager
@@ -646,10 +646,10 @@ pub(crate) fn send_chunk_endorsement_to_block_producers(
 
     let chunk_hash = chunk_header.chunk_hash();
     tracing::debug!(
-        target: "stateless_validation",
+        target: "client",
         chunk_hash=?chunk_hash,
         ?block_producers,
-        "Chunk validated successfully, sending endorsement",
+        "send_chunk_endorsement",
     );
 
     let endorsement = ChunkEndorsement::new(chunk_header.chunk_hash(), signer);
@@ -702,7 +702,7 @@ impl Client {
             self.partially_validate_state_witness(&encoded_witness)?;
 
         tracing::debug!(
-            target: "stateless_validation",
+            target: "client",
             chunk_hash=?witness.chunk_header.chunk_hash(),
             shard_id=witness.chunk_header.shard_id(),
             "process_chunk_state_witness",
@@ -725,7 +725,7 @@ impl Client {
         if let Ok(final_head) = self.chain.final_head() {
             if witness.chunk_header.height_created() <= final_head.height {
                 tracing::warn!(
-                    target: "stateless_validation",
+                    target: "client",
                     chunk_hash=?witness.chunk_header.chunk_hash(),
                     shard_id=witness.chunk_header.shard_id(),
                     witness_height=witness.chunk_header.height_created(),