Unverified Commit 33301e77 authored by Bastian Köcher's avatar Bastian Köcher Committed by GitHub
Browse files

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
parent 96a2d293
Pipeline #120588 passed with stages
in 22 minutes and 47 seconds
...@@ -386,7 +386,7 @@ struct BackgroundValidationParams<F> { ...@@ -386,7 +386,7 @@ struct BackgroundValidationParams<F> {
} }
async fn validate_and_make_available( async fn validate_and_make_available(
params: BackgroundValidationParams<impl Fn(BackgroundValidationResult) -> ValidatedCandidateCommand>, params: BackgroundValidationParams<impl Fn(BackgroundValidationResult) -> ValidatedCandidateCommand + Sync>,
) -> Result<(), Error> { ) -> Result<(), Error> {
let BackgroundValidationParams { let BackgroundValidationParams {
mut tx_from, mut tx_from,
...@@ -421,11 +421,17 @@ async fn validate_and_make_available( ...@@ -421,11 +421,17 @@ async fn validate_and_make_available(
let res = match v { let res = match v {
ValidationResult::Valid(commitments, validation_data) => { 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 validation produces a new set of commitments, we vote the candidate as invalid.
if commitments.hash() != expected_commitments_hash { if commitments.hash() != expected_commitments_hash {
tracing::trace!( tracing::debug!(
target: LOG_TARGET, target: LOG_TARGET,
candidate_receipt = ?candidate, candidate_hash = ?candidate.hash(),
actual_commitments = ?commitments, actual_commitments = ?commitments,
"Commitments obtained with validation don't match the announced by the candidate receipt", "Commitments obtained with validation don't match the announced by the candidate receipt",
); );
...@@ -445,9 +451,9 @@ async fn validate_and_make_available( ...@@ -445,9 +451,9 @@ async fn validate_and_make_available(
match erasure_valid { match erasure_valid {
Ok(()) => Ok((candidate, commitments, pov.clone())), Ok(()) => Ok((candidate, commitments, pov.clone())),
Err(InvalidErasureRoot) => { Err(InvalidErasureRoot) => {
tracing::trace!( tracing::debug!(
target: LOG_TARGET, target: LOG_TARGET,
candidate_receipt = ?candidate, candidate_hash = ?candidate.hash(),
actual_commitments = ?commitments, actual_commitments = ?commitments,
"Erasure root doesn't match the announced by the candidate receipt", "Erasure root doesn't match the announced by the candidate receipt",
); );
...@@ -457,9 +463,9 @@ async fn validate_and_make_available( ...@@ -457,9 +463,9 @@ async fn validate_and_make_available(
} }
} }
ValidationResult::Invalid(reason) => { ValidationResult::Invalid(reason) => {
tracing::trace!( tracing::debug!(
target: LOG_TARGET, target: LOG_TARGET,
candidate_receipt = ?candidate, candidate_hash = ?candidate.hash(),
reason = ?reason, reason = ?reason,
"Validation yielded an invalid candidate", "Validation yielded an invalid candidate",
); );
...@@ -467,9 +473,7 @@ async fn validate_and_make_available( ...@@ -467,9 +473,7 @@ async fn validate_and_make_available(
} }
}; };
let command = make_command(res); tx_command.send(make_command(res)).await.map_err(Into::into)
tx_command.send(command).await?;
Ok(())
} }
impl CandidateBackingJob { impl CandidateBackingJob {
...@@ -558,7 +562,7 @@ impl CandidateBackingJob { ...@@ -558,7 +562,7 @@ impl CandidateBackingJob {
async fn background_validate_and_make_available( async fn background_validate_and_make_available(
&mut self, &mut self,
params: BackgroundValidationParams< params: BackgroundValidationParams<
impl Fn(BackgroundValidationResult) -> ValidatedCandidateCommand + Send + 'static impl Fn(BackgroundValidationResult) -> ValidatedCandidateCommand + Send + 'static + Sync
>, >,
) -> Result<(), Error> { ) -> Result<(), Error> {
let candidate_hash = params.candidate.hash(); let candidate_hash = params.candidate.hash();
...@@ -604,6 +608,13 @@ impl CandidateBackingJob { ...@@ -604,6 +608,13 @@ impl CandidateBackingJob {
let candidate_hash = candidate.hash(); let candidate_hash = candidate.hash();
let span = self.get_unbacked_validation_child(parent_span, 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 { self.background_validate_and_make_available(BackgroundValidationParams {
tx_from: self.tx_from.clone(), tx_from: self.tx_from.clone(),
tx_command: self.background_validation_tx.clone(), tx_command: self.background_validation_tx.clone(),
...@@ -675,6 +686,12 @@ impl CandidateBackingJob { ...@@ -675,6 +686,12 @@ impl CandidateBackingJob {
statement: &SignedFullStatement, statement: &SignedFullStatement,
parent_span: &JaegerSpan, parent_span: &JaegerSpan,
) -> Result<Option<TableSummary>, Error> { ) -> Result<Option<TableSummary>, Error> {
tracing::debug!(
target: LOG_TARGET,
statement = ?statement.payload().to_compact(),
"Importing statement",
);
let import_statement_span = { let import_statement_span = {
// create a span only for candidates we're already aware of. // create a span only for candidates we're already aware of.
let candidate_hash = statement.payload().candidate_hash(); let candidate_hash = statement.payload().candidate_hash();
...@@ -696,6 +713,12 @@ impl CandidateBackingJob { ...@@ -696,6 +713,12 @@ impl CandidateBackingJob {
if let Some(backed) = if let Some(backed) =
table_attested_to_backed(attested, &self.table_context) table_attested_to_backed(attested, &self.table_context)
{ {
tracing::debug!(
target: LOG_TARGET,
candidate_hash = ?candidate_hash,
"Candidate backed",
);
let message = ProvisionerMessage::ProvisionableData( let message = ProvisionerMessage::ProvisionableData(
self.parent, self.parent,
ProvisionableData::BackedCandidate(backed.receipt()), ProvisionableData::BackedCandidate(backed.receipt()),
...@@ -794,6 +817,13 @@ impl CandidateBackingJob { ...@@ -794,6 +817,13 @@ impl CandidateBackingJob {
let candidate = self.table.get_candidate(&candidate_hash).ok_or(Error::CandidateNotFound)?.to_plain(); let candidate = self.table.get_candidate(&candidate_hash).ok_or(Error::CandidateNotFound)?.to_plain();
let descriptor = candidate.descriptor().clone(); 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. // Check that candidate is collated by the right collator.
if self.required_collator.as_ref() if self.required_collator.as_ref()
.map_or(false, |c| c != &descriptor.collator) .map_or(false, |c| c != &descriptor.collator)
......
...@@ -368,6 +368,12 @@ where ...@@ -368,6 +368,12 @@ where
if let Some(per_request) = state.requests_info.remove(&id) { if let Some(per_request) = state.requests_info.remove(&id) {
let _ = per_request.received.send(()); let _ = per_request.received.send(());
if let Some(collator_id) = state.known_collators.get(&origin) { 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())); let _ = per_request.result.send((receipt.clone(), pov.clone()));
state.metrics.on_request(Ok(())); state.metrics.on_request(Ok(()));
...@@ -420,8 +426,8 @@ where ...@@ -420,8 +426,8 @@ where
tracing::trace!( tracing::trace!(
target: LOG_TARGET, target: LOG_TARGET,
peer_id = %peer_id, peer_id = %peer_id,
para_id = %para_id, %para_id,
relay_parent = %relay_parent, ?relay_parent,
"collation has already been requested", "collation has already been requested",
); );
return; return;
...@@ -449,6 +455,15 @@ where ...@@ -449,6 +455,15 @@ where
state.requests_in_progress.push(request.wait().boxed()); 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( let wire_message = protocol_v1::CollatorProtocolMessage::RequestCollation(
request_id, request_id,
relay_parent, relay_parent,
...@@ -737,7 +752,7 @@ where ...@@ -737,7 +752,7 @@ where
// if the chain has not moved on yet. // if the chain has not moved on yet.
match request { match request {
CollationRequestResult::Timeout(id) => { 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; request_timed_out(&mut ctx, &mut state, id).await;
} }
CollationRequestResult::Received(id) => { CollationRequestResult::Received(id) => {
......
...@@ -33,6 +33,8 @@ const WORKER_ARG: &'static str = "validation-worker"; ...@@ -33,6 +33,8 @@ const WORKER_ARG: &'static str = "validation-worker";
/// CLI Argument to start in validation worker mode. /// CLI Argument to start in validation worker mode.
pub const WORKER_ARGS: &[&'static str] = &[WORKER_ARG]; pub const WORKER_ARGS: &[&'static str] = &[WORKER_ARG];
const LOG_TARGET: &'static str = "validation-worker";
/// Execution timeout in seconds; /// Execution timeout in seconds;
#[cfg(debug_assertions)] #[cfg(debug_assertions)]
pub const EXECUTION_TIMEOUT_SEC: u64 = 30; pub const EXECUTION_TIMEOUT_SEC: u64 = 30;
...@@ -128,7 +130,7 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> { ...@@ -128,7 +130,7 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> {
let mut memory = match SharedMem::open(mem_id) { let mut memory = match SharedMem::open(mem_id) {
Ok(memory) => memory, Ok(memory) => memory,
Err(e) => { 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)); return Err(format!("Error opening shared memory: {:?}", e));
} }
}; };
...@@ -142,7 +144,7 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> { ...@@ -142,7 +144,7 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> {
let mut in_data = Vec::new(); let mut in_data = Vec::new();
// pipe terminates when parent process exits // pipe terminates when parent process exits
std::io::stdin().read_to_end(&mut in_data).ok(); 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); exit.store(true, atomic::Ordering::Relaxed);
}); });
...@@ -154,18 +156,18 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> { ...@@ -154,18 +156,18 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> {
break; 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)) { match memory.wait(Event::CandidateReady as usize, shared_memory::Timeout::Sec(3)) {
Err(e) => { Err(e) => {
// Timeout // Timeout
trace!("{} Timeout waiting for candidate: {:?}", process::id(), e); trace!(target: LOG_TARGET, "{} Timeout waiting for candidate: {:?}", process::id(), e);
continue; continue;
} }
Ok(()) => {} Ok(()) => {}
} }
{ {
debug!("{} Processing candidate", process::id()); debug!(target: LOG_TARGET, "{} Processing candidate", process::id());
// we have candidate data // we have candidate data
let mut slice = memory.wlock_as_slice(0) let mut slice = memory.wlock_as_slice(0)
.map_err(|e| format!("Error locking shared memory: {:?}", e))?; .map_err(|e| format!("Error locking shared memory: {:?}", e))?;
...@@ -176,14 +178,14 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> { ...@@ -176,14 +178,14 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> {
let mut header_buf: &[u8] = header_buf; let mut header_buf: &[u8] = header_buf;
let header = ValidationHeader::decode(&mut header_buf) let header = ValidationHeader::decode(&mut header_buf)
.map_err(|_| format!("Error decoding validation request."))?; .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, rest) = rest.split_at_mut(MAX_CODE_MEM);
let (code, _) = code.split_at_mut(header.code_size as usize); let (code, _) = code.split_at_mut(header.code_size as usize);
let (call_data, _) = rest.split_at_mut(MAX_RUNTIME_MEM); let (call_data, _) = rest.split_at_mut(MAX_RUNTIME_MEM);
let (call_data, _) = call_data.split_at_mut(header.params_size as usize); let (call_data, _) = call_data.split_at_mut(header.params_size as usize);
let result = validate_candidate_internal(code, call_data, task_executor.clone()); 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 { match result {
Ok(r) => ValidationResultHeader::Ok(r), Ok(r) => ValidationResultHeader::Ok(r),
...@@ -196,7 +198,7 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> { ...@@ -196,7 +198,7 @@ pub fn run_worker(mem_id: &str) -> Result<(), String> {
let mut data: &mut[u8] = &mut **slice; let mut data: &mut[u8] = &mut **slice;
result.encode_to(&mut data); 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) memory.set(Event::ResultReady as usize, EventState::Signaled)
.map_err(|e| format!("Error setting shared event: {:?}", e))?; .map_err(|e| format!("Error setting shared event: {:?}", e))?;
} }
...@@ -285,7 +287,13 @@ impl ValidationHost { ...@@ -285,7 +287,13 @@ impl ValidationHost {
let memory = Self::create_memory()?; 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) let worker = process::Command::new(cmd)
.args(args) .args(args)
.arg(memory.get_os_path()) .arg(memory.get_os_path())
...@@ -342,14 +350,14 @@ impl ValidationHost { ...@@ -342,14 +350,14 @@ impl ValidationHost {
header.encode_to(&mut header_buf); 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) memory.set(Event::CandidateReady as usize, EventState::Signaled)
.map_err(|e| ValidationError::Internal(e.into()))?; .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)) { match memory.wait(Event::ResultReady as usize, shared_memory::Timeout::Sec(EXECUTION_TIMEOUT_SEC as usize)) {
Err(e) => { Err(e) => {
debug!("Worker timeout: {:?}", e); debug!(target: LOG_TARGET, "Worker timeout: {:?}", e);
if let Some(mut worker) = self.worker.take() { if let Some(mut worker) = self.worker.take() {
worker.kill().ok(); worker.kill().ok();
} }
...@@ -359,7 +367,7 @@ impl ValidationHost { ...@@ -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) let data: &[u8] = &**memory.wlock_as_slice(0)
.map_err(|e| ValidationError::Internal(e.into()))?; .map_err(|e| ValidationError::Internal(e.into()))?;
let (header_buf, _) = data.split_at(MAX_VALIDATION_RESULT_HEADER_MEM); let (header_buf, _) = data.split_at(MAX_VALIDATION_RESULT_HEADER_MEM);
...@@ -375,11 +383,11 @@ impl ValidationHost { ...@@ -375,11 +383,11 @@ impl ValidationHost {
match header { match header {
ValidationResultHeader::Ok(result) => Ok(result), ValidationResultHeader::Ok(result) => Ok(result),
ValidationResultHeader::Error(WorkerValidationError::InternalError(e)) => { 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))) Err(ValidationError::Internal(InternalError::WasmWorker(e)))
}, },
ValidationResultHeader::Error(WorkerValidationError::ValidationError(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))) Err(ValidationError::InvalidCandidate(InvalidCandidate::ExternalWasmExecutor(e)))
} }
} }
......
Supports Markdown
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment