gnosis/lighthouse
1
0
Fork 0
mirror of https://github.com/sigp/lighthouse.git synced 2026-07-04 05:14:33 +00:00
Code Issues Packages Projects Releases Wiki Activity

Consistent logging of full root in lookup debug logs (#5700)

Browse Source 
* Consistent logging of full root in lookup debug logs

* Tag sync log with service

* More logs

* Log when new peers are added

* Don't shortcircuit add_peer
This commit is contained in:
Lion - dapplion
2024-05-07 00:41:38 +09:00
committed by GitHub
parent da9d38698d
commit 436d54e4bf
3 changed files with 51 additions and 37 deletions
Download Patch File Download Diff File Expand all files Collapse all files

49
beacon_node/network/src/sync/block_lookups/mod.rs
View File

@@ -16,7 +16,7 @@ use fnv::FnvHashMap;
use lighthouse_network::{PeerAction, PeerId}; use lighthouse_network::{PeerAction, PeerId};
use lru_cache::LRUTimeCache; use lru_cache::LRUTimeCache;
pub use single_block_lookup::{BlobRequestState, BlockRequestState}; pub use single_block_lookup::{BlobRequestState, BlockRequestState};
use slog::{debug, error, trace, warn, Logger}; use slog::{debug, error, warn, Logger};
use std::collections::hash_map::Entry; use std::collections::hash_map::Entry;
use std::sync::Arc; use std::sync::Arc;
use std::time::Duration; use std::time::Duration;
@@ -233,13 +233,17 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
.iter_mut() .iter_mut()
.find(|(_id, lookup)| lookup.is_for_block(block_root)) .find(|(_id, lookup)| lookup.is_for_block(block_root))
{ {
trace!(self.log, "Adding peer to existing single block lookup"; "block_root" => %block_root); for peer in peers {
lookup.add_peers(peers); if lookup.add_peer(*peer) {
debug!(self.log, "Adding peer to existing single block lookup"; "block_root" => ?block_root, "peer" => ?peer);
}
}
if let Some(block_component) = block_component { if let Some(block_component) = block_component {
let component_type = block_component.get_type(); let component_type = block_component.get_type();
let imported = lookup.add_child_components(block_component); let imported = lookup.add_child_components(block_component);
if !imported { if !imported {
debug!(self.log, "Lookup child component ignored"; "block_root" => %block_root, "type" => component_type); debug!(self.log, "Lookup child component ignored"; "block_root" => ?block_root, "type" => component_type);
} }
} }
return true; return true;
@@ -252,10 +256,15 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
.iter() .iter()
.any(|(_, lookup)| lookup.is_for_block(awaiting_parent)) .any(|(_, lookup)| lookup.is_for_block(awaiting_parent))
{ {
warn!(self.log, "Ignoring child lookup parent lookup not found"; "block_root" => ?awaiting_parent);
return false; return false;
} }
} }
// If we know that this lookup has unknown parent (is awaiting a parent lookup to resolve),
// signal here to hold processing downloaded data.
let mut lookup = SingleBlockLookup::new(block_root, peers, cx.next_id(), awaiting_parent);
let msg = if block_component.is_some() { let msg = if block_component.is_some() {
"Searching for components of a block with unknown parent" "Searching for components of a block with unknown parent"
} else { } else {
@@ -265,14 +274,11 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
self.log, self.log,
"{}", msg; "{}", msg;
"peer_ids" => ?peers, "peer_ids" => ?peers,
"block" => ?block_root, "block_root" => ?block_root,
"id" => lookup.id,
); );
metrics::inc_counter(&metrics::SYNC_LOOKUP_CREATED); metrics::inc_counter(&metrics::SYNC_LOOKUP_CREATED);
// If we know that this lookup has unknown parent (is awaiting a parent lookup to resolve),
// signal here to hold processing downloaded data.
let mut lookup = SingleBlockLookup::new(block_root, peers, cx.next_id(), awaiting_parent);
// Add block components to the new request // Add block components to the new request
if let Some(block_component) = block_component { if let Some(block_component) = block_component {
lookup.add_child_components(block_component); lookup.add_child_components(block_component);
@@ -338,7 +344,8 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
Ok((response, seen_timestamp)) => { Ok((response, seen_timestamp)) => {
debug!(self.log, debug!(self.log,
"Received lookup download success"; "Received lookup download success";
"block_root" => %block_root, "block_root" => ?block_root,
"id" => id,
"peer_id" => %peer_id, "peer_id" => %peer_id,
"response_type" => ?response_type, "response_type" => ?response_type,
); );
@@ -357,7 +364,8 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
Err(e) => { Err(e) => {
debug!(self.log, debug!(self.log,
"Received lookup download failure"; "Received lookup download failure";
"block_root" => %block_root, "block_root" => ?block_root,
"id" => id,
"peer_id" => %peer_id, "peer_id" => %peer_id,
"response_type" => ?response_type, "response_type" => ?response_type,
"error" => %e, "error" => %e,
@@ -380,7 +388,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
req.should_drop_lookup_on_disconnected_peer(peer_id ); req.should_drop_lookup_on_disconnected_peer(peer_id );
if should_drop_lookup { if should_drop_lookup {
debug!(self.log, "Dropping single lookup after peer disconnection"; "block_root" => %req.block_root()); debug!(self.log, "Dropping single lookup after peer disconnection"; "block_root" => ?req.block_root());
} }
!should_drop_lookup !should_drop_lookup
@@ -425,6 +433,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
"Received lookup processing result"; "Received lookup processing result";
"component" => ?R::response_type(), "component" => ?R::response_type(),
"block_root" => ?block_root, "block_root" => ?block_root,
"id" => lookup_id,
"result" => ?result, "result" => ?result,
); );
@@ -496,7 +505,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
debug!( debug!(
self.log, self.log,
"Single block lookup failed. Execution layer is offline / unsynced / misconfigured"; "Single block lookup failed. Execution layer is offline / unsynced / misconfigured";
"block_root" => %block_root, "block_root" => ?block_root,
"error" => ?e "error" => ?e
); );
Action::Drop Action::Drop
@@ -505,7 +514,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
if e.category() == AvailabilityCheckErrorCategory::Internal => if e.category() == AvailabilityCheckErrorCategory::Internal =>
{ {
// There errors indicate internal problems and should not downscore the peer // There errors indicate internal problems and should not downscore the peer
warn!(self.log, "Internal availability check failure"; "block_root" => %block_root, "error" => ?e); warn!(self.log, "Internal availability check failure"; "block_root" => ?block_root, "error" => ?e);
// Here we choose *not* to call `on_processing_failure` because this could result in a bad // Here we choose *not* to call `on_processing_failure` because this could result in a bad
// lookup state transition. This error invalidates both blob and block requests, and we don't know the // lookup state transition. This error invalidates both blob and block requests, and we don't know the
@@ -514,7 +523,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
Action::Drop Action::Drop
} }
other => { other => {
debug!(self.log, "Invalid lookup component"; "block_root" => %block_root, "component" => ?R::response_type(), "error" => ?other); debug!(self.log, "Invalid lookup component"; "block_root" => ?block_root, "component" => ?R::response_type(), "error" => ?other);
let peer_id = request_state.on_processing_failure()?; let peer_id = request_state.on_processing_failure()?;
cx.report_peer( cx.report_peer(
peer_id, peer_id,
@@ -540,7 +549,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
Action::ParentUnknown { parent_root } => { Action::ParentUnknown { parent_root } => {
let peers = lookup.all_available_peers().cloned().collect::<Vec<_>>(); let peers = lookup.all_available_peers().cloned().collect::<Vec<_>>();
lookup.set_awaiting_parent(parent_root); lookup.set_awaiting_parent(parent_root);
debug!(self.log, "Marking lookup as awaiting parent"; "lookup" => %block_root, "parent_root" => %parent_root); debug!(self.log, "Marking lookup as awaiting parent"; "id" => lookup.id, "block_root" => ?block_root, "parent_root" => ?parent_root);
self.search_parent_of_child(parent_root, block_root, &peers, cx); self.search_parent_of_child(parent_root, block_root, &peers, cx);
Ok(LookupResult::Pending) Ok(LookupResult::Pending)
} }
@@ -562,7 +571,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
for (id, lookup) in self.single_block_lookups.iter_mut() { for (id, lookup) in self.single_block_lookups.iter_mut() {
if lookup.awaiting_parent() == Some(block_root) { if lookup.awaiting_parent() == Some(block_root) {
lookup.resolve_awaiting_parent(); lookup.resolve_awaiting_parent();
debug!(self.log, "Continuing child lookup"; "parent_root" => %block_root, "block_root" => %lookup.block_root()); debug!(self.log, "Continuing child lookup"; "parent_root" => ?block_root, "id" => id, "block_root" => ?lookup.block_root());
let result = lookup.continue_requests(cx); let result = lookup.continue_requests(cx);
lookup_results.push((*id, result)); lookup_results.push((*id, result));
} }
@@ -578,7 +587,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
/// dropped. /// dropped.
pub fn drop_lookup_and_children(&mut self, dropped_id: SingleLookupId) { pub fn drop_lookup_and_children(&mut self, dropped_id: SingleLookupId) {
if let Some(dropped_lookup) = self.single_block_lookups.remove(&dropped_id) { if let Some(dropped_lookup) = self.single_block_lookups.remove(&dropped_id) {
debug!(self.log, "Dropping child lookup"; "id" => ?dropped_id, "block_root" => %dropped_lookup.block_root()); debug!(self.log, "Dropping child lookup"; "id" => ?dropped_id, "block_root" => ?dropped_lookup.block_root());
let child_lookups = self let child_lookups = self
.single_block_lookups .single_block_lookups
@@ -605,11 +614,13 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
Ok(LookupResult::Pending) => {} // no action Ok(LookupResult::Pending) => {} // no action
Ok(LookupResult::Completed) => { Ok(LookupResult::Completed) => {
if let Some(lookup) = self.single_block_lookups.remove(&id) { if let Some(lookup) = self.single_block_lookups.remove(&id) {
debug!(self.log, "Dropping completed lookup"; "block" => %lookup.block_root()); debug!(self.log, "Dropping completed lookup"; "block" => ?lookup.block_root(), "id" => id);
metrics::inc_counter(&metrics::SYNC_LOOKUP_COMPLETED); metrics::inc_counter(&metrics::SYNC_LOOKUP_COMPLETED);
// Block imported, continue the requests of pending child blocks // Block imported, continue the requests of pending child blocks
self.continue_child_lookups(lookup.block_root(), cx); self.continue_child_lookups(lookup.block_root(), cx);
self.update_metrics(); self.update_metrics();
} else {
debug!(self.log, "Attempting to drop non-existent lookup"; "id" => id);
} }
} }
Err(error) => { Err(error) => {

24
beacon_node/network/src/sync/block_lookups/single_block_lookup.rs
View File

@@ -172,17 +172,12 @@ impl<T: BeaconChainTypes> SingleBlockLookup<T> {
) )
} }
/// Add all given peers to both block and blob request states. /// Add peer to all request states. The peer must be able to serve this request.
pub fn add_peer(&mut self, peer_id: PeerId) { /// Returns true if the peer was newly inserted into some request state.
self.block_request_state.state.add_peer(&peer_id); pub fn add_peer(&mut self, peer_id: PeerId) -> bool {
self.blob_request_state.state.add_peer(&peer_id); let inserted_block = self.block_request_state.state.add_peer(&peer_id);
} let inserted_blob = self.blob_request_state.state.add_peer(&peer_id);
inserted_block || inserted_blob
/// Add all given peers to both block and blob request states.
pub fn add_peers(&mut self, peers: &[PeerId]) {
for peer in peers {
self.add_peer(*peer);
}
} }
/// Returns true if the block has already been downloaded. /// Returns true if the block has already been downloaded.
@@ -464,9 +459,10 @@ impl<T: Clone> SingleLookupRequestState<T> {
self.failed_processing >= self.failed_downloading self.failed_processing >= self.failed_downloading
} }
/// This method should be used for peers wrapped in `PeerId::BlockAndBlobs`. /// Add peer to this request states. The peer must be able to serve this request.
pub fn add_peer(&mut self, peer_id: &PeerId) { /// Returns true if the peer is newly inserted.
self.available_peers.insert(*peer_id); pub fn add_peer(&mut self, peer_id: &PeerId) -> bool {
self.available_peers.insert(*peer_id)
} }
/// If a peer disconnects, this request could be failed. If so, an error is returned /// If a peer disconnects, this request could be failed. If so, an error is returned

15
beacon_node/network/src/sync/manager.rs
View File

@@ -56,7 +56,7 @@ use lighthouse_network::rpc::RPCError;
use lighthouse_network::types::{NetworkGlobals, SyncState}; use lighthouse_network::types::{NetworkGlobals, SyncState};
use lighthouse_network::SyncInfo; use lighthouse_network::SyncInfo;
use lighthouse_network::{PeerAction, PeerId}; use lighthouse_network::{PeerAction, PeerId};
use slog::{crit, debug, error, info, trace, warn, Logger}; use slog::{crit, debug, error, info, o, trace, warn, Logger};
use std::ops::Sub; use std::ops::Sub;
use std::sync::Arc; use std::sync::Arc;
use std::time::Duration; use std::time::Duration;
@@ -257,9 +257,16 @@ impl<T: BeaconChainTypes> SyncManager<T> {
beacon_chain.clone(), beacon_chain.clone(),
log.clone(), log.clone(),
), ),
range_sync: RangeSync::new(beacon_chain.clone(), log.clone()), range_sync: RangeSync::new(
backfill_sync: BackFillSync::new(beacon_chain.clone(), network_globals, log.clone()), beacon_chain.clone(),
block_lookups: BlockLookups::new(log.clone()), log.new(o!("service" => "range_sync")),
),
backfill_sync: BackFillSync::new(
beacon_chain.clone(),
network_globals,
log.new(o!("service" => "backfill_sync")),
),
block_lookups: BlockLookups::new(log.new(o!("service"=> "lookup_sync"))),
log: log.clone(), log: log.clone(),
} }
} }