cerc-io/lighthouse
16
0
Fork 0
Code Issues 1 Pull Requests Packages Projects Releases Wiki Activity

Reduce validator monitor logging verbosity (#2606)

Browse Source 
## 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.
This commit is contained in:
Pawan Dhananjay 2021-10-12 05:06:48 +00:00
parent a73d698e30
commit 34d22b5920
1 changed files with 68 additions and 11 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

69
beacon_node/beacon_chain/src/validator_monitor.rs
View File

@ -389,13 +389,19 @@ impl<T: EthSpec> ValidatorMonitor<T> {
summary: &EpochProcessingSummary<T>, summary: &EpochProcessingSummary<T>,
spec: &ChainSpec, spec: &ChainSpec,
) -> Result<(), EpochProcessingError> { ) -> Result<(), EpochProcessingError> {
for (pubkey, monitored_validator) in self.validators.iter() { 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. // 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 it being the previous epoch.
// - One to account for the state advancing an epoch whilst generating the validator // - One to account for the state advancing an epoch whilst generating the validator
// statuses. // statuses.
let prev_epoch = epoch - 2; let prev_epoch = epoch - 2;
for (pubkey, monitored_validator) in self.validators.iter() {
if let Some(i) = monitored_validator.index { if let Some(i) = monitored_validator.index {
let i = i as usize; let i = i as usize;
let id = &monitored_validator.id; let id = &monitored_validator.id;
@ -433,7 +439,8 @@ impl<T: EthSpec> ValidatorMonitor<T> {
&metrics::VALIDATOR_MONITOR_PREV_EPOCH_ON_CHAIN_ATTESTER_HIT, &metrics::VALIDATOR_MONITOR_PREV_EPOCH_ON_CHAIN_ATTESTER_HIT,
&[id], &[id],
); );
info!( attestation_success.push(id);
debug!(
self.log, self.log,
"Previous epoch attestation success"; "Previous epoch attestation success";
"matched_source" => previous_epoch_matched_source, "matched_source" => previous_epoch_matched_source,
@ -447,7 +454,8 @@ impl<T: EthSpec> ValidatorMonitor<T> {
&metrics::VALIDATOR_MONITOR_PREV_EPOCH_ON_CHAIN_ATTESTER_MISS, &metrics::VALIDATOR_MONITOR_PREV_EPOCH_ON_CHAIN_ATTESTER_MISS,
&[id], &[id],
); );
error!( attestation_miss.push(id);
debug!(
self.log, self.log,
"Previous epoch attestation missing"; "Previous epoch attestation missing";
"epoch" => prev_epoch, "epoch" => prev_epoch,
@ -466,7 +474,8 @@ impl<T: EthSpec> ValidatorMonitor<T> {
&metrics::VALIDATOR_MONITOR_PREV_EPOCH_ON_CHAIN_HEAD_ATTESTER_MISS, &metrics::VALIDATOR_MONITOR_PREV_EPOCH_ON_CHAIN_HEAD_ATTESTER_MISS,
&[id], &[id],
); );
warn!( head_miss.push(id);
debug!(
self.log, self.log,
"Attestation failed to match head"; "Attestation failed to match head";
"epoch" => prev_epoch, "epoch" => prev_epoch,
@ -485,7 +494,8 @@ impl<T: EthSpec> ValidatorMonitor<T> {
&metrics::VALIDATOR_MONITOR_PREV_EPOCH_ON_CHAIN_TARGET_ATTESTER_MISS, &metrics::VALIDATOR_MONITOR_PREV_EPOCH_ON_CHAIN_TARGET_ATTESTER_MISS,
&[id], &[id],
); );
warn!( target_miss.push(id);
debug!(
self.log, self.log,
"Attestation failed to match target"; "Attestation failed to match target";
"epoch" => prev_epoch, "epoch" => prev_epoch,
@ -504,7 +514,8 @@ impl<T: EthSpec> ValidatorMonitor<T> {
); );
if let Some(inclusion_delay) = min_inclusion_distance { if let Some(inclusion_delay) = min_inclusion_distance {
if inclusion_delay > spec.min_attestation_inclusion_delay { if inclusion_delay > spec.min_attestation_inclusion_delay {
warn!( suboptimal_inclusion.push(id);
debug!(
self.log, self.log,
"Potential sub-optimal inclusion delay"; "Potential sub-optimal inclusion delay";
"optimal" => spec.min_attestation_inclusion_delay, "optimal" => spec.min_attestation_inclusion_delay,
@ -562,6 +573,52 @@ impl<T: EthSpec> ValidatorMonitor<T> {
} }
} }
// 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(()) Ok(())
} }