From 19976fb267aee81f7a54509a74af10e31fda4f0d Mon Sep 17 00:00:00 2001 From: chatton Date: Tue, 24 Feb 2026 11:39:53 +0000 Subject: [PATCH 1/4] trace: add #[instrument] spans to payload building, validation, and txpool Add structured tracing spans to the four key code paths: - build_payload: per-block span with parent_hash, tx_count, gas_limit - try_build: outer Engine API entry point with payload_id - ensure_well_formed_payload: inbound payload validation with block_number - validate_transaction: txpool validation with origin and tx_hash - Per-transaction debug_span in the execution loop Also cleans up log messages to use structured fields and lean on span context instead of verbose prefixes. --- crates/node/src/builder.rs | 48 ++++++++++++------------------ crates/node/src/payload_service.rs | 17 ++++++----- crates/node/src/txpool.rs | 6 +++- crates/node/src/validator.rs | 18 +++++------ 4 files changed, 41 insertions(+), 48 deletions(-) diff --git a/crates/node/src/builder.rs b/crates/node/src/builder.rs index 038b6894..7b928394 100644 --- a/crates/node/src/builder.rs +++ b/crates/node/src/builder.rs @@ -15,7 +15,7 @@ use reth_primitives_traits::SealedBlock; use reth_provider::{HeaderProvider, StateProviderFactory}; use reth_revm::{database::StateProviderDatabase, State}; use std::sync::Arc; -use tracing::{debug, info}; +use tracing::{debug, debug_span, info, instrument}; type EvolveEthEvmConfig = EvEvmConfig; @@ -62,6 +62,11 @@ where } /// Builds a payload using the provided attributes + #[instrument(skip(self, attributes), fields( + parent_hash = %attributes.parent_hash, + tx_count = attributes.transactions.len(), + gas_limit = ?attributes.gas_limit, + ))] pub async fn build_payload( &self, attributes: EvolvePayloadAttributes, @@ -136,43 +141,28 @@ where .map_err(|err| PayloadBuilderError::Internal(err.into()))?; // Execute transactions - tracing::info!( - transaction_count = attributes.transactions.len(), - "Evolve payload builder: executing transactions" - ); + info!(tx_count = attributes.transactions.len(), "executing transactions"); for (i, tx) in attributes.transactions.iter().enumerate() { - tracing::debug!( + let _span = debug_span!("execute_tx", index = i, - hash = ?tx.tx_hash(), + hash = %tx.tx_hash(), nonce = tx.nonce(), - gas_price = ?tx.gas_price(), gas_limit = tx.gas_limit(), - "Processing transaction" - ); + ) + .entered(); - // Convert to recovered transaction for execution let recovered_tx = tx.try_clone_into_recovered().map_err(|_| { PayloadBuilderError::Internal(RethError::Other( "Failed to recover transaction".into(), )) })?; - // Execute the transaction match builder.execute_transaction(recovered_tx) { Ok(gas_used) => { - tracing::debug!(index = i, gas_used, "Transaction executed successfully"); - debug!( - "[debug] execute_transaction ok: index={}, gas_used={}", - i, gas_used - ); + debug!(gas_used, "transaction executed successfully"); } Err(err) => { - // Log the error but continue with other transactions - tracing::warn!(index = i, error = ?err, "Transaction execution failed"); - debug!( - "[debug] execute_transaction err: index={}, err={:?}", - i, err - ); + tracing::warn!(error = ?err, "transaction execution failed"); } } } @@ -189,12 +179,12 @@ where let sealed_block = block.sealed_block().clone(); - tracing::info!( - block_number = sealed_block.number, - block_hash = ?sealed_block.hash(), - transaction_count = sealed_block.transaction_count(), - gas_used = sealed_block.gas_used, - "Evolve payload builder: built block" + info!( + block_number = sealed_block.number, + block_hash = ?sealed_block.hash(), + tx_count = sealed_block.transaction_count(), + gas_used = sealed_block.gas_used, + "built block" ); // Return the sealed block diff --git a/crates/node/src/payload_service.rs b/crates/node/src/payload_service.rs index a0107c0b..cbf225ee 100644 --- a/crates/node/src/payload_service.rs +++ b/crates/node/src/payload_service.rs @@ -20,7 +20,7 @@ use reth_payload_builder::PayloadBuilderError; use reth_provider::HeaderProvider; use reth_revm::cached::CachedReads; use tokio::runtime::Handle; -use tracing::info; +use tracing::{info, instrument}; use crate::{ attributes::EvolveEnginePayloadBuilderAttributes, builder::EvolvePayloadBuilder, @@ -131,6 +131,10 @@ where type Attributes = EvolveEnginePayloadBuilderAttributes; type BuiltPayload = EvBuiltPayload; + #[instrument(skip(self, args), fields( + tx_count = args.config.attributes.transactions.len(), + payload_id = %args.config.attributes.payload_id(), + ))] fn try_build( &self, args: BuildArguments, @@ -146,10 +150,7 @@ where attributes, } = config; - info!( - "Evolve engine payload builder: building payload with {} transactions", - attributes.transactions.len() - ); + info!("building payload"); // Convert Engine API attributes to Evolve payload attributes. // If no gas_limit provided, default to the parent header's gas limit (genesis for first block). @@ -189,9 +190,9 @@ where .map_err(PayloadBuilderError::other)?; info!( - "Evolve engine payload builder: built block with {} transactions, gas used: {}", - sealed_block.transaction_count(), - sealed_block.gas_used + tx_count = sealed_block.transaction_count(), + gas_used = sealed_block.gas_used, + "built block" ); // Convert to EvBuiltPayload. diff --git a/crates/node/src/txpool.rs b/crates/node/src/txpool.rs index b9d2b726..bffd97a9 100644 --- a/crates/node/src/txpool.rs +++ b/crates/node/src/txpool.rs @@ -29,7 +29,7 @@ use reth_transaction_pool::{ EthTransactionValidator, PoolTransaction, TransactionOrigin, TransactionValidationOutcome, TransactionValidationTaskExecutor, TransactionValidator, }; -use tracing::{debug, info, warn}; +use tracing::{debug, info, instrument, warn}; /// Pool transaction wrapper for `EvTxEnvelope`. #[derive(Debug, Clone)] @@ -477,6 +477,10 @@ where type Transaction = EvPooledTransaction; type Block = ::Block; + #[instrument(skip(self, transaction), fields( + origin = ?origin, + tx_hash = %transaction.hash(), + ))] async fn validate_transaction( &self, origin: TransactionOrigin, diff --git a/crates/node/src/validator.rs b/crates/node/src/validator.rs index 70eb590e..74a3161a 100644 --- a/crates/node/src/validator.rs +++ b/crates/node/src/validator.rs @@ -20,7 +20,7 @@ use reth_ethereum::{ }; use reth_ethereum_payload_builder::EthereumExecutionPayloadValidator; use reth_primitives_traits::{Block as _, RecoveredBlock, SealedBlock}; -use tracing::info; +use tracing::{debug, info, instrument}; use crate::{attributes::EvolveEnginePayloadAttributes, node::EvolveEngineTypes}; @@ -57,24 +57,25 @@ impl PayloadValidator for EvolveEngineValidator { .map_err(NewPayloadError::other) } + #[instrument(skip(self, payload), fields( + block_number = payload.payload.block_number(), + tx_count = payload.payload.transactions().len(), + ))] fn ensure_well_formed_payload( &self, payload: ExecutionData, ) -> Result, NewPayloadError> { - info!("Evolve engine validator: validating payload"); - // Use inner validator but with custom evolve handling. match self.inner.ensure_well_formed_payload(payload.clone()) { Ok(sealed_block) => { - info!("Evolve engine validator: payload validation succeeded"); + info!("payload validation succeeded"); let ev_block = convert_sealed_block(sealed_block); ev_block .try_recover() .map_err(|e| NewPayloadError::Other(e.into())) } Err(err) => { - // Log the error for debugging. - tracing::debug!("Evolve payload validation error: {:?}", err); + debug!(error = ?err, "payload validation error"); // Check if this is an error we can bypass for evolve: // 1. BlockHash mismatch - ev-reth computes different hash due to custom tx types @@ -90,10 +91,7 @@ impl PayloadValidator for EvolveEngineValidator { || is_unknown_tx_type_error(&err); if should_bypass { - info!( - "Evolve engine validator: bypassing validation error for ev-reth: {:?}", - err - ); + info!(error = ?err, "bypassing validation error for ev-reth"); // For evolve, we trust the payload builder - parse the block with EvNode support. let ev_block = parse_evolve_payload(payload)?; ev_block From 03619b34294d9f782aec5036f0e7673e3554b345 Mon Sep 17 00:00:00 2001 From: chatton Date: Tue, 24 Feb 2026 13:39:37 +0000 Subject: [PATCH 2/4] test: add span assertion tests for all instrumented functions Cover the remaining 4 #[instrument] call sites with SpanCollector-based tests: execute_tx, ensure_well_formed_payload, try_build, and validate_transaction. --- Cargo.lock | 1 + crates/node/Cargo.toml | 1 + crates/node/src/builder.rs | 163 ++++++++++++++++++++++++++++- crates/node/src/lib.rs | 3 + crates/node/src/payload_service.rs | 95 +++++++++++++++++ crates/node/src/test_utils.rs | 101 ++++++++++++++++++ crates/node/src/txpool.rs | 28 +++++ crates/node/src/validator.rs | 66 ++++++++++++ 8 files changed, 457 insertions(+), 1 deletion(-) create mode 100644 crates/node/src/test_utils.rs diff --git a/Cargo.lock b/Cargo.lock index 27172bdf..1a7c01ae 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2987,6 +2987,7 @@ dependencies = [ "thiserror 2.0.18", "tokio", "tracing", + "tracing-subscriber 0.3.22", ] [[package]] diff --git a/crates/node/Cargo.toml b/crates/node/Cargo.toml index 6756e8df..1d4e57fd 100644 --- a/crates/node/Cargo.toml +++ b/crates/node/Cargo.toml @@ -90,6 +90,7 @@ reth-tracing.workspace = true tempfile.workspace = true hex = "0.4" alloy-rlp.workspace = true +tracing-subscriber = "0.3.20" [lints] workspace = true diff --git a/crates/node/src/builder.rs b/crates/node/src/builder.rs index 7b928394..b41d5413 100644 --- a/crates/node/src/builder.rs +++ b/crates/node/src/builder.rs @@ -192,7 +192,7 @@ where } } -/// Creates a new payload builder service +/// Creates a new payload builder service. pub fn create_payload_builder_service( client: Arc, evm_config: EvolveEthEvmConfig, @@ -222,3 +222,164 @@ where Some(EvolvePayloadBuilder::new(client, evm_config, config)) } + +#[cfg(test)] +mod tests { + use super::*; + use crate::config::EvolvePayloadBuilderConfig; + use crate::executor::EvolveEvmConfig; + use crate::test_utils::SpanCollector; + use alloy_primitives::B256; + use evolve_ev_reth::EvolvePayloadAttributes; + use reth_chainspec::ChainSpecBuilder; + use reth_primitives::Header; + use reth_provider::test_utils::MockEthProvider; + + #[tokio::test] + async fn build_payload_span_has_expected_fields() { + let collector = SpanCollector::new(); + let _guard = collector.as_default(); + + let genesis: alloy_genesis::Genesis = + serde_json::from_str(include_str!("../../tests/assets/genesis.json")) + .expect("valid genesis"); + let chain_spec = Arc::new( + ChainSpecBuilder::default() + .chain(reth_chainspec::Chain::from_id(1234)) + .genesis(genesis) + .cancun_activated() + .build(), + ); + + let provider = MockEthProvider::default(); + let genesis_hash = + B256::from_slice(&hex::decode("2b8bbb1ea1e04f9c9809b4b278a8687806edc061a356c7dbc491930d8e922503").unwrap()); + let genesis_state_root = + B256::from_slice(&hex::decode("05e9954443da80d86f2104e56ffdfd98fe21988730684360104865b3dc8191b4").unwrap()); + + let genesis_header = Header { + state_root: genesis_state_root, + number: 0, + gas_limit: 30_000_000, + timestamp: 1710338135, + base_fee_per_gas: Some(0), + excess_blob_gas: Some(0), + blob_gas_used: Some(0), + parent_beacon_block_root: Some(B256::ZERO), + ..Default::default() + }; + provider.add_header(genesis_hash, genesis_header); + + let config = + EvolvePayloadBuilderConfig::from_chain_spec(chain_spec.as_ref()).unwrap(); + let evm_config = EvolveEvmConfig::new(chain_spec); + let builder = + EvolvePayloadBuilder::new(Arc::new(provider), evm_config, config); + + let attributes = EvolvePayloadAttributes::new( + vec![], + Some(30_000_000), + 1710338136, + B256::random(), + Address::random(), + genesis_hash, + 1, + ); + + // we only care that the span was created with the right fields, + // not whether the payload build itself succeeds. + let _ = builder.build_payload(attributes).await; + + let span = collector + .find_span("build_payload") + .expect("build_payload span should be recorded"); + + assert!(span.has_field("parent_hash"), "span missing parent_hash field"); + assert!(span.has_field("tx_count"), "span missing tx_count field"); + assert!(span.has_field("gas_limit"), "span missing gas_limit field"); + } + + #[tokio::test] + async fn execute_tx_span_has_expected_fields() { + use alloy_consensus::TxLegacy; + use alloy_primitives::{Bytes, ChainId, Signature, TxKind, U256}; + use ev_primitives::EvTxEnvelope; + + let collector = SpanCollector::new(); + let _guard = collector.as_default(); + + let genesis: alloy_genesis::Genesis = + serde_json::from_str(include_str!("../../tests/assets/genesis.json")) + .expect("valid genesis"); + let chain_spec = Arc::new( + ChainSpecBuilder::default() + .chain(reth_chainspec::Chain::from_id(1234)) + .genesis(genesis) + .cancun_activated() + .build(), + ); + + let provider = MockEthProvider::default(); + let genesis_hash = + B256::from_slice(&hex::decode("2b8bbb1ea1e04f9c9809b4b278a8687806edc061a356c7dbc491930d8e922503").unwrap()); + let genesis_state_root = + B256::from_slice(&hex::decode("05e9954443da80d86f2104e56ffdfd98fe21988730684360104865b3dc8191b4").unwrap()); + + let genesis_header = Header { + state_root: genesis_state_root, + number: 0, + gas_limit: 30_000_000, + timestamp: 1710338135, + base_fee_per_gas: Some(0), + excess_blob_gas: Some(0), + blob_gas_used: Some(0), + parent_beacon_block_root: Some(B256::ZERO), + ..Default::default() + }; + provider.add_header(genesis_hash, genesis_header); + + let config = + EvolvePayloadBuilderConfig::from_chain_spec(chain_spec.as_ref()).unwrap(); + let evm_config = EvolveEvmConfig::new(chain_spec); + let builder = + EvolvePayloadBuilder::new(Arc::new(provider), evm_config, config); + + let legacy_tx = TxLegacy { + chain_id: Some(ChainId::from(1234u64)), + nonce: 0, + gas_price: 0, + gas_limit: 21_000, + to: TxKind::Call(Address::ZERO), + value: U256::ZERO, + input: Bytes::default(), + }; + let signed = alloy_consensus::Signed::new_unhashed( + reth_primitives::Transaction::Legacy(legacy_tx), + Signature::test_signature(), + ); + let tx = EvTxEnvelope::Ethereum( + reth_ethereum_primitives::TransactionSigned::from(signed), + ); + + let attributes = EvolvePayloadAttributes::new( + vec![tx], + Some(30_000_000), + 1710338136, + B256::random(), + Address::random(), + genesis_hash, + 1, + ); + + let _ = builder.build_payload(attributes).await; + + let span = collector + .find_span("execute_tx") + .expect("execute_tx span should be recorded"); + + assert!(span.has_field("index"), "span missing index field"); + assert!(span.has_field("hash"), "span missing hash field"); + assert!(span.has_field("nonce"), "span missing nonce field"); + assert!(span.has_field("gas_limit"), "span missing gas_limit field"); + } +} diff --git a/crates/node/src/lib.rs b/crates/node/src/lib.rs index 7a9d5254..aee43b8d 100644 --- a/crates/node/src/lib.rs +++ b/crates/node/src/lib.rs @@ -34,6 +34,9 @@ pub mod txpool; /// Payload validator integration. pub mod validator; +#[cfg(test)] +mod test_utils; + // Re-export public types for convenience. pub use args::EvolveArgs; pub use attributes::{EvolveEnginePayloadAttributes, EvolveEnginePayloadBuilderAttributes}; diff --git a/crates/node/src/payload_service.rs b/crates/node/src/payload_service.rs index cbf225ee..ba8469c5 100644 --- a/crates/node/src/payload_service.rs +++ b/crates/node/src/payload_service.rs @@ -278,3 +278,98 @@ where MissingPayloadBehaviour::AwaitInProgress } } + +#[cfg(test)] +mod tests { + use super::*; + use crate::config::EvolvePayloadBuilderConfig; + use crate::executor::EvolveEvmConfig; + use crate::test_utils::SpanCollector; + use alloy_primitives::B256; + use alloy_rpc_types::engine::PayloadAttributes as RpcPayloadAttributes; + use reth_basic_payload_builder::PayloadConfig; + use reth_chainspec::ChainSpecBuilder; + use reth_payload_builder::EthPayloadBuilderAttributes; + use reth_primitives_traits::SealedHeader; + use reth_provider::test_utils::MockEthProvider; + use reth_revm::{cached::CachedReads, cancelled::CancelOnDrop}; + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn try_build_span_has_expected_fields() { + let collector = SpanCollector::new(); + let _guard = collector.as_default(); + + let genesis: alloy_genesis::Genesis = + serde_json::from_str(include_str!("../../tests/assets/genesis.json")) + .expect("valid genesis"); + let chain_spec = Arc::new( + ChainSpecBuilder::default() + .chain(reth_chainspec::Chain::from_id(1234)) + .genesis(genesis) + .cancun_activated() + .build(), + ); + + let provider = MockEthProvider::default(); + let genesis_hash = + B256::from_slice(&hex::decode("2b8bbb1ea1e04f9c9809b4b278a8687806edc061a356c7dbc491930d8e922503").unwrap()); + let genesis_state_root = + B256::from_slice(&hex::decode("05e9954443da80d86f2104e56ffdfd98fe21988730684360104865b3dc8191b4").unwrap()); + + let genesis_header = Header { + state_root: genesis_state_root, + number: 0, + gas_limit: 30_000_000, + timestamp: 1710338135, + base_fee_per_gas: Some(0), + excess_blob_gas: Some(0), + blob_gas_used: Some(0), + parent_beacon_block_root: Some(B256::ZERO), + ..Default::default() + }; + provider.add_header(genesis_hash, genesis_header.clone()); + + let config = + EvolvePayloadBuilderConfig::from_chain_spec(chain_spec.as_ref()).unwrap(); + let evm_config = EvolveEvmConfig::new(chain_spec); + let evolve_builder = Arc::new(EvolvePayloadBuilder::new( + Arc::new(provider), + evm_config, + config.clone(), + )); + + let engine_builder = EvolveEnginePayloadBuilder { + evolve_builder, + config, + }; + + let rpc_attrs = RpcPayloadAttributes { + timestamp: 1710338136, + prev_randao: B256::random(), + suggested_fee_recipient: Address::random(), + withdrawals: Some(vec![]), + parent_beacon_block_root: Some(B256::ZERO), + }; + let eth_attrs = EthPayloadBuilderAttributes::new(genesis_hash, rpc_attrs); + let builder_attrs = EvolveEnginePayloadBuilderAttributes::from(eth_attrs); + + let sealed_parent = SealedHeader::new(genesis_header, genesis_hash); + let payload_config = PayloadConfig::new(Arc::new(sealed_parent), builder_attrs); + let args = BuildArguments::new( + CachedReads::default(), + payload_config, + CancelOnDrop::default(), + None, + ); + + // we only care that the span was created with the right fields. + let _ = engine_builder.try_build(args); + + let span = collector + .find_span("try_build") + .expect("try_build span should be recorded"); + + assert!(span.has_field("tx_count"), "span missing tx_count field"); + assert!(span.has_field("payload_id"), "span missing payload_id field"); + } +} diff --git a/crates/node/src/test_utils.rs b/crates/node/src/test_utils.rs new file mode 100644 index 00000000..e54cd841 --- /dev/null +++ b/crates/node/src/test_utils.rs @@ -0,0 +1,101 @@ +//! test utilities for verifying tracing instrumentation. + +use std::sync::{Arc, Mutex}; +use tracing::field::{Field, Visit}; +use tracing::subscriber::set_default; +use tracing::Subscriber; +use tracing_subscriber::{layer::Context, layer::SubscriberExt, registry::LookupSpan, Layer}; + +/// a recorded span with its name and captured fields. +#[derive(Debug, Clone)] +pub(crate) struct SpanRecord { + pub(crate) name: String, + pub(crate) fields: Vec<(String, String)>, +} + +impl SpanRecord { + pub(crate) fn has_field(&self, name: &str) -> bool { + self.fields.iter().any(|(k, _)| k == name) + } +} + +/// collects field values from span attributes. +struct FieldCollector { + fields: Vec<(String, String)>, +} + +impl FieldCollector { + fn new() -> Self { + Self { fields: Vec::new() } + } +} + +impl Visit for FieldCollector { + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + self.fields + .push((field.name().to_string(), format!("{:?}", value))); + } + + fn record_str(&mut self, field: &Field, value: &str) { + self.fields + .push((field.name().to_string(), value.to_string())); + } + + fn record_u64(&mut self, field: &Field, value: u64) { + self.fields + .push((field.name().to_string(), value.to_string())); + } +} + +/// a tracing layer that records span metadata for test assertions. +#[derive(Debug, Clone)] +pub(crate) struct SpanCollector { + spans: Arc>>, +} + +impl SpanCollector { + pub(crate) fn new() -> Self { + Self { + spans: Arc::new(Mutex::new(Vec::new())), + } + } + + /// finds the first span with the given name. + pub(crate) fn find_span(&self, name: &str) -> Option { + self.spans + .lock() + .unwrap() + .iter() + .find(|s| s.name == name) + .cloned() + } + + /// installs this collector as the default subscriber for the current thread, + /// returning a guard that restores the previous subscriber on drop. + pub(crate) fn as_default(&self) -> tracing::subscriber::DefaultGuard { + let subscriber = tracing_subscriber::registry().with(self.clone()); + set_default(subscriber) + } +} + +impl Layer for SpanCollector +where + S: Subscriber + for<'lookup> LookupSpan<'lookup>, +{ + fn on_new_span( + &self, + attrs: &tracing::span::Attributes<'_>, + _id: &tracing::span::Id, + _ctx: Context<'_, S>, + ) { + let mut collector = FieldCollector::new(); + attrs.record(&mut collector); + + let record = SpanRecord { + name: attrs.metadata().name().to_string(), + fields: collector.fields, + }; + + self.spans.lock().unwrap().push(record); + } +} diff --git a/crates/node/src/txpool.rs b/crates/node/src/txpool.rs index bffd97a9..e82cc41b 100644 --- a/crates/node/src/txpool.rs +++ b/crates/node/src/txpool.rs @@ -760,6 +760,34 @@ mod tests { ); } + #[tokio::test] + async fn validate_transaction_span_has_expected_fields() { + use crate::test_utils::SpanCollector; + + let collector = SpanCollector::new(); + let _guard = collector.as_default(); + + let validator = create_test_validator(None); + + let gas_limit = 21_000u64; + let max_fee_per_gas = 1_000_000_000u128; + let signed_tx = create_non_sponsored_evnode_tx(gas_limit, max_fee_per_gas); + + let signer = Address::random(); + let pooled = create_pooled_tx(signed_tx, signer); + + let _ = validator + .validate_transaction(TransactionOrigin::External, pooled) + .await; + + let span = collector + .find_span("validate_transaction") + .expect("validate_transaction span should be recorded"); + + assert!(span.has_field("origin"), "span missing origin field"); + assert!(span.has_field("tx_hash"), "span missing tx_hash field"); + } + /// Tests pool-level deploy allowlist rejection for `EvNode` CREATE when caller not allowlisted. #[test] fn evnode_create_rejected_when_not_allowlisted() { diff --git a/crates/node/src/validator.rs b/crates/node/src/validator.rs index 74a3161a..464faaf5 100644 --- a/crates/node/src/validator.rs +++ b/crates/node/src/validator.rs @@ -280,6 +280,72 @@ mod tests { ); } + #[test] + fn ensure_well_formed_payload_span_has_expected_fields() { + use crate::test_utils::SpanCollector; + use alloy_primitives::{Address, Bloom, Bytes, B256, U256}; + use alloy_rpc_types::engine::{ + ExecutionData, ExecutionPayload, ExecutionPayloadSidecar, ExecutionPayloadV1, + ExecutionPayloadV2, ExecutionPayloadV3, + }; + use reth_chainspec::ChainSpecBuilder; + + let collector = SpanCollector::new(); + let _guard = collector.as_default(); + + let chain_spec = std::sync::Arc::new( + ChainSpecBuilder::default() + .chain(reth_chainspec::Chain::from_id(1234)) + .genesis( + serde_json::from_str(include_str!("../../tests/assets/genesis.json")) + .expect("valid genesis"), + ) + .cancun_activated() + .build(), + ); + let validator = EvolveEngineValidator::new(chain_spec); + + let v1 = ExecutionPayloadV1 { + parent_hash: B256::ZERO, + fee_recipient: Address::ZERO, + state_root: B256::ZERO, + receipts_root: B256::ZERO, + logs_bloom: Bloom::ZERO, + prev_randao: B256::ZERO, + block_number: 1, + gas_limit: 30_000_000, + gas_used: 0, + timestamp: 1710338136, + extra_data: Bytes::default(), + base_fee_per_gas: U256::ZERO, + block_hash: B256::ZERO, + transactions: vec![], + }; + let v2 = ExecutionPayloadV2 { + payload_inner: v1, + withdrawals: vec![], + }; + let v3 = ExecutionPayloadV3 { + payload_inner: v2, + blob_gas_used: 0, + excess_blob_gas: 0, + }; + + let payload = ExecutionPayload::V3(v3); + let sidecar = ExecutionPayloadSidecar::default(); + let execution_data = ExecutionData::new(payload, sidecar); + + // we only care that the span was created, not whether validation succeeds. + let _ = PayloadValidator::ensure_well_formed_payload(&validator, execution_data); + + let span = collector + .find_span("ensure_well_formed_payload") + .expect("ensure_well_formed_payload span should be recorded"); + + assert!(span.has_field("block_number"), "span missing block_number field"); + assert!(span.has_field("tx_count"), "span missing tx_count field"); + } + /// Verifies that `is_unknown_tx_type_error` correctly identifies decode errors /// with the expected message. #[test] From 0751bf861829f712b30e070ee659dd5cdb5d7c72 Mon Sep 17 00:00:00 2001 From: chatton Date: Tue, 24 Feb 2026 13:59:06 +0000 Subject: [PATCH 3/4] trace: add duration_ms, block_hash, and tx_hash to spans Apply review feedback: add duration_ms timing to all instrumented spans, add block_hash to ensure_well_formed_payload (recorded after computation), and add tx_hash to the execute_tx error warn log. --- crates/node/src/builder.rs | 8 +++++++- crates/node/src/payload_service.rs | 5 +++++ crates/node/src/test_utils.rs | 18 ++++++++++++++++++ crates/node/src/txpool.rs | 10 ++++++++-- crates/node/src/validator.rs | 11 +++++++++++ 5 files changed, 49 insertions(+), 3 deletions(-) diff --git a/crates/node/src/builder.rs b/crates/node/src/builder.rs index b41d5413..08cc05dc 100644 --- a/crates/node/src/builder.rs +++ b/crates/node/src/builder.rs @@ -66,11 +66,14 @@ where parent_hash = %attributes.parent_hash, tx_count = attributes.transactions.len(), gas_limit = ?attributes.gas_limit, + duration_ms = tracing::field::Empty, ))] pub async fn build_payload( &self, attributes: EvolvePayloadAttributes, ) -> Result, PayloadBuilderError> { + let _start = std::time::Instant::now(); + // Validate attributes attributes .validate() @@ -162,7 +165,7 @@ where debug!(gas_used, "transaction executed successfully"); } Err(err) => { - tracing::warn!(error = ?err, "transaction execution failed"); + tracing::warn!(error = ?err, tx_hash = %tx.tx_hash(), "transaction execution failed"); } } } @@ -179,6 +182,8 @@ where let sealed_block = block.sealed_block().clone(); + tracing::Span::current().record("duration_ms", _start.elapsed().as_millis() as u64); + info!( block_number = sealed_block.number, block_hash = ?sealed_block.hash(), @@ -297,6 +302,7 @@ mod tests { assert!(span.has_field("parent_hash"), "span missing parent_hash field"); assert!(span.has_field("tx_count"), "span missing tx_count field"); assert!(span.has_field("gas_limit"), "span missing gas_limit field"); + assert!(span.has_field("duration_ms"), "span missing duration_ms field"); } #[tokio::test] diff --git a/crates/node/src/payload_service.rs b/crates/node/src/payload_service.rs index ba8469c5..9bc94e28 100644 --- a/crates/node/src/payload_service.rs +++ b/crates/node/src/payload_service.rs @@ -134,11 +134,13 @@ where #[instrument(skip(self, args), fields( tx_count = args.config.attributes.transactions.len(), payload_id = %args.config.attributes.payload_id(), + duration_ms = tracing::field::Empty, ))] fn try_build( &self, args: BuildArguments, ) -> Result, PayloadBuilderError> { + let _start = std::time::Instant::now(); let BuildArguments { cached_reads: _, config, @@ -204,6 +206,8 @@ where None, // No blob sidecar for evolve. ); + tracing::Span::current().record("duration_ms", _start.elapsed().as_millis() as u64); + Ok(BuildOutcome::Better { payload: built_payload, cached_reads: CachedReads::default(), @@ -371,5 +375,6 @@ mod tests { assert!(span.has_field("tx_count"), "span missing tx_count field"); assert!(span.has_field("payload_id"), "span missing payload_id field"); + assert!(span.has_field("duration_ms"), "span missing duration_ms field"); } } diff --git a/crates/node/src/test_utils.rs b/crates/node/src/test_utils.rs index e54cd841..55ccd4d2 100644 --- a/crates/node/src/test_utils.rs +++ b/crates/node/src/test_utils.rs @@ -98,4 +98,22 @@ where self.spans.lock().unwrap().push(record); } + + fn on_record( + &self, + id: &tracing::span::Id, + values: &tracing::span::Record<'_>, + ctx: Context<'_, S>, + ) { + let mut collector = FieldCollector::new(); + values.record(&mut collector); + + if let Some(span_ref) = ctx.span(id) { + let name = span_ref.name().to_string(); + let mut spans = self.spans.lock().unwrap(); + if let Some(record) = spans.iter_mut().find(|s| s.name == name) { + record.fields.extend(collector.fields); + } + } + } } diff --git a/crates/node/src/txpool.rs b/crates/node/src/txpool.rs index e82cc41b..49a7c213 100644 --- a/crates/node/src/txpool.rs +++ b/crates/node/src/txpool.rs @@ -480,18 +480,20 @@ where #[instrument(skip(self, transaction), fields( origin = ?origin, tx_hash = %transaction.hash(), + duration_ms = tracing::field::Empty, ))] async fn validate_transaction( &self, origin: TransactionOrigin, transaction: ::Transaction, ) -> TransactionValidationOutcome { + let _start = std::time::Instant::now(); let mut state = None; let outcome = self .inner .validate_one_with_state(origin, transaction, &mut state); - match outcome { + let result = match outcome { TransactionValidationOutcome::Valid { balance, state_nonce, @@ -513,7 +515,10 @@ where } }, other => other, - } + }; + + tracing::Span::current().record("duration_ms", _start.elapsed().as_millis() as u64); + result } } @@ -786,6 +791,7 @@ mod tests { assert!(span.has_field("origin"), "span missing origin field"); assert!(span.has_field("tx_hash"), "span missing tx_hash field"); + assert!(span.has_field("duration_ms"), "span missing duration_ms field"); } /// Tests pool-level deploy allowlist rejection for `EvNode` CREATE when caller not allowlisted. diff --git a/crates/node/src/validator.rs b/crates/node/src/validator.rs index 464faaf5..f464d5d5 100644 --- a/crates/node/src/validator.rs +++ b/crates/node/src/validator.rs @@ -60,14 +60,20 @@ impl PayloadValidator for EvolveEngineValidator { #[instrument(skip(self, payload), fields( block_number = payload.payload.block_number(), tx_count = payload.payload.transactions().len(), + block_hash = tracing::field::Empty, + duration_ms = tracing::field::Empty, ))] fn ensure_well_formed_payload( &self, payload: ExecutionData, ) -> Result, NewPayloadError> { + let _start = std::time::Instant::now(); // Use inner validator but with custom evolve handling. match self.inner.ensure_well_formed_payload(payload.clone()) { Ok(sealed_block) => { + let span = tracing::Span::current(); + span.record("block_hash", tracing::field::display(sealed_block.hash())); + span.record("duration_ms", _start.elapsed().as_millis() as u64); info!("payload validation succeeded"); let ev_block = convert_sealed_block(sealed_block); ev_block @@ -94,6 +100,9 @@ impl PayloadValidator for EvolveEngineValidator { info!(error = ?err, "bypassing validation error for ev-reth"); // For evolve, we trust the payload builder - parse the block with EvNode support. let ev_block = parse_evolve_payload(payload)?; + let span = tracing::Span::current(); + span.record("block_hash", tracing::field::display(ev_block.hash())); + span.record("duration_ms", _start.elapsed().as_millis() as u64); ev_block .try_recover() .map_err(|e| NewPayloadError::Other(e.into())) @@ -344,6 +353,8 @@ mod tests { assert!(span.has_field("block_number"), "span missing block_number field"); assert!(span.has_field("tx_count"), "span missing tx_count field"); + assert!(span.has_field("block_hash"), "span missing block_hash field"); + assert!(span.has_field("duration_ms"), "span missing duration_ms field"); } /// Verifies that `is_unknown_tx_type_error` correctly identifies decode errors From 89536dbc88c7035c08fa4493f266b88b651266cc Mon Sep 17 00:00:00 2001 From: chatton Date: Tue, 24 Feb 2026 13:59:06 +0000 Subject: [PATCH 4/4] trace: add duration_ms, block_hash, and tx_hash to spans Apply review feedback: add duration_ms timing to all instrumented spans, add block_hash to ensure_well_formed_payload (recorded after computation), and add tx_hash to the execute_tx error warn log. --- crates/node/src/builder.rs | 61 ++++++++++++++++++------------ crates/node/src/payload_service.rs | 31 +++++++++------ crates/node/src/test_utils.rs | 14 +++++-- crates/node/src/txpool.rs | 5 ++- crates/node/src/validator.rs | 15 ++++++-- 5 files changed, 82 insertions(+), 44 deletions(-) diff --git a/crates/node/src/builder.rs b/crates/node/src/builder.rs index 08cc05dc..e25257af 100644 --- a/crates/node/src/builder.rs +++ b/crates/node/src/builder.rs @@ -144,7 +144,10 @@ where .map_err(|err| PayloadBuilderError::Internal(err.into()))?; // Execute transactions - info!(tx_count = attributes.transactions.len(), "executing transactions"); + info!( + tx_count = attributes.transactions.len(), + "executing transactions" + ); for (i, tx) in attributes.transactions.iter().enumerate() { let _span = debug_span!("execute_tx", index = i, @@ -231,9 +234,9 @@ where #[cfg(test)] mod tests { use super::*; - use crate::config::EvolvePayloadBuilderConfig; - use crate::executor::EvolveEvmConfig; - use crate::test_utils::SpanCollector; + use crate::{ + config::EvolvePayloadBuilderConfig, executor::EvolveEvmConfig, test_utils::SpanCollector, + }; use alloy_primitives::B256; use evolve_ev_reth::EvolvePayloadAttributes; use reth_chainspec::ChainSpecBuilder; @@ -257,10 +260,14 @@ mod tests { ); let provider = MockEthProvider::default(); - let genesis_hash = - B256::from_slice(&hex::decode("2b8bbb1ea1e04f9c9809b4b278a8687806edc061a356c7dbc491930d8e922503").unwrap()); - let genesis_state_root = - B256::from_slice(&hex::decode("05e9954443da80d86f2104e56ffdfd98fe21988730684360104865b3dc8191b4").unwrap()); + let genesis_hash = B256::from_slice( + &hex::decode("2b8bbb1ea1e04f9c9809b4b278a8687806edc061a356c7dbc491930d8e922503") + .unwrap(), + ); + let genesis_state_root = B256::from_slice( + &hex::decode("05e9954443da80d86f2104e56ffdfd98fe21988730684360104865b3dc8191b4") + .unwrap(), + ); let genesis_header = Header { state_root: genesis_state_root, @@ -275,11 +282,9 @@ mod tests { }; provider.add_header(genesis_hash, genesis_header); - let config = - EvolvePayloadBuilderConfig::from_chain_spec(chain_spec.as_ref()).unwrap(); + let config = EvolvePayloadBuilderConfig::from_chain_spec(chain_spec.as_ref()).unwrap(); let evm_config = EvolveEvmConfig::new(chain_spec); - let builder = - EvolvePayloadBuilder::new(Arc::new(provider), evm_config, config); + let builder = EvolvePayloadBuilder::new(Arc::new(provider), evm_config, config); let attributes = EvolvePayloadAttributes::new( vec![], @@ -299,10 +304,16 @@ mod tests { .find_span("build_payload") .expect("build_payload span should be recorded"); - assert!(span.has_field("parent_hash"), "span missing parent_hash field"); + assert!( + span.has_field("parent_hash"), + "span missing parent_hash field" + ); assert!(span.has_field("tx_count"), "span missing tx_count field"); assert!(span.has_field("gas_limit"), "span missing gas_limit field"); - assert!(span.has_field("duration_ms"), "span missing duration_ms field"); + assert!( + span.has_field("duration_ms"), + "span missing duration_ms field" + ); } #[tokio::test] @@ -326,10 +337,14 @@ mod tests { ); let provider = MockEthProvider::default(); - let genesis_hash = - B256::from_slice(&hex::decode("2b8bbb1ea1e04f9c9809b4b278a8687806edc061a356c7dbc491930d8e922503").unwrap()); - let genesis_state_root = - B256::from_slice(&hex::decode("05e9954443da80d86f2104e56ffdfd98fe21988730684360104865b3dc8191b4").unwrap()); + let genesis_hash = B256::from_slice( + &hex::decode("2b8bbb1ea1e04f9c9809b4b278a8687806edc061a356c7dbc491930d8e922503") + .unwrap(), + ); + let genesis_state_root = B256::from_slice( + &hex::decode("05e9954443da80d86f2104e56ffdfd98fe21988730684360104865b3dc8191b4") + .unwrap(), + ); let genesis_header = Header { state_root: genesis_state_root, @@ -344,11 +359,9 @@ mod tests { }; provider.add_header(genesis_hash, genesis_header); - let config = - EvolvePayloadBuilderConfig::from_chain_spec(chain_spec.as_ref()).unwrap(); + let config = EvolvePayloadBuilderConfig::from_chain_spec(chain_spec.as_ref()).unwrap(); let evm_config = EvolveEvmConfig::new(chain_spec); - let builder = - EvolvePayloadBuilder::new(Arc::new(provider), evm_config, config); + let builder = EvolvePayloadBuilder::new(Arc::new(provider), evm_config, config); let legacy_tx = TxLegacy { chain_id: Some(ChainId::from(1234u64)), @@ -363,9 +376,7 @@ mod tests { reth_primitives::Transaction::Legacy(legacy_tx), Signature::test_signature(), ); - let tx = EvTxEnvelope::Ethereum( - reth_ethereum_primitives::TransactionSigned::from(signed), - ); + let tx = EvTxEnvelope::Ethereum(reth_ethereum_primitives::TransactionSigned::from(signed)); let attributes = EvolvePayloadAttributes::new( vec![tx], diff --git a/crates/node/src/payload_service.rs b/crates/node/src/payload_service.rs index 9bc94e28..e12075a9 100644 --- a/crates/node/src/payload_service.rs +++ b/crates/node/src/payload_service.rs @@ -286,9 +286,9 @@ where #[cfg(test)] mod tests { use super::*; - use crate::config::EvolvePayloadBuilderConfig; - use crate::executor::EvolveEvmConfig; - use crate::test_utils::SpanCollector; + use crate::{ + config::EvolvePayloadBuilderConfig, executor::EvolveEvmConfig, test_utils::SpanCollector, + }; use alloy_primitives::B256; use alloy_rpc_types::engine::PayloadAttributes as RpcPayloadAttributes; use reth_basic_payload_builder::PayloadConfig; @@ -315,10 +315,14 @@ mod tests { ); let provider = MockEthProvider::default(); - let genesis_hash = - B256::from_slice(&hex::decode("2b8bbb1ea1e04f9c9809b4b278a8687806edc061a356c7dbc491930d8e922503").unwrap()); - let genesis_state_root = - B256::from_slice(&hex::decode("05e9954443da80d86f2104e56ffdfd98fe21988730684360104865b3dc8191b4").unwrap()); + let genesis_hash = B256::from_slice( + &hex::decode("2b8bbb1ea1e04f9c9809b4b278a8687806edc061a356c7dbc491930d8e922503") + .unwrap(), + ); + let genesis_state_root = B256::from_slice( + &hex::decode("05e9954443da80d86f2104e56ffdfd98fe21988730684360104865b3dc8191b4") + .unwrap(), + ); let genesis_header = Header { state_root: genesis_state_root, @@ -333,8 +337,7 @@ mod tests { }; provider.add_header(genesis_hash, genesis_header.clone()); - let config = - EvolvePayloadBuilderConfig::from_chain_spec(chain_spec.as_ref()).unwrap(); + let config = EvolvePayloadBuilderConfig::from_chain_spec(chain_spec.as_ref()).unwrap(); let evm_config = EvolveEvmConfig::new(chain_spec); let evolve_builder = Arc::new(EvolvePayloadBuilder::new( Arc::new(provider), @@ -374,7 +377,13 @@ mod tests { .expect("try_build span should be recorded"); assert!(span.has_field("tx_count"), "span missing tx_count field"); - assert!(span.has_field("payload_id"), "span missing payload_id field"); - assert!(span.has_field("duration_ms"), "span missing duration_ms field"); + assert!( + span.has_field("payload_id"), + "span missing payload_id field" + ); + assert!( + span.has_field("duration_ms"), + "span missing duration_ms field" + ); } } diff --git a/crates/node/src/test_utils.rs b/crates/node/src/test_utils.rs index 55ccd4d2..e0c8ac80 100644 --- a/crates/node/src/test_utils.rs +++ b/crates/node/src/test_utils.rs @@ -1,10 +1,16 @@ //! test utilities for verifying tracing instrumentation. use std::sync::{Arc, Mutex}; -use tracing::field::{Field, Visit}; -use tracing::subscriber::set_default; -use tracing::Subscriber; -use tracing_subscriber::{layer::Context, layer::SubscriberExt, registry::LookupSpan, Layer}; +use tracing::{ + field::{Field, Visit}, + subscriber::set_default, + Subscriber, +}; +use tracing_subscriber::{ + layer::{Context, SubscriberExt}, + registry::LookupSpan, + Layer, +}; /// a recorded span with its name and captured fields. #[derive(Debug, Clone)] diff --git a/crates/node/src/txpool.rs b/crates/node/src/txpool.rs index 49a7c213..efeff56b 100644 --- a/crates/node/src/txpool.rs +++ b/crates/node/src/txpool.rs @@ -791,7 +791,10 @@ mod tests { assert!(span.has_field("origin"), "span missing origin field"); assert!(span.has_field("tx_hash"), "span missing tx_hash field"); - assert!(span.has_field("duration_ms"), "span missing duration_ms field"); + assert!( + span.has_field("duration_ms"), + "span missing duration_ms field" + ); } /// Tests pool-level deploy allowlist rejection for `EvNode` CREATE when caller not allowlisted. diff --git a/crates/node/src/validator.rs b/crates/node/src/validator.rs index f464d5d5..c0bdf555 100644 --- a/crates/node/src/validator.rs +++ b/crates/node/src/validator.rs @@ -351,10 +351,19 @@ mod tests { .find_span("ensure_well_formed_payload") .expect("ensure_well_formed_payload span should be recorded"); - assert!(span.has_field("block_number"), "span missing block_number field"); + assert!( + span.has_field("block_number"), + "span missing block_number field" + ); assert!(span.has_field("tx_count"), "span missing tx_count field"); - assert!(span.has_field("block_hash"), "span missing block_hash field"); - assert!(span.has_field("duration_ms"), "span missing duration_ms field"); + assert!( + span.has_field("block_hash"), + "span missing block_hash field" + ); + assert!( + span.has_field("duration_ms"), + "span missing duration_ms field" + ); } /// Verifies that `is_unknown_tx_type_error` correctly identifies decode errors