From a4862cc4711aca5dc8bd7052b910b6cf524f4e36 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Fri, 16 Dec 2022 23:42:12 +0100 Subject: [PATCH 1/2] Adding some more logs More logs are always better! Joke aside, these logs help to debug certain issues. --- .../src/requester/fetch_task/mod.rs | 21 ++++++++++++++----- node/network/bridge/src/network.rs | 14 +++++++++++++ 2 files changed, 30 insertions(+), 5 deletions(-) diff --git a/node/network/availability-distribution/src/requester/fetch_task/mod.rs b/node/network/availability-distribution/src/requester/fetch_task/mod.rs index 89b634a5ce7e..a81f518aeb9e 100644 --- a/node/network/availability-distribution/src/requester/fetch_task/mod.rs +++ b/node/network/availability-distribution/src/requester/fetch_task/mod.rs @@ -326,6 +326,17 @@ impl RunningTask { &mut self, validator: &AuthorityDiscoveryId, ) -> std::result::Result { + gum::debug!( + target: LOG_TARGET, + origin = ?validator, + relay_parent = ?self.relay_parent, + group_index = ?self.group_index, + session_index = ?self.session_index, + chunk_index = ?self.request.index, + candidate_hash = ?self.request.candidate_hash, + "Starting chunk request", + ); + let (full_request, response_recv) = OutgoingRequest::new(Recipient::Authority(validator.clone()), self.request); let requests = Requests::ChunkFetchingV1(full_request); @@ -346,13 +357,13 @@ impl RunningTask { Err(RequestError::InvalidResponse(err)) => { gum::warn!( target: LOG_TARGET, - origin= ?validator, + origin = ?validator, relay_parent = ?self.relay_parent, group_index = ?self.group_index, session_index = ?self.session_index, chunk_index = ?self.request.index, candidate_hash = ?self.request.candidate_hash, - err= ?err, + err = ?err, "Peer sent us invalid erasure chunk data" ); Err(TaskError::PeerError) @@ -360,13 +371,13 @@ impl RunningTask { Err(RequestError::NetworkError(err)) => { gum::debug!( target: LOG_TARGET, - origin= ?validator, + origin = ?validator, relay_parent = ?self.relay_parent, group_index = ?self.group_index, session_index = ?self.session_index, chunk_index = ?self.request.index, candidate_hash = ?self.request.candidate_hash, - err= ?err, + err = ?err, "Some network error occurred when fetching erasure chunk" ); Err(TaskError::PeerError) @@ -374,7 +385,7 @@ impl RunningTask { Err(RequestError::Canceled(oneshot::Canceled)) => { gum::debug!( target: LOG_TARGET, - origin= ?validator, + origin = ?validator, relay_parent = ?self.relay_parent, group_index = ?self.group_index, session_index = ?self.session_index, diff --git a/node/network/bridge/src/network.rs b/node/network/bridge/src/network.rs index 32dc79d25814..713baa3f717c 100644 --- a/node/network/bridge/src/network.rs +++ b/node/network/bridge/src/network.rs @@ -161,6 +161,12 @@ impl Network for Arc> { let peer_id = match peer { Recipient::Peer(peer_id) => Some(peer_id), Recipient::Authority(authority) => { + gum::debug!( + target: LOG_TARGET, + ?authority, + "Searching for peer id to connect to authority", + ); + let mut found_peer_id = None; // Note: `get_addresses_by_authority_id` searched in a cache, and it thus expected // to be very quick. @@ -196,6 +202,14 @@ impl Network for Arc> { Some(peer_id) => peer_id, }; + gum::debug!( + target: LOG_TARGET, + %peer_id, + protocol = %req_protocol_names.get_name(protocol), + ?if_disconnected, + "Starting request", + ); + NetworkService::start_request( self, peer_id, From 41b161bb675014f39cec16db018a902109d8732d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Sat, 17 Dec 2022 09:49:04 +0100 Subject: [PATCH 2/2] Apply suggestions from code review --- .../availability-distribution/src/requester/fetch_task/mod.rs | 2 +- node/network/bridge/src/network.rs | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/node/network/availability-distribution/src/requester/fetch_task/mod.rs b/node/network/availability-distribution/src/requester/fetch_task/mod.rs index a81f518aeb9e..c6356c9ccd5f 100644 --- a/node/network/availability-distribution/src/requester/fetch_task/mod.rs +++ b/node/network/availability-distribution/src/requester/fetch_task/mod.rs @@ -326,7 +326,7 @@ impl RunningTask { &mut self, validator: &AuthorityDiscoveryId, ) -> std::result::Result { - gum::debug!( + gum::trace!( target: LOG_TARGET, origin = ?validator, relay_parent = ?self.relay_parent, diff --git a/node/network/bridge/src/network.rs b/node/network/bridge/src/network.rs index 713baa3f717c..ec7623bb2e1d 100644 --- a/node/network/bridge/src/network.rs +++ b/node/network/bridge/src/network.rs @@ -161,7 +161,7 @@ impl Network for Arc> { let peer_id = match peer { Recipient::Peer(peer_id) => Some(peer_id), Recipient::Authority(authority) => { - gum::debug!( + gum::trace!( target: LOG_TARGET, ?authority, "Searching for peer id to connect to authority", @@ -202,7 +202,7 @@ impl Network for Arc> { Some(peer_id) => peer_id, }; - gum::debug!( + gum::trace!( target: LOG_TARGET, %peer_id, protocol = %req_protocol_names.get_name(protocol),