From 843f6497ca0c3cdc4117b6b9fa2f84934bb64981 Mon Sep 17 00:00:00 2001 From: Nico Flaig Date: Wed, 27 Sep 2023 16:39:37 +0200 Subject: [PATCH] feat: add option to log validator monitor events as info --- packages/beacon-node/src/metrics/metrics.ts | 2 +- packages/beacon-node/src/metrics/options.ts | 12 +-- .../src/metrics/validatorMonitor.ts | 78 ++++++++++++------- packages/cli/src/cmds/beacon/handler.ts | 1 + packages/cli/src/cmds/beacon/options.ts | 6 ++ 5 files changed, 66 insertions(+), 33 deletions(-) diff --git a/packages/beacon-node/src/metrics/metrics.ts b/packages/beacon-node/src/metrics/metrics.ts index 5adb4bffac97..58a48e34bbd5 100644 --- a/packages/beacon-node/src/metrics/metrics.ts +++ b/packages/beacon-node/src/metrics/metrics.ts @@ -25,7 +25,7 @@ export function createMetrics( const lodestar = createLodestarMetrics(register, opts.metadata, anchorState); const genesisTime = anchorState.genesisTime; - const validatorMonitor = createValidatorMonitor(lodestar, config, genesisTime, logger); + const validatorMonitor = createValidatorMonitor(lodestar, config, genesisTime, logger, opts); // Register a single collect() function to run all validatorMonitor metrics lodestar.validatorMonitor.validatorsConnected.addCollect(() => { const clockSlot = getCurrentSlot(config, genesisTime); diff --git a/packages/beacon-node/src/metrics/options.ts b/packages/beacon-node/src/metrics/options.ts index 9a19e033a291..1abfb6c7ffd1 100644 --- a/packages/beacon-node/src/metrics/options.ts +++ b/packages/beacon-node/src/metrics/options.ts @@ -1,4 +1,5 @@ import {HttpMetricsServerOpts} from "./server/index.js"; +import {ValidatorMonitorOpts} from "./validatorMonitor.js"; export type LodestarMetadata = { /** "v0.16.0/developer/feature-1/ac99f2b5" */ @@ -9,11 +10,12 @@ export type LodestarMetadata = { network: string; }; -export type MetricsOptions = HttpMetricsServerOpts & { - enabled: boolean; - /** Optional metadata to send to Prometheus */ - metadata?: LodestarMetadata; -}; +export type MetricsOptions = ValidatorMonitorOpts & + HttpMetricsServerOpts & { + enabled: boolean; + /** Optional metadata to send to Prometheus */ + metadata?: LodestarMetadata; + }; export const defaultMetricsOptions: MetricsOptions = { enabled: false, diff --git a/packages/beacon-node/src/metrics/validatorMonitor.ts b/packages/beacon-node/src/metrics/validatorMonitor.ts index de350c36ccbe..699443cde4df 100644 --- a/packages/beacon-node/src/metrics/validatorMonitor.ts +++ b/packages/beacon-node/src/metrics/validatorMonitor.ts @@ -9,7 +9,7 @@ import { getBlockRootAtSlot, ParticipationFlags, } from "@lodestar/state-transition"; -import {Logger, MapDef, MapDefMax, toHex} from "@lodestar/utils"; +import {LogData, LogHandler, LogLevel, Logger, MapDef, MapDefMax, toHex} from "@lodestar/utils"; import {RootHex, allForks, altair, deneb} from "@lodestar/types"; import {ChainConfig, ChainForkConfig} from "@lodestar/config"; import {ForkSeq, INTERVALS_PER_SLOT, MIN_ATTESTATION_INCLUSION_DELAY, SLOTS_PER_EPOCH} from "@lodestar/params"; @@ -76,6 +76,11 @@ export type ValidatorMonitor = { scrapeMetrics(slotClock: Slot): void; }; +export type ValidatorMonitorOpts = { + /** Log validator monitor events as info */ + validatorMonitorLogs?: boolean; +}; + /** Information required to reward some validator during the current and previous epoch. */ type ValidatorStatus = { /** True if the validator has been slashed, ever. */ @@ -136,7 +141,7 @@ type EpochSummary = { /** The delay between when the attestation should have been produced and when it was observed. */ attestationMinDelay: Seconds | null; /** The number of times a validators attestation was seen in an aggregate. */ - attestationAggregateIncusions: number; + attestationAggregateInclusions: number; /** The number of times a validators attestation was seen in a block. */ attestationBlockInclusions: number; /** The minimum observed inclusion distance for an attestation for this epoch.. */ @@ -176,7 +181,7 @@ function getEpochSummary(validator: MonitoredValidator, epoch: Epoch): EpochSumm summary = { attestations: 0, attestationMinDelay: null, - attestationAggregateIncusions: 0, + attestationAggregateInclusions: 0, attestationBlockInclusions: 0, attestationMinBlockInclusionDistance: null, blocks: 0, @@ -239,8 +244,14 @@ export function createValidatorMonitor( metrics: LodestarMetrics, config: ChainForkConfig, genesisTime: number, - logger: Logger + logger: Logger, + opts: ValidatorMonitorOpts ): ValidatorMonitor { + const log: LogHandler = (message: string, context?: LogData) => { + const logLevel = opts.validatorMonitorLogs ? LogLevel.info : LogLevel.debug; + logger[logLevel](message, context); + }; + /** The validators that require additional monitoring. */ const validators = new MapDef(() => ({ summaries: new Map(), @@ -345,8 +356,8 @@ export function createValidatorMonitor( } if (!summary.isPrevSourceAttester || !summary.isPrevTargetAttester || !summary.isPrevHeadAttester) { - logger.debug("Failed attestation in previous epoch", { - validatorIndex: index, + log("Failed attestation in previous epoch", { + validator: index, prevEpoch: currentEpoch - 1, isPrevSourceAttester: summary.isPrevSourceAttester, isPrevHeadAttester: summary.isPrevHeadAttester, @@ -411,13 +422,13 @@ export function createValidatorMonitor( if (validator) { metrics.validatorMonitor.unaggregatedAttestationSubmittedSentPeers.observe(sentPeers); metrics.validatorMonitor.unaggregatedAttestationDelaySeconds.observe({src: OpSource.api}, delaySec); - logger.debug("Local validator published unaggregated attestation", { - validatorIndex: index, + log("Published unaggregated attestation", { + validator: index, slot: data.slot, committeeIndex: data.index, subnet, sentPeers, - delaySec, + delaySec: delaySec.toFixed(4), }); const attestationSummary = validator.attestations @@ -461,12 +472,12 @@ export function createValidatorMonitor( const validator = validators.get(index); if (validator) { metrics.validatorMonitor.aggregatedAttestationDelaySeconds.observe({src: OpSource.api}, delaySec); - logger.debug("Local validator published aggregated attestation", { - validatorIndex: index, + log("Published aggregated attestation", { + validator: index, slot: data.slot, committeeIndex: data.index, sentPeers, - delaySec, + delaySec: delaySec.toFixed(4), }); validator.attestations @@ -481,15 +492,15 @@ export function createValidatorMonitor( const src = OpSource.gossip; const data = indexedAttestation.data; const epoch = computeEpochAtSlot(data.slot); - // Returns the duration between when a `AggregateAndproof` with `data` could be produced (2/3rd through the slot) and `seenTimestamp`. + // Returns the duration between when a `AggregateAndProof` with `data` could be produced (2/3rd through the slot) and `seenTimestamp`. const delaySec = seenTimestampSec - (genesisTime + (data.slot + 2 / 3) * config.SECONDS_PER_SLOT); const aggregatorIndex = signedAggregateAndProof.message.aggregatorIndex; - const validtorAggregator = validators.get(aggregatorIndex); - if (validtorAggregator) { + const validatorAggregator = validators.get(aggregatorIndex); + if (validatorAggregator) { metrics.validatorMonitor.aggregatedAttestationTotal.inc({src}); metrics.validatorMonitor.aggregatedAttestationDelaySeconds.observe({src}, delaySec); - const summary = getEpochSummary(validtorAggregator, epoch); + const summary = getEpochSummary(validatorAggregator, epoch); summary.aggregates += 1; summary.aggregateMinDelay = Math.min(delaySec, summary.aggregateMinDelay ?? Infinity); } @@ -500,11 +511,12 @@ export function createValidatorMonitor( metrics.validatorMonitor.attestationInAggregateTotal.inc({src}); metrics.validatorMonitor.attestationInAggregateDelaySeconds.observe({src}, delaySec); const summary = getEpochSummary(validator, epoch); - summary.attestationAggregateIncusions += 1; - logger.debug("Local validator attestation is included in AggregatedAndProof", { - validatorIndex: index, + summary.attestationAggregateInclusions += 1; + log("Attestation is included in aggregate", { + validator: index, slot: data.slot, committeeIndex: data.index, + aggregatorIndex, }); validator.attestations @@ -562,8 +574,8 @@ export function createValidatorMonitor( attestationSlot: indexedAttestation.data.slot, }); - logger.debug("Local validator attestation is included in block", { - validatorIndex: index, + log("Attestation is included in block", { + validator: index, slot: data.slot, committeeIndex: data.index, inclusionDistance, @@ -627,8 +639,12 @@ export function createValidatorMonitor( for (const [index, validator] of validators.entries()) { const flags = parseParticipationFlags(previousEpochParticipation.get(index)); const attestationSummary = validator.attestations.get(prevEpoch)?.get(prevEpochTargetRoot); - metrics.validatorMonitor.prevEpochAttestationSummary.inc({ - summary: renderAttestationSummary(config, rootCache, attestationSummary, flags), + const summary = renderAttestationSummary(config, rootCache, attestationSummary, flags); + metrics.validatorMonitor.prevEpochAttestationSummary.inc({summary}); + log("Previous epoch attestation", { + validator: index, + epoch: prevEpoch, + summary, }); } } @@ -639,9 +655,15 @@ export function createValidatorMonitor( const validator = validators.get(validatorIndex); if (validator) { // If expected proposer is a tracked validator - const summary = validator.summaries.get(prevEpoch); - metrics.validatorMonitor.prevEpochBlockProposalSummary.inc({ - summary: renderBlockProposalSummary(config, rootCache, summary, SLOTS_PER_EPOCH * prevEpoch + slotIndex), + const epochSummary = validator.summaries.get(prevEpoch); + const proposalSlot = SLOTS_PER_EPOCH * prevEpoch + slotIndex; + const summary = renderBlockProposalSummary(config, rootCache, epochSummary, proposalSlot); + metrics.validatorMonitor.prevEpochBlockProposalSummary.inc({summary}); + log("Previous epoch block proposal", { + validator: validatorIndex, + slot: proposalSlot, + epoch: prevEpoch, + summary, }); } } @@ -698,7 +720,9 @@ export function createValidatorMonitor( metrics.validatorMonitor.prevEpochAttestations.observe(summary.attestations); if (summary.attestationMinDelay !== null) metrics.validatorMonitor.prevEpochAttestationsMinDelaySeconds.observe(summary.attestationMinDelay); - metrics.validatorMonitor.prevEpochAttestationAggregateInclusions.observe(summary.attestationAggregateIncusions); + metrics.validatorMonitor.prevEpochAttestationAggregateInclusions.observe( + summary.attestationAggregateInclusions + ); metrics.validatorMonitor.prevEpochAttestationBlockInclusions.observe(summary.attestationBlockInclusions); if (summary.attestationMinBlockInclusionDistance !== null) { metrics.validatorMonitor.prevEpochAttestationBlockMinInclusionDistance.observe( diff --git a/packages/cli/src/cmds/beacon/handler.ts b/packages/cli/src/cmds/beacon/handler.ts index 0d7fd8b4521a..4a61c4ab9dee 100644 --- a/packages/cli/src/cmds/beacon/handler.ts +++ b/packages/cli/src/cmds/beacon/handler.ts @@ -169,6 +169,7 @@ export async function beaconHandlerInit(args: BeaconArgs & GlobalArgs) { beaconNodeOptions.set({chain: {persistInvalidSszObjectsDir: beaconPaths.persistInvalidSszObjectsDir}}); // Add metrics metadata to show versioning + network info in Prometheus + Grafana beaconNodeOptions.set({metrics: {metadata: {version, commit, network}}}); + beaconNodeOptions.set({metrics: {validatorMonitorLogs: args.validatorMonitorLogs}}); // Add detailed version string for API node/version endpoint beaconNodeOptions.set({api: {version}}); diff --git a/packages/cli/src/cmds/beacon/options.ts b/packages/cli/src/cmds/beacon/options.ts index db593e7d7224..fff9a0912db6 100644 --- a/packages/cli/src/cmds/beacon/options.ts +++ b/packages/cli/src/cmds/beacon/options.ts @@ -20,6 +20,7 @@ type BeaconExtraArgs = { peerStoreDir?: string; persistNetworkIdentity?: boolean; private?: boolean; + validatorMonitorLogs?: boolean; attachToGlobalThis?: boolean; }; @@ -120,6 +121,11 @@ export const beaconExtraOptions: CliCommandOptions = { type: "boolean", }, + validatorMonitorLogs: { + description: "Log validator monitor events as info. This requires metrics to be enabled.", + type: "boolean", + }, + attachToGlobalThis: { hidden: true, description: "Attach the beacon node to `globalThis`. Useful to inspect a running beacon node.",