Additional tracing in provisioner, vote_selection

node/core/provisioner/src/disputes/prioritized_selection/mod.rs

@@ -100,7 +100,15 @@ where
 
 	// Fetch the onchain disputes. We'll do a prioritization based on them.
 	let onchain = match get_onchain_disputes(sender, leaf.hash).await {
-		Ok(r) => r,
+		Ok(r) => {
+			gum::trace!(
+				target: LOG_TARGET,
+				?leaf,
+				"Successfully fetched {} onchain disputes",
+				r.len()
+			);
+			r
+		},
 		Err(GetOnchainDisputesError::NotSupported(runtime_api_err, relay_parent)) => {
 			// Runtime version is checked before calling this method, so the error below should never happen!
 			gum::error!(
@@ -130,6 +138,7 @@ where
 		},
 	};
 
+	gum::trace!(target: LOG_TARGET, ?leaf, "Fetching recent disputes");
 	let recent_disputes = request_disputes(sender).await;
 	gum::trace!(
 		target: LOG_TARGET,
@@ -139,26 +148,32 @@ where
 		onchain.len(),
 	);
 
+	gum::trace!(target: LOG_TARGET, ?leaf, "Filtering recent disputes");
+
 	// Filter out unconfirmed disputes. However if the dispute is already onchain - don't skip it.
 	// In this case we'd better push as much fresh votes as possible to bring it to conclusion faster.
 	let recent_disputes = recent_disputes
 		.into_iter()
 		.filter(|d| d.2.is_confirmed_concluded() || onchain.contains_key(&(d.0, d.1)))
 		.collect::<Vec<_>>();
 
+	gum::trace!(target: LOG_TARGET, ?leaf, "Partitioning recent disputes");
 	let partitioned = partition_recent_disputes(recent_disputes, &onchain);
 	metrics.on_partition_recent_disputes(&partitioned);
 
 	if partitioned.inactive_unknown_onchain.len() > 0 {
 		gum::warn!(
 			target: LOG_TARGET,
 			?leaf,
-			"Got {} inactive unknown onchain disputes. This should not happen!",
+			"Got {} inactive unknown onchain disputes. This should not happen in normal conditions!",
 			partitioned.inactive_unknown_onchain.len()
 		);
 	}
+
+	gum::trace!(target: LOG_TARGET, ?leaf, "Vote selection for recent disputes");
 	let result = vote_selection(sender, partitioned, &onchain).await;
 
+	gum::trace!(target: LOG_TARGET, ?leaf, "Convert to multi dispute statement set");
 	make_multi_dispute_statement_set(metrics, result)
 }
 
@@ -179,31 +194,52 @@ where
 	let mut result = BTreeMap::new();
 	let mut request_votes_counter = 0;
 	while !disputes.is_empty() {
+		gum::trace!(target: LOG_TARGET, "has to process {} disputes left", disputes.len());
 		let batch_size = std::cmp::min(VOTES_SELECTION_BATCH_SIZE, disputes.len());
 		let batch = Vec::from_iter(disputes.drain(0..batch_size));
 
 		// Filter votes which are already onchain
 		request_votes_counter += 1;
+		gum::trace!(target: LOG_TARGET, "requesting onchain votes",);
 		let votes = super::request_votes(sender, batch)
 			.await
 			.into_iter()
 			.map(|(session_index, candidate_hash, mut votes)| {
+				gum::trace!(target: LOG_TARGET, ?session_index, ?candidate_hash, "filtering votes");
 				let onchain_state =
 					if let Some(onchain_state) = onchain.get(&(session_index, candidate_hash)) {
 						onchain_state
 					} else {
 						// onchain knows nothing about this dispute - add all votes
+						gum::trace!(
+							target: LOG_TARGET,
+							?session_index,
+							?candidate_hash,
+							"Dispute unknown onchain - add all votes"
+						);
 						return (session_index, candidate_hash, votes)
 					};
 
 				votes.valid.retain(|validator_idx, (statement_kind, _)| {
+					gum::trace!(
+						target: LOG_TARGET,
+						?session_index,
+						?candidate_hash,
+						"Retain valid votes"
+					);
 					is_vote_worth_to_keep(
 						validator_idx,
 						DisputeStatement::Valid(*statement_kind),
 						&onchain_state,
 					)
 				});
 				votes.invalid.retain(|validator_idx, (statement_kind, _)| {
+					gum::trace!(
+						target: LOG_TARGET,
+						?session_index,
+						?candidate_hash,
+						"Retain invalid votes"
+					);
 					is_vote_worth_to_keep(
 						validator_idx,
 						DisputeStatement::Invalid(*statement_kind),
@@ -213,6 +249,7 @@ where
 				(session_index, candidate_hash, votes)
 			})
 			.collect::<Vec<_>>();
+		gum::trace!(target: LOG_TARGET, "got {} onchain votes after processing", votes.len());
 
 		// Check if votes are within the limit
 		for (session_index, candidate_hash, selected_votes) in votes {
@@ -221,8 +258,23 @@ where
 				// we are done - no more votes can be added. Importantly, we don't add any votes for a dispute here
 				// if we can't fit them all. This gives us an important invariant, that backing votes for
 				// disputes make it into the provisioned vote set.
+				gum::trace!(
+					target: LOG_TARGET,
+					?request_votes_counter,
+					?total_votes_len,
+					"vote_selection DisputeCoordinatorMessage::QueryCandidateVotes counter",
+				);
+
 				return result
 			}
+			gum::trace!(
+				target: LOG_TARGET,
+				?session_index,
+				?candidate_hash,
+				candidate_reepipt=?selected_votes.candidate_receipt,
+				"Added {} valid and {} invalid votes to the result",
+				selected_votes.valid.keys().len(), selected_votes.invalid.keys().len()
+			);
 			result.insert((session_index, candidate_hash), selected_votes);
 			total_votes_len += votes_len
 		}
@@ -231,6 +283,7 @@ where
 	gum::trace!(
 		target: LOG_TARGET,
 		?request_votes_counter,
+		?total_votes_len,
 		"vote_selection DisputeCoordinatorMessage::QueryCandidateVotes counter",
 	);
 

node/core/provisioner/src/lib.rs

@@ -179,11 +179,14 @@ fn handle_active_leaves_update(
 	per_relay_parent: &mut HashMap<Hash, PerRelayParent>,
 	inherent_delays: &mut InherentDelays,
 ) {
+	gum::trace!(target: LOG_TARGET, "Handle ActiveLeavesUpdate");
 	for deactivated in &update.deactivated {
+		gum::trace!(target: LOG_TARGET, leaf_hash=?deactivated, "Removing delay");
 		per_relay_parent.remove(deactivated);
 	}
 
 	if let Some(leaf) = update.activated {
+		gum::trace!(target: LOG_TARGET, leaf_hash=?leaf.hash, "Adding delay");
 		let delay_fut = Delay::new(PRE_PROPOSE_TIMEOUT).map(move |_| leaf.hash).boxed();
 		per_relay_parent.insert(leaf.hash, PerRelayParent::new(leaf));
 		inherent_delays.push(delay_fut);
@@ -590,6 +593,10 @@ async fn select_candidates(
 		}
 	}
 
+	gum::trace!(target: LOG_TARGET, 
+		leaf_hash=?relay_parent,
+		"before GetBackedCandidates");
+
 	// now get the backed candidates corresponding to these candidate receipts
 	let (tx, rx) = oneshot::channel();
 	sender.send_unbounded_message(CandidateBackingMessage::GetBackedCandidates(
@@ -598,6 +605,8 @@ async fn select_candidates(
 		tx,
 	));
 	let mut candidates = rx.await.map_err(|err| Error::CanceledBackedCandidates(err))?;
+	gum::trace!(target: LOG_TARGET, leaf_hash=?relay_parent,
+				"Got {} backed candidates", candidates.len());
 
 	// `selected_candidates` is generated in ascending order by core index, and `GetBackedCandidates`
 	// _should_ preserve that property, but let's just make sure.