From 34d22b5920701ead844c9fabdbfef0dc4b219076 Mon Sep 17 00:00:00 2001 From: Pawan Dhananjay Date: Tue, 12 Oct 2021 05:06:48 +0000 Subject: [PATCH] Reduce validator monitor logging verbosity (#2606) ## Issue Addressed Resolves #2541 ## Proposed Changes Reduces verbosity of validator monitor per epoch logging by batching info logs for multiple validators. Instead of a log for every validator managed by the validator monitor, we now batch logs for attestation records for previous epoch. Before: ```log Sep 20 06:53:08.239 INFO Previous epoch attestation success validator: 1, epoch: 65875, matched_head: true, matched_target: true, inclusion_lag: 0 slot(s), service: val_mon Sep 20 06:53:08.239 INFO Previous epoch attestation success validator: 2, epoch: 65875, matched_head: true, matched_target: true, inclusion_lag: 0 slot(s), service: val_mon Sep 20 06:53:08.239 INFO Previous epoch attestation success validator: 3, epoch: 65875, matched_head: true, matched_target: true, inclusion_lag: 0 slot(s), service: val_mon Sep 20 06:53:08.239 INFO Previous epoch attestation success validator: 4, epoch: 65875, matched_head: true, matched_target: true, inclusion_lag: 0 slot(s), service: val_mon Sep 20 06:53:08.239 INFO Previous epoch attestation success validator: 5, epoch: 65875, matched_head: false, matched_target: true, inclusion_lag: 0 slot(s), service: val_mon Sep 20 06:53:08.239 WARN Attestation failed to match head validator: 5, epoch: 65875, service: val_mon Sep 20 06:53:08.239 INFO Previous epoch attestation success validator: 6, epoch: 65875, matched_head: false, matched_target: true, inclusion_lag: 0 slot(s), service: val_mon Sep 20 06:53:08.239 WARN Attestation failed to match head validator: 6, epoch: 65875, service: val_mon Sep 20 06:53:08.239 INFO Previous epoch attestation success validator: 7, epoch: 65875, matched_head: true, matched_target: false, inclusion_lag: 1 slot(s), service: val_mon Sep 20 06:53:08.239 WARN Attestation failed to match target validator: 7, epoch: 65875, service: val_mon Sep 20 06:53:08.239 WARN Sub-optimal inclusion delay validator: 7, epoch: 65875, optimal: 1, delay: 2, service: val_mon Sep 20 06:53:08.239 INFO Previous epoch attestation success validator: 8, epoch: 65875, matched_head: true, matched_target: false, inclusion_lag: 1 slot(s), service: val_mon Sep 20 06:53:08.239 WARN Attestation failed to match target validator: 8, epoch: 65875, service: val_mon Sep 20 06:53:08.239 WARN Sub-optimal inclusion delay validator: 8, epoch: 65875, optimal: 1, delay: 2, service: val_mon Sep 20 06:53:08.239 ERRO Previous epoch attestation missing validator: 9, epoch: 65875, service: val_mon Sep 20 06:53:08.239 ERRO Previous epoch attestation missing validator: 10, epoch: 65875, service: val_mon ``` after ``` Sep 20 06:53:08.239 INFO Previous epoch attestation success validators: [1,2,3,4,5,6,7,8,9] , epoch: 65875, service: val_mon Sep 20 06:53:08.239 WARN Previous epoch attestation failed to match head, validators: [5,6], epoch: 65875, service: val_mon Sep 20 06:53:08.239 WARN Previous epoch attestation failed to match target, validators: [7,8], epoch: 65875, service: val_mon Sep 20 06:53:08.239 WARN Previous epoch attestations had sub-optimal inclusion delay, validators: [7,8], epoch: 65875, service: val_mon Sep 20 06:53:08.239 ERRO Previous epoch attestation missing validators: [9,10], epoch: 65875, service: val_mon ``` The detailed individual logs are downgraded to debug logs. --- .../beacon_chain/src/validator_monitor.rs | 79 ++++++++++++++++--- 1 file changed, 68 insertions(+), 11 deletions(-) diff --git a/beacon_node/beacon_chain/src/validator_monitor.rs b/beacon_node/beacon_chain/src/validator_monitor.rs index 7d6744b97..ef3632f26 100644 --- a/beacon_node/beacon_chain/src/validator_monitor.rs +++ b/beacon_node/beacon_chain/src/validator_monitor.rs @@ -389,13 +389,19 @@ impl ValidatorMonitor { summary: &EpochProcessingSummary, spec: &ChainSpec, ) -> Result<(), EpochProcessingError> { + let mut attestation_success = Vec::new(); + let mut attestation_miss = Vec::new(); + let mut head_miss = Vec::new(); + let mut target_miss = Vec::new(); + let mut suboptimal_inclusion = Vec::new(); + + // We subtract two from the state of the epoch that generated these summaries. + // + // - One to account for it being the previous epoch. + // - One to account for the state advancing an epoch whilst generating the validator + // statuses. + let prev_epoch = epoch - 2; for (pubkey, monitored_validator) in self.validators.iter() { - // We subtract two from the state of the epoch that generated these summaries. - // - // - One to account for it being the previous epoch. - // - One to account for the state advancing an epoch whilst generating the validator - // statuses. - let prev_epoch = epoch - 2; if let Some(i) = monitored_validator.index { let i = i as usize; let id = &monitored_validator.id; @@ -433,7 +439,8 @@ impl ValidatorMonitor { &metrics::VALIDATOR_MONITOR_PREV_EPOCH_ON_CHAIN_ATTESTER_HIT, &[id], ); - info!( + attestation_success.push(id); + debug!( self.log, "Previous epoch attestation success"; "matched_source" => previous_epoch_matched_source, @@ -447,7 +454,8 @@ impl ValidatorMonitor { &metrics::VALIDATOR_MONITOR_PREV_EPOCH_ON_CHAIN_ATTESTER_MISS, &[id], ); - error!( + attestation_miss.push(id); + debug!( self.log, "Previous epoch attestation missing"; "epoch" => prev_epoch, @@ -466,7 +474,8 @@ impl ValidatorMonitor { &metrics::VALIDATOR_MONITOR_PREV_EPOCH_ON_CHAIN_HEAD_ATTESTER_MISS, &[id], ); - warn!( + head_miss.push(id); + debug!( self.log, "Attestation failed to match head"; "epoch" => prev_epoch, @@ -485,7 +494,8 @@ impl ValidatorMonitor { &metrics::VALIDATOR_MONITOR_PREV_EPOCH_ON_CHAIN_TARGET_ATTESTER_MISS, &[id], ); - warn!( + target_miss.push(id); + debug!( self.log, "Attestation failed to match target"; "epoch" => prev_epoch, @@ -504,7 +514,8 @@ impl ValidatorMonitor { ); if let Some(inclusion_delay) = min_inclusion_distance { if inclusion_delay > spec.min_attestation_inclusion_delay { - warn!( + suboptimal_inclusion.push(id); + debug!( self.log, "Potential sub-optimal inclusion delay"; "optimal" => spec.min_attestation_inclusion_delay, @@ -562,6 +573,52 @@ impl ValidatorMonitor { } } + // Aggregate logging for attestation success/failures over an epoch + // for all validators managed by the validator monitor. + if !attestation_success.is_empty() { + info!( + self.log, + "Previous epoch attestation(s) success"; + "epoch" => prev_epoch, + "validators" => ?attestation_success, + ); + } + if !attestation_miss.is_empty() { + error!( + self.log, + "Previous epoch attestation(s) missing"; + "epoch" => prev_epoch, + "validators" => ?attestation_miss, + ); + } + + if !head_miss.is_empty() { + warn!( + self.log, + "Previous epoch attestation(s) failed to match head"; + "epoch" => prev_epoch, + "validators" => ?head_miss, + ); + } + + if !target_miss.is_empty() { + warn!( + self.log, + "Previous epoch attestation(s) failed to match target"; + "epoch" => prev_epoch, + "validators" => ?target_miss, + ); + } + + if !suboptimal_inclusion.is_empty() { + warn!( + self.log, + "Previous epoch attestation(s) had sub-optimal inclusion delay"; + "epoch" => prev_epoch, + "validators" => ?suboptimal_inclusion, + ); + } + Ok(()) }