From 34e5812171e7da2bd3c6dbf32c3c596edc04dd6f Mon Sep 17 00:00:00 2001
From: Sergei Shulepov <sergei@parity.io>
Date: Wed, 16 Dec 2020 17:34:26 +0100
Subject: [PATCH] Add logging to collation-generation (#2121)

Right now if the collation is not happening one will have to sprinkle
log statements and then recompile the code. It's doubly annoying if that
happens when working with Cumulus: that means one has to resort to
.cargo/config's `paths` or `diener`, which both are not ideal.

This just adds some verbose logging to save the investigators some time
when looking why the collations are not happening
---
 polkadot/node/collation-generation/src/lib.rs | 37 +++++++++++++++++--
 1 file changed, 34 insertions(+), 3 deletions(-)

diff --git a/polkadot/node/collation-generation/src/lib.rs b/polkadot/node/collation-generation/src/lib.rs
index b3e62cdf1c..0b2b714c6b 100644
--- a/polkadot/node/collation-generation/src/lib.rs
+++ b/polkadot/node/collation-generation/src/lib.rs
@@ -202,7 +202,7 @@ async fn handle_new_activations<Context: SubsystemContext>(
 		let availability_cores = availability_cores??;
 		let n_validators = validators??.len();
 
-		for core in availability_cores {
+		for (core_idx, core) in availability_cores.into_iter().enumerate() {
 			let _availability_core_timer = metrics.time_new_activations_availability_core();
 
 			let (scheduled_core, assumption) = match core {
@@ -211,12 +211,33 @@ async fn handle_new_activations<Context: SubsystemContext>(
 				}
 				CoreState::Occupied(_occupied_core) => {
 					// TODO: https://github.com/paritytech/polkadot/issues/1573
+					tracing::trace!(
+						target: LOG_TARGET,
+						core_idx = %core_idx,
+						relay_parent = ?relay_parent,
+						"core is occupied. Keep going.",
+					);
 					continue;
 				}
-				_ => continue,
+				CoreState::Free => {
+					tracing::trace!(
+						target: LOG_TARGET,
+						core_idx = %core_idx,
+						"core is free. Keep going.",
+					);
+					continue
+				}
 			};
 
 			if scheduled_core.para_id != config.para_id {
+				tracing::trace!(
+					target: LOG_TARGET,
+					core_idx = %core_idx,
+					relay_parent = ?relay_parent,
+					our_para = %config.para_id,
+					their_para = %scheduled_core.para_id,
+					"core is not assigned to our para. Keep going.",
+				);
 				continue;
 			}
 
@@ -233,7 +254,17 @@ async fn handle_new_activations<Context: SubsystemContext>(
 			.await??
 			{
 				Some(v) => v,
-				None => continue,
+				None => {
+					tracing::trace!(
+						target: LOG_TARGET,
+						core_idx = %core_idx,
+						relay_parent = ?relay_parent,
+						our_para = %config.para_id,
+						their_para = %scheduled_core.para_id,
+						"validation data is not available",
+					);
+					continue
+				}
 			};
 
 			let task_config = config.clone();