Improve logging (#2669)

* Improve logging

* Review feedback

* Fix some warning and some further logging changes

node/core/av-store/src/lib.rs

@@ -679,7 +679,7 @@ fn note_block_backed(
 ) -> Result<(), Error> {
 	let candidate_hash = candidate.hash();
 
-	tracing::trace!(
+	tracing::debug!(
 		target: LOG_TARGET,
 		?candidate_hash,
 		"Candidate backed",
@@ -716,14 +716,14 @@ fn note_block_included(
 			// Warn and ignore.
 			tracing::warn!(
 				target: LOG_TARGET,
-				"Candidate {}, included without being backed?",
-				candidate_hash,
+				?candidate_hash,
+				"Candidate included without being backed?",
 			);
 		}
 		Some(mut meta) => {
 			let be_block = (BEBlockNumber(block.0), block.1);
 
-			tracing::trace!(
+			tracing::debug!(
 				target: LOG_TARGET,
 				?candidate_hash,
 				"Candidate included",
@@ -1126,8 +1126,8 @@ fn store_available_data(
 
 	tracing::debug!(
 		target: LOG_TARGET,
-		"Stored data and chunks for candidate={}",
-		candidate_hash,
+		?candidate_hash,
+		"Stored data and chunks",
 	);
 
 	Ok(())

node/core/bitfield-signing/src/lib.rs

@@ -157,6 +157,7 @@ async fn construct_availability_bitfield(
 
 	tracing::debug!(
 		target: LOG_TARGET,
+		?relay_parent,
 		"Signing Bitfield for {} cores: {:?}",
 		availability_cores.len(),
 		results,

node/network/collator-protocol/src/collator_side.rs

@@ -279,7 +279,7 @@ async fn distribute_collation(
 	if !state.view.contains(&relay_parent) {
 		tracing::warn!(
 			target: LOG_TARGET,
-			relay_parent = %relay_parent,
+			?relay_parent,
 			"distribute collation message parent is outside of our view",
 		);
 
@@ -299,7 +299,7 @@ async fn distribute_collation(
 			tracing::warn!(
 				target: LOG_TARGET,
 				para_id = %id,
-				relay_parent = %relay_parent,
+				?relay_parent,
 				"looks like no core is assigned to {} at {}", id, relay_parent,
 			);
 
@@ -451,24 +451,32 @@ async fn advertise_collation(
 
 	match (state.collations.get_mut(&relay_parent), should_advertise) {
 		(None, _) => {
-			tracing::trace!(
+			tracing::debug!(
 				target: LOG_TARGET,
-				relay_parent = ?relay_parent,
+				?relay_parent,
 				peer_id = %peer,
 				"No collation to advertise.",
 			);
 			return
 		},
 		(_, false) => {
-			tracing::trace!(
+			tracing::debug!(
 				target: LOG_TARGET,
-				relay_parent = ?relay_parent,
+				?relay_parent,
 				peer_id = %peer,
 				"Not advertising collation as we already advertised it to this validator.",
 			);
 			return
 		}
-		(Some(collation), true) => collation.status.advance_to_advertised(),
+		(Some(collation), true) => {
+			tracing::debug!(
+				target: LOG_TARGET,
+				?relay_parent,
+				peer_id = %peer,
+				"Advertising collation.",
+			);
+			collation.status.advance_to_advertised()
+		},
 	}
 
 	let wire_message = protocol_v1::CollatorProtocolMessage::AdvertiseCollation(relay_parent, collating_on);

node/network/collator-protocol/src/validator_side.rs

@@ -299,7 +299,7 @@ where
 	Context: SubsystemContext<Message = CollatorProtocolMessage>
 {
 	if !state.view.contains(&relay_parent) {
-		tracing::trace!(
+		tracing::debug!(
 			target: LOG_TARGET,
 			peer_id = %peer_id,
 			para_id = %para_id,
@@ -387,6 +387,11 @@ where
 
 	match msg {
 		Declare(id) => {
+			tracing::debug!(
+				target: LOG_TARGET,
+				peer_id = ?origin,
+				"Declared as collator",
+			);
 			state.known_collators.insert(origin.clone(), id);
 			state.peer_views.entry(origin).or_default();
 		}
@@ -395,12 +400,22 @@ where
 			state.advertisements.entry(origin.clone()).or_default().insert((para_id, relay_parent));
 
 			if let Some(collator) = state.known_collators.get(&origin) {
+				tracing::debug!(
+					target: LOG_TARGET,
+					peer_id = ?origin,
+					%para_id,
+					?relay_parent,
+					"Received advertise collation",
+				);
+
 				notify_candidate_selection(ctx, collator.clone(), relay_parent, para_id).await;
 			} else {
 				tracing::debug!(
 					target: LOG_TARGET,
 					peer_id = ?origin,
-					"advertise collation received from an unknown collator",
+					%para_id,
+					?relay_parent,
+					"Advertise collation received from an unknown collator",
 				);
 			}
 		}

node/network/gossip-support/src/lib.rs

@@ -45,7 +45,7 @@ pub struct GossipSupport {}
 struct State {
 	last_session_index: Option<SessionIndex>,
 	/// when we overwrite this, it automatically drops the previous request
-	last_connection_request: Option<ConnectionRequest>,
+	_last_connection_request: Option<ConnectionRequest>,
 }
 
 impl GossipSupport {
@@ -82,7 +82,7 @@ impl GossipSupport {
 
 					let leaves = activated.into_iter().map(|(h, _)| h);
 					if let Err(e) = state.handle_active_leaves(&mut ctx, leaves).await {
-						tracing::debug!(target: LOG_TARGET, "Error {}", e);
+						tracing::debug!(target: LOG_TARGET, error = ?e);
 					}
 				}
 				FromOverseer::Signal(OverseerSignal::BlockFinalized(_hash, _number)) => {},
@@ -131,10 +131,10 @@ impl State {
 			};
 
 			if let Some((new_session, relay_parent)) = maybe_new_session {
-				tracing::debug!(target: LOG_TARGET, "New session detected {}", new_session);
+				tracing::debug!(target: LOG_TARGET, %new_session, "New session detected");
 				let validators = determine_relevant_validators(ctx, relay_parent, new_session).await?;
 				let validators = choose_random_subset(validators);
-				tracing::debug!(target: LOG_TARGET, "Issuing a connection request to {:?}", validators);
+				tracing::debug!(target: LOG_TARGET, targets = ?validators, "Issuing a connection request");
 
 				let request = validator_discovery::connect_to_validators_in_session(
 					ctx,
@@ -145,7 +145,7 @@ impl State {
 				).await?;
 
 				self.last_session_index = Some(new_session);
-				self.last_connection_request = Some(request);
+				self._last_connection_request = Some(request);
 			}
 		}