diff --git a/polkadot/node/core/backing/src/lib.rs b/polkadot/node/core/backing/src/lib.rs index e915d75e0e..0a33a01327 100644 --- a/polkadot/node/core/backing/src/lib.rs +++ b/polkadot/node/core/backing/src/lib.rs @@ -386,7 +386,7 @@ struct BackgroundValidationParams { } async fn validate_and_make_available( - params: BackgroundValidationParams ValidatedCandidateCommand>, + params: BackgroundValidationParams 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, 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) diff --git a/polkadot/node/network/collator-protocol/src/validator_side.rs b/polkadot/node/network/collator-protocol/src/validator_side.rs index 561dda7d74..23fde5c75c 100644 --- a/polkadot/node/network/collator-protocol/src/validator_side.rs +++ b/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) => { diff --git a/polkadot/parachain/src/wasm_executor/validation_host.rs b/polkadot/parachain/src/wasm_executor/validation_host.rs index d49f82b6bd..79de685199 100644 --- a/polkadot/parachain/src/wasm_executor/validation_host.rs +++ b/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))) } }