diff --git a/CLAUDE.md b/CLAUDE.md index b3633e0e..dbe0095f 100644 --- 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 index dd70cad1..88a3df47 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2061,6 +2061,7 @@ dependencies = [ "serde", "serde_json", "thiserror 2.0.17", + "tracing", ] [[package]] diff --git a/crates/blockchain/src/lib.rs b/crates/blockchain/src/lib.rs index 3fe6eb4b..a438a460 100644 --- 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 index 8b28e372..e9e252ca 100644 --- 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 index 01d06b06..d5335b8f 100644 --- 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 index 2c9b4f2d..815b737e 100644 --- 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 index d344562c..8192f005 100644 --- 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 index f9caedf5..5dd9a9b0 100644 --- 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 index 06f77ad2..97097cc9 100644 --- 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 { let result = if error.to_string().to_lowercase().contains("timed out") {