diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index f222f28c3..2a2225cbd 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -12,6 +12,7 @@ pub use engine_api::*; pub use engine_api::{http, http::deposit_methods, http::HttpJsonRpc}; use engines::{Engine, EngineError}; pub use engines::{EngineState, ForkChoiceState}; +use eth2::types::{builder_bid::SignedBuilderBid, ForkVersionedResponse}; use fork_choice::ForkchoiceUpdateParameters; use lru::LruCache; use payload_status::process_payload_status; @@ -21,11 +22,13 @@ use serde::{Deserialize, Serialize}; use slog::{crit, debug, error, info, trace, warn, Logger}; use slot_clock::SlotClock; use std::collections::HashMap; +use std::fmt; use std::future::Future; use std::io::Write; use std::path::PathBuf; use std::sync::Arc; -use std::time::{Duration, SystemTime, UNIX_EPOCH}; +use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH}; +use strum::AsRefStr; use task_executor::TaskExecutor; use tokio::{ sync::{Mutex, MutexGuard, RwLock}, @@ -34,7 +37,7 @@ use tokio::{ use tokio_stream::wrappers::WatchStream; use types::{ BlindedPayload, BlockType, ChainSpec, Epoch, ExecPayload, ExecutionBlockHash, ForkName, - ProposerPreparationData, PublicKeyBytes, SignedBeaconBlock, Slot, + ProposerPreparationData, PublicKeyBytes, Signature, SignedBeaconBlock, Slot, Uint256, }; mod engine_api; @@ -66,6 +69,14 @@ const DEFAULT_SUGGESTED_FEE_RECIPIENT: [u8; 20] = const CONFIG_POLL_INTERVAL: Duration = Duration::from_secs(60); +/// A payload alongside some information about where it came from. +enum ProvenancedPayload

{ + /// A good ol' fashioned farm-to-table payload from your local EE. + Local(P), + /// A payload from a builder (e.g. mev-boost). + Builder(P), +} + #[derive(Debug)] pub enum Error { NoEngine, @@ -73,6 +84,7 @@ pub enum Error { ApiError(ApiError), Builder(builder_client::Error), NoHeaderFromBuilder, + CannotProduceHeader, EngineError(Box), NotSynced, ShuttingDown, @@ -550,7 +562,7 @@ impl ExecutionLayer { ) -> Result { let suggested_fee_recipient = self.get_suggested_fee_recipient(proposer_index).await; - match Payload::block_type() { + let payload_result = match Payload::block_type() { BlockType::Blinded => { let _timer = metrics::start_timer_vec( &metrics::EXECUTION_LAYER_REQUEST_TIMES, @@ -580,6 +592,40 @@ impl ExecutionLayer { forkchoice_update_params, ) .await + .map(ProvenancedPayload::Local) + } + }; + + // Track some metrics and return the result. + match payload_result { + Ok(ProvenancedPayload::Local(payload)) => { + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_OUTCOME, + &[metrics::SUCCESS], + ); + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_SOURCE, + &[metrics::LOCAL], + ); + Ok(payload) + } + Ok(ProvenancedPayload::Builder(payload)) => { + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_OUTCOME, + &[metrics::SUCCESS], + ); + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_SOURCE, + &[metrics::BUILDER], + ); + Ok(payload) + } + Err(e) => { + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_OUTCOME, + &[metrics::FAILURE], + ); + Err(e) } } } @@ -594,7 +640,7 @@ impl ExecutionLayer { forkchoice_update_params: ForkchoiceUpdateParameters, builder_params: BuilderParams, spec: &ChainSpec, - ) -> Result { + ) -> Result, Error> { if let Some(builder) = self.builder() { let slot = builder_params.slot; let pubkey = builder_params.pubkey; @@ -608,130 +654,202 @@ impl ExecutionLayer { "pubkey" => ?pubkey, "parent_hash" => ?parent_hash, ); - let (relay_result, local_result) = tokio::join!( - builder.get_builder_header::(slot, parent_hash, &pubkey), - self.get_full_payload_caching( - parent_hash, - timestamp, - prev_randao, - suggested_fee_recipient, - forkchoice_update_params, - ) + + // Wait for the builder *and* local EL to produce a payload (or return an error). + let ((relay_result, relay_duration), (local_result, local_duration)) = tokio::join!( + timed_future(metrics::GET_BLINDED_PAYLOAD_BUILDER, async { + builder + .get_builder_header::(slot, parent_hash, &pubkey) + .await + }), + timed_future(metrics::GET_BLINDED_PAYLOAD_LOCAL, async { + self.get_full_payload_caching::( + parent_hash, + timestamp, + prev_randao, + suggested_fee_recipient, + forkchoice_update_params, + ) + .await + }) + ); + + info!( + self.log(), + "Requested blinded execution payload"; + "relay_fee_recipient" => match &relay_result { + Ok(Some(r)) => format!("{:?}", r.data.message.header.fee_recipient()), + Ok(None) => "empty response".to_string(), + Err(_) => "request failed".to_string(), + }, + "relay_response_ms" => relay_duration.as_millis(), + "local_fee_recipient" => match &local_result { + Ok(header) => format!("{:?}", header.fee_recipient()), + Err(_) => "request failed".to_string() + }, + "local_response_ms" => local_duration.as_millis(), + "parent_hash" => ?parent_hash, ); return match (relay_result, local_result) { (Err(e), Ok(local)) => { warn!( self.log(), - "Unable to retrieve a payload from a connected \ - builder, falling back to the local execution client: {e:?}" + "Builder error when requesting payload"; + "info" => "falling back to local execution client", + "relay_error" => ?e, + "local_block_hash" => ?local.block_hash(), + "parent_hash" => ?parent_hash, ); - Ok(local) + Ok(ProvenancedPayload::Local(local)) } (Ok(None), Ok(local)) => { info!( self.log(), - "No payload provided by connected builder. \ - Attempting to propose through local execution engine" + "Builder did not return a payload"; + "info" => "falling back to local execution client", + "local_block_hash" => ?local.block_hash(), + "parent_hash" => ?parent_hash, ); - Ok(local) + Ok(ProvenancedPayload::Local(local)) } (Ok(Some(relay)), Ok(local)) => { - let is_signature_valid = relay.data.verify_signature(spec); - let header = relay.data.message.header; + let header = &relay.data.message.header; info!( self.log(), - "Received a payload header from the connected builder"; - "block_hash" => ?header.block_hash(), + "Received local and builder payloads"; + "relay_block_hash" => ?header.block_hash(), + "local_block_hash" => ?local.block_hash(), + "parent_hash" => ?parent_hash, ); - let relay_value = relay.data.message.value; - let configured_value = self.inner.builder_profit_threshold; - if relay_value < configured_value { - info!( - self.log(), - "The value offered by the connected builder does not meet \ - the configured profit threshold. Using local payload."; - "configured_value" => ?configured_value, "relay_value" => ?relay_value - ); - Ok(local) - } else if header.parent_hash() != parent_hash { - warn!( - self.log(), - "Invalid parent hash from connected builder, \ - falling back to local execution engine." - ); - Ok(local) - } else if header.prev_randao() != prev_randao { - warn!( - self.log(), - "Invalid prev randao from connected builder, \ - falling back to local execution engine." - ); - Ok(local) - } else if header.timestamp() != local.timestamp() { - warn!( - self.log(), - "Invalid timestamp from connected builder, \ - falling back to local execution engine." - ); - Ok(local) - } else if header.block_number() != local.block_number() { - warn!( - self.log(), - "Invalid block number from connected builder, \ - falling back to local execution engine." - ); - Ok(local) - } else if !matches!(relay.version, Some(ForkName::Merge)) { - // Once fork information is added to the payload, we will need to - // check that the local and relay payloads match. At this point, if - // we are requesting a payload at all, we have to assume this is - // the Bellatrix fork. - warn!( - self.log(), - "Invalid fork from connected builder, falling \ - back to local execution engine." - ); - Ok(local) - } else if !is_signature_valid { - let pubkey_bytes = relay.data.message.pubkey; - warn!(self.log(), "Invalid signature for pubkey {pubkey_bytes} on \ - bid from connected builder, falling back to local execution engine."); - Ok(local) - } else { - if header.fee_recipient() != suggested_fee_recipient { + match verify_builder_bid( + &relay, + parent_hash, + prev_randao, + timestamp, + Some(local.block_number()), + self.inner.builder_profit_threshold, + spec, + ) { + Ok(()) => { + Ok(ProvenancedPayload::Builder(relay.data.message.header)) + } + Err(reason) if !reason.payload_invalid() => { info!( self.log(), - "Fee recipient from connected builder does \ - not match, using it anyways." + "Builder payload ignored"; + "info" => "using local payload", + "reason" => %reason, + "relay_block_hash" => ?header.block_hash(), + "parent_hash" => ?parent_hash, ); + Ok(ProvenancedPayload::Local(local)) + } + Err(reason) => { + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_BUILDER_REJECTIONS, + &[reason.as_ref().as_ref()], + ); + warn!( + self.log(), + "Builder returned invalid payload"; + "info" => "using local payload", + "reason" => %reason, + "relay_block_hash" => ?header.block_hash(), + "parent_hash" => ?parent_hash, + ); + Ok(ProvenancedPayload::Local(local)) } - Ok(header) } } - (relay_result, Err(local_error)) => { - warn!(self.log(), "Failure from local execution engine. Attempting to \ - propose through connected builder"; "error" => ?local_error); - relay_result - .map_err(Error::Builder)? - .ok_or(Error::NoHeaderFromBuilder) - .map(|d| d.data.message.header) + (Ok(Some(relay)), Err(local_error)) => { + let header = &relay.data.message.header; + + info!( + self.log(), + "Received builder payload with local error"; + "relay_block_hash" => ?header.block_hash(), + "local_error" => ?local_error, + "parent_hash" => ?parent_hash, + ); + + match verify_builder_bid( + &relay, + parent_hash, + prev_randao, + timestamp, + None, + self.inner.builder_profit_threshold, + spec, + ) { + Ok(()) => { + Ok(ProvenancedPayload::Builder(relay.data.message.header)) + } + // If the payload is valid then use it. The local EE failed + // to produce a payload so we have no alternative. + Err(e) if !e.payload_invalid() => { + Ok(ProvenancedPayload::Builder(relay.data.message.header)) + } + Err(reason) => { + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_BUILDER_REJECTIONS, + &[reason.as_ref().as_ref()], + ); + crit!( + self.log(), + "Builder returned invalid payload"; + "info" => "no local payload either - unable to propose block", + "reason" => %reason, + "relay_block_hash" => ?header.block_hash(), + "parent_hash" => ?parent_hash, + ); + Err(Error::CannotProduceHeader) + } + } + } + (Err(relay_error), Err(local_error)) => { + crit!( + self.log(), + "Unable to produce execution payload"; + "info" => "the local EL and builder both failed - unable to propose block", + "relay_error" => ?relay_error, + "local_error" => ?local_error, + "parent_hash" => ?parent_hash, + ); + + Err(Error::CannotProduceHeader) + } + (Ok(None), Err(local_error)) => { + crit!( + self.log(), + "Unable to produce execution payload"; + "info" => "the local EL failed and the builder returned nothing - \ + the block proposal will be missed", + "local_error" => ?local_error, + "parent_hash" => ?parent_hash, + ); + + Err(Error::CannotProduceHeader) } }; } - ChainHealth::Unhealthy(condition) => { - info!(self.log(), "Due to poor chain health the local execution engine will be used \ - for payload construction. To adjust chain health conditions \ - Use `builder-fallback` prefixed flags"; - "failed_condition" => ?condition) - } + ChainHealth::Unhealthy(condition) => info!( + self.log(), + "Chain is unhealthy, using local payload"; + "info" => "this helps protect the network. the --builder-fallback flags \ + can adjust the expected health conditions.", + "failed_condition" => ?condition + ), // Intentional no-op, so we never attempt builder API proposals pre-merge. ChainHealth::PreMerge => (), - ChainHealth::Optimistic => info!(self.log(), "The local execution engine is syncing \ - so the builder network cannot safely be used. Attempting \ - to build a block with the local execution engine"), + ChainHealth::Optimistic => info!( + self.log(), + "Chain is optimistic; can't build payload"; + "info" => "the local execution engine is syncing and the builder network \ + cannot safely be used - unable to propose block" + ), } } self.get_full_payload_caching( @@ -742,6 +860,7 @@ impl ExecutionLayer { forkchoice_update_params, ) .await + .map(ProvenancedPayload::Local) } /// Get a full payload without caching its result in the execution layer's payload cache. @@ -1404,18 +1523,223 @@ impl ExecutionLayer { "Sending block to builder"; "root" => ?block_root, ); + if let Some(builder) = self.builder() { - builder - .post_builder_blinded_blocks(block) - .await - .map_err(Error::Builder) - .map(|d| d.data) + let (payload_result, duration) = + timed_future(metrics::POST_BLINDED_PAYLOAD_BUILDER, async { + builder + .post_builder_blinded_blocks(block) + .await + .map_err(Error::Builder) + .map(|d| d.data) + }) + .await; + + match &payload_result { + Ok(payload) => { + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_BUILDER_REVEAL_PAYLOAD_OUTCOME, + &[metrics::SUCCESS], + ); + info!( + self.log(), + "Builder successfully revealed payload"; + "relay_response_ms" => duration.as_millis(), + "block_root" => ?block_root, + "fee_recipient" => ?payload.fee_recipient, + "block_hash" => ?payload.block_hash, + "parent_hash" => ?payload.parent_hash + ) + } + Err(e) => { + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_BUILDER_REVEAL_PAYLOAD_OUTCOME, + &[metrics::FAILURE], + ); + crit!( + self.log(), + "Builder failed to reveal payload"; + "info" => "this relay failure may cause a missed proposal", + "error" => ?e, + "relay_response_ms" => duration.as_millis(), + "block_root" => ?block_root, + "parent_hash" => ?block + .message() + .execution_payload() + .map(|payload| format!("{}", payload.parent_hash())) + .unwrap_or_else(|_| "unknown".to_string()) + ) + } + } + + payload_result } else { Err(Error::NoPayloadBuilder) } } } +#[derive(AsRefStr)] +#[strum(serialize_all = "snake_case")] +enum InvalidBuilderPayload { + LowValue { + profit_threshold: Uint256, + payload_value: Uint256, + }, + ParentHash { + payload: ExecutionBlockHash, + expected: ExecutionBlockHash, + }, + PrevRandao { + payload: Hash256, + expected: Hash256, + }, + Timestamp { + payload: u64, + expected: u64, + }, + BlockNumber { + payload: u64, + expected: Option, + }, + Fork { + payload: Option, + expected: ForkName, + }, + Signature { + signature: Signature, + pubkey: PublicKeyBytes, + }, +} + +impl InvalidBuilderPayload { + /// Returns `true` if a payload is objectively invalid and should never be included on chain. + fn payload_invalid(&self) -> bool { + match self { + // A low-value payload isn't invalid, it should just be avoided if possible. + InvalidBuilderPayload::LowValue { .. } => false, + InvalidBuilderPayload::ParentHash { .. } => true, + InvalidBuilderPayload::PrevRandao { .. } => true, + InvalidBuilderPayload::Timestamp { .. } => true, + InvalidBuilderPayload::BlockNumber { .. } => true, + InvalidBuilderPayload::Fork { .. } => true, + InvalidBuilderPayload::Signature { .. } => true, + } + } +} + +impl fmt::Display for InvalidBuilderPayload { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self { + InvalidBuilderPayload::LowValue { + profit_threshold, + payload_value, + } => write!( + f, + "payload value of {} does not meet user-configured profit-threshold of {}", + payload_value, profit_threshold + ), + InvalidBuilderPayload::ParentHash { payload, expected } => { + write!(f, "payload block hash was {} not {}", payload, expected) + } + InvalidBuilderPayload::PrevRandao { payload, expected } => { + write!(f, "payload prev randao was {} not {}", payload, expected) + } + InvalidBuilderPayload::Timestamp { payload, expected } => { + write!(f, "payload timestamp was {} not {}", payload, expected) + } + InvalidBuilderPayload::BlockNumber { payload, expected } => { + write!(f, "payload block number was {} not {:?}", payload, expected) + } + InvalidBuilderPayload::Fork { payload, expected } => { + write!(f, "payload fork was {:?} not {}", payload, expected) + } + InvalidBuilderPayload::Signature { signature, pubkey } => write!( + f, + "invalid payload signature {} for pubkey {}", + signature, pubkey + ), + } + } +} + +/// Perform some cursory, non-exhaustive validation of the bid returned from the builder. +fn verify_builder_bid>( + bid: &ForkVersionedResponse>, + parent_hash: ExecutionBlockHash, + prev_randao: Hash256, + timestamp: u64, + block_number: Option, + profit_threshold: Uint256, + spec: &ChainSpec, +) -> Result<(), Box> { + let is_signature_valid = bid.data.verify_signature(spec); + let header = &bid.data.message.header; + let payload_value = bid.data.message.value; + + // Avoid logging values that we can't represent with our Prometheus library. + let payload_value_gwei = bid.data.message.value / 1_000_000_000; + if payload_value_gwei <= Uint256::from(i64::max_value()) { + metrics::set_gauge_vec( + &metrics::EXECUTION_LAYER_PAYLOAD_BIDS, + &[metrics::BUILDER], + payload_value_gwei.low_u64() as i64, + ); + } + + if payload_value < profit_threshold { + Err(Box::new(InvalidBuilderPayload::LowValue { + profit_threshold, + payload_value, + })) + } else if header.parent_hash() != parent_hash { + Err(Box::new(InvalidBuilderPayload::ParentHash { + payload: header.parent_hash(), + expected: parent_hash, + })) + } else if header.prev_randao() != prev_randao { + Err(Box::new(InvalidBuilderPayload::PrevRandao { + payload: header.prev_randao(), + expected: prev_randao, + })) + } else if header.timestamp() != timestamp { + Err(Box::new(InvalidBuilderPayload::Timestamp { + payload: header.timestamp(), + expected: timestamp, + })) + } else if block_number.map_or(false, |n| n != header.block_number()) { + Err(Box::new(InvalidBuilderPayload::BlockNumber { + payload: header.block_number(), + expected: block_number, + })) + } else if !matches!(bid.version, Some(ForkName::Merge)) { + // Once fork information is added to the payload, we will need to + // check that the local and relay payloads match. At this point, if + // we are requesting a payload at all, we have to assume this is + // the Bellatrix fork. + Err(Box::new(InvalidBuilderPayload::Fork { + payload: bid.version, + expected: ForkName::Merge, + })) + } else if !is_signature_valid { + Err(Box::new(InvalidBuilderPayload::Signature { + signature: bid.data.signature.clone(), + pubkey: bid.data.message.pubkey, + })) + } else { + Ok(()) + } +} + +/// A helper function to record the time it takes to execute a future. +async fn timed_future, T>(metric: &str, future: F) -> (T, Duration) { + let start = Instant::now(); + let result = future.await; + let duration = start.elapsed(); + metrics::observe_timer_vec(&metrics::EXECUTION_LAYER_REQUEST_TIMES, &[metric], duration); + (result, duration) +} + #[cfg(test)] mod test { use super::*; diff --git a/beacon_node/execution_layer/src/metrics.rs b/beacon_node/execution_layer/src/metrics.rs index 9b00193a4..bb5a1088d 100644 --- a/beacon_node/execution_layer/src/metrics.rs +++ b/beacon_node/execution_layer/src/metrics.rs @@ -4,10 +4,17 @@ pub const HIT: &str = "hit"; pub const MISS: &str = "miss"; pub const GET_PAYLOAD: &str = "get_payload"; pub const GET_BLINDED_PAYLOAD: &str = "get_blinded_payload"; +pub const GET_BLINDED_PAYLOAD_LOCAL: &str = "get_blinded_payload_local"; +pub const GET_BLINDED_PAYLOAD_BUILDER: &str = "get_blinded_payload_builder"; +pub const POST_BLINDED_PAYLOAD_BUILDER: &str = "post_blinded_payload_builder"; pub const NEW_PAYLOAD: &str = "new_payload"; pub const FORKCHOICE_UPDATED: &str = "forkchoice_updated"; pub const GET_TERMINAL_POW_BLOCK_HASH: &str = "get_terminal_pow_block_hash"; pub const IS_VALID_TERMINAL_POW_BLOCK_HASH: &str = "is_valid_terminal_pow_block_hash"; +pub const LOCAL: &str = "local"; +pub const BUILDER: &str = "builder"; +pub const SUCCESS: &str = "success"; +pub const FAILURE: &str = "failure"; lazy_static::lazy_static! { pub static ref EXECUTION_LAYER_PROPOSER_INSERTED: Result = try_create_int_counter( @@ -18,9 +25,11 @@ lazy_static::lazy_static! { "execution_layer_proposer_data_updated", "Count of times new proposer data is supplied", ); - pub static ref EXECUTION_LAYER_REQUEST_TIMES: Result = try_create_histogram_vec( + pub static ref EXECUTION_LAYER_REQUEST_TIMES: Result = + try_create_histogram_vec_with_buckets( "execution_layer_request_times", "Duration of calls to ELs", + decimal_buckets(-2, 1), &["method"] ); pub static ref EXECUTION_LAYER_PAYLOAD_ATTRIBUTES_LOOKAHEAD: Result = try_create_histogram( @@ -41,4 +50,29 @@ lazy_static::lazy_static! { "Indicates the payload status returned for a particular method", &["method", "status"] ); + pub static ref EXECUTION_LAYER_GET_PAYLOAD_OUTCOME: Result = try_create_int_counter_vec( + "execution_layer_get_payload_outcome", + "The success/failure outcomes from calling get_payload", + &["outcome"] + ); + pub static ref EXECUTION_LAYER_BUILDER_REVEAL_PAYLOAD_OUTCOME: Result = try_create_int_counter_vec( + "execution_layer_builder_reveal_payload_outcome", + "The success/failure outcomes from a builder un-blinding a payload", + &["outcome"] + ); + pub static ref EXECUTION_LAYER_GET_PAYLOAD_SOURCE: Result = try_create_int_counter_vec( + "execution_layer_get_payload_source", + "The source of each payload returned from get_payload", + &["source"] + ); + pub static ref EXECUTION_LAYER_GET_PAYLOAD_BUILDER_REJECTIONS: Result = try_create_int_counter_vec( + "execution_layer_get_payload_builder_rejections", + "The reasons why a payload from a builder was rejected", + &["reason"] + ); + pub static ref EXECUTION_LAYER_PAYLOAD_BIDS: Result = try_create_int_gauge_vec( + "execution_layer_payload_bids", + "The gwei bid value of payloads received by local EEs or builders. Only shows values up to i64::max_value.", + &["source"] + ); }