From b748c8a13096a7637ffbfa71262cd31bf1cc61c8 Mon Sep 17 00:00:00 2001 From: Jan Bujak Date: Fri, 8 Apr 2022 05:45:44 +0000 Subject: [PATCH 1/4] Print out original the runtime API error --- node/subsystem-types/src/errors.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/node/subsystem-types/src/errors.rs b/node/subsystem-types/src/errors.rs index 14febb2d7db4..306b326e053e 100644 --- a/node/subsystem-types/src/errors.rs +++ b/node/subsystem-types/src/errors.rs @@ -21,8 +21,8 @@ use crate::JaegerError; /// A description of an error causing the runtime API request to be unservable. #[derive(thiserror::Error, Debug, Clone)] pub enum RuntimeApiError { - /// The runtime API cannot be executed due to a - #[error("The runtime API '{runtime_api_name}' cannot be executed")] + /// The runtime API cannot be executed due to a runtime error. + #[error("The runtime API '{runtime_api_name}' cannot be executed: {source}")] Execution { /// The runtime API being called runtime_api_name: &'static str, From 9d625e11a87ef53b634b3ed6ab9dec3a74d1da12 Mon Sep 17 00:00:00 2001 From: Jan Bujak Date: Fri, 8 Apr 2022 05:46:04 +0000 Subject: [PATCH 2/4] Improved error handling in approval voting block import --- Cargo.lock | 1 + node/core/approval-voting/Cargo.toml | 1 + node/core/approval-voting/src/import.rs | 78 ++++++++++++++++--------- 3 files changed, 54 insertions(+), 26 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index d46733dacddc..9c02454c8391 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6682,6 +6682,7 @@ dependencies = [ "sp-keyring", "sp-keystore", "sp-runtime", + "thiserror", "tracing-gum", ] diff --git a/node/core/approval-voting/Cargo.toml b/node/core/approval-voting/Cargo.toml index d4d8b46a272d..622a019da248 100644 --- a/node/core/approval-voting/Cargo.toml +++ b/node/core/approval-voting/Cargo.toml @@ -15,6 +15,7 @@ merlin = "2.0" schnorrkel = "0.9.1" kvdb = "0.11.0" derive_more = "0.99.17" +thiserror = "1.0.30" polkadot-node-subsystem = { path = "../../subsystem" } polkadot-node-subsystem-util = { path = "../../subsystem-util" } diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 7bfddb278744..656d84882af3 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -38,7 +38,7 @@ use polkadot_node_subsystem::{ ApprovalDistributionMessage, ChainApiMessage, ChainSelectionMessage, RuntimeApiMessage, RuntimeApiRequest, }, - overseer, SubsystemContext, SubsystemError, SubsystemResult, + overseer, RuntimeApiError, SubsystemContext, SubsystemError, SubsystemResult, }; use polkadot_node_subsystem_util::{ determine_new_blocks, @@ -66,6 +66,7 @@ use crate::{ use super::{State, LOG_TARGET}; +#[derive(Debug)] struct ImportedBlockInfo { included_candidates: Vec<(CandidateHash, CandidateReceipt, CoreIndex, GroupIndex)>, session_index: SessionIndex, @@ -82,6 +83,29 @@ struct ImportedBlockInfoEnv<'a> { keystore: &'a LocalKeystore, } +#[derive(Debug, thiserror::Error)] +enum ImportedBlockInfoError { + // NOTE: The `RuntimeApiError` already prints out which request it was, + // so it's not necessary to include that here. + #[error(transparent)] + RuntimeError(RuntimeApiError), + + #[error("future cancalled while requesting {0}")] + FutureCancelled(&'static str, futures::channel::oneshot::Canceled), + + #[error(transparent)] + ApprovalError(approval_types::ApprovalError), + + #[error("block is from an ancient session")] + BlockFromAncientSession, + + #[error("session info unavailable")] + SessionInfoUnavailable, + + #[error("VRF info unavailable")] + VrfInfoUnavailable, +} + // Computes information about the imported block. Returns `None` if the info couldn't be extracted - // failure to communicate with overseer, async fn imported_block_info( @@ -89,7 +113,7 @@ async fn imported_block_info( env: ImportedBlockInfoEnv<'_>, block_hash: Hash, block_header: &Header, -) -> SubsystemResult> { +) -> Result { // Ignore any runtime API errors - that means these blocks are old and finalized. // Only unfinalized blocks factor into the approval voting process. @@ -104,8 +128,9 @@ async fn imported_block_info( let events: Vec = match c_rx.await { Ok(Ok(events)) => events, - Ok(Err(_)) => return Ok(None), - Err(_) => return Ok(None), + Ok(Err(error)) => return Err(ImportedBlockInfoError::RuntimeError(error)), + Err(error) => + return Err(ImportedBlockInfoError::FutureCancelled("CandidateEvents", error)), }; events @@ -130,8 +155,9 @@ async fn imported_block_info( let session_index = match s_rx.await { Ok(Ok(s)) => s, - Ok(Err(_)) => return Ok(None), - Err(_) => return Ok(None), + Ok(Err(error)) => return Err(ImportedBlockInfoError::RuntimeError(error)), + Err(error) => + return Err(ImportedBlockInfoError::FutureCancelled("SessionIndexForChild", error)), }; if env @@ -146,7 +172,7 @@ async fn imported_block_info( session_index ); - return Ok(None) + return Err(ImportedBlockInfoError::BlockFromAncientSession) } session_index @@ -180,8 +206,9 @@ async fn imported_block_info( match s_rx.await { Ok(Ok(s)) => s, - Ok(Err(_)) => return Ok(None), - Err(_) => return Ok(None), + Ok(Err(error)) => return Err(ImportedBlockInfoError::RuntimeError(error)), + Err(error) => + return Err(ImportedBlockInfoError::FutureCancelled("CurrentBabeEpoch", error)), } }; @@ -191,7 +218,7 @@ async fn imported_block_info( None => { gum::debug!(target: LOG_TARGET, "Session info unavailable for block {}", block_hash,); - return Ok(None) + return Err(ImportedBlockInfoError::SessionInfoUnavailable) }, }; @@ -220,7 +247,7 @@ async fn imported_block_info( (assignments, slot, relay_vrf) }, - Err(_) => return Ok(None), + Err(error) => return Err(ImportedBlockInfoError::ApprovalError(error)), } }, None => { @@ -230,7 +257,7 @@ async fn imported_block_info( block_hash, ); - return Ok(None) + return Err(ImportedBlockInfoError::VrfInfoUnavailable) }, } }; @@ -264,7 +291,7 @@ async fn imported_block_info( }, }); - Ok(Some(ImportedBlockInfo { + Ok(ImportedBlockInfo { included_candidates, session_index, assignments, @@ -272,7 +299,7 @@ async fn imported_block_info( relay_vrf_story, slot, force_approve, - })) + }) } /// Information about a block and imported candidates. @@ -382,9 +409,9 @@ pub(crate) async fn handle_new_head( keystore: &state.keystore, }; - match imported_block_info(ctx, env, block_hash, &block_header).await? { - Some(i) => imported_blocks_and_info.push((block_hash, block_header, i)), - None => { + match imported_block_info(ctx, env, block_hash, &block_header).await { + Ok(i) => imported_blocks_and_info.push((block_hash, block_header, i)), + Err(error) => { // It's possible that we've lost a race with finality. let (tx, rx) = oneshot::channel(); ctx.send_message(ChainApiMessage::FinalizedBlockHash( @@ -403,8 +430,9 @@ pub(crate) async fn handle_new_head( // in the approval-db. gum::warn!( target: LOG_TARGET, - "Unable to gather info about imported block {:?}. Skipping chain.", + "Skipping chain: unable to gather info about imported block {:?}: {}", (block_hash, block_header.number), + error, ); } @@ -757,8 +785,7 @@ pub(crate) mod tests { keystore: &LocalKeystore::in_memory(), }; - let info = - imported_block_info(&mut ctx, env, hash, &header).await.unwrap().unwrap(); + let info = imported_block_info(&mut ctx, env, hash, &header).await.unwrap(); assert_eq!(info.included_candidates, included_candidates); assert_eq!(info.session_index, session); @@ -866,9 +893,9 @@ pub(crate) mod tests { keystore: &LocalKeystore::in_memory(), }; - let info = imported_block_info(&mut ctx, env, hash, &header).await.unwrap(); + let info = imported_block_info(&mut ctx, env, hash, &header).await; - assert!(info.is_none()); + assert_matches!(info, Err(ImportedBlockInfoError::VrfInfoUnavailable)); }) }; @@ -964,9 +991,9 @@ pub(crate) mod tests { keystore: &LocalKeystore::in_memory(), }; - let info = imported_block_info(&mut ctx, env, hash, &header).await.unwrap(); + let info = imported_block_info(&mut ctx, env, hash, &header).await; - assert!(info.is_none()); + assert_matches!(info, Err(ImportedBlockInfoError::SessionInfoUnavailable)); }) }; @@ -1063,8 +1090,7 @@ pub(crate) mod tests { keystore: &LocalKeystore::in_memory(), }; - let info = - imported_block_info(&mut ctx, env, hash, &header).await.unwrap().unwrap(); + let info = imported_block_info(&mut ctx, env, hash, &header).await.unwrap(); assert_eq!(info.included_candidates, included_candidates); assert_eq!(info.session_index, session); From 8d5e0196c0bc357e588b2597d261f3c7e37a1b0b Mon Sep 17 00:00:00 2001 From: Jan Bujak Date: Fri, 8 Apr 2022 06:05:04 +0000 Subject: [PATCH 3/4] Fix test --- node/core/approval-voting/src/import.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 656d84882af3..9053426e8c53 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -993,7 +993,7 @@ pub(crate) mod tests { let info = imported_block_info(&mut ctx, env, hash, &header).await; - assert_matches!(info, Err(ImportedBlockInfoError::SessionInfoUnavailable)); + assert_matches!(info, Err(ImportedBlockInfoError::BlockFromAncientSession)); }) }; From d3d392c60452975d17928d002791b4e23e195583 Mon Sep 17 00:00:00 2001 From: Jan Bujak Date: Fri, 8 Apr 2022 06:13:33 +0000 Subject: [PATCH 4/4] Update comment --- node/core/approval-voting/src/import.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/node/core/approval-voting/src/import.rs b/node/core/approval-voting/src/import.rs index 9053426e8c53..d023dffe78c9 100644 --- a/node/core/approval-voting/src/import.rs +++ b/node/core/approval-voting/src/import.rs @@ -106,8 +106,7 @@ enum ImportedBlockInfoError { VrfInfoUnavailable, } -// Computes information about the imported block. Returns `None` if the info couldn't be extracted - -// failure to communicate with overseer, +/// Computes information about the imported block. Returns an error if the info couldn't be extracted. async fn imported_block_info( ctx: &mut (impl SubsystemContext + overseer::SubsystemContext), env: ImportedBlockInfoEnv<'_>,