chore: add more payload tracing

crates/payload/basic/src/lib.rs

@@ -16,7 +16,7 @@ use futures_util::FutureExt;
 use reth_interfaces::{RethError, RethResult};
 use reth_payload_builder::{
     database::CachedReads, error::PayloadBuilderError, BuiltPayload, KeepPayloadJobAlive,
-    PayloadBuilderAttributes, PayloadJob, PayloadJobGenerator,
+    PayloadBuilderAttributes, PayloadId, PayloadJob, PayloadJobGenerator,
 };
 use reth_primitives::{
     bytes::BytesMut,
@@ -53,7 +53,7 @@ use tokio::{
     sync::{oneshot, Semaphore},
     time::{Interval, Sleep},
 };
-use tracing::{debug, trace};
+use tracing::{debug, trace, warn};
 
 mod metrics;
 
@@ -448,6 +448,8 @@ where
         let mut empty_payload = None;
 
         if best_payload.is_none() {
+            debug!(target: "payload_builder", id=%self.config.payload_id(), "no best payload yet to resolve, building empty payload");
+
             // if no payload has been built yet
             self.metrics.inc_requested_empty_payload();
             // no payload built yet, so we need to return an empty payload
@@ -464,31 +466,33 @@ where
             // upfront with the list of transactions sent in the attributes without caring about
             // the results of the polling job, if a best payload has not already been built.
             #[cfg(feature = "optimism")]
-            if self.config.chain_spec.is_optimism() &&
-                self.config.attributes.optimism_payload_attributes.no_tx_pool
             {
-                let args = BuildArguments {
-                    client: self.client.clone(),
-                    pool: self.pool.clone(),
-                    cached_reads: self.cached_reads.take().unwrap_or_default(),
-                    config: self.config.clone(),
-                    cancel: Cancelled::default(),
-                    best_payload: None,
-                };
-                if let Ok(BuildOutcome::Better { payload, cached_reads }) =
-                    self.builder.try_build(args)
+                if self.config.chain_spec.is_optimism() &&
+                    self.config.attributes.optimism_payload_attributes.no_tx_pool
                 {
-                    self.cached_reads = Some(cached_reads);
-                    trace!(target: "payload_builder", "[OPTIMISM] Forced best payload");
-                    let payload = Arc::new(payload);
-                    return (
-                        ResolveBestPayload {
-                            best_payload: Some(payload),
-                            maybe_better,
-                            empty_payload,
-                        },
-                        KeepPayloadJobAlive::Yes,
-                    )
+                    let args = BuildArguments {
+                        client: self.client.clone(),
+                        pool: self.pool.clone(),
+                        cached_reads: self.cached_reads.take().unwrap_or_default(),
+                        config: self.config.clone(),
+                        cancel: Cancelled::default(),
+                        best_payload: None,
+                    };
+                    if let Ok(BuildOutcome::Better { payload, cached_reads }) =
+                        self.builder.try_build(args)
+                    {
+                        self.cached_reads = Some(cached_reads);
+                        trace!(target: "payload_builder", "[OPTIMISM] Forced best payload");
+                        let payload = Arc::new(payload);
+                        return (
+                            ResolveBestPayload {
+                                best_payload: Some(payload),
+                                maybe_better,
+                                empty_payload,
+                            },
+                            KeepPayloadJobAlive::Yes,
+                        )
+                    }
                 }
             }
 
@@ -531,18 +535,27 @@ impl Future for ResolveBestPayload {
             if let Poll::Ready(res) = fut.poll(cx) {
                 this.maybe_better = None;
                 if let Ok(BuildOutcome::Better { payload, .. }) = res {
+                    debug!(target: "payload_builder", "resolving better payload");
                     return Poll::Ready(Ok(Arc::new(payload)))
                 }
             }
         }
 
         if let Some(best) = this.best_payload.take() {
+            debug!(target: "payload_builder", "resolving best payload");
             return Poll::Ready(Ok(best))
         }
 
         let mut empty_payload = this.empty_payload.take().expect("polled after completion");
         match empty_payload.poll_unpin(cx) {
-            Poll::Ready(Ok(res)) => Poll::Ready(res.map(Arc::new)),
+            Poll::Ready(Ok(res)) => {
+                if let Err(err) = &res {
+                    warn!(target: "payload_builder", ?err, "failed to resolve empty payload");
+                } else {
+                    debug!(target: "payload_builder", "resolving empty payload");
+                }
+                Poll::Ready(res.map(Arc::new))
+            }
             Poll::Ready(Err(err)) => Poll::Ready(Err(err.into())),
             Poll::Pending => {
                 this.empty_payload = Some(empty_payload);
@@ -622,6 +635,10 @@ impl PayloadConfig {
         }
         self.extra_data.clone()
     }
+
+    pub(crate) fn payload_id(&self) -> PayloadId {
+        self.attributes.id
+    }
 }
 
 impl PayloadConfig {
@@ -770,7 +787,7 @@ where
         ..
     } = config;
 
-    debug!(target: "payload_builder", parent_hash = ?parent_block.hash, parent_number = parent_block.number, "building new payload");
+    debug!(target: "payload_builder", id=%attributes.id, parent_hash = ?parent_block.hash, parent_number = parent_block.number, "building new payload");
     let mut cumulative_gas_used = 0;
     let mut sum_blob_gas_used = 0;
     let block_gas_limit: u64 = initialized_block_env.gas_limit.try_into().unwrap_or(u64::MAX);
@@ -1019,7 +1036,10 @@ where
 
     debug!(target: "payload_builder", parent_hash = ?parent_block.hash, parent_number = parent_block.number, "building empty payload");
 
-    let state = client.state_by_block_hash(parent_block.hash)?;
+    let state = client.state_by_block_hash(parent_block.hash).map_err(|err| {
+        warn!(target: "payload_builder", parent_hash=%parent_block.hash, ?err,  "failed to get state for empty payload");
+        err
+    })?;
     let mut db = State::builder()
         .with_database_boxed(Box::new(StateProviderDatabase::new(&state)))
         .with_bundle_update()
@@ -1037,10 +1057,16 @@ where
         &initialized_cfg,
         &initialized_block_env,
         &attributes,
-    )?;
+    ).map_err(|err| {
+        warn!(target: "payload_builder", parent_hash=%parent_block.hash, ?err,  "failed to apply beacon root contract call for empty payload");
+        err
+    })?;
 
     let WithdrawalsOutcome { withdrawals_root, withdrawals } =
-        commit_withdrawals(&mut db, &chain_spec, attributes.timestamp, attributes.withdrawals)?;
+        commit_withdrawals(&mut db, &chain_spec, attributes.timestamp, attributes.withdrawals).map_err(|err| {
+            warn!(target: "payload_builder", parent_hash=%parent_block.hash,?err,  "failed to commit withdrawals for empty payload");
+            err
+        })?;
 
     // merge all transitions into bundle state, this would apply the withdrawal balance changes and
     // 4788 contract call
@@ -1049,7 +1075,10 @@ where
     // calculate the state root
     let bundle_state =
         BundleStateWithReceipts::new(db.take_bundle(), Receipts::new(), block_number);
-    let state_root = state.state_root(&bundle_state)?;
+    let state_root = state.state_root(&bundle_state).map_err(|err| {
+        warn!(target: "payload_builder", parent_hash=%parent_block.hash, ?err,  "failed to calculate state root for empty payload");
+        err
+    })?;
 
     let header = Header {
         parent_hash: parent_block.hash,

crates/payload/basic/src/optimism.rs

@@ -36,7 +36,7 @@ where
         ..
     } = config;
 
-    debug!(target: "payload_builder", parent_hash = ?parent_block.hash, parent_number = parent_block.number, "building new payload");
+    debug!(target: "payload_builder", id=%attributes.id, parent_hash = ?parent_block.hash, parent_number = parent_block.number, "building new payload");
     let mut cumulative_gas_used = 0;
     let block_gas_limit: u64 = attributes
         .optimism_payload_attributes

crates/payload/builder/src/service.rs

@@ -229,15 +229,24 @@ where
         &self,
         id: PayloadId,
     ) -> Option<Result<PayloadBuilderAttributes, PayloadBuilderError>> {
-        self.payload_jobs
+        let attributes = self
+            .payload_jobs
             .iter()
             .find(|(_, job_id)| *job_id == id)
-            .map(|(j, _)| j.payload_attributes())
+            .map(|(j, _)| j.payload_attributes());
+
+        if attributes.is_none() {
+            trace!(%id, "no matching payload job found to get attributes for");
+        }
+
+        attributes
     }
 
     /// Returns the best payload for the given identifier that has been built so far and terminates
     /// the job if requested.
     fn resolve(&mut self, id: PayloadId) -> Option<PayloadFuture> {
+        trace!(%id, "resolving payload job");
+
         let job = self.payload_jobs.iter().position(|(_, job_id)| *job_id == id)?;
         let (fut, keep_alive) = self.payload_jobs[job].0.resolve();
 

crates/rpc/rpc-engine-api/src/engine_api.rs

@@ -6,7 +6,7 @@ use async_trait::async_trait;
 use jsonrpsee_core::RpcResult;
 use reth_beacon_consensus::BeaconConsensusEngineHandle;
 use reth_interfaces::consensus::ForkchoiceState;
-use reth_payload_builder::PayloadStore;
+use reth_payload_builder::{PayloadBuilderAttributes, PayloadStore};
 use reth_primitives::{BlockHash, BlockHashOrNumber, BlockNumber, ChainSpec, Hardfork, B256, U64};
 use reth_provider::{BlockReader, EvmEnvProvider, HeaderProvider, StateProviderFactory};
 use reth_rpc_api::EngineApiServer;
@@ -74,6 +74,19 @@ where
         Self { inner }
     }
 
+    /// Fetches the attributes for the payload with the given id.
+    async fn get_payload_attributes(
+        &self,
+        payload_id: PayloadId,
+    ) -> EngineApiResult<PayloadBuilderAttributes> {
+        Ok(self
+            .inner
+            .payload_store
+            .payload_attributes(payload_id)
+            .await
+            .ok_or(EngineApiError::UnknownPayload)??)
+    }
+
     /// See also <https://github.com/ethereum/execution-apis/blob/3d627c95a4d3510a8187dd02e0250ecb4331d27e/src/engine/paris.md#engine_newpayloadv1>
     /// Caution: This should not accept the `withdrawals` field
     pub async fn new_payload_v1(
@@ -189,12 +202,7 @@ where
         payload_id: PayloadId,
     ) -> EngineApiResult<ExecutionPayloadEnvelopeV2> {
         // First we fetch the payload attributes to check the timestamp
-        let attributes = self
-            .inner
-            .payload_store
-            .payload_attributes(payload_id)
-            .await
-            .ok_or(EngineApiError::UnknownPayload)??;
+        let attributes = self.get_payload_attributes(payload_id).await?;
 
         // validate timestamp according to engine rules
         self.validate_payload_timestamp(EngineApiMessageVersion::V2, attributes.timestamp)?;
@@ -221,12 +229,7 @@ where
         payload_id: PayloadId,
     ) -> EngineApiResult<ExecutionPayloadEnvelopeV3> {
         // First we fetch the payload attributes to check the timestamp
-        let attributes = self
-            .inner
-            .payload_store
-            .payload_attributes(payload_id)
-            .await
-            .ok_or(EngineApiError::UnknownPayload)??;
+        let attributes = self.get_payload_attributes(payload_id).await?;
 
         // validate timestamp according to engine rules
         self.validate_payload_timestamp(EngineApiMessageVersion::V3, attributes.timestamp)?;