From 93e42fb2138093cbee419b00a5a9964243813c75 Mon Sep 17 00:00:00 2001 From: Andronik Ordian <write@reusable.software> Date: Sun, 13 Jun 2021 17:34:05 +0200 Subject: [PATCH] approval votes checking logs (#3233) * approval-voting: logs for invalid votes * proper errors for assignment checks * proper errors for approval checks --- polkadot/node/core/approval-voting/src/lib.rs | 88 ++++++++++++------- .../node/core/approval-voting/src/tests.rs | 15 ++-- .../network/approval-distribution/src/lib.rs | 21 ++++- .../approval-distribution/src/tests.rs | 3 +- polkadot/node/subsystem/src/messages.rs | 48 +++++++++- .../src/types/overseer-protocol.md | 24 ++++- 6 files changed, 149 insertions(+), 50 deletions(-) diff --git a/polkadot/node/core/approval-voting/src/lib.rs b/polkadot/node/core/approval-voting/src/lib.rs index 67cdec11a37..029f21cec59 100644 --- a/polkadot/node/core/approval-voting/src/lib.rs +++ b/polkadot/node/core/approval-voting/src/lib.rs @@ -23,9 +23,10 @@ use polkadot_node_subsystem::{ messages::{ - AssignmentCheckResult, ApprovalCheckResult, ApprovalVotingMessage, - RuntimeApiMessage, RuntimeApiRequest, ChainApiMessage, ApprovalDistributionMessage, - ValidationFailed, CandidateValidationMessage, AvailabilityRecoveryMessage, + AssignmentCheckError, AssignmentCheckResult, ApprovalCheckError, ApprovalCheckResult, + ApprovalVotingMessage, RuntimeApiMessage, RuntimeApiRequest, ChainApiMessage, + ApprovalDistributionMessage, ValidationFailed, CandidateValidationMessage, + AvailabilityRecoveryMessage, }, errors::RecoveryError, Subsystem, SubsystemContext, SubsystemError, SubsystemResult, SpawnedSubsystem, @@ -1334,14 +1335,17 @@ fn check_and_import_assignment( let tick_now = state.clock.tick_now(); let block_entry = match state.db.load_block_entry(&assignment.block_hash)? { Some(b) => b, - None => return Ok((AssignmentCheckResult::Bad, Vec::new())), + None => return Ok((AssignmentCheckResult::Bad( + AssignmentCheckError::UnknownBlock(assignment.block_hash), + ), Vec::new())), }; let session_info = match state.session_info(block_entry.session()) { Some(s) => s, None => { - tracing::warn!(target: LOG_TARGET, "Unknown session info for {}", block_entry.session()); - return Ok((AssignmentCheckResult::Bad, Vec::new())); + return Ok((AssignmentCheckResult::Bad( + AssignmentCheckError::UnknownSessionIndex(block_entry.session()), + ), Vec::new())); } }; @@ -1349,20 +1353,17 @@ fn check_and_import_assignment( = match block_entry.candidate(candidate_index as usize) { Some((c, h)) => (*c, *h), - None => return Ok((AssignmentCheckResult::Bad, Vec::new())), // no candidate at core. + None => return Ok((AssignmentCheckResult::Bad( + AssignmentCheckError::InvalidCandidateIndex(candidate_index), + ), Vec::new())), // no candidate at core. }; let mut candidate_entry = match state.db.load_candidate_entry(&assigned_candidate_hash)? { Some(c) => c, None => { - tracing::warn!( - target: LOG_TARGET, - "Missing candidate entry {} referenced in live block {}", - assigned_candidate_hash, - assignment.block_hash, - ); - - return Ok((AssignmentCheckResult::Bad, Vec::new())); + return Ok((AssignmentCheckResult::Bad( + AssignmentCheckError::InvalidCandidate(candidate_index, assigned_candidate_hash), + ), Vec::new())); } }; @@ -1372,7 +1373,9 @@ fn check_and_import_assignment( candidate_entry.approval_entry_mut(&assignment.block_hash) { Some(a) => a, - None => return Ok((AssignmentCheckResult::Bad, Vec::new())), + None => return Ok((AssignmentCheckResult::Bad( + AssignmentCheckError::Internal(assignment.block_hash, assigned_candidate_hash), + ), Vec::new())), }; let res = state.assignment_criteria.check_assignment_cert( @@ -1385,7 +1388,9 @@ fn check_and_import_assignment( ); let tranche = match res { - Err(crate::criteria::InvalidAssignment) => return Ok((AssignmentCheckResult::Bad, Vec::new())), + Err(crate::criteria::InvalidAssignment) => return Ok((AssignmentCheckResult::Bad( + AssignmentCheckError::InvalidCert(assignment.validator), + ), Vec::new())), Ok(tranche) => { let current_tranche = state.clock.tranche_now( state.slot_duration_millis, @@ -1455,20 +1460,27 @@ fn check_and_import_approval<T>( let block_entry = match state.db.load_block_entry(&approval.block_hash)? { Some(b) => b, - None => respond_early!(ApprovalCheckResult::Bad) + None => { + respond_early!(ApprovalCheckResult::Bad( + ApprovalCheckError::UnknownBlock(approval.block_hash), + )) + } }; let session_info = match state.session_info(block_entry.session()) { Some(s) => s, None => { - tracing::warn!(target: LOG_TARGET, "Unknown session info for {}", block_entry.session()); - respond_early!(ApprovalCheckResult::Bad) + respond_early!(ApprovalCheckResult::Bad( + ApprovalCheckError::UnknownSessionIndex(block_entry.session()), + )) } }; let approved_candidate_hash = match block_entry.candidate(approval.candidate_index as usize) { Some((_, h)) => *h, - None => respond_early!(ApprovalCheckResult::Bad) + None => respond_early!(ApprovalCheckResult::Bad( + ApprovalCheckError::InvalidCandidateIndex(approval.candidate_index), + )) }; let approval_payload = ApprovalVote(approved_candidate_hash) @@ -1476,33 +1488,41 @@ fn check_and_import_approval<T>( let pubkey = match session_info.validators.get(approval.validator.0 as usize) { Some(k) => k, - None => respond_early!(ApprovalCheckResult::Bad) + None => respond_early!(ApprovalCheckResult::Bad( + ApprovalCheckError::InvalidValidatorIndex(approval.validator), + )) }; let approval_sig_valid = approval.signature.verify(approval_payload.as_slice(), pubkey); if !approval_sig_valid { - respond_early!(ApprovalCheckResult::Bad) + respond_early!(ApprovalCheckResult::Bad( + ApprovalCheckError::InvalidSignature(approval.validator), + )) } let candidate_entry = match state.db.load_candidate_entry(&approved_candidate_hash)? { Some(c) => c, None => { - tracing::warn!( - target: LOG_TARGET, - "Unknown candidate entry for {}", - approved_candidate_hash, - ); - - respond_early!(ApprovalCheckResult::Bad) + respond_early!(ApprovalCheckResult::Bad( + ApprovalCheckError::InvalidCandidate(approval.candidate_index, approved_candidate_hash), + )) } }; // Don't accept approvals until assignment. - if candidate_entry.approval_entry(&approval.block_hash) - .map_or(true, |e| !e.is_assigned(approval.validator)) - { - respond_early!(ApprovalCheckResult::Bad) + match candidate_entry.approval_entry(&approval.block_hash) { + None => { + respond_early!(ApprovalCheckResult::Bad( + ApprovalCheckError::Internal(approval.block_hash, approved_candidate_hash), + )) + } + Some(e) if !e.is_assigned(approval.validator) => { + respond_early!(ApprovalCheckResult::Bad( + ApprovalCheckError::NoAssignment(approval.validator), + )) + } + _ => {}, } // importing the approval can be heavy as it may trigger acceptance for a series of blocks. diff --git a/polkadot/node/core/approval-voting/src/tests.rs b/polkadot/node/core/approval-voting/src/tests.rs index 1dc20e3962c..5603c362fd2 100644 --- a/polkadot/node/core/approval-voting/src/tests.rs +++ b/polkadot/node/core/approval-voting/src/tests.rs @@ -397,8 +397,9 @@ fn rejects_bad_assignment() { assert!(res.1.iter().any(|action| matches!(action, Action::WriteCandidateEntry(..)))); // unknown hash + let unknown_hash = Hash::repeat_byte(0x02); let assignment = IndirectAssignmentCert { - block_hash: Hash::repeat_byte(0x02), + block_hash: unknown_hash, validator: ValidatorIndex(0), cert: garbage_assignment_cert( AssignmentCertKind::RelayVRFModulo { @@ -412,7 +413,7 @@ fn rejects_bad_assignment() { assignment, candidate_index, ).unwrap(); - assert_eq!(res.0, AssignmentCheckResult::Bad); + assert_eq!(res.0, AssignmentCheckResult::Bad(AssignmentCheckError::UnknownBlock(unknown_hash))); let mut state = State { assignment_criteria: Box::new(MockAssignmentCriteria::check_only(|| { @@ -427,7 +428,7 @@ fn rejects_bad_assignment() { assignment_good, candidate_index, ).unwrap(); - assert_eq!(res.0, AssignmentCheckResult::Bad); + assert_eq!(res.0, AssignmentCheckResult::Bad(AssignmentCheckError::InvalidCert(ValidatorIndex(0)))); } #[test] @@ -495,7 +496,7 @@ fn rejects_assignment_with_unknown_candidate() { assignment.clone(), candidate_index, ).unwrap(); - assert_eq!(res.0, AssignmentCheckResult::Bad); + assert_eq!(res.0, AssignmentCheckResult::Bad(AssignmentCheckError::InvalidCandidateIndex(candidate_index))); } #[test] @@ -579,7 +580,7 @@ fn rejects_approval_before_assignment() { |r| r ).unwrap(); - assert_eq!(res, ApprovalCheckResult::Bad); + assert_eq!(res, ApprovalCheckResult::Bad(ApprovalCheckError::NoAssignment(ValidatorIndex(0)))); assert!(actions.is_empty()); } @@ -611,7 +612,7 @@ fn rejects_approval_if_no_candidate_entry() { |r| r ).unwrap(); - assert_eq!(res, ApprovalCheckResult::Bad); + assert_eq!(res, ApprovalCheckResult::Bad(ApprovalCheckError::InvalidCandidate(0, candidate_hash))); assert!(actions.is_empty()); } @@ -649,7 +650,7 @@ fn rejects_approval_if_no_block_entry() { |r| r ).unwrap(); - assert_eq!(res, ApprovalCheckResult::Bad); + assert_eq!(res, ApprovalCheckResult::Bad(ApprovalCheckError::UnknownBlock(block_hash))); assert!(actions.is_empty()); } diff --git a/polkadot/node/network/approval-distribution/src/lib.rs b/polkadot/node/network/approval-distribution/src/lib.rs index 04cc835e219..52be6b9b4b4 100644 --- a/polkadot/node/network/approval-distribution/src/lib.rs +++ b/polkadot/node/network/approval-distribution/src/lib.rs @@ -624,13 +624,29 @@ impl State { if let Some(peer_knowledge) = entry.known_by.get_mut(&peer_id) { peer_knowledge.received.insert(fingerprint); } + tracing::debug!( + target: LOG_TARGET, + ?peer_id, + "Got an `AcceptedDuplicate` assignment", + ); return; } AssignmentCheckResult::TooFarInFuture => { + tracing::debug!( + target: LOG_TARGET, + ?peer_id, + "Got an assignment too far in the future", + ); modify_reputation(ctx, peer_id, COST_ASSIGNMENT_TOO_FAR_IN_THE_FUTURE).await; return; } - AssignmentCheckResult::Bad => { + AssignmentCheckResult::Bad(error) => { + tracing::info!( + target: LOG_TARGET, + ?peer_id, + %error, + "Got a bad assignment from peer", + ); modify_reputation(ctx, peer_id, COST_INVALID_MESSAGE).await; return; } @@ -844,11 +860,12 @@ impl State { peer_knowledge.received.insert(fingerprint.clone()); } } - ApprovalCheckResult::Bad => { + ApprovalCheckResult::Bad(error) => { modify_reputation(ctx, peer_id, COST_INVALID_MESSAGE).await; tracing::info!( target: LOG_TARGET, ?peer_id, + %error, "Got a bad approval from peer", ); return; diff --git a/polkadot/node/network/approval-distribution/src/tests.rs b/polkadot/node/network/approval-distribution/src/tests.rs index 47a444fc779..675761ef14b 100644 --- a/polkadot/node/network/approval-distribution/src/tests.rs +++ b/polkadot/node/network/approval-distribution/src/tests.rs @@ -17,6 +17,7 @@ use std::time::Duration; use futures::{future, Future, executor}; use assert_matches::assert_matches; +use polkadot_node_subsystem::messages::ApprovalCheckError; use polkadot_node_subsystem_test_helpers as test_helpers; use polkadot_node_subsystem_util::TimeoutExt as _; use polkadot_node_network_protocol::{view, ObservedRole}; @@ -594,7 +595,7 @@ fn import_approval_bad() { tx, )) => { assert_eq!(vote, approval); - tx.send(ApprovalCheckResult::Bad).unwrap(); + tx.send(ApprovalCheckResult::Bad(ApprovalCheckError::UnknownBlock(hash))).unwrap(); } ); diff --git a/polkadot/node/subsystem/src/messages.rs b/polkadot/node/subsystem/src/messages.rs index 05833d1e673..cf5e75d7c54 100644 --- a/polkadot/node/subsystem/src/messages.rs +++ b/polkadot/node/subsystem/src/messages.rs @@ -646,7 +646,7 @@ impl CollationGenerationMessage { } /// The result type of [`ApprovalVotingMessage::CheckAndImportAssignment`] request. -#[derive(Debug, Clone, Copy, PartialEq, Eq)] +#[derive(Debug, Clone, PartialEq, Eq)] pub enum AssignmentCheckResult { /// The vote was accepted and should be propagated onwards. Accepted, @@ -655,16 +655,56 @@ pub enum AssignmentCheckResult { /// The vote was valid but too far in the future to accept right now. TooFarInFuture, /// The vote was bad and should be ignored, reporting the peer who propagated it. - Bad, + Bad(AssignmentCheckError), +} + +/// The error result type of [`ApprovalVotingMessage::CheckAndImportAssignment`] request. +#[derive(Error, Debug, Clone, PartialEq, Eq)] +#[allow(missing_docs)] +pub enum AssignmentCheckError { + #[error("Unknown block: {0:?}")] + UnknownBlock(Hash), + #[error("Unknown session index: {0}")] + UnknownSessionIndex(SessionIndex), + #[error("Invalid candidate index: {0}")] + InvalidCandidateIndex(CandidateIndex), + #[error("Invalid candidate {0}: {1:?}")] + InvalidCandidate(CandidateIndex, CandidateHash), + #[error("Invalid cert: {0:?}")] + InvalidCert(ValidatorIndex), + #[error("Internal state mismatch: {0:?}, {1:?}")] + Internal(Hash, CandidateHash), } /// The result type of [`ApprovalVotingMessage::CheckAndImportApproval`] request. -#[derive(Debug, Clone, Copy, PartialEq, Eq)] +#[derive(Debug, Clone, PartialEq, Eq)] pub enum ApprovalCheckResult { /// The vote was accepted and should be propagated onwards. Accepted, /// The vote was bad and should be ignored, reporting the peer who propagated it. - Bad, + Bad(ApprovalCheckError) +} + +/// The error result type of [`ApprovalVotingMessage::CheckAndImportApproval`] request. +#[derive(Error, Debug, Clone, PartialEq, Eq)] +#[allow(missing_docs)] +pub enum ApprovalCheckError { + #[error("Unknown block: {0:?}")] + UnknownBlock(Hash), + #[error("Unknown session index: {0}")] + UnknownSessionIndex(SessionIndex), + #[error("Invalid candidate index: {0}")] + InvalidCandidateIndex(CandidateIndex), + #[error("Invalid validator index: {0:?}")] + InvalidValidatorIndex(ValidatorIndex), + #[error("Invalid candidate {0}: {1:?}")] + InvalidCandidate(CandidateIndex, CandidateHash), + #[error("Invalid signature: {0:?}")] + InvalidSignature(ValidatorIndex), + #[error("No assignment for {0:?}")] + NoAssignment(ValidatorIndex), + #[error("Internal state mismatch: {0:?}, {1:?}")] + Internal(Hash, CandidateHash), } /// Message to the Approval Voting subsystem. diff --git a/polkadot/roadmap/implementers-guide/src/types/overseer-protocol.md b/polkadot/roadmap/implementers-guide/src/types/overseer-protocol.md index 88f9deb4088..84dd8f7474e 100644 --- a/polkadot/roadmap/implementers-guide/src/types/overseer-protocol.md +++ b/polkadot/roadmap/implementers-guide/src/types/overseer-protocol.md @@ -58,14 +58,34 @@ enum AssignmentCheckResult { // The vote was valid but too far in the future to accept right now. TooFarInFuture, // The vote was bad and should be ignored, reporting the peer who propagated it. - Bad, + Bad(AssignmentCheckError), +} + +pub enum AssignmentCheckError { + UnknownBlock(Hash), + UnknownSessionIndex(SessionIndex), + InvalidCandidateIndex(CandidateIndex), + InvalidCandidate(CandidateIndex, CandidateHash), + InvalidCert(ValidatorIndex), + Internal(Hash, CandidateHash), } enum ApprovalCheckResult { // The vote was accepted and should be propagated onwards. Accepted, // The vote was bad and should be ignored, reporting the peer who propagated it. - Bad, + Bad(ApprovalCheckError), +} + +pub enum ApprovalCheckError { + UnknownBlock(Hash), + UnknownSessionIndex(SessionIndex), + InvalidCandidateIndex(CandidateIndex), + InvalidValidatorIndex(ValidatorIndex), + InvalidCandidate(CandidateIndex, CandidateHash), + InvalidSignature(ValidatorIndex), + NoAssignment(ValidatorIndex), + Internal(Hash, CandidateHash), } enum ApprovalVotingMessage { -- GitLab