From e76b69ea3817cadf12ae074f45709585339cad04 Mon Sep 17 00:00:00 2001 From: Jimmy Chen Date: Wed, 12 Feb 2025 17:14:57 +1100 Subject: [PATCH 1/5] Add missing error log and remove redundant id field from lookup logs. --- beacon_node/network/src/sync/network_context.rs | 8 ++++++++ beacon_node/network/src/sync/network_context/custody.rs | 4 ---- 2 files changed, 8 insertions(+), 4 deletions(-) diff --git a/beacon_node/network/src/sync/network_context.rs b/beacon_node/network/src/sync/network_context.rs index 968a9bcdddc..5faf7cfbfcc 100644 --- a/beacon_node/network/src/sync/network_context.rs +++ b/beacon_node/network/src/sync/network_context.rs @@ -486,6 +486,14 @@ impl SyncNetworkContext { let request = entry.remove(); let blocks = request .into_responses(&self.chain.spec) + .inspect_err(|e| { + debug!( + self.log, + "Failed to convert range block components into RpcBlock"; + "id" => %id, + "error" => e + ) + }) .map_err(RpcResponseError::BlockComponentCouplingError); Some(blocks) } else { diff --git a/beacon_node/network/src/sync/network_context/custody.rs b/beacon_node/network/src/sync/network_context/custody.rs index 38353d3ea24..f10d9473574 100644 --- a/beacon_node/network/src/sync/network_context/custody.rs +++ b/beacon_node/network/src/sync/network_context/custody.rs @@ -106,7 +106,6 @@ impl ActiveCustodyRequest { let Some(batch_request) = self.active_batch_columns_requests.get_mut(&req_id) else { warn!(self.log, "Received custody column response for unrequested index"; - "id" => ?self.custody_id, "block_root" => ?self.block_root, "req_id" => %req_id, ); @@ -117,7 +116,6 @@ impl ActiveCustodyRequest { Ok((data_columns, seen_timestamp)) => { debug!(self.log, "Custody column download success"; - "id" => ?self.custody_id, "block_root" => ?self.block_root, "req_id" => %req_id, "peer" => %peer_id, @@ -165,7 +163,6 @@ impl ActiveCustodyRequest { // Note: Batch logging that columns are missing to not spam logger debug!(self.log, "Custody column peer claims to not have some data"; - "id" => ?self.custody_id, "block_root" => ?self.block_root, "req_id" => %req_id, "peer" => %peer_id, @@ -179,7 +176,6 @@ impl ActiveCustodyRequest { Err(err) => { debug!(self.log, "Custody column download error"; - "id" => ?self.custody_id, "block_root" => ?self.block_root, "req_id" => %req_id, "peer" => %peer_id, From e09e5b7796e9d7bc920c10640f932b4b3ebf55fc Mon Sep 17 00:00:00 2001 From: Jimmy Chen Date: Fri, 21 Mar 2025 15:25:11 +1100 Subject: [PATCH 2/5] Fix getBlobs metric and record metric as soon as possible to prevent miscount. --- beacon_node/beacon_chain/src/fetch_blobs.rs | 26 +++++++++------------ 1 file changed, 11 insertions(+), 15 deletions(-) diff --git a/beacon_node/beacon_chain/src/fetch_blobs.rs b/beacon_node/beacon_chain/src/fetch_blobs.rs index f1da1ffc2f9..20778d5acb7 100644 --- a/beacon_node/beacon_chain/src/fetch_blobs.rs +++ b/beacon_node/beacon_chain/src/fetch_blobs.rs @@ -73,13 +73,23 @@ pub async fn fetch_and_process_engine_blobs( .as_ref() .ok_or(FetchEngineBlobError::ExecutionLayerMissing)?; + inc_counter_by( + &metrics::BLOBS_FROM_EL_EXPECTED_TOTAL, + num_expected_blobs as u64, + ); debug!(num_expected_blobs, "Fetching blobs from the EL"); let response = execution_layer .get_blobs(versioned_hashes) .await .map_err(FetchEngineBlobError::RequestFailed)?; - if response.is_empty() || response.iter().all(|opt| opt.is_none()) { + let num_fetched_blobs = response.iter().filter(|opt| opt.is_some()).count(); + inc_counter_by( + &metrics::BLOBS_FROM_EL_RECEIVED_TOTAL, + num_fetched_blobs as u64, + ); + + if num_fetched_blobs == 0 { debug!(num_expected_blobs, "No blobs fetched from the EL"); inc_counter(&metrics::BLOBS_FROM_EL_MISS_TOTAL); return Ok(None); @@ -99,20 +109,6 @@ pub async fn fetch_and_process_engine_blobs( &chain.spec, )?; - let num_fetched_blobs = fixed_blob_sidecar_list - .iter() - .filter(|b| b.is_some()) - .count(); - - inc_counter_by( - &metrics::BLOBS_FROM_EL_EXPECTED_TOTAL, - num_expected_blobs as u64, - ); - inc_counter_by( - &metrics::BLOBS_FROM_EL_RECEIVED_TOTAL, - num_fetched_blobs as u64, - ); - // Gossip verify blobs before publishing. This prevents blobs with invalid KZG proofs from // the EL making it into the data availability checker. We do not immediately add these // blobs to the observed blobs/columns cache because we want to allow blobs/columns to arrive on gossip From f602d2e62e066d511db43e552c8cdb20f565af89 Mon Sep 17 00:00:00 2001 From: Jimmy Chen Date: Tue, 1 Apr 2025 18:17:05 +1100 Subject: [PATCH 3/5] Change EL blob metrics to histogram and added a failed EL blob request metric. --- beacon_node/beacon_chain/src/fetch_blobs.rs | 15 ++++++--------- beacon_node/beacon_chain/src/metrics.rs | 21 +++++++++++++++------ 2 files changed, 21 insertions(+), 15 deletions(-) diff --git a/beacon_node/beacon_chain/src/fetch_blobs.rs b/beacon_node/beacon_chain/src/fetch_blobs.rs index 20778d5acb7..fa7a0e5f1a0 100644 --- a/beacon_node/beacon_chain/src/fetch_blobs.rs +++ b/beacon_node/beacon_chain/src/fetch_blobs.rs @@ -13,7 +13,7 @@ use crate::observed_data_sidecars::DoNotObserve; use crate::{metrics, AvailabilityProcessingStatus, BeaconChain, BeaconChainTypes, BlockError}; use execution_layer::json_structures::BlobAndProofV1; use execution_layer::Error as ExecutionLayerError; -use metrics::{inc_counter, inc_counter_by, TryExt}; +use metrics::{inc_counter, TryExt}; use ssz_types::FixedVector; use state_processing::per_block_processing::deneb::kzg_commitment_to_versioned_hash; use std::sync::Arc; @@ -73,21 +73,18 @@ pub async fn fetch_and_process_engine_blobs( .as_ref() .ok_or(FetchEngineBlobError::ExecutionLayerMissing)?; - inc_counter_by( - &metrics::BLOBS_FROM_EL_EXPECTED_TOTAL, - num_expected_blobs as u64, - ); + metrics::observe(&metrics::BLOBS_FROM_EL_EXPECTED, num_expected_blobs as f64); debug!(num_expected_blobs, "Fetching blobs from the EL"); let response = execution_layer .get_blobs(versioned_hashes) .await + .inspect_err(|_| { + inc_counter(&metrics::BLOBS_FROM_EL_ERROR_TOTAL); + }) .map_err(FetchEngineBlobError::RequestFailed)?; let num_fetched_blobs = response.iter().filter(|opt| opt.is_some()).count(); - inc_counter_by( - &metrics::BLOBS_FROM_EL_RECEIVED_TOTAL, - num_fetched_blobs as u64, - ); + metrics::observe(&metrics::BLOBS_FROM_EL_RECEIVED, num_fetched_blobs as f64); if num_fetched_blobs == 0 { debug!(num_expected_blobs, "No blobs fetched from the EL"); diff --git a/beacon_node/beacon_chain/src/metrics.rs b/beacon_node/beacon_chain/src/metrics.rs index d1c7a2a5dff..47ecf48e724 100644 --- a/beacon_node/beacon_chain/src/metrics.rs +++ b/beacon_node/beacon_chain/src/metrics.rs @@ -1662,28 +1662,37 @@ pub static DATA_COLUMN_SIDECAR_GOSSIP_VERIFICATION_TIMES: LazyLock> = LazyLock::new(|| { try_create_int_counter( "beacon_blobs_from_el_hit_total", - "Number of blob batches fetched from the execution layer", + "Number of non-empty blob batches fetched from the execution layer", ) }); pub static BLOBS_FROM_EL_MISS_TOTAL: LazyLock> = LazyLock::new(|| { try_create_int_counter( "beacon_blobs_from_el_miss_total", - "Number of blob batches failed to fetch from the execution layer", + "Number of empty blob responses from the execution layer", ) }); -pub static BLOBS_FROM_EL_EXPECTED_TOTAL: LazyLock> = LazyLock::new(|| { +pub static BLOBS_FROM_EL_ERROR_TOTAL: LazyLock> = LazyLock::new(|| { try_create_int_counter( - "beacon_blobs_from_el_expected_total", + "beacon_blobs_from_el_error_total", + "Number of failed blob fetches from the execution layer", + ) +}); + +pub static BLOBS_FROM_EL_EXPECTED: LazyLock> = LazyLock::new(|| { + try_create_histogram_with_buckets( + "beacon_blobs_from_el_expected", "Number of blobs expected from the execution layer", + linear_buckets(0.0, 4.0, 20), ) }); -pub static BLOBS_FROM_EL_RECEIVED_TOTAL: LazyLock> = LazyLock::new(|| { - try_create_int_counter( +pub static BLOBS_FROM_EL_RECEIVED: LazyLock> = LazyLock::new(|| { + try_create_histogram_with_buckets( "beacon_blobs_from_el_received_total", "Number of blobs fetched from the execution layer", + linear_buckets(0.0, 4.0, 20), ) }); From 5eb0c6e587c4f4ca5887acf54f869840842db044 Mon Sep 17 00:00:00 2001 From: Jimmy Chen Date: Tue, 1 Apr 2025 18:23:24 +1100 Subject: [PATCH 4/5] Delete logging. --- beacon_node/network/src/sync/network_context.rs | 8 -------- 1 file changed, 8 deletions(-) diff --git a/beacon_node/network/src/sync/network_context.rs b/beacon_node/network/src/sync/network_context.rs index 5faf7cfbfcc..968a9bcdddc 100644 --- a/beacon_node/network/src/sync/network_context.rs +++ b/beacon_node/network/src/sync/network_context.rs @@ -486,14 +486,6 @@ impl SyncNetworkContext { let request = entry.remove(); let blocks = request .into_responses(&self.chain.spec) - .inspect_err(|e| { - debug!( - self.log, - "Failed to convert range block components into RpcBlock"; - "id" => %id, - "error" => e - ) - }) .map_err(RpcResponseError::BlockComponentCouplingError); Some(blocks) } else { From 6a788db663a4e00834ac654dcb49bf40e075874e Mon Sep 17 00:00:00 2001 From: Jimmy Chen Date: Wed, 2 Apr 2025 14:56:35 +1100 Subject: [PATCH 5/5] Adjust buckets based on suggestion. --- beacon_node/beacon_chain/src/metrics.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/beacon_node/beacon_chain/src/metrics.rs b/beacon_node/beacon_chain/src/metrics.rs index 47ecf48e724..463319a1f5d 100644 --- a/beacon_node/beacon_chain/src/metrics.rs +++ b/beacon_node/beacon_chain/src/metrics.rs @@ -1684,7 +1684,7 @@ pub static BLOBS_FROM_EL_EXPECTED: LazyLock> = LazyLock::new(| try_create_histogram_with_buckets( "beacon_blobs_from_el_expected", "Number of blobs expected from the execution layer", - linear_buckets(0.0, 4.0, 20), + Ok(vec![0.0, 3.0, 6.0, 9.0, 12.0, 18.0, 24.0, 30.0]), ) });