feat: improve log messages (#66)

MegaRedHand · greptile-apps[bot] · web-flow · commit c276928c5f97 · 2026-01-29T19:33:21.000-03:00
Adds structured logging improvements to make ethlambda's logs more
useful for debugging and monitoring.

## New Log Messages

**Block Events:**
```
INFO slot=5 proposer=5 block_root=d0fd6225 parent_root=0c3dd6a5 attestation_count=4 Received block from gossip
INFO slot=5 proposer=5 block_root=d0fd6225 parent_root=0c3dd6a5 Block imported successfully
INFO slot=5 proposer=5 block_root=d0fd6225 parent_root=0c3dd6a5 attestation_count=4 Published block to gossipsub
```

**Attestation Events:**
```
INFO slot=5 validator=2 head_root=a1b2c3d4 target_slot=5 target_root=e5f6g7h8 source_slot=0 source_root=i9j0k1l2 Received attestation from gossip
INFO slot=5 validator=2 target_slot=5 target_root=e5f6g7h8 source_slot=0 source_root=i9j0k1l2 Attestation processed
INFO slot=5 validator=2 target_slot=5 target_root=e5f6g7h8 source_slot=0 source_root=i9j0k1l2 Published attestation to gossipsub
```

**Consensus Events:**
```
INFO justified_slot=21 justified_root=f3876ca3 vote_count=5 threshold=4 Checkpoint justified
INFO finalized_slot=18 finalized_root=b7ba899b previous_finalized=12 justified_slot=21 Checkpoint finalized
INFO head_slot=26 head_root=b688cd00 previous_head_slot=24 previous_head_root=c577d911 justified_slot=21 finalized_slot=18 Fork choice head updated
```

**Network Events:**
```
INFO peer_id=16Uiu2HAm7TYV direction=inbound peer_count=5 their_finalized_slot=15 their_head_slot=26 Peer connected
INFO peer_id=16Uiu2HAm7TYV direction=inbound reason=remote_close peer_count=4 Peer disconnected
```

## Changes

- Added `ShortRoot` display helper for consistent 8-char root truncation
- Enhanced block reception, import, and publication logs with consistent
field ordering
- Enhanced attestation reception, processing, and publication logs with
complete root information
- Added finalization and justification event logging
- Added fork choice head update logging
- Added peer count to connection logs
- Improved error context in block processing failures
- Standardized field ordering: temporal → identity → identifiers →
context → metadata

---------

Co-authored-by: greptile-apps[bot] &lt;165735046+greptile-apps[bot]@users.noreply.github.com&gt;
diff --git a/CLAUDE.md b/CLAUDE.md
@@ -87,6 +87,51 @@ rm -rf leanSpec && make leanSpec/fixtures    # Regenerate test fixtures (require
 let _timing = metrics::time_state_transition();
 ```
 
+### Logging Patterns
+
+**Use tracing shorthand syntax for cleaner logs:**
+```rust
+// ✅ GOOD: Shorthand for simple variables
+let slot = block.slot;
+let proposer = block.proposer_index;
+info!(
+    %slot,              // Shorthand for slot = %slot (Display)
+    proposer,           // Shorthand for proposer = proposer
+    block_root = %ShortRoot(&block_root.0),  // Named expression
+    "Block imported"
+);
+
+// ❌ BAD: Verbose
+info!(
+    slot = %slot,
+    proposer = proposer,
+    ...
+);
+```
+
+**Standardized field ordering (temporal → identity → identifiers → context → metadata):**
+```rust
+// Block logs
+info!(%slot, proposer, block_root = ..., parent_root = ..., attestation_count, "...");
+
+// Attestation logs
+info!(%slot, validator, target_slot, target_root = ..., source_slot, source_root = ..., "...");
+
+// Consensus events
+info!(finalized_slot, finalized_root = ..., previous_finalized, justified_slot, "...");
+
+// Peer events
+info!(%peer_id, %direction, peer_count, our_finalized_slot, our_head_slot, "...");
+```
+
+**Root hash truncation:**
+```rust
+use ethlambda_types::ShortRoot;
+
+// Always use ShortRoot for consistent 8-char display (4 bytes)
+info!(block_root = %ShortRoot(&root.0), "...");
+```
+
 ### Relative Indexing (justified_slots)
 ```rust
 // Bounded storage: index relative to finalized_slot
diff --git a/Cargo.lock b/Cargo.lock
diff --git a/crates/blockchain/src/lib.rs b/crates/blockchain/src/lib.rs
@@ -5,6 +5,7 @@ use ethlambda_state_transition::is_proposer;
 use ethlambda_storage::Store;
 use ethlambda_types::primitives::H256;
 use ethlambda_types::{
+    ShortRoot,
     attestation::{Attestation, AttestationData, SignedAttestation},
     block::{BlockSignatures, BlockWithAttestation, SignedBlockWithAttestation},
     primitives::TreeHash,
@@ -277,6 +278,7 @@ impl BlockChainServer {
         let slot = signed_block.message.block.slot;
         let block_root = signed_block.message.block.tree_hash_root();
         let parent_root = signed_block.message.block.parent_root;
+        let proposer = signed_block.message.block.proposer_index;
 
         // Check if parent block exists before attempting to process
         if !self.store.contains_block(&parent_root) {
@@ -296,13 +298,26 @@ impl BlockChainServer {
         // Parent exists, proceed with processing
         match self.process_block(signed_block) {
             Ok(_) => {
-                info!(%slot, "Block processed successfully");
+                info!(
+                    %slot,
+                    proposer,
+                    block_root = %ShortRoot(&block_root.0),
+                    parent_root = %ShortRoot(&parent_root.0),
+                    "Block imported successfully"
+                );
 
                 // Check if any pending blocks can now be processed
                 self.process_pending_children(block_root);
             }
             Err(err) => {
-                warn!(%slot, %err, "Failed to process block");
+                warn!(
+                    %slot,
+                    proposer,
+                    block_root = %ShortRoot(&block_root.0),
+                    parent_root = %ShortRoot(&parent_root.0),
+                    %err,
+                    "Failed to process block"
+                );
             }
         }
     }
diff --git a/crates/blockchain/src/store.rs b/crates/blockchain/src/store.rs
@@ -6,6 +6,7 @@ use ethlambda_state_transition::{
 };
 use ethlambda_storage::{ForkCheckpoints, SignatureKey, Store};
 use ethlambda_types::{
+    ShortRoot,
     attestation::{AggregatedAttestation, Attestation, AttestationData, SignedAttestation},
     block::{
         AggregatedAttestations, AggregatedSignatureProof, AggregationBits, Block, BlockBody,
@@ -43,6 +44,22 @@ fn update_head(store: &mut Store) {
         info!(%old_head, %new_head, "Fork choice reorg detected");
     }
     store.update_checkpoints(ForkCheckpoints::head_only(new_head));
+
+    if old_head != new_head {
+        let old_slot = store.get_block(&old_head).map(|b| b.slot).unwrap_or(0);
+        let new_slot = store.get_block(&new_head).map(|b| b.slot).unwrap_or(0);
+        let justified_slot = store.latest_justified().slot;
+        let finalized_slot = store.latest_finalized().slot;
+        info!(
+            head_slot = new_slot,
+            head_root = %ShortRoot(&new_head.0),
+            previous_head_slot = old_slot,
+            previous_head_root = %ShortRoot(&old_head.0),
+            justified_slot,
+            finalized_slot,
+            "Fork choice head updated"
+        );
+    }
 }
 
 /// Update the safe target for attestation.
@@ -196,7 +213,7 @@ pub fn on_gossip_attestation(
             return Err(StoreError::SignatureVerificationFailed);
         }
     }
-    on_attestation(store, attestation, false)?;
+    on_attestation(store, attestation.clone(), false)?;
 
     if cfg!(not(feature = "skip-signature-verification")) {
         // Store signature for later lookup during block building
@@ -206,6 +223,20 @@ pub fn on_gossip_attestation(
         store.insert_gossip_signature(signature_key, signature);
     }
     metrics::inc_attestations_valid("gossip");
+
+    let slot = attestation.data.slot;
+    let target_slot = attestation.data.target.slot;
+    let source_slot = attestation.data.source.slot;
+    info!(
+        slot,
+        validator = validator_id,
+        target_slot,
+        target_root = %ShortRoot(&attestation.data.target.root.0),
+        source_slot,
+        source_root = %ShortRoot(&attestation.data.source.root.0),
+        "Attestation processed"
+    );
+
     Ok(())
 }
 
diff --git a/crates/blockchain/state_transition/Cargo.toml b/crates/blockchain/state_transition/Cargo.toml
@@ -14,6 +14,7 @@ ethlambda-types.workspace = true
 ethlambda-metrics.workspace = true
 
 thiserror.workspace = true
+tracing.workspace = true
 
 [dev-dependencies]
 serde.workspace = true
diff --git a/crates/blockchain/state_transition/src/lib.rs b/crates/blockchain/state_transition/src/lib.rs
@@ -1,10 +1,12 @@
 use std::collections::HashMap;
 
 use ethlambda_types::{
+    ShortRoot,
     block::{AggregatedAttestations, Block, BlockHeader},
     primitives::{H256, TreeHash},
     state::{Checkpoint, JustificationValidators, State},
 };
+use tracing::info;
 
 mod justified_slots_ops;
 pub mod metrics;
@@ -296,6 +298,16 @@ fn process_attestations(
                 target.slot,
             );
 
+            let justified_slot = target.slot;
+            let threshold = (2 * validator_count).div_ceil(3);
+            info!(
+                justified_slot,
+                justified_root = %ShortRoot(&target.root.0),
+                vote_count,
+                threshold,
+                "Checkpoint justified"
+            );
+
             justifications.remove(&target.root);
 
             // Consider whether finalization can advance.
@@ -307,6 +319,17 @@ fn process_attestations(
                 state.latest_finalized = source;
                 metrics::inc_finalizations("success");
 
+                let finalized_slot = source.slot;
+                let previous_finalized = old_finalized_slot;
+                let justified_slot = state.latest_justified.slot;
+                info!(
+                    finalized_slot,
+                    finalized_root = %ShortRoot(&source.root.0),
+                    previous_finalized,
+                    justified_slot,
+                    "Checkpoint finalized"
+                );
+
                 // Shift window to drop finalized slots from the front
                 let delta = (state.latest_finalized.slot - old_finalized_slot) as usize;
                 justified_slots_ops::shift_window(&mut state.justified_slots, delta);
diff --git a/crates/common/types/src/lib.rs b/crates/common/types/src/lib.rs
@@ -4,3 +4,15 @@ pub mod genesis;
 pub mod primitives;
 pub mod signature;
 pub mod state;
+
+/// Display helper for truncated root hashes (8 hex chars)
+pub struct ShortRoot<'a>(pub &'a [u8; 32]);
+
+impl std::fmt::Display for ShortRoot<'_> {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        for byte in &self.0[..4] {
+            write!(f, "{:02x}", byte)?;
+        }
+        Ok(())
+    }
+}
diff --git a/crates/net/p2p/src/gossipsub/handler.rs b/crates/net/p2p/src/gossipsub/handler.rs
@@ -1,7 +1,10 @@
-use ethlambda_types::{attestation::SignedAttestation, block::SignedBlockWithAttestation};
+use ethlambda_types::{
+    ShortRoot, attestation::SignedAttestation, block::SignedBlockWithAttestation,
+};
 use libp2p::gossipsub::Event;
 use ssz::{Decode, Encode};
 use tracing::{error, info, trace};
+use tree_hash::TreeHash;
 
 use super::{
     encoding::{compress_message, decompress_message},
@@ -32,7 +35,18 @@ pub async fn handle_gossipsub_message(server: &mut P2PServer, event: Event) {
                 return;
             };
             let slot = signed_block.message.block.slot;
-            info!(%slot, "Received new block from gossipsub, sending for processing");
+            let block_root = signed_block.message.block.tree_hash_root();
+            let proposer = signed_block.message.block.proposer_index;
+            let parent_root = signed_block.message.block.parent_root;
+            let attestation_count = signed_block.message.block.body.attestations.len();
+            info!(
+                %slot,
+                proposer,
+                block_root = %ShortRoot(&block_root.0),
+                parent_root = %ShortRoot(&parent_root.0),
+                attestation_count,
+                "Received block from gossip"
+            );
             server.blockchain.notify_new_block(signed_block).await;
         }
         Some(ATTESTATION_TOPIC_KIND) => {
@@ -49,7 +63,16 @@ pub async fn handle_gossipsub_message(server: &mut P2PServer, event: Event) {
             };
             let slot = signed_attestation.message.slot;
             let validator = signed_attestation.validator_id;
-            info!(%slot, %validator, "Received new attestation from gossipsub, sending for processing");
+            info!(
+                %slot,
+                validator,
+                head_root = %ShortRoot(&signed_attestation.message.head.root.0),
+                target_slot = signed_attestation.message.target.slot,
+                target_root = %ShortRoot(&signed_attestation.message.target.root.0),
+                source_slot = signed_attestation.message.source.slot,
+                source_root = %ShortRoot(&signed_attestation.message.source.root.0),
+                "Received attestation from gossip"
+            );
             server
                 .blockchain
                 .notify_new_attestation(signed_attestation)
@@ -77,7 +100,15 @@ pub async fn publish_attestation(server: &mut P2PServer, attestation: SignedAtte
         .behaviour_mut()
         .gossipsub
         .publish(server.attestation_topic.clone(), compressed)
-        .inspect(|_| trace!(%slot, %validator, "Published attestation to gossipsub"))
+        .inspect(|_| info!(
+            %slot,
+            validator,
+            target_slot = attestation.message.target.slot,
+            target_root = %ShortRoot(&attestation.message.target.root.0),
+            source_slot = attestation.message.source.slot,
+            source_root = %ShortRoot(&attestation.message.source.root.0),
+            "Published attestation to gossipsub"
+        ))
         .inspect_err(|err| {
             tracing::warn!(%slot, %validator, %err, "Failed to publish attestation to gossipsub")
         });
@@ -86,6 +117,9 @@ pub async fn publish_attestation(server: &mut P2PServer, attestation: SignedAtte
 pub async fn publish_block(server: &mut P2PServer, signed_block: SignedBlockWithAttestation) {
     let slot = signed_block.message.block.slot;
     let proposer = signed_block.message.block.proposer_index;
+    let block_root = signed_block.message.block.tree_hash_root();
+    let parent_root = signed_block.message.block.parent_root;
+    let attestation_count = signed_block.message.block.body.attestations.len();
 
     // Encode to SSZ
     let ssz_bytes = signed_block.as_ssz_bytes();
@@ -99,7 +133,16 @@ pub async fn publish_block(server: &mut P2PServer, signed_block: SignedBlockWith
         .behaviour_mut()
         .gossipsub
         .publish(server.block_topic.clone(), compressed)
-        .inspect(|_| info!(%slot, %proposer, "Published block to gossipsub"))
+        .inspect(|_| {
+            info!(
+                %slot,
+                proposer,
+                block_root = %ShortRoot(&block_root.0),
+                parent_root = %ShortRoot(&parent_root.0),
+                attestation_count,
+                "Published block to gossipsub"
+            )
+        })
         .inspect_err(
             |err| tracing::warn!(%slot, %proposer, %err, "Failed to publish block to gossipsub"),
         );
diff --git a/crates/net/p2p/src/lib.rs b/crates/net/p2p/src/lib.rs
@@ -246,10 +246,20 @@ async fn handle_swarm_event(server: &mut P2PServer, event: SwarmEvent<BehaviourE
             let direction = connection_direction(&endpoint);
             if num_established.get() == 1 {
                 server.connected_peers.insert(peer_id);
+                let peer_count = server.connected_peers.len();
                 metrics::notify_peer_connected(&Some(peer_id), direction, "success");
                 // Send status request on first connection to this peer
                 let our_status = build_status(&server.store);
-                info!(%peer_id, %direction, finalized_slot=%our_status.finalized.slot, head_slot=%our_status.head.slot, "Added connection to new peer, sending status request");
+                let our_finalized_slot = our_status.finalized.slot;
+                let our_head_slot = our_status.head.slot;
+                info!(
+                    %peer_id,
+                    %direction,
+                    peer_count,
+                    our_finalized_slot,
+                    our_head_slot,
+                    "Peer connected"
+                );
                 server
                     .swarm
                     .behaviour_mut()
@@ -290,9 +300,18 @@ async fn handle_swarm_event(server: &mut P2PServer, event: SwarmEvent<BehaviourE
             };
             if num_established == 0 {
                 server.connected_peers.remove(&peer_id);
+                let peer_count = server.connected_peers.len();
                 metrics::notify_peer_disconnected(&Some(peer_id), direction, reason);
+                info!(
+                    %peer_id,
+                    %direction,
+                    %reason,
+                    peer_count,
+                    "Peer disconnected"
+                );
+            } else {
+                info!(%peer_id, %direction, %reason, "Peer connection closed but other connections remain");
             }
-            info!(%peer_id, %direction, %reason, "Peer disconnected");
         }
         SwarmEvent::OutgoingConnectionError { peer_id, error, .. } => {
             let result = if error.to_string().to_lowercase().contains("timed out") {
