diff --git a/rs/consensus/idkg/src/complaints.rs b/rs/consensus/idkg/src/complaints.rs index 890deb5f2a5d..d5c04a85db3e 100644 --- a/rs/consensus/idkg/src/complaints.rs +++ b/rs/consensus/idkg/src/complaints.rs @@ -11,7 +11,7 @@ use ic_interfaces::{ idkg::{IDkgChangeAction, IDkgChangeSet, IDkgPool}, }; use ic_interfaces_state_manager::{CertifiedStateSnapshot, StateReader}; -use ic_logger::{ReplicaLogger, debug, warn}; +use ic_logger::{ReplicaLogger, warn}; use ic_metrics::MetricsRegistry; use ic_replicated_state::ReplicatedState; use ic_types::{ @@ -399,7 +399,8 @@ impl IDkgComplaintHandlerImpl { )); } else { // Defer in case of transient errors - debug!( + warn!( + every_n_seconds => 10, self.log, "Complaint signature validation(transient error): {}, error = {:?}", signed_complaint, @@ -427,7 +428,8 @@ impl IDkgComplaintHandlerImpl { )) } Err(error) => { - debug!( + warn!( + every_n_seconds => 10, self.log, "Complaint validation(transient error): {}, error = {:?}", signed_complaint, @@ -523,7 +525,8 @@ impl IDkgComplaintHandlerImpl { ), )); } else { - debug!( + warn!( + every_n_seconds => 10, self.log, "Opening signature validation(transient error): {}, error = {:?}", signed_opening, @@ -553,7 +556,8 @@ impl IDkgComplaintHandlerImpl { )) } Err(error) => { - debug!( + warn!( + every_n_seconds => 10, self.log, "Opening validation(transient error): {}, error = {:?}", signed_opening, error ); @@ -686,6 +690,7 @@ impl IDkgComplaintHandlerImpl { } Err(error) => { warn!( + every_n_seconds => 10, self.log, "Failed to resolve complaint ref: reason = {}, \ transcript_ref = {:?}, error = {:?}", @@ -886,6 +891,7 @@ impl IDkgTranscriptLoader for IDkgComplaintHandlerImpl { } Err(err) => { warn!( + every_n_seconds => 10, self.log, "Failed to load transcript: transcript_id: {:?}, error = {:?}", transcript.transcript_id, @@ -936,6 +942,7 @@ impl IDkgTranscriptLoader for IDkgComplaintHandlerImpl { } Err(err) => { warn!( + every_n_seconds => 10, self.log, "Failed to load transcript with openings: transcript_id: {:?}, error = {:?}", transcript.transcript_id, diff --git a/rs/consensus/idkg/src/lib.rs b/rs/consensus/idkg/src/lib.rs index 6afe3721263c..c6fbc5372b9a 100644 --- a/rs/consensus/idkg/src/lib.rs +++ b/rs/consensus/idkg/src/lib.rs @@ -327,8 +327,9 @@ impl IDkgImpl { Ok(transcripts) => transcripts, Err(err) => { warn!( + every_n_seconds => 10, self.logger, - "purge_inactive_transcripts(): abort due to: {}", err, + "purge_inactive_transcripts(): abort due to: {}", err ); return; } @@ -337,6 +338,7 @@ impl IDkgImpl { match IDkgProtocol::retain_active_transcripts(&*self.crypto, &active_transcripts) { Err(IDkgRetainKeysError::TransientInternalError { internal_error }) => { warn!( + every_n_seconds => 10, self.logger, "purge_inactive_transcripts(): failed due to transient error: {}", internal_error @@ -348,6 +350,7 @@ impl IDkgImpl { } Err(error) => { error!( + every_n_seconds => 10, self.logger, "{}: failed with error = {:?}", CRITICAL_ERROR_IDKG_RETAIN_ACTIVE_TRANSCRIPTS, @@ -387,11 +390,12 @@ fn get_active_transcripts( } Err(error) => { warn!( + every_n_seconds => 10, logger, "purge_inactive_transcripts(): failed to resolve transcript ref: err = {:?}, \ {:?}", error, - transcript_ref, + transcript_ref ); metrics .client_errors diff --git a/rs/consensus/idkg/src/metrics.rs b/rs/consensus/idkg/src/metrics.rs index 157bc75a9e46..17618e4e1a48 100644 --- a/rs/consensus/idkg/src/metrics.rs +++ b/rs/consensus/idkg/src/metrics.rs @@ -233,6 +233,18 @@ impl IDkgPayloadMetrics { } } +pub(crate) trait IDkgPayloadMetricsOptionExt { + fn payload_errors_inc(self, label: &str); +} + +impl IDkgPayloadMetricsOptionExt for Option<&IDkgPayloadMetrics> { + fn payload_errors_inc(self, label: &str) { + if let Some(metrics) = self { + metrics.payload_errors_inc(label); + } + } +} + pub fn timed_call(label: &str, call_fn: F, metric: &HistogramVec) -> R where F: FnOnce() -> R, diff --git a/rs/consensus/idkg/src/payload_builder.rs b/rs/consensus/idkg/src/payload_builder.rs index a73de95d01d8..6236ed597d6a 100644 --- a/rs/consensus/idkg/src/payload_builder.rs +++ b/rs/consensus/idkg/src/payload_builder.rs @@ -135,6 +135,7 @@ pub fn make_bootstrap_summary_with_initial_dealings( None => { // Leave the feature disabled if the initial dealings are incorrect. warn!( + every_n_seconds => 10, log, "make_idkg_genesis_summary(): failed to unpack initial dealings" ); @@ -536,6 +537,7 @@ pub fn create_data_payload( &transcript_builder, state_manager, registry_client, + Some(idkg_payload_metrics), log, )?; @@ -575,6 +577,7 @@ pub(crate) fn create_data_payload_helper( transcript_builder: &dyn IDkgTranscriptBuilder, state_manager: &dyn StateManager, registry_client: &dyn RegistryClient, + idkg_payload_metrics: Option<&IDkgPayloadMetrics>, log: &ReplicaLogger, ) -> Result, IDkgPayloadError> { let height = parent_block.height().increment(); @@ -615,6 +618,7 @@ pub(crate) fn create_data_payload_helper( total_pre_signatures, block_reader, transcript_builder, + idkg_payload_metrics, log, )?; @@ -632,6 +636,7 @@ pub(crate) fn create_data_payload_helper_2( total_pre_signatures: BTreeMap, block_reader: &dyn IDkgBlockReader, transcript_builder: &dyn IDkgTranscriptBuilder, + idkg_payload_metrics: Option<&IDkgPayloadMetrics>, log: &ReplicaLogger, ) -> Result<(), IDkgPayloadError> { // Check if we are creating a new key, if so, start using it immediately. @@ -656,6 +661,7 @@ pub(crate) fn create_data_payload_helper_2( idkg_payload, transcript_builder, height, + idkg_payload_metrics, log, )?, key_transcript::update_next_key_transcripts( @@ -693,6 +699,7 @@ pub(crate) fn create_data_payload_helper_2( idkg_dealings_contexts, block_reader, transcript_builder, + idkg_payload_metrics, log, ); resharing::initiate_reshare_requests( @@ -701,6 +708,8 @@ pub(crate) fn create_data_payload_helper_2( idkg_dealings_contexts, validation_context_registry_version, ), + idkg_payload_metrics, + log, ); Ok(()) } @@ -878,6 +887,7 @@ mod tests { BTreeMap::from([(key_id.clone(), 2)]), &TestIDkgBlockReader::new(), &TestIDkgTranscriptBuilder::new(), + None, &ic_logger::replica_logger::no_op_logger(), ) .unwrap(); @@ -1025,6 +1035,7 @@ mod tests { &mut idkg_payload, &transcript_builder, parent_block_height, + None, &no_op_logger(), ) .unwrap(); @@ -1284,6 +1295,7 @@ mod tests { &mut idkg_payload, &transcript_builder, parent_block_height, + None, &no_op_logger(), ) .unwrap(); @@ -1887,6 +1899,7 @@ mod tests { BTreeMap::default(), &block_reader, &transcript_builder, + None, &no_op_logger(), ) .unwrap(); @@ -1911,6 +1924,7 @@ mod tests { BTreeMap::default(), &block_reader, &transcript_builder, + None, &no_op_logger(), ) .unwrap(); @@ -1994,6 +2008,7 @@ mod tests { BTreeMap::default(), &block_reader, &transcript_builder, + None, &no_op_logger(), ); assert!(result.is_ok()); @@ -2102,6 +2117,7 @@ mod tests { BTreeMap::default(), &block_reader, &transcript_builder, + None, &no_op_logger(), ) .unwrap(); @@ -2219,6 +2235,7 @@ mod tests { BTreeMap::default(), &block_reader, &transcript_builder, + None, &no_op_logger(), ); assert!(result.is_ok()); @@ -2244,6 +2261,7 @@ mod tests { BTreeMap::default(), &block_reader, &transcript_builder, + None, &no_op_logger(), ); assert!(result.is_ok()); @@ -2267,6 +2285,7 @@ mod tests { BTreeMap::default(), &block_reader, &transcript_builder, + None, &no_op_logger(), ); assert!(result.is_ok()); diff --git a/rs/consensus/idkg/src/payload_builder/pre_signatures.rs b/rs/consensus/idkg/src/payload_builder/pre_signatures.rs index 3af2c66b1e16..2a56d78a09d4 100644 --- a/rs/consensus/idkg/src/payload_builder/pre_signatures.rs +++ b/rs/consensus/idkg/src/payload_builder/pre_signatures.rs @@ -1,6 +1,10 @@ -use crate::{payload_builder::IDkgPayloadError, pre_signer::IDkgTranscriptBuilder}; +use crate::{ + metrics::{IDkgPayloadMetrics, IDkgPayloadMetricsOptionExt}, + payload_builder::IDkgPayloadError, + pre_signer::IDkgTranscriptBuilder, +}; use ic_interfaces_state_manager::Labeled; -use ic_logger::{ReplicaLogger, debug, error}; +use ic_logger::{ReplicaLogger, error}; use ic_management_canister_types_private::MasterPublicKeyId; use ic_registry_subnet_features::ChainKeyConfig; use ic_replicated_state::ReplicatedState; @@ -8,7 +12,7 @@ use ic_types::{ Height, NodeId, RegistryVersion, consensus::idkg::{ self, HasIDkgMasterPublicKeyId, IDkgBlockReader, IDkgMasterPublicKeyId, IDkgUIDGenerator, - PreSigId, TranscriptAttributes, UnmaskedTranscriptWithAttributes, + TranscriptAttributes, UnmaskedTranscriptWithAttributes, common::{PreSignatureInCreation, PreSignatureRef}, ecdsa::{PreSignatureQuadrupleRef, QuadrupleInCreation}, schnorr::{PreSignatureTranscriptRef, TranscriptInCreation}, @@ -31,6 +35,7 @@ pub(super) fn update_pre_signatures_in_creation( payload: &mut idkg::IDkgPayload, transcript_builder: &dyn IDkgTranscriptBuilder, height: Height, + idkg_payload_metrics: Option<&IDkgPayloadMetrics>, log: &ReplicaLogger, ) -> Result, IDkgPayloadError> { let mut newly_available = BTreeMap::new(); @@ -46,27 +51,24 @@ pub(super) fn update_pre_signatures_in_creation( log, "The IDKG payload is missing a key transcript with key_id: {}", pre_signature.key_id()); + idkg_payload_metrics.payload_errors_inc("pre_signature_missing_key_transcript"); continue; }; let (finished, transcripts) = match pre_signature { PreSignatureInCreation::Ecdsa(quadruple) => update_ecdsa_quadruple_in_creation( - *pre_signature_id, quadruple, key_transcript, transcript_builder, &mut payload.uid_generator, height, + idkg_payload_metrics, log, )?, - PreSignatureInCreation::Schnorr(transcript) => update_schnorr_transcript_in_creation( - *pre_signature_id, - transcript, - transcript_builder, - height, - log, - )?, + PreSignatureInCreation::Schnorr(transcript) => { + update_schnorr_transcript_in_creation(transcript, transcript_builder, height)? + } }; new_transcripts.extend(transcripts); @@ -106,11 +108,6 @@ pub(super) fn update_pre_signatures_in_creation( } }; - debug!( - log, - "update_pre_signatures_in_creation: making of pre-signature {:?} is complete", - pre_signature_id - ); payload .available_pre_signatures .insert(pre_signature_id, pre_signature); @@ -125,12 +122,12 @@ pub(super) fn update_pre_signatures_in_creation( /// /// Returns the newly created transcripts and if creation of this pre-signature has finished. fn update_ecdsa_quadruple_in_creation( - pre_signature_id: PreSigId, quadruple: &mut QuadrupleInCreation, key_transcript: &UnmaskedTranscriptWithAttributes, transcript_builder: &dyn IDkgTranscriptBuilder, uid_generator: &mut IDkgUIDGenerator, height: Height, + idkg_payload_metrics: Option<&IDkgPayloadMetrics>, log: &ReplicaLogger, ) -> Result<(bool, Vec), IDkgPayloadError> { let mut new_transcripts = Vec::new(); @@ -141,11 +138,6 @@ fn update_ecdsa_quadruple_in_creation( && let Some(transcript) = transcript_builder .get_completed_transcript(quadruple.lambda_config.as_ref().transcript_id) { - debug!( - log, - "update_ecdsa_quadruple_in_creation: {:?} lamdba_masked transcript is made", - pre_signature_id - ); quadruple.lambda_masked = Some(idkg::MaskedTranscript::try_from((height, &transcript))?); new_transcripts.push(transcript); } @@ -153,13 +145,6 @@ fn update_ecdsa_quadruple_in_creation( && let Some(transcript) = transcript_builder .get_completed_transcript(quadruple.kappa_unmasked_config.as_ref().transcript_id) { - debug!( - log, - "update_ecdsa_quadruple_in_creation: {:?} kappa_unmasked transcript {:?} is \ - made from unmasked config", - pre_signature_id, - transcript.get_type() - ); quadruple.kappa_unmasked = Some(idkg::UnmaskedTranscript::try_from((height, &transcript))?); new_transcripts.push(transcript); } @@ -168,11 +153,6 @@ fn update_ecdsa_quadruple_in_creation( && let Some(transcript) = transcript_builder.get_completed_transcript(config.as_ref().transcript_id) { - debug!( - log, - "update_ecdsa_quadruple_in_creation: {:?} key_times_lambda transcript is made", - pre_signature_id - ); quadruple.key_times_lambda = Some(idkg::MaskedTranscript::try_from((height, &transcript))?); new_transcripts.push(transcript); } @@ -181,11 +161,6 @@ fn update_ecdsa_quadruple_in_creation( && let Some(transcript) = transcript_builder.get_completed_transcript(config.as_ref().transcript_id) { - debug!( - log, - "update_ecdsa_quadruple_in_creation: {:?} kappa_times_lambda transcript is made", - pre_signature_id - ); quadruple.kappa_times_lambda = Some(idkg::MaskedTranscript::try_from((height, &transcript))?); new_transcripts.push(transcript); @@ -197,11 +172,13 @@ fn update_ecdsa_quadruple_in_creation( let lambda_config = quadruple.lambda_config.as_ref(); if key_transcript.receivers() != lambda_config.receivers() { error!( + every_n_seconds => 10, log, "Key transcript has a different receiver set than lambda_config: {:?} {:?}", key_transcript, lambda_config ); + idkg_payload_metrics.payload_errors_inc("key_lambda_receiver_mismatch"); } else { quadruple.key_times_lambda_config = Some(idkg::UnmaskedTimesMaskedParams::new( uid_generator.next_transcript_id(), @@ -221,11 +198,13 @@ fn update_ecdsa_quadruple_in_creation( let kappa_config = quadruple.kappa_unmasked_config.as_ref(); if kappa_config.receivers() != lambda_config.receivers() { error!( + every_n_seconds => 10, log, "kappa_config has a different receiver set than lambda_config: {:?} {:?}", kappa_config, lambda_config ); + idkg_payload_metrics.payload_errors_inc("kappa_lambda_receiver_mismatch"); } else { quadruple.kappa_times_lambda_config = Some(idkg::UnmaskedTimesMaskedParams::new( uid_generator.next_transcript_id(), @@ -248,11 +227,9 @@ fn update_ecdsa_quadruple_in_creation( /// from the pool. Returns the newly created transcripts and if this pre-signature creation /// is finished. fn update_schnorr_transcript_in_creation( - pre_signature_id: PreSigId, pre_signature: &mut TranscriptInCreation, transcript_builder: &dyn IDkgTranscriptBuilder, height: Height, - log: &ReplicaLogger, ) -> Result<(bool, Vec), IDkgPayloadError> { let mut new_transcripts = Vec::new(); // Update pre_signature with completed transcripts @@ -260,11 +237,6 @@ fn update_schnorr_transcript_in_creation( && let Some(transcript) = transcript_builder .get_completed_transcript(pre_signature.blinder_unmasked_config.as_ref().transcript_id) { - debug!( - log, - "update_schnorr_transcript_in_creation: {:?} blinder_unmasked transcript is made", - pre_signature_id - ); pre_signature.blinder_unmasked = Some(idkg::UnmaskedTranscript::try_from((height, &transcript))?); new_transcripts.push(transcript); @@ -1294,14 +1266,9 @@ pub(super) mod tests { let mut pre_sig = TranscriptInCreation::new(key_id, blinder_config); assert!(pre_sig.blinder_unmasked.is_none()); - let (finished, new_transcripts) = update_schnorr_transcript_in_creation( - PreSigId(0), - &mut pre_sig, - &transcript_builder, - height, - &no_op_logger(), - ) - .expect("Update should succeed"); + let (finished, new_transcripts) = + update_schnorr_transcript_in_creation(&mut pre_sig, &transcript_builder, height) + .expect("Update should succeed"); assert!(!finished); assert!(new_transcripts.is_empty()); @@ -1314,26 +1281,16 @@ pub(super) mod tests { ); transcript_builder.add_transcript(param.transcript_id, blinder_unmasked_transcript); - let (finished, new_transcripts) = update_schnorr_transcript_in_creation( - PreSigId(0), - &mut pre_sig, - &transcript_builder, - height, - &no_op_logger(), - ) - .expect("Update should succeed"); + let (finished, new_transcripts) = + update_schnorr_transcript_in_creation(&mut pre_sig, &transcript_builder, height) + .expect("Update should succeed"); assert!(finished); assert_eq!(new_transcripts.len(), 1); - let (finished, new_transcripts) = update_schnorr_transcript_in_creation( - PreSigId(0), - &mut pre_sig, - &transcript_builder, - height, - &no_op_logger(), - ) - .expect("Update should succeed"); + let (finished, new_transcripts) = + update_schnorr_transcript_in_creation(&mut pre_sig, &transcript_builder, height) + .expect("Update should succeed"); assert!(finished); assert!(new_transcripts.is_empty()); @@ -1370,6 +1327,7 @@ pub(super) mod tests { &mut payload, &transcript_builder, cur_height, + None, &no_op_logger(), ); assert!(result.unwrap().is_empty()); @@ -1393,6 +1351,7 @@ pub(super) mod tests { &mut payload, &transcript_builder, cur_height, + None, &no_op_logger(), ) .unwrap(); @@ -1427,6 +1386,7 @@ pub(super) mod tests { &mut payload, &transcript_builder, cur_height, + None, &no_op_logger(), ) .unwrap(); @@ -1478,6 +1438,7 @@ pub(super) mod tests { &mut payload, &transcript_builder, cur_height, + None, &no_op_logger(), ) .unwrap(); @@ -1538,6 +1499,7 @@ pub(super) mod tests { &mut payload, &transcript_builder, cur_height, + None, &no_op_logger(), ); assert!(result.unwrap().is_empty()); @@ -1561,6 +1523,7 @@ pub(super) mod tests { &mut payload, &transcript_builder, cur_height, + None, &no_op_logger(), ) .unwrap(); diff --git a/rs/consensus/idkg/src/payload_builder/resharing.rs b/rs/consensus/idkg/src/payload_builder/resharing.rs index ed0b4112c6ca..989dbe6a4647 100644 --- a/rs/consensus/idkg/src/payload_builder/resharing.rs +++ b/rs/consensus/idkg/src/payload_builder/resharing.rs @@ -1,4 +1,8 @@ -use crate::{payload_builder::IDkgDealingContext, pre_signer::IDkgTranscriptBuilder}; +use crate::{ + metrics::{IDkgPayloadMetrics, IDkgPayloadMetricsOptionExt}, + payload_builder::IDkgDealingContext, + pre_signer::IDkgTranscriptBuilder, +}; use ic_logger::{ReplicaLogger, warn}; use ic_management_canister_types_private::ReshareChainKeyResponse; use ic_types::{ @@ -17,6 +21,8 @@ use std::collections::{BTreeMap, BTreeSet}; pub(crate) fn initiate_reshare_requests( payload: &mut idkg::IDkgPayload, reshare_requests: BTreeSet, + idkg_payload_metrics: Option<&IDkgPayloadMetrics>, + log: &ReplicaLogger, ) { for request in reshare_requests { let Some(key_transcript) = payload @@ -24,6 +30,13 @@ pub(crate) fn initiate_reshare_requests( .get(&request.key_id()) .and_then(|key_transcript| key_transcript.current.as_ref()) else { + warn!( + every_n_seconds => 10, + log, + "Cannot initiate reshare request because key transcript is unavailable: {:?}", + request + ); + idkg_payload_metrics.payload_errors_inc("reshare_request_missing_key_transcript"); continue; }; @@ -83,11 +96,18 @@ pub(crate) fn update_completed_reshare_requests( idkg_dealings_contexts: &BTreeMap>, resolver: &dyn IDkgBlockReader, transcript_builder: &dyn IDkgTranscriptBuilder, + idkg_payload_metrics: Option<&IDkgPayloadMetrics>, log: &ReplicaLogger, ) { let mut completed_reshares = BTreeMap::new(); for (request, reshare_param) in &payload.ongoing_xnet_reshares { if payload.current_key_transcript(&request.key_id()).is_none() { + warn!( + every_n_seconds => 10, + log, + "Skipping ongoing reshare request without a current key transcript: {:?}", request + ); + idkg_payload_metrics.payload_errors_inc("ongoing_reshare_missing_key_transcript"); continue; } @@ -100,9 +120,11 @@ pub(crate) fn update_completed_reshare_requests( Ok(params) => params, Err(err) => { warn!( + every_n_seconds => 10, log, "Failed to resolve reshare transcript params: {:?}", err ); + idkg_payload_metrics.payload_errors_inc("reshare_transcript_params_resolution"); continue; } }; @@ -114,7 +136,12 @@ pub(crate) fn update_completed_reshare_requests( } Err(InitialIDkgDealingsValidationError::UnsatisfiedCollectionThreshold { .. }) => (), Err(err) => { - warn!(log, "Failed to create initial dealings: {:?}", err); + warn!( + every_n_seconds => 10, + log, + "Failed to create initial dealings: {:?}", err + ); + idkg_payload_metrics.payload_errors_inc("reshare_initial_dealings_creation"); } }; } @@ -146,9 +173,11 @@ pub(crate) fn update_completed_reshare_requests( .insert(request, idkg::CompletedReshareRequest::Unreported(response)); } else { warn!( + every_n_seconds => 10, log, "Cannot find the request for the initial dealings created: {:?}", request ); + idkg_payload_metrics.payload_errors_inc("reshare_request_context_missing"); } } } @@ -299,7 +328,12 @@ mod tests { ); let request = create_reshare_request(key_id, 1, 1); - initiate_reshare_requests(&mut payload, BTreeSet::from([request])); + initiate_reshare_requests( + &mut payload, + BTreeSet::from([request]), + None, + &no_op_logger(), + ); assert!(payload.ongoing_xnet_reshares.is_empty()); assert!(payload.xnet_reshare_agreements.is_empty()); @@ -316,7 +350,12 @@ mod tests { ); let request = create_reshare_request(key_id.clone(), 1, 1); - initiate_reshare_requests(&mut payload, BTreeSet::from([request.clone()])); + initiate_reshare_requests( + &mut payload, + BTreeSet::from([request.clone()]), + None, + &no_op_logger(), + ); let params = payload .ongoing_xnet_reshares @@ -342,8 +381,18 @@ mod tests { let request = create_reshare_request(key_id.clone(), 1, 1); let request_2 = create_reshare_request(key_id.clone(), 2, 2); - initiate_reshare_requests(&mut payload, BTreeSet::from([request.clone()])); - initiate_reshare_requests(&mut payload, BTreeSet::from([request_2.clone()])); + initiate_reshare_requests( + &mut payload, + BTreeSet::from([request.clone()]), + None, + &no_op_logger(), + ); + initiate_reshare_requests( + &mut payload, + BTreeSet::from([request_2.clone()]), + None, + &no_op_logger(), + ); let params = payload .ongoing_xnet_reshares @@ -379,7 +428,12 @@ mod tests { idkg::CompletedReshareRequest::ReportedToExecution, ); - initiate_reshare_requests(&mut payload, BTreeSet::from([request])); + initiate_reshare_requests( + &mut payload, + BTreeSet::from([request]), + None, + &no_op_logger(), + ); assert!(payload.ongoing_xnet_reshares.is_empty()); assert_eq!(payload.xnet_reshare_agreements.len(), 1); @@ -406,6 +460,8 @@ mod tests { initiate_reshare_requests( &mut payload, BTreeSet::from([request_1.clone(), request_2.clone()]), + None, + &no_op_logger(), ); let callback_1 = ic_types::messages::CallbackId::new(1); @@ -441,6 +497,7 @@ mod tests { &contexts, &block_reader, &transcript_builder, + None, &no_op_logger(), ); assert_eq!(payload.ongoing_xnet_reshares.len(), 1); @@ -478,6 +535,7 @@ mod tests { &contexts, &block_reader, &transcript_builder, + None, &no_op_logger(), ); assert!(payload.ongoing_xnet_reshares.is_empty()); @@ -506,6 +564,7 @@ mod tests { &contexts, &block_reader, &transcript_builder, + None, &no_op_logger(), ); assert!(payload.ongoing_xnet_reshares.is_empty()); @@ -531,6 +590,7 @@ mod tests { &contexts, &block_reader, &transcript_builder, + None, &no_op_logger(), ); assert!(payload.ongoing_xnet_reshares.is_empty()); diff --git a/rs/consensus/idkg/src/payload_verifier.rs b/rs/consensus/idkg/src/payload_verifier.rs index 1798cee005eb..c16f67a33304 100644 --- a/rs/consensus/idkg/src/payload_verifier.rs +++ b/rs/consensus/idkg/src/payload_verifier.rs @@ -437,6 +437,7 @@ fn validate_data_payload( &builder, state_manager, registry_client, + None, &ic_logger::replica_logger::no_op_logger(), ) { Ok(idkg_payload) => { @@ -801,7 +802,12 @@ mod test { let (key_transcript, key_transcript_ref) = payload.generate_current_key(&key_id, &env, &mut rng); block_reader.add_transcript(*key_transcript_ref.as_ref(), key_transcript); - initiate_reshare_requests(&mut payload, reshare_requests.clone()); + initiate_reshare_requests( + &mut payload, + reshare_requests.clone(), + None, + &no_op_logger(), + ); let prev_payload = payload.clone(); // Create completed dealings for request 1. @@ -817,6 +823,7 @@ mod test { &contexts, &block_reader, &transcript_builder, + None, &no_op_logger(), ); assert_eq!(payload.xnet_reshare_agreements.len(), 1); @@ -855,6 +862,7 @@ mod test { &contexts, &block_reader, &transcript_builder, + None, &no_op_logger(), ); diff --git a/rs/consensus/idkg/src/pre_signer.rs b/rs/consensus/idkg/src/pre_signer.rs index 07b95c262a82..97722adfd5ba 100644 --- a/rs/consensus/idkg/src/pre_signer.rs +++ b/rs/consensus/idkg/src/pre_signer.rs @@ -11,7 +11,7 @@ use ic_interfaces::{ crypto::{ErrorReproducibility, IDkgProtocol}, idkg::{IDkgChangeAction, IDkgChangeSet, IDkgPool}, }; -use ic_logger::{ReplicaLogger, debug, warn}; +use ic_logger::{ReplicaLogger, warn}; use ic_metrics::MetricsRegistry; use ic_types::{ Height, NodeId, @@ -142,9 +142,10 @@ impl IDkgPreSignerImpl { self.metrics .pre_sign_errors_inc("create_dealing_for_xnet_transcript"); warn!( + every_n_seconds => 10, self.log, "Dealing creation: dealing for target xnet dealing: {:?}", - transcript_params, + transcript_params ); } self.crypto_create_dealing(idkg_pool, transcript_loader, &transcript_params) @@ -278,6 +279,7 @@ impl IDkgPreSignerImpl { self.metrics .pre_sign_errors_inc("create_support_id_dealing_hash"); warn!( + every_n_seconds => 10, self.log, "send_dealing_support(): Failed to get dealing hash: {:?}", id ); @@ -325,9 +327,10 @@ impl IDkgPreSignerImpl { self.metrics .pre_sign_errors_inc("create_support_for_xnet_transcript"); warn!( + every_n_seconds => 10, self.log, "Dealing support creation: support for target xnet dealing: {}", - signed_dealing, + signed_dealing ); } @@ -370,6 +373,7 @@ impl IDkgPreSignerImpl { self.metrics .pre_sign_errors_inc("validate_dealing_support_id_dealing_hash"); warn!( + every_n_seconds => 10, self.log, "validate_dealing_support(): Failed to get dealing hash: {:?}", id ) @@ -530,8 +534,9 @@ impl IDkgPreSignerImpl { self.metrics .pre_sign_errors_inc("missing_hash_invalid_dealer"); warn!( + every_n_seconds => 10, self.log, - "validate_dealing_support(): Missing hash, invalid dealer: {support}", + "validate_dealing_support(): Missing hash, invalid dealer: {support}" ); return Some(IDkgChangeAction::RemoveUnvalidated(id)); } @@ -553,8 +558,9 @@ impl IDkgPreSignerImpl { self.metrics .pre_sign_errors_inc("missing_hash_meta_data_mismatch"); warn!( + every_n_seconds => 10, self.log, - "validate_dealing_support(): Missing hash, meta data mismatch: {support}", + "validate_dealing_support(): Missing hash, meta data mismatch: {support}" ); return Some(IDkgChangeAction::RemoveUnvalidated(id)); } @@ -609,6 +615,7 @@ impl IDkgPreSignerImpl { self.metrics .pre_sign_errors_inc("build_transcript_id_dealing_hash"); warn!( + every_n_seconds => 10, self.log, "build_transcript(): Failed to get dealing hash: {:?}", id ); @@ -622,6 +629,7 @@ impl IDkgPreSignerImpl { { if let Err(err) = transcript_state.add_dealing_support(support) { warn!( + every_n_seconds => 10, self.log, "Failed to add support: transcript_id = {:?}, error = {:?}", transcript_id, @@ -786,6 +794,7 @@ impl IDkgPreSignerImpl { } Err(IDkgCreateDealingError::SignatureError { internal_error }) => { warn!( + every_n_seconds => 10, self.log, "Failed to sign dealing: transcript_id = {:?}, type = {:?}, error = {:?}", transcript_params.transcript_id(), @@ -800,6 +809,7 @@ impl IDkgPreSignerImpl { // will most likely fail again. This should be signaled up so that the bad // transcript params can be acted on warn!( + every_n_seconds => 10, self.log, "Failed to create dealing: transcript_id = {:?}, type = {:?}, error = {:?}", transcript_params.transcript_id(), @@ -832,7 +842,8 @@ impl IDkgPreSignerImpl { } Err(error) => { // Defer in case of transient errors - debug!( + warn!( + every_n_seconds => 10, self.log, "Dealing validation(transient error): {}, error = {:?}", signed_dealing, error ); @@ -864,6 +875,7 @@ impl IDkgPreSignerImpl { self.metrics .pre_sign_errors_inc("verify_dealing_private_permanent"); warn!( + every_n_seconds => 10, self.log, "Dealing private verification(permanent error): {}, error = {:?}", dealing, @@ -878,7 +890,8 @@ impl IDkgPreSignerImpl { } else { self.metrics .pre_sign_errors_inc("verify_dealing_private_transient"); - debug!( + warn!( + every_n_seconds => 10, self.log, "Dealing private verification(transient error): {}, error = {:?}", dealing, @@ -897,7 +910,8 @@ impl IDkgPreSignerImpl { ) .map_or_else( |error| { - debug!( + warn!( + every_n_seconds => 10, self.log, "Dealing multi sign failed: {}, error = {:?}", dealing, error ); @@ -984,6 +998,7 @@ impl IDkgPreSignerImpl { ret.map_or_else( |error| { warn!( + every_n_seconds => 10, self.log, "Failed to aggregate: transcript_id = {:?}, error = {:?}", transcript_params.transcript_id(), @@ -1023,6 +1038,7 @@ impl IDkgPreSignerImpl { ret.map_or_else( |error| { warn!( + every_n_seconds => 10, self.log, "Failed to create transcript: transcript_id = {:?}, error = {:?}", transcript_params.transcript_id(), @@ -1135,6 +1151,7 @@ impl IDkgPreSignerImpl { } Err(error) => { warn!( + every_n_seconds => 10, self.log, "Failed to translate transcript ref: reason = {}, \ transcript_params_ref = {:?}, tip = {:?}, error = {:?}", diff --git a/rs/consensus/idkg/src/signer.rs b/rs/consensus/idkg/src/signer.rs index 16cae0aa7ab4..148b121e6e3d 100644 --- a/rs/consensus/idkg/src/signer.rs +++ b/rs/consensus/idkg/src/signer.rs @@ -14,7 +14,7 @@ use ic_interfaces::{ idkg::{IDkgChangeAction, IDkgChangeSet, IDkgPool}, }; use ic_interfaces_state_manager::{CertifiedStateSnapshot, StateReader}; -use ic_logger::{ReplicaLogger, debug, warn}; +use ic_logger::{ReplicaLogger, warn}; use ic_metrics::MetricsRegistry; use ic_replicated_state::ReplicatedState; use ic_types::{ @@ -277,7 +277,8 @@ impl ThresholdSignerImpl { } Err(error) => { // Defer in case of transient errors - debug!( + warn!( + every_n_seconds => 10, self.log, "Signature share validation(transient error): {}, error = {:?}", share_string, diff --git a/rs/consensus/idkg/src/utils.rs b/rs/consensus/idkg/src/utils.rs index 10e88cd98b70..ce093ebf6d62 100644 --- a/rs/consensus/idkg/src/utils.rs +++ b/rs/consensus/idkg/src/utils.rs @@ -2,7 +2,7 @@ use crate::{ complaints::{IDkgTranscriptLoader, TranscriptLoadStatus}, - metrics::{IDkgPayloadMetrics, IDkgPayloadStats}, + metrics::{IDkgPayloadMetrics, IDkgPayloadMetricsOptionExt, IDkgPayloadStats}, }; use ic_consensus_utils::{RoundRobin, pool_reader::PoolReader, range_len}; use ic_crypto::get_master_public_key_from_transcript; @@ -179,12 +179,11 @@ pub(super) fn block_chain_reader( .map(IDkgBlockReaderImpl::new) .map_err(|err| { warn!( + every_n_seconds => 10, log, "block_chain_reader(): failed to build chain cache: {}", err ); - if let Some(metrics) = idkg_payload_metrics { - metrics.payload_errors_inc("summary_invalid_chain_cache"); - }; + idkg_payload_metrics.payload_errors_inc("summary_invalid_chain_cache"); err }) } @@ -429,6 +428,7 @@ pub fn get_idkg_subnet_public_keys_and_pre_signatures( stats.transcript_resolution_errors += 1; } error!( + every_n_seconds => 10, log, "{}: Failed to retrieve IDKg subnet master public key of key id {}: {:?}", CRITICAL_ERROR_IDKG_RESOLVE_TRANSCRIPT_REFS, @@ -450,6 +450,7 @@ pub fn get_idkg_subnet_public_keys_and_pre_signatures( stats.transcript_resolution_errors += 1; } error!( + every_n_seconds => 10, log, "{}: Failed to translate key transcript ref {:?} of key {}: {:?}", CRITICAL_ERROR_IDKG_RESOLVE_TRANSCRIPT_REFS, @@ -478,6 +479,7 @@ pub fn get_idkg_subnet_public_keys_and_pre_signatures( stats.transcript_resolution_errors += 1; } error!( + every_n_seconds => 10, log, "{}: Failed to translate Pre-signature ref of key {}: {:?}", CRITICAL_ERROR_IDKG_RESOLVE_TRANSCRIPT_REFS,