diff --git a/substrate/client/network/src/protocol/sync.rs b/substrate/client/network/src/protocol/sync.rs index 8929fc75f8dd8447a69d50aa3b4c8250ee240ab3..a513d47ca419862db6598ba4e421a890b0ff3864 100644 --- a/substrate/client/network/src/protocol/sync.rs +++ b/substrate/client/network/src/protocol/sync.rs @@ -308,8 +308,8 @@ impl<B: BlockT> ChainSync<B> { best_queued_hash: info.best_hash, best_queued_number: info.best_number, best_imported_number: info.best_number, - extra_finality_proofs: ExtraRequests::new(), - extra_justifications: ExtraRequests::new(), + extra_finality_proofs: ExtraRequests::new("finality proof"), + extra_justifications: ExtraRequests::new("justification"), role, required_block_attributes, queue_blocks: Default::default(), diff --git a/substrate/client/network/src/protocol/sync/extra_requests.rs b/substrate/client/network/src/protocol/sync/extra_requests.rs index a0ea68af5f334f61d362f7cba4587590acbffc9b..44b42b154fff2724d78abf36b0d6d5247023f49d 100644 --- a/substrate/client/network/src/protocol/sync/extra_requests.rs +++ b/substrate/client/network/src/protocol/sync/extra_requests.rs @@ -18,7 +18,7 @@ use sp_blockchain::Error as ClientError; use crate::protocol::sync::{PeerSync, PeerSyncState}; use fork_tree::ForkTree; use libp2p::PeerId; -use log::{debug, warn}; +use log::{debug, trace, warn}; use sp_runtime::traits::{Block as BlockT, NumberFor, Zero}; use std::collections::{HashMap, HashSet, VecDeque}; use std::time::{Duration, Instant}; @@ -48,10 +48,12 @@ pub(crate) struct ExtraRequests<B: BlockT> { failed_requests: HashMap<ExtraRequest<B>, Vec<(PeerId, Instant)>>, /// successful requests importing_requests: HashSet<ExtraRequest<B>>, + /// the name of this type of extra request (useful for logging.) + request_type_name: &'static str, } impl<B: BlockT> ExtraRequests<B> { - pub(crate) fn new() -> Self { + pub(crate) fn new(request_type_name: &'static str) -> Self { ExtraRequests { tree: ForkTree::new(), best_seen_finalized_number: Zero::zero(), @@ -59,6 +61,7 @@ impl<B: BlockT> ExtraRequests<B> { active_requests: HashMap::new(), failed_requests: HashMap::new(), importing_requests: HashSet::new(), + request_type_name, } } @@ -113,11 +116,28 @@ impl<B: BlockT> ExtraRequests<B> { // messages to chain sync. if let Some(request) = self.active_requests.remove(&who) { if let Some(r) = resp { + trace!(target: "sync", "Queuing import of {} from {:?} for {:?}", + self.request_type_name, + who, + request, + ); + self.importing_requests.insert(request); return Some((who, request.0, request.1, r)) + } else { + trace!(target: "sync", "Empty {} response from {:?} for {:?}", + self.request_type_name, + who, + request, + ); } self.failed_requests.entry(request).or_insert(Vec::new()).push((who, Instant::now())); self.pending_requests.push_front(request); + } else { + trace!(target: "sync", "No active {} request to {:?}", + self.request_type_name, + who, + ); } None } @@ -265,6 +285,13 @@ impl<'a, B: BlockT> Matcher<'a, B> { continue } self.extras.active_requests.insert(peer.clone(), request); + + trace!(target: "sync", "Sending {} request to {:?} for {:?}", + self.extras.request_type_name, + peer, + request, + ); + return Some((peer.clone(), request)) } @@ -293,7 +320,7 @@ mod tests { #[test] fn requests_are_processed_in_order() { fn property(mut peers: ArbitraryPeers) { - let mut requests = ExtraRequests::<Block>::new(); + let mut requests = ExtraRequests::<Block>::new("test"); let num_peers_available = peers.0.values() .filter(|s| s.state == PeerSyncState::Available).count(); @@ -319,7 +346,7 @@ mod tests { #[test] fn new_roots_schedule_new_request() { fn property(data: Vec<BlockNumber>) { - let mut requests = ExtraRequests::<Block>::new(); + let mut requests = ExtraRequests::<Block>::new("test"); for (i, number) in data.into_iter().enumerate() { let hash = [i as u8; 32].into(); let pending = requests.pending_requests.len(); @@ -336,7 +363,7 @@ mod tests { #[test] fn disconnecting_implies_rescheduling() { fn property(mut peers: ArbitraryPeers) -> bool { - let mut requests = ExtraRequests::<Block>::new(); + let mut requests = ExtraRequests::<Block>::new("test"); let num_peers_available = peers.0.values() .filter(|s| s.state == PeerSyncState::Available).count(); @@ -371,7 +398,7 @@ mod tests { #[test] fn no_response_reschedules() { fn property(mut peers: ArbitraryPeers) { - let mut requests = ExtraRequests::<Block>::new(); + let mut requests = ExtraRequests::<Block>::new("test"); let num_peers_available = peers.0.values() .filter(|s| s.state == PeerSyncState::Available).count(); @@ -404,7 +431,7 @@ mod tests { fn request_is_rescheduled_when_earlier_block_is_finalized() { let _ = ::env_logger::try_init(); - let mut finality_proofs = ExtraRequests::<Block>::new(); + let mut finality_proofs = ExtraRequests::<Block>::new("test"); let hash4 = [4; 32].into(); let hash5 = [5; 32].into(); @@ -442,7 +469,7 @@ mod tests { #[test] fn anecstor_roots_are_finalized_when_finality_notification_is_missed() { - let mut finality_proofs = ExtraRequests::<Block>::new(); + let mut finality_proofs = ExtraRequests::<Block>::new("test"); let hash4 = [4; 32].into(); let hash5 = [5; 32].into();