From 6f5455be7960bf762b78492b5a86d2ef90345446 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Tue, 15 Nov 2022 11:08:40 +1100 Subject: [PATCH 01/14] Refactor `get_blinded_payload` --- beacon_node/execution_layer/src/lib.rs | 371 ++++++++++++++++----- beacon_node/execution_layer/src/metrics.rs | 2 + 2 files changed, 281 insertions(+), 92 deletions(-) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index f222f28c33f..12d3c8b167a 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,12 @@ 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 task_executor::TaskExecutor; use tokio::{ sync::{Mutex, MutexGuard, RwLock}, @@ -34,7 +36,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; @@ -73,6 +75,7 @@ pub enum Error { ApiError(ApiError), Builder(builder_client::Error), NoHeaderFromBuilder, + CannotProduceHeader, EngineError(Box), NotSynced, ShuttingDown, @@ -608,130 +611,190 @@ 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, + + // 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 = Instant::now().duration_since(start); + let _timer = metrics::observe_timer_vec( + &metrics::EXECUTION_LAYER_REQUEST_TIMES, + &[metric], + duration + ); + (result, duration) + } + + // Wait for the build *and* relay 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(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(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!( + match verify_builder_bid( + &relay, + parent_hash, + prev_randao, + timestamp, + Some(local.block_number()), + self.inner.builder_profit_threshold, + spec + ) { + Ok(()) => Ok(relay.data.message.header), + Err(reason) => { + warn!( 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 + "Builder returned invalid payload"; + "info" => "using local payload", + "reason" => %reason, + "relay_block_hash" => ?header.block_hash(), + "parent_hash" => %parent_hash, ); - 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 { - info!( + Ok(local) + } + } + } + (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(relay.data.message.header), + Err(reason) => { + crit!( self.log(), - "Fee recipient from connected builder does \ - not match, using it anyways." + "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) } - 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) + (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( @@ -1416,6 +1479,130 @@ impl ExecutionLayer { } } +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 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; + 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(()) + } +} + #[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 9b00193a4a6..a6e731da88e 100644 --- a/beacon_node/execution_layer/src/metrics.rs +++ b/beacon_node/execution_layer/src/metrics.rs @@ -4,6 +4,8 @@ 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 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"; From dd97a89bd58c1dc11d214c87ec5bd47334e84f36 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Tue, 15 Nov 2022 12:30:24 +1100 Subject: [PATCH 02/14] Add metrics and logs for payload unblinding --- beacon_node/execution_layer/src/lib.rs | 69 ++++++++++++++++------ beacon_node/execution_layer/src/metrics.rs | 1 + 2 files changed, 52 insertions(+), 18 deletions(-) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index 12d3c8b167a..7ed38efcd68 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -612,19 +612,6 @@ impl ExecutionLayer { "parent_hash" => ?parent_hash, ); - // 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 = Instant::now().duration_since(start); - let _timer = metrics::observe_timer_vec( - &metrics::EXECUTION_LAYER_REQUEST_TIMES, - &[metric], - duration - ); - (result, duration) - } - // Wait for the build *and* relay to produce a payload (or return an error). let ((relay_result, relay_duration), (local_result, local_duration)) = tokio::join!( timed_future( @@ -1467,12 +1454,45 @@ 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) => 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) => crit!( + self.log(), + "Builder failed to reveal payload"; + "info" => "this relay failure has caused 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) } @@ -1603,6 +1623,19 @@ fn verify_builder_bid>( } } +/// 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 = Instant::now().duration_since(start); + 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 a6e731da88e..20c836bffe0 100644 --- a/beacon_node/execution_layer/src/metrics.rs +++ b/beacon_node/execution_layer/src/metrics.rs @@ -6,6 +6,7 @@ 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"; From 80f6a1ee5b9db2cf7d46077b526588100905666a Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Tue, 15 Nov 2022 14:20:09 +1100 Subject: [PATCH 03/14] Run `cargo fmt` --- beacon_node/execution_layer/src/lib.rs | 56 +++++++++++--------------- 1 file changed, 24 insertions(+), 32 deletions(-) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index 7ed38efcd68..60e82c262c7 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -614,24 +614,21 @@ impl ExecutionLayer { // Wait for the build *and* relay 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 - } - ) + 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!( @@ -691,7 +688,7 @@ impl ExecutionLayer { timestamp, Some(local.block_number()), self.inner.builder_profit_threshold, - spec + spec, ) { Ok(()) => Ok(relay.data.message.header), Err(reason) => { @@ -725,7 +722,7 @@ impl ExecutionLayer { timestamp, None, self.inner.builder_profit_threshold, - spec + spec, ) { Ok(()) => Ok(relay.data.message.header), Err(reason) => { @@ -781,7 +778,7 @@ impl ExecutionLayer { "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( @@ -1456,16 +1453,15 @@ impl ExecutionLayer { ); if let Some(builder) = self.builder() { - let (payload_result, duration) = timed_future( - metrics::POST_BLINDED_PAYLOAD_BUILDER, - async { + 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; + }) + .await; match &payload_result { Ok(payload) => info!( @@ -1489,7 +1485,7 @@ impl ExecutionLayer { .execution_payload() .map(|payload| format!("{}", payload.parent_hash())) .unwrap_or_else(|_| "unknown".to_string()) - ) + ), } payload_result @@ -1628,11 +1624,7 @@ async fn timed_future, T>(metric: &str, future: F) -> (T, let start = Instant::now(); let result = future.await; let duration = Instant::now().duration_since(start); - metrics::observe_timer_vec( - &metrics::EXECUTION_LAYER_REQUEST_TIMES, - &[metric], - duration - ); + metrics::observe_timer_vec(&metrics::EXECUTION_LAYER_REQUEST_TIMES, &[metric], duration); (result, duration) } From 34eab88f9c571219d85b692c9dd9352da1e598a8 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Tue, 15 Nov 2022 16:20:14 +1100 Subject: [PATCH 04/14] Tidy, add buckets --- beacon_node/execution_layer/src/lib.rs | 2 +- beacon_node/execution_layer/src/metrics.rs | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index 60e82c262c7..b08009c0596 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -612,7 +612,7 @@ impl ExecutionLayer { "parent_hash" => ?parent_hash, ); - // Wait for the build *and* relay to produce a payload (or return an error). + // Wait for the builder *and* relay 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 diff --git a/beacon_node/execution_layer/src/metrics.rs b/beacon_node/execution_layer/src/metrics.rs index 20c836bffe0..171ba3c7871 100644 --- a/beacon_node/execution_layer/src/metrics.rs +++ b/beacon_node/execution_layer/src/metrics.rs @@ -21,9 +21,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( From 71c670be8691c131e1f0f5a7ad75ef4dbedf16a6 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Mon, 28 Nov 2022 14:37:28 +1100 Subject: [PATCH 05/14] Apply suggestions from code review Co-authored-by: Michael Sproul --- beacon_node/execution_layer/src/lib.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index b08009c0596..37b0ff0cd96 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -612,7 +612,7 @@ impl ExecutionLayer { "parent_hash" => ?parent_hash, ); - // Wait for the builder *and* relay to produce a payload (or return an error). + // 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 @@ -1476,7 +1476,7 @@ impl ExecutionLayer { Err(e) => crit!( self.log(), "Builder failed to reveal payload"; - "info" => "this relay failure has caused a missed proposal", + "info" => "this relay failure may cause a missed proposal", "error" => ?e, "relay_response_ms" => duration.as_millis(), "block_root" => %block_root, @@ -1623,7 +1623,7 @@ fn verify_builder_bid>( async fn timed_future, T>(metric: &str, future: F) -> (T, Duration) { let start = Instant::now(); let result = future.await; - let duration = Instant::now().duration_since(start); + let duration = start.elapsed(); metrics::observe_timer_vec(&metrics::EXECUTION_LAYER_REQUEST_TIMES, &[metric], duration); (result, duration) } From 26118a49af162ea07c57ce00823b9ac1692c3bd1 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Mon, 28 Nov 2022 14:50:34 +1100 Subject: [PATCH 06/14] Print full hash/root in several places --- beacon_node/execution_layer/src/lib.rs | 30 +++++++++++++------------- 1 file changed, 15 insertions(+), 15 deletions(-) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index 37b0ff0cd96..05ac066edd0 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -609,7 +609,7 @@ impl ExecutionLayer { "Requesting blinded header from connected builder"; "slot" => ?slot, "pubkey" => ?pubkey, - "parent_hash" => ?parent_hash, + "parent_hash" => %parent_hash, ); // Wait for the builder *and* local EL to produce a payload (or return an error). @@ -676,7 +676,7 @@ impl ExecutionLayer { info!( self.log(), "Received local and builder payloads"; - "relay_block_hash" => ?header.block_hash(), + "relay_block_hash" => %header.block_hash(), "local_block_hash" => %local.block_hash(), "parent_hash" => %parent_hash, ); @@ -697,7 +697,7 @@ impl ExecutionLayer { "Builder returned invalid payload"; "info" => "using local payload", "reason" => %reason, - "relay_block_hash" => ?header.block_hash(), + "relay_block_hash" => %header.block_hash(), "parent_hash" => %parent_hash, ); Ok(local) @@ -710,7 +710,7 @@ impl ExecutionLayer { info!( self.log(), "Received builder payload with local error"; - "relay_block_hash" => ?header.block_hash(), + "relay_block_hash" => %header.block_hash(), "local_error" => ?local_error, "parent_hash" => %parent_hash, ); @@ -731,7 +731,7 @@ impl ExecutionLayer { "Builder returned invalid payload"; "info" => "no local payload either - unable to propose block", "reason" => %reason, - "relay_block_hash" => ?header.block_hash(), + "relay_block_hash" => %header.block_hash(), "parent_hash" => %parent_hash, ); Err(Error::CannotProduceHeader) @@ -846,7 +846,7 @@ impl ExecutionLayer { "suggested_fee_recipient" => ?suggested_fee_recipient, "prev_randao" => ?prev_randao, "timestamp" => timestamp, - "parent_hash" => ?parent_hash, + "parent_hash" => %parent_hash, ); self.engine() .request(|engine| async move { @@ -963,8 +963,8 @@ impl ExecutionLayer { trace!( self.log(), "Issuing engine_newPayload"; - "parent_hash" => ?execution_payload.parent_hash, - "block_hash" => ?execution_payload.block_hash, + "parent_hash" => %execution_payload.parent_hash, + "block_hash" => %execution_payload.block_hash, "block_number" => execution_payload.block_number, ); @@ -1035,7 +1035,7 @@ impl ExecutionLayer { self.log(), "Beacon proposer found"; "payload_attributes" => ?proposer.payload_attributes, - "head_block_root" => ?head_block_root, + "head_block_root" => %head_block_root, "slot" => current_slot, "validator_index" => proposer.validator_index, ); @@ -1072,9 +1072,9 @@ impl ExecutionLayer { trace!( self.log(), "Issuing engine_forkchoiceUpdated"; - "finalized_block_hash" => ?finalized_block_hash, - "justified_block_hash" => ?justified_block_hash, - "head_block_hash" => ?head_block_hash, + "finalized_block_hash" => %finalized_block_hash, + "justified_block_hash" => %justified_block_hash, + "head_block_hash" => %head_block_hash, ); let next_slot = current_slot + 1; @@ -1237,9 +1237,9 @@ impl ExecutionLayer { info!( self.log(), "Found terminal block hash"; - "terminal_block_hash_override" => ?spec.terminal_block_hash, + "terminal_block_hash_override" => %spec.terminal_block_hash, "terminal_total_difficulty" => ?spec.terminal_total_difficulty, - "block_hash" => ?hash, + "block_hash" => %hash, ); } @@ -1449,7 +1449,7 @@ impl ExecutionLayer { debug!( self.log(), "Sending block to builder"; - "root" => ?block_root, + "root" => %block_root, ); if let Some(builder) = self.builder() { From 0a86b244bffe686cdcbb75d6c01e42fad08bb417 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Mon, 28 Nov 2022 18:03:13 +1100 Subject: [PATCH 07/14] Handle low value payload when there's no alternative --- beacon_node/execution_layer/src/lib.rs | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index 05ac066edd0..c12d900bb4e 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -725,6 +725,9 @@ impl ExecutionLayer { spec, ) { Ok(()) => Ok(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(relay.data.message.header), Err(reason) => { crit!( self.log(), @@ -1526,6 +1529,22 @@ enum InvalidBuilderPayload { }, } +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 { From 339698ba3c3c4fb5ed2ca1994ae52e96c4071541 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Mon, 28 Nov 2022 18:56:25 +1100 Subject: [PATCH 08/14] Add more metrics --- beacon_node/execution_layer/src/lib.rs | 182 +++++++++++++++------ beacon_node/execution_layer/src/metrics.rs | 29 ++++ 2 files changed, 162 insertions(+), 49 deletions(-) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index c12d900bb4e..451a3948722 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -28,6 +28,7 @@ use std::io::Write; use std::path::PathBuf; use std::sync::Arc; use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH}; +use strum::AsRefStr; use task_executor::TaskExecutor; use tokio::{ sync::{Mutex, MutexGuard, RwLock}, @@ -68,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, @@ -553,38 +562,75 @@ 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, &[metrics::GET_BLINDED_PAYLOAD], ); - self.get_blinded_payload( - parent_hash, - timestamp, - prev_randao, - suggested_fee_recipient, - forkchoice_update_params, - builder_params, - spec, - ) - .await + match self + .get_blinded_payload( + parent_hash, + timestamp, + prev_randao, + suggested_fee_recipient, + forkchoice_update_params, + builder_params, + spec, + ) + .await? + { + ProvenancedPayload::Local(payload) => { + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_SOURCE, + &[metrics::LOCAL], + ); + Ok(payload) + } + ProvenancedPayload::Builder(payload) => { + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_SOURCE, + &[metrics::BUILDER], + ); + Ok(payload) + } + } } BlockType::Full => { let _timer = metrics::start_timer_vec( &metrics::EXECUTION_LAYER_REQUEST_TIMES, &[metrics::GET_PAYLOAD], ); - self.get_full_payload( - parent_hash, - timestamp, - prev_randao, - suggested_fee_recipient, - forkchoice_update_params, - ) - .await + let payload = self + .get_full_payload( + parent_hash, + timestamp, + prev_randao, + suggested_fee_recipient, + forkchoice_update_params, + ) + .await?; + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_SOURCE, + &[metrics::LOCAL], + ); + Ok(payload) } + }; + + if payload_result.is_ok() { + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_OUTCOME, + &[metrics::SUCCESS], + ) + } else { + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_OUTCOME, + &[metrics::FAILURE], + ) } + + payload_result } #[allow(clippy::too_many_arguments)] @@ -597,7 +643,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; @@ -658,7 +704,7 @@ impl ExecutionLayer { "local_block_hash" => %local.block_hash(), "parent_hash" => %parent_hash, ); - Ok(local) + Ok(ProvenancedPayload::Local(local)) } (Ok(None), Ok(local)) => { info!( @@ -668,7 +714,7 @@ impl ExecutionLayer { "local_block_hash" => %local.block_hash(), "parent_hash" => %parent_hash, ); - Ok(local) + Ok(ProvenancedPayload::Local(local)) } (Ok(Some(relay)), Ok(local)) => { let header = &relay.data.message.header; @@ -690,8 +736,14 @@ impl ExecutionLayer { self.inner.builder_profit_threshold, spec, ) { - Ok(()) => Ok(relay.data.message.header), + Ok(()) => { + 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()], + ); warn!( self.log(), "Builder returned invalid payload"; @@ -700,7 +752,7 @@ impl ExecutionLayer { "relay_block_hash" => %header.block_hash(), "parent_hash" => %parent_hash, ); - Ok(local) + Ok(ProvenancedPayload::Local(local)) } } } @@ -724,11 +776,19 @@ impl ExecutionLayer { self.inner.builder_profit_threshold, spec, ) { - Ok(()) => Ok(relay.data.message.header), + 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(relay.data.message.header), + 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"; @@ -792,6 +852,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. @@ -1467,28 +1528,40 @@ impl ExecutionLayer { .await; match &payload_result { - Ok(payload) => 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) => 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()) - ), + 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 @@ -1498,6 +1571,8 @@ impl ExecutionLayer { } } +#[derive(AsRefStr)] +#[strum(serialize_all = "snake_case")] enum InvalidBuilderPayload { LowValue { profit_threshold: Uint256, @@ -1592,8 +1667,17 @@ fn verify_builder_bid>( ) -> 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. + if payload_value <= Uint256::from(i64::max_value()) { + metrics::set_gauge_vec( + &metrics::EXECUTION_LAYER_PAYLOAD_BIDS, + &[metrics::BUILDER], + payload_value.low_u64() as i64, + ); + } + if payload_value < profit_threshold { Err(Box::new(InvalidBuilderPayload::LowValue { profit_threshold, diff --git a/beacon_node/execution_layer/src/metrics.rs b/beacon_node/execution_layer/src/metrics.rs index 171ba3c7871..268618fade9 100644 --- a/beacon_node/execution_layer/src/metrics.rs +++ b/beacon_node/execution_layer/src/metrics.rs @@ -11,6 +11,10 @@ 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( @@ -46,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 bid value of payloads received by local EEs or builders. Only shows values up to i64::max_value.", + &["source"] + ); } From 55e0b9e53a749d437ee4918d41c751a38e345166 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Mon, 28 Nov 2022 19:16:02 +1100 Subject: [PATCH 09/14] Fix metric tracking for get_payload --- beacon_node/execution_layer/src/lib.rs | 97 +++++++++++++------------- 1 file changed, 47 insertions(+), 50 deletions(-) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index 451a3948722..caaa95a7e90 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -568,69 +568,66 @@ impl ExecutionLayer { &metrics::EXECUTION_LAYER_REQUEST_TIMES, &[metrics::GET_BLINDED_PAYLOAD], ); - match self - .get_blinded_payload( - parent_hash, - timestamp, - prev_randao, - suggested_fee_recipient, - forkchoice_update_params, - builder_params, - spec, - ) - .await? - { - ProvenancedPayload::Local(payload) => { - metrics::inc_counter_vec( - &metrics::EXECUTION_LAYER_GET_PAYLOAD_SOURCE, - &[metrics::LOCAL], - ); - Ok(payload) - } - ProvenancedPayload::Builder(payload) => { - metrics::inc_counter_vec( - &metrics::EXECUTION_LAYER_GET_PAYLOAD_SOURCE, - &[metrics::BUILDER], - ); - Ok(payload) - } - } + self.get_blinded_payload( + parent_hash, + timestamp, + prev_randao, + suggested_fee_recipient, + forkchoice_update_params, + builder_params, + spec, + ) + .await } BlockType::Full => { let _timer = metrics::start_timer_vec( &metrics::EXECUTION_LAYER_REQUEST_TIMES, &[metrics::GET_PAYLOAD], ); - let payload = self - .get_full_payload( - parent_hash, - timestamp, - prev_randao, - suggested_fee_recipient, - forkchoice_update_params, - ) - .await?; + self.get_full_payload( + parent_hash, + timestamp, + prev_randao, + suggested_fee_recipient, + 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) } - }; - - if payload_result.is_ok() { - metrics::inc_counter_vec( - &metrics::EXECUTION_LAYER_GET_PAYLOAD_OUTCOME, - &[metrics::SUCCESS], - ) - } else { - metrics::inc_counter_vec( - &metrics::EXECUTION_LAYER_GET_PAYLOAD_OUTCOME, - &[metrics::FAILURE], - ) + 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::LOCAL], + ); + Ok(payload) + } + Err(e) => { + metrics::inc_counter_vec( + &metrics::EXECUTION_LAYER_GET_PAYLOAD_OUTCOME, + &[metrics::FAILURE], + ); + Err(e) + } } - - payload_result } #[allow(clippy::too_many_arguments)] From 54390beae4d0c3afdca5bf8bcfca4242bebd0206 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Mon, 28 Nov 2022 19:39:04 +1100 Subject: [PATCH 10/14] Log bid in gwei --- beacon_node/execution_layer/src/lib.rs | 3 ++- beacon_node/execution_layer/src/metrics.rs | 2 +- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index caaa95a7e90..6e6f86c6e75 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -1667,7 +1667,8 @@ fn verify_builder_bid>( let payload_value = bid.data.message.value; // Avoid logging values that we can't represent with our Prometheus library. - if payload_value <= Uint256::from(i64::max_value()) { + 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], diff --git a/beacon_node/execution_layer/src/metrics.rs b/beacon_node/execution_layer/src/metrics.rs index 268618fade9..bb5a1088d1a 100644 --- a/beacon_node/execution_layer/src/metrics.rs +++ b/beacon_node/execution_layer/src/metrics.rs @@ -72,7 +72,7 @@ lazy_static::lazy_static! { ); pub static ref EXECUTION_LAYER_PAYLOAD_BIDS: Result = try_create_int_gauge_vec( "execution_layer_payload_bids", - "The bid value of payloads received by local EEs or builders. Only shows values up to i64::max_value.", + "The gwei bid value of payloads received by local EEs or builders. Only shows values up to i64::max_value.", &["source"] ); } From c9b7d00b8b677ee50fca26ac02987d9f28a4e59d Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Tue, 29 Nov 2022 11:29:40 +1100 Subject: [PATCH 11/14] Update beacon_node/execution_layer/src/lib.rs Co-authored-by: Michael Sproul --- beacon_node/execution_layer/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index 6e6f86c6e75..8556b1b7ecd 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -616,7 +616,7 @@ impl ExecutionLayer { ); metrics::inc_counter_vec( &metrics::EXECUTION_LAYER_GET_PAYLOAD_SOURCE, - &[metrics::LOCAL], + &[metrics::BUILDER], ); Ok(payload) } From e0b2b1aa48e57f8ce8e372495074bc7eca36b24b Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Tue, 29 Nov 2022 11:36:33 +1100 Subject: [PATCH 12/14] Avoid warning with low-value builder payload --- beacon_node/execution_layer/src/lib.rs | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index 8556b1b7ecd..33bb4be2fea 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -736,6 +736,17 @@ impl ExecutionLayer { Ok(()) => { Ok(ProvenancedPayload::Builder(relay.data.message.header)) } + Err(reason) if !reason.payload_invalid() => { + info!( + self.log(), + "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, From e8bd2be26ad40590544d25d92ad71f29cd8bd1ed Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Tue, 29 Nov 2022 11:43:14 +1100 Subject: [PATCH 13/14] Move roots/hashes back to debug --- beacon_node/execution_layer/src/lib.rs | 74 +++++++++++++------------- 1 file changed, 37 insertions(+), 37 deletions(-) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index 33bb4be2fea..b4b6a6861c1 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -652,7 +652,7 @@ impl ExecutionLayer { "Requesting blinded header from connected builder"; "slot" => ?slot, "pubkey" => ?pubkey, - "parent_hash" => %parent_hash, + "parent_hash" => ?parent_hash, ); // Wait for the builder *and* local EL to produce a payload (or return an error). @@ -678,17 +678,17 @@ impl ExecutionLayer { self.log(), "Requested blinded execution payload"; "relay_fee_recipient" => match &relay_result { - Ok(Some(r)) => format!("{}", r.data.message.header.fee_recipient()), + 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()), + Ok(header) => format!("{:?}", header.fee_recipient()), Err(_) => "request failed".to_string() }, "local_response_ms" => local_duration.as_millis(), - "parent_hash" => %parent_hash, + "parent_hash" => ?parent_hash, ); return match (relay_result, local_result) { @@ -698,8 +698,8 @@ impl ExecutionLayer { "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, + "local_block_hash" => ?local.block_hash(), + "parent_hash" => ?parent_hash, ); Ok(ProvenancedPayload::Local(local)) } @@ -708,8 +708,8 @@ impl ExecutionLayer { self.log(), "Builder did not return a payload"; "info" => "falling back to local execution client", - "local_block_hash" => %local.block_hash(), - "parent_hash" => %parent_hash, + "local_block_hash" => ?local.block_hash(), + "parent_hash" => ?parent_hash, ); Ok(ProvenancedPayload::Local(local)) } @@ -719,9 +719,9 @@ impl ExecutionLayer { info!( self.log(), "Received local and builder payloads"; - "relay_block_hash" => %header.block_hash(), - "local_block_hash" => %local.block_hash(), - "parent_hash" => %parent_hash, + "relay_block_hash" => ?header.block_hash(), + "local_block_hash" => ?local.block_hash(), + "parent_hash" => ?parent_hash, ); match verify_builder_bid( @@ -742,8 +742,8 @@ impl ExecutionLayer { "Builder payload ignored"; "info" => "using local payload", "reason" => %reason, - "relay_block_hash" => %header.block_hash(), - "parent_hash" => %parent_hash, + "relay_block_hash" => ?header.block_hash(), + "parent_hash" => ?parent_hash, ); Ok(ProvenancedPayload::Local(local)) } @@ -757,8 +757,8 @@ impl ExecutionLayer { "Builder returned invalid payload"; "info" => "using local payload", "reason" => %reason, - "relay_block_hash" => %header.block_hash(), - "parent_hash" => %parent_hash, + "relay_block_hash" => ?header.block_hash(), + "parent_hash" => ?parent_hash, ); Ok(ProvenancedPayload::Local(local)) } @@ -770,9 +770,9 @@ impl ExecutionLayer { info!( self.log(), "Received builder payload with local error"; - "relay_block_hash" => %header.block_hash(), + "relay_block_hash" => ?header.block_hash(), "local_error" => ?local_error, - "parent_hash" => %parent_hash, + "parent_hash" => ?parent_hash, ); match verify_builder_bid( @@ -802,8 +802,8 @@ impl ExecutionLayer { "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, + "relay_block_hash" => ?header.block_hash(), + "parent_hash" => ?parent_hash, ); Err(Error::CannotProduceHeader) } @@ -816,7 +816,7 @@ impl ExecutionLayer { "info" => "the local EL and builder both failed - unable to propose block", "relay_error" => ?relay_error, "local_error" => ?local_error, - "parent_hash" => %parent_hash, + "parent_hash" => ?parent_hash, ); Err(Error::CannotProduceHeader) @@ -828,7 +828,7 @@ impl ExecutionLayer { "info" => "the local EL failed and the builder returned nothing - \ the block proposal will be missed", "local_error" => ?local_error, - "parent_hash" => %parent_hash, + "parent_hash" => ?parent_hash, ); Err(Error::CannotProduceHeader) @@ -918,7 +918,7 @@ impl ExecutionLayer { "suggested_fee_recipient" => ?suggested_fee_recipient, "prev_randao" => ?prev_randao, "timestamp" => timestamp, - "parent_hash" => %parent_hash, + "parent_hash" => ?parent_hash, ); self.engine() .request(|engine| async move { @@ -1035,8 +1035,8 @@ impl ExecutionLayer { trace!( self.log(), "Issuing engine_newPayload"; - "parent_hash" => %execution_payload.parent_hash, - "block_hash" => %execution_payload.block_hash, + "parent_hash" => ?execution_payload.parent_hash, + "block_hash" => ?execution_payload.block_hash, "block_number" => execution_payload.block_number, ); @@ -1107,7 +1107,7 @@ impl ExecutionLayer { self.log(), "Beacon proposer found"; "payload_attributes" => ?proposer.payload_attributes, - "head_block_root" => %head_block_root, + "head_block_root" => ?head_block_root, "slot" => current_slot, "validator_index" => proposer.validator_index, ); @@ -1144,9 +1144,9 @@ impl ExecutionLayer { trace!( self.log(), "Issuing engine_forkchoiceUpdated"; - "finalized_block_hash" => %finalized_block_hash, - "justified_block_hash" => %justified_block_hash, - "head_block_hash" => %head_block_hash, + "finalized_block_hash" => ?finalized_block_hash, + "justified_block_hash" => ?justified_block_hash, + "head_block_hash" => ?head_block_hash, ); let next_slot = current_slot + 1; @@ -1309,9 +1309,9 @@ impl ExecutionLayer { info!( self.log(), "Found terminal block hash"; - "terminal_block_hash_override" => %spec.terminal_block_hash, + "terminal_block_hash_override" => ?spec.terminal_block_hash, "terminal_total_difficulty" => ?spec.terminal_total_difficulty, - "block_hash" => %hash, + "block_hash" => ?hash, ); } @@ -1521,7 +1521,7 @@ impl ExecutionLayer { debug!( self.log(), "Sending block to builder"; - "root" => %block_root, + "root" => ?block_root, ); if let Some(builder) = self.builder() { @@ -1545,10 +1545,10 @@ impl ExecutionLayer { 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 + "block_root" => ?block_root, + "fee_recipient" => ?payload.fee_recipient, + "block_hash" => ?payload.block_hash, + "parent_hash" => ?payload.parent_hash ) } Err(e) => { @@ -1562,8 +1562,8 @@ impl ExecutionLayer { "info" => "this relay failure may cause a missed proposal", "error" => ?e, "relay_response_ms" => duration.as_millis(), - "block_root" => %block_root, - "parent_hash" => %block + "block_root" => ?block_root, + "parent_hash" => ?block .message() .execution_payload() .map(|payload| format!("{}", payload.parent_hash())) From c6256e10adfe4c57751218fdfdfc3839fdadb5a7 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Tue, 29 Nov 2022 16:21:19 +1100 Subject: [PATCH 14/14] Fix bug with gwei calculation --- beacon_node/execution_layer/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index b4b6a6861c1..2a2225cbdfd 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -1683,7 +1683,7 @@ fn verify_builder_bid>( metrics::set_gauge_vec( &metrics::EXECUTION_LAYER_PAYLOAD_BIDS, &[metrics::BUILDER], - payload_value.low_u64() as i64, + payload_value_gwei.low_u64() as i64, ); }