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.

Author: chatton

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<SealedBlock<ev_primitives::Block>, 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]

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<Self::Attributes, Self::BuiltPayload>,
     ) -> Result<BuildOutcome<Self::BuiltPayload>, 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");
     }
 }

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);
+            }
+        }
+    }
 }

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: <Self as TransactionValidator>::Transaction,
     ) -> TransactionValidationOutcome<Self::Transaction> {
+        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.

crates/node/src/validator.rs

@@ -60,14 +60,20 @@ impl PayloadValidator<EvolveEngineTypes> 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<RecoveredBlock<Self::Block>, 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<EvolveEngineTypes> 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