Improve logging to make debugging parachains easier (#2279)

* Improve logging to make debugging parachains easier

This pr should make debugging parachains easier, by printing more
information about the validation process.

* 🤦

* moare

* Convert to debug

polkadot/node/core/backing/src/lib.rs

@@ -386,7 +386,7 @@ struct BackgroundValidationParams<F> {
 }
 
 async fn validate_and_make_available(
-	params: BackgroundValidationParams<impl Fn(BackgroundValidationResult) -> ValidatedCandidateCommand>,
+	params: BackgroundValidationParams<impl Fn(BackgroundValidationResult) -> ValidatedCandidateCommand + Sync>,
 ) -> Result<(), Error> {
 	let BackgroundValidationParams {
 		mut tx_from,
@@ -421,11 +421,17 @@ async fn validate_and_make_available(
 
 	let res = match v {
 		ValidationResult::Valid(commitments, validation_data) => {
+			tracing::debug!(
+				target: LOG_TARGET,
+				candidate_hash = ?candidate.hash(),
+				"Validation successful",
+			);
+
 			// If validation produces a new set of commitments, we vote the candidate as invalid.
 			if commitments.hash() != expected_commitments_hash {
-				tracing::trace!(
+				tracing::debug!(
 					target: LOG_TARGET,
-					candidate_receipt = ?candidate,
+					candidate_hash = ?candidate.hash(),
 					actual_commitments = ?commitments,
 					"Commitments obtained with validation don't match the announced by the candidate receipt",
 				);
@@ -445,9 +451,9 @@ async fn validate_and_make_available(
 				match erasure_valid {
 					Ok(()) => Ok((candidate, commitments, pov.clone())),
 					Err(InvalidErasureRoot) => {
-						tracing::trace!(
+						tracing::debug!(
 							target: LOG_TARGET,
-							candidate_receipt = ?candidate,
+							candidate_hash = ?candidate.hash(),
 							actual_commitments = ?commitments,
 							"Erasure root doesn't match the announced by the candidate receipt",
 						);
@@ -457,9 +463,9 @@ async fn validate_and_make_available(
 			}
 		}
 		ValidationResult::Invalid(reason) => {
-			tracing::trace!(
+			tracing::debug!(
 				target: LOG_TARGET,
-				candidate_receipt = ?candidate,
+				candidate_hash = ?candidate.hash(),
 				reason = ?reason,
 				"Validation yielded an invalid candidate",
 			);
@@ -467,9 +473,7 @@ async fn validate_and_make_available(
 		}
 	};
 
-	let command = make_command(res);
-	tx_command.send(command).await?;
-	Ok(())
+	tx_command.send(make_command(res)).await.map_err(Into::into)
 }
 
 impl CandidateBackingJob {
@@ -558,7 +562,7 @@ impl CandidateBackingJob {
 	async fn background_validate_and_make_available(
 		&mut self,
 		params: BackgroundValidationParams<
-			impl Fn(BackgroundValidationResult) -> ValidatedCandidateCommand + Send + 'static
+			impl Fn(BackgroundValidationResult) -> ValidatedCandidateCommand + Send + 'static + Sync
 		>,
 	) -> Result<(), Error> {
 		let candidate_hash = params.candidate.hash();
@@ -604,6 +608,13 @@ impl CandidateBackingJob {
 		let candidate_hash = candidate.hash();
 		let span = self.get_unbacked_validation_child(parent_span, candidate_hash);
 
+		tracing::debug!(
+			target: LOG_TARGET,
+			candidate_hash = ?candidate_hash,
+			candidate_receipt = ?candidate,
+			"Validate and second candidate",
+		);
+
 		self.background_validate_and_make_available(BackgroundValidationParams {
 			tx_from: self.tx_from.clone(),
 			tx_command: self.background_validation_tx.clone(),
@@ -675,6 +686,12 @@ impl CandidateBackingJob {
 		statement: &SignedFullStatement,
 		parent_span: &JaegerSpan,
 	) -> Result<Option<TableSummary>, Error> {
+		tracing::debug!(
+			target: LOG_TARGET,
+			statement = ?statement.payload().to_compact(),
+			"Importing statement",
+		);
+
 		let import_statement_span = {
 			// create a span only for candidates we're already aware of.
 			let candidate_hash = statement.payload().candidate_hash();
@@ -696,6 +713,12 @@ impl CandidateBackingJob {
 				if let Some(backed) =
 					table_attested_to_backed(attested, &self.table_context)
 				{
+					tracing::debug!(
+						target: LOG_TARGET,
+						candidate_hash = ?candidate_hash,
+						"Candidate backed",
+					);
+
 					let message = ProvisionerMessage::ProvisionableData(
 						self.parent,
 						ProvisionableData::BackedCandidate(backed.receipt()),
@@ -794,6 +817,13 @@ impl CandidateBackingJob {
 		let candidate = self.table.get_candidate(&candidate_hash).ok_or(Error::CandidateNotFound)?.to_plain();
 		let descriptor = candidate.descriptor().clone();
 
+		tracing::debug!(
+			target: LOG_TARGET,
+			candidate_hash = ?candidate_hash,
+			candidate_receipt = ?candidate,
+			"Kicking off validation",
+		);
+
 		// Check that candidate is collated by the right collator.
 		if self.required_collator.as_ref()
 			.map_or(false, |c| c != &descriptor.collator)

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

@@ -368,6 +368,12 @@ where
 			if let Some(per_request) = state.requests_info.remove(&id) {
 				let _ = per_request.received.send(());
 				if let Some(collator_id) = state.known_collators.get(&origin) {
+					tracing::debug!(
+						target: LOG_TARGET,
+						%request_id,
+						"Received collation",
+					);
+
 					let _ = per_request.result.send((receipt.clone(), pov.clone()));
 					state.metrics.on_request(Ok(()));
 
@@ -420,8 +426,8 @@ where
 		tracing::trace!(
 			target: LOG_TARGET,
 			peer_id = %peer_id,
-			para_id = %para_id,
-			relay_parent = %relay_parent,
+			%para_id,
+			?relay_parent,
 			"collation has already been requested",
 		);
 		return;
@@ -449,6 +455,15 @@ where
 
 	state.requests_in_progress.push(request.wait().boxed());
 
+	tracing::debug!(
+		target: LOG_TARGET,
+		peer_id = %peer_id,
+		%para_id,
+		%request_id,
+		?relay_parent,
+		"Requesting collation",
+	);
+
 	let wire_message = protocol_v1::CollatorProtocolMessage::RequestCollation(
 		request_id,
 		relay_parent,
@@ -737,7 +752,7 @@ where
 			// if the chain has not moved on yet.
 			match request {
 				CollationRequestResult::Timeout(id) => {
-					tracing::trace!(target: LOG_TARGET, id, "request timed out");
+					tracing::debug!(target: LOG_TARGET, request_id=%id, "Collation timed out");
 					request_timed_out(&mut ctx, &mut state, id).await;
 				}
 				CollationRequestResult::Received(id) => {

polkadot/parachain/src/wasm_executor/validation_host.rs

@@ -33,6 +33,8 @@ const WORKER_ARG: &'static str = "validation-worker";
 /// CLI Argument to start in validation worker mode.
 pub const WORKER_ARGS: &[&'static str] = &[WORKER_ARG];
 
+const LOG_TARGET: &'static str = "validation-worker";
+
 /// Execution timeout in seconds;
 #[cfg(debug_assertions)]
 pub const EXECUTION_TIMEOUT_SEC: u64 =  30;
@@ -128,7 +130,7 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> {
 	let mut memory = match SharedMem::open(mem_id) {
 		Ok(memory) => memory,
 		Err(e) => {
-			debug!("{} Error opening shared memory: {:?}", process::id(), e);
+			debug!(target: LOG_TARGET, "{} Error opening shared memory: {:?}", process::id(), e);
 			return Err(format!("Error opening shared memory: {:?}", e));
 		}
 	};
@@ -142,7 +144,7 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> {
 		let mut in_data = Vec::new();
 		// pipe terminates when parent process exits
 		std::io::stdin().read_to_end(&mut in_data).ok();
-		debug!("{} Parent process is dead. Exiting", process::id());
+		debug!(target: LOG_TARGET, "{} Parent process is dead. Exiting", process::id());
 		exit.store(true, atomic::Ordering::Relaxed);
 	});
 
@@ -154,18 +156,18 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> {
 			break;
 		}
 
-		debug!("{} Waiting for candidate", process::id());
+		debug!(target: LOG_TARGET, "{} Waiting for candidate", process::id());
 		match memory.wait(Event::CandidateReady as usize, shared_memory::Timeout::Sec(3)) {
 			Err(e) => {
 				// Timeout
-				trace!("{} Timeout waiting for candidate: {:?}", process::id(), e);
+				trace!(target: LOG_TARGET, "{} Timeout waiting for candidate: {:?}", process::id(), e);
 				continue;
 			}
 			Ok(()) => {}
 		}
 
 		{
-			debug!("{} Processing candidate", process::id());
+			debug!(target: LOG_TARGET, "{} Processing candidate", process::id());
 			// we have candidate data
 			let mut slice = memory.wlock_as_slice(0)
 				.map_err(|e| format!("Error locking shared memory: {:?}", e))?;
@@ -176,14 +178,14 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> {
 				let mut header_buf: &[u8] = header_buf;
 				let header = ValidationHeader::decode(&mut header_buf)
 					.map_err(|_| format!("Error decoding validation request."))?;
-				debug!("{} Candidate header: {:?}", process::id(), header);
+				debug!(target: LOG_TARGET, "{} Candidate header: {:?}", process::id(), header);
 				let (code, rest) = rest.split_at_mut(MAX_CODE_MEM);
 				let (code, _) = code.split_at_mut(header.code_size as usize);
 				let (call_data, _) = rest.split_at_mut(MAX_RUNTIME_MEM);
 				let (call_data, _) = call_data.split_at_mut(header.params_size as usize);
 
 				let result = validate_candidate_internal(code, call_data, task_executor.clone());
-				debug!("{} Candidate validated: {:?}", process::id(), result);
+				debug!(target: LOG_TARGET, "{} Candidate validated: {:?}", process::id(), result);
 
 				match result {
 					Ok(r) => ValidationResultHeader::Ok(r),
@@ -196,7 +198,7 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> {
 			let mut data: &mut[u8] = &mut **slice;
 			result.encode_to(&mut data);
 		}
-		debug!("{} Signaling result", process::id());
+		debug!(target: LOG_TARGET, "{} Signaling result", process::id());
 		memory.set(Event::ResultReady as usize, EventState::Signaled)
 			.map_err(|e| format!("Error setting shared event: {:?}", e))?;
 	}
@@ -285,7 +287,13 @@ impl ValidationHost {
 
 		let memory = Self::create_memory()?;
 
-		debug!("Starting worker at {:?} with arguments: {:?} and {:?}", cmd, args, memory.get_os_path());
+		debug!(
+			target: LOG_TARGET,
+			"Starting worker at {:?} with arguments: {:?} and {:?}",
+			cmd,
+			args,
+			memory.get_os_path(),
+		);
 		let worker = process::Command::new(cmd)
 			.args(args)
 			.arg(memory.get_os_path())
@@ -342,14 +350,14 @@ impl ValidationHost {
 			header.encode_to(&mut header_buf);
 		}
 
-		debug!("{} Signaling candidate", self.id);
+		debug!(target: LOG_TARGET, "{} Signaling candidate", self.id);
 		memory.set(Event::CandidateReady as usize, EventState::Signaled)
 			.map_err(|e| ValidationError::Internal(e.into()))?;
 
-		debug!("{} Waiting for results", self.id);
+		debug!(target: LOG_TARGET, "{} Waiting for results", self.id);
 		match memory.wait(Event::ResultReady as usize, shared_memory::Timeout::Sec(EXECUTION_TIMEOUT_SEC as usize)) {
 			Err(e) => {
-				debug!("Worker timeout: {:?}", e);
+				debug!(target: LOG_TARGET, "Worker timeout: {:?}", e);
 				if let Some(mut worker) = self.worker.take() {
 					worker.kill().ok();
 				}
@@ -359,7 +367,7 @@ impl ValidationHost {
 		}
 
 		{
-			debug!("{} Reading results", self.id);
+			debug!(target: LOG_TARGET, "{} Reading results", self.id);
 			let data: &[u8] = &**memory.wlock_as_slice(0)
 				.map_err(|e| ValidationError::Internal(e.into()))?;
 			let (header_buf, _) = data.split_at(MAX_VALIDATION_RESULT_HEADER_MEM);
@@ -375,11 +383,11 @@ impl ValidationHost {
 			match header {
 				ValidationResultHeader::Ok(result) => Ok(result),
 				ValidationResultHeader::Error(WorkerValidationError::InternalError(e)) => {
-					debug!("{} Internal validation error: {}", self.id, e);
+					debug!(target: LOG_TARGET, "{} Internal validation error: {}", self.id, e);
 					Err(ValidationError::Internal(InternalError::WasmWorker(e)))
 				},
 				ValidationResultHeader::Error(WorkerValidationError::ValidationError(e)) => {
-					debug!("{} External validation error: {}", self.id, e);
+					debug!(target: LOG_TARGET, "{} External validation error: {}", self.id, e);
 					Err(ValidationError::InvalidCandidate(InvalidCandidate::ExternalWasmExecutor(e)))
 				}
 			}