From edcbbfed7253fb92d08917ffbbf668eaa8717285 Mon Sep 17 00:00:00 2001 From: iurii Date: Tue, 26 May 2026 16:31:14 +0300 Subject: [PATCH 1/5] observability: restart-resilient counters + proposal-parent labels MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Phase 1 of ssvlabs/ssv-node-board#1069. Splits observability.Initialize into InitializeLogger (early) and Initialize (late) so operator_id can be baked into OTel resource attributes after operatorDataStore is ready — every metric and trace then carries ssv.operator_id automatically. New WithResourceAttributes option carries the late-known attribute set. New operators not yet registered on-chain are emitted without the label rather than with operator_id=0; they pick it up after a restart following registration. Adds observability/metrics.RegisterSparseCounter + EmitBaselines so PromQL increase()/rate() return correct values after process restart. Applied to 26 sparse counters across 10 packages (proposal_parent and attestation_data sets in beacon/goclient plus 16 vulnerable counters from a broader audit: network/streams oversized payloads, network/peers connection events, network/discovery skipped peers, message/validation ignored/rejected, eth/executionclient client lifecycle + RPC errors, eth/eventhandler failures, operator/validator removals/errors/dropped, protocol/v2/ssv/runner submission failures, protocol/v2/qbft round changes). Limitation: only baselines the unlabeled series — counters that emit with per-call attributes still produce one un-baselined series per attribute set on first labeled increment. Per-attribute-set baselines are future work. beacon/goclient/proposer.go: - slot==0 guard in verifyProposalParent (prevents uint64 underflow) - demote mismatch log from Warn to Info: observability-only with no corrective action, and the metric commonly fires during normal fork resolution (cache-vs-BN drift) rather than true staleness — Warn was alert noise - thread bestClient through getProposalParallel and label all four proposal_parent counter Add() sites with ssv.beacon.client Incidental cleanups: - observability/metrics and observability/traces package loggers default to zap.NewNop() so they don't panic on a nil pointer if InitLogger hasn't been called yet (latent bug) - operator/validator validators.removed description corrected from "total number of validator errors" copy-paste Deferred to follow-ups (noted in #1069): - beacon_client label for the 8 attestation_data counters (simpleAttestationData uses gc.multiClient which doesn't expose which underlying client returned the data) - ssvsigner sparse counters (separate Go module — needs a small duplicate of the baseline mechanism there) - per-attribute-set baselines for fully-labeled increase()/rate() to work after restart --- beacon/goclient/observability.go | 51 +++++++++------ beacon/goclient/proposer.go | 49 ++++++++++---- cli/operator/node.go | 76 +++++++++++++++------- eth/eventhandler/observability.go | 5 +- eth/executionclient/observability.go | 21 +++--- message/validation/observability.go | 9 +-- network/discovery/observability.go | 6 +- network/peers/connections/observability.go | 13 ++-- network/streams/observability.go | 5 +- observability/attributes.go | 18 +++++ observability/config.go | 14 ++-- observability/configurator.go | 63 ++++++++++-------- observability/metrics/baseline.go | 60 +++++++++++++++++ observability/metrics/metric.go | 5 +- observability/option.go | 26 ++++---- observability/resources.go | 16 +++-- observability/traces/trace.go | 6 +- operator/validator/observability.go | 15 +++-- protocol/v2/qbft/instance/observability.go | 5 +- protocol/v2/ssv/runner/observability.go | 5 +- 20 files changed, 321 insertions(+), 147 deletions(-) create mode 100644 observability/metrics/baseline.go diff --git a/beacon/goclient/observability.go b/beacon/goclient/observability.go index b81ab95e79..8203a16d0a 100644 --- a/beacon/goclient/observability.go +++ b/beacon/goclient/observability.go @@ -70,66 +70,75 @@ var ( metric.WithUnit("{match}"), metric.WithDescription("attestation data head matched cached HeadEvent"))) - attestationDataHeadCacheMissCounter = metrics.New( + // Sparse: only fires when cache lookup fails for an attestation; registered for + // baseline emission so increase()/rate() work correctly after process restart. + attestationDataHeadCacheMissCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "attestation_data.head_cache_miss"), metric.WithUnit("{miss}"), - metric.WithDescription("head root was not cached (no verification performed)"))) + metric.WithDescription("head root was not cached (no verification performed)")))) - attestationDataHeadMismatchCounter = metrics.New( + // Sparse: only fires on a head-mismatch (rare condition). + attestationDataHeadMismatchCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "attestation_data.head_mismatch"), metric.WithUnit("{mismatch}"), - metric.WithDescription("attestation data head did not match cached HeadEvent"))) + metric.WithDescription("attestation data head did not match cached HeadEvent")))) - attestationDataRefetchSuccessCounter = metrics.New( + // Sparse: only fires when a re-fetch succeeds (which only happens after a mismatch). + attestationDataRefetchSuccessCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "attestation_data.refetch_success"), metric.WithUnit("{refetch}"), - metric.WithDescription("re-fetch got correct head after mismatch"))) + metric.WithDescription("re-fetch got correct head after mismatch")))) - attestationDataRefetchFailedCounter = metrics.New( + // Sparse: only fires on re-fetch failure (which only happens after a mismatch). + attestationDataRefetchFailedCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "attestation_data.refetch_failed"), metric.WithUnit("{refetch}"), - metric.WithDescription("re-fetch failed or timed out"))) + metric.WithDescription("re-fetch failed or timed out")))) - attestationDataRefetchStillMismatchCounter = metrics.New( + // Sparse: only fires when a re-fetch returns the same stale data (likely reorg). + attestationDataRefetchStillMismatchCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "attestation_data.refetch_still_mismatch"), metric.WithUnit("{refetch}"), - metric.WithDescription("re-fetch still had wrong head (possible reorg)"))) + metric.WithDescription("re-fetch still had wrong head (possible reorg)")))) - attestationDataRefetchSkippedCounter = metrics.New( + // Sparse: only fires when re-fetch is skipped due to insufficient deadline budget. + attestationDataRefetchSkippedCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "attestation_data.refetch_skipped"), metric.WithUnit("{skip}"), - metric.WithDescription("retry skipped due to insufficient time before deadline"))) + metric.WithDescription("retry skipped due to insufficient time before deadline")))) - // Proposal parent verification metrics (observability only, no re-fetch) - proposalParentVerifyCounter = metrics.New( + // Proposal parent verification metrics (observability only, no re-fetch). All four are + // sparse — proposals occur once per slot at most, and only when this operator is the + // proposer for the slot. Registered for baseline emission so increase()/rate() work. + proposalParentVerifyCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "proposal.parent_verify"), metric.WithUnit("{verification}"), - metric.WithDescription("total proposals that attempted parent root verification"))) + metric.WithDescription("total proposals that attempted parent root verification")))) - proposalParentMatchCounter = metrics.New( + proposalParentMatchCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "proposal.parent_match"), metric.WithUnit("{match}"), - metric.WithDescription("proposal parent root matched cached HeadEvent"))) + metric.WithDescription("proposal parent root matched cached HeadEvent")))) - proposalParentCacheMissCounter = metrics.New( + proposalParentCacheMissCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "proposal.parent_cache_miss"), metric.WithUnit("{miss}"), - metric.WithDescription("parent slot head was not cached (no verification performed)"))) + metric.WithDescription("parent slot head was not cached (no verification performed)")))) - proposalParentMismatchCounter = metrics.New( + proposalParentMismatchCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "proposal.parent_mismatch"), metric.WithUnit("{mismatch}"), - metric.WithDescription("proposal parent root did not match cached HeadEvent"))) + metric.WithDescription("proposal parent root did not match cached HeadEvent")))) ) func recordRequest( diff --git a/beacon/goclient/proposer.go b/beacon/goclient/proposer.go index a072c476f0..fd0eee57a1 100644 --- a/beacon/goclient/proposer.go +++ b/beacon/goclient/proposer.go @@ -22,8 +22,10 @@ import ( "github.com/attestantio/go-eth2-client/spec/phase0" ssz "github.com/ferranbt/fastssz" spectypes "github.com/ssvlabs/ssv-spec/types" + "go.opentelemetry.io/otel/metric" "go.uber.org/zap" + "github.com/ssvlabs/ssv/observability" "github.com/ssvlabs/ssv/observability/log/fields" "github.com/ssvlabs/ssv/observability/traces" ) @@ -97,24 +99,27 @@ func (gc *GoClient) GetBeaconBlock( copy(graffiti[:], graffitiBytes[:]) var beaconBlock *api.VersionedProposal + var beaconClient string // address of the BN that produced the selected proposal — used for metric labeling var err error // For single client, use direct call to avoid multi-client overhead if len(gc.clients) == 1 { - beaconBlock, err = gc.fetchProposal(ctx, gc.clients[0], slot, sig, graffiti) + client := gc.clients[0] + beaconBlock, err = gc.fetchProposal(ctx, client, slot, sig, graffiti) if err != nil { return nil, nil, err } + beaconClient = client.Address() } else { // For multiple clients, race them in parallel for the fastest response - beaconBlock, err = gc.getProposalParallel(ctx, logger, slot, sig, graffiti) + beaconBlock, beaconClient, err = gc.getProposalParallel(ctx, logger, slot, sig, graffiti) if err != nil { return nil, nil, err } } // Verify proposal parent root against cached HeadEvent (observability only). - gc.verifyProposalParent(ctx, logger, slot, beaconBlock) + gc.verifyProposalParent(ctx, logger, slot, beaconBlock, beaconClient) // Check and log if fee recipient is missing (for both single and multi-client paths) feeRecipient, err := beaconBlock.FeeRecipient() @@ -173,13 +178,17 @@ func (gc *GoClient) GetBeaconBlock( // The parent context (from duty runner, bounded by slot timing) serves as the hard // deadline. We never give up early on getting a block proposal - missing a proposal // is catastrophic, so we wait as long as the slot allows. +// +// Returns the selected proposal along with the address of the beacon client that +// produced it — used for metric labeling so we can attribute stale-parent proposals +// (and other diagnostics) to specific beacon clients in operators' setups. func (gc *GoClient) getProposalParallel( ctx context.Context, logger *zap.Logger, slot phase0.Slot, sig phase0.BLSSignature, graffiti [32]byte, -) (*api.VersionedProposal, error) { +) (*api.VersionedProposal, string, error) { // Create a context for the collection period - during this time we gather // proposals from multiple beacon nodes to select the best one. // After this expires, we return the best seen so far or wait for the first valid one. @@ -274,7 +283,7 @@ collect: fields.Slot(slot), ) - return bestProposal, nil + return bestProposal, bestClient, nil } logger.Debug("did not receive any valid proposals during the collection period", @@ -304,15 +313,15 @@ collect: zap.Bool("blinded", res.proposal.Blinded), fields.Slot(slot), ) - return res.proposal, nil + return res.proposal, res.client, nil case <-ctx.Done(): // Parent context canceled (duty deadline reached) - return nil, ctx.Err() + return nil, "", ctx.Err() } } - return nil, fmt.Errorf("all %d clients failed to get proposal for slot %d, encountered errors: %w", len(gc.clients), slot, errs) + return nil, "", fmt.Errorf("all %d clients failed to get proposal for slot %d, encountered errors: %w", len(gc.clients), slot, errs) } // scoreProposal computes a score for a beacon proposal. @@ -326,13 +335,23 @@ func (gc *GoClient) scoreProposal( // verifyProposalParent checks the proposal's parent root against cached HeadEvent. // This is observability only - no re-fetch, just metrics and logging. +// beaconClient is the address of the beacon node that produced the proposal, attached as +// a metric label so per-client staleness rates can be measured. func (gc *GoClient) verifyProposalParent( ctx context.Context, logger *zap.Logger, slot phase0.Slot, proposal *api.VersionedProposal, + beaconClient string, ) { - proposalParentVerifyCounter.Add(ctx, 1) + if slot == 0 { + // Genesis has no parent to verify; also guards against uint64 underflow below. + return + } + + clientAttr := metric.WithAttributes(observability.BeaconClientAttribute(beaconClient)) + + proposalParentVerifyCounter.Add(ctx, 1, clientAttr) parentRoot, err := proposal.ParentRoot() if err != nil { @@ -344,22 +363,26 @@ func (gc *GoClient) verifyProposalParent( parentSlot := slot - 1 item := gc.headCache.Get(parentSlot) if item == nil { - proposalParentCacheMissCounter.Add(ctx, 1) + proposalParentCacheMissCounter.Add(ctx, 1, clientAttr) return } expectedRoot := item.Value() if parentRoot == expectedRoot { - proposalParentMatchCounter.Add(ctx, 1) + proposalParentMatchCounter.Add(ctx, 1, clientAttr) return } - proposalParentMismatchCounter.Add(ctx, 1) - logger.Warn("proposal parent root mismatch detected", + proposalParentMismatchCounter.Add(ctx, 1, clientAttr) + // Logged at Info: this is observability-only with no corrective action. The metric + // commonly fires during normal fork resolution (cache-vs-BN drift), not staleness — + // Warn would create alert fatigue. Revisit if the check becomes actionable. + logger.Info("proposal parent root mismatch detected", fields.Slot(slot), zap.Uint64("parent_slot", uint64(parentSlot)), zap.Stringer("expected_root", expectedRoot), zap.Stringer("got_root", parentRoot), + zap.String("beacon_client", beaconClient), ) } diff --git a/cli/operator/node.go b/cli/operator/node.go index c3df393f1f..539bd2d39a 100644 --- a/cli/operator/node.go +++ b/cli/operator/node.go @@ -147,16 +147,26 @@ var StartNodeCmd = &cobra.Command{ } } - observabilityOptions := []observability.Option{ - observability.WithLogger( - cfg.LogLevel, - cfg.LogLevelFormat, - cfg.LogFormat, - cfg.LogFilePath, - cfg.LogFileSize, - cfg.LogFileBackups, - ), + if err := observability.InitializeLogger( + cfg.LogLevel, + cfg.LogLevelFormat, + cfg.LogFormat, + cfg.LogFilePath, + cfg.LogFileSize, + cfg.LogFileBackups, + ); err != nil { + log.Fatal("could not initialize logger", zap.Error(err)) } + + logger := zap.L() + defer ssvlog.CapturePanic(logger) + + // Metric and trace provider initialization is deferred until later in startup + // (after operatorDataStore is set up) so that operator_id can be baked into the + // OTel resource attributes — every emitted metric/trace is then automatically + // labeled with the operator. Metrics emitted before that point are dropped, which + // is an acceptable trade-off for accurate per-operator labeling. + observabilityOptions := []observability.Option{} if cfg.MetricsAPIPort > 0 { observabilityOptions = append(observabilityOptions, observability.WithMetrics()) } @@ -164,22 +174,14 @@ var StartNodeCmd = &cobra.Command{ observabilityOptions = append(observabilityOptions, observability.WithTraces()) } - observabilityShutdown, err := observability.Initialize( - cmd.Context(), - cmd.Parent().Short, - cmd.Parent().Version, - observabilityOptions...) - if err != nil { - log.Fatal("could not initialize observability configuration", zap.Error(err)) - } - - logger := zap.L() - defer ssvlog.CapturePanic(logger) - + var observabilityShutdown func(context.Context) error defer func() { + if observabilityShutdown == nil { + return // Initialize never ran (e.g. fatal before reaching it) + } shutdownCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second) defer cancel() - if err = observabilityShutdown(shutdownCtx); err != nil { + if err := observabilityShutdown(shutdownCtx); err != nil { logger.Error("could not shutdown observability stack", zap.Error(err)) } }() @@ -359,6 +361,36 @@ var StartNodeCmd = &cobra.Command{ cfg.P2pNetworkConfig.Ctx = cmd.Context() operatorDataStore := setupOperatorDataStore(logger, nodeStorage, operatorPubKeyBase64) + + // Now that operatorDataStore is set up, initialize metric + trace providers with + // operator_id baked into the OTel resource attributes (only if the ID is ready — + // new operators not yet registered on-chain will have ID=0 and we skip the label + // rather than emit misleading metrics; the operator will need to restart after + // registration to pick up the correct ID in metric labels). + if operatorDataStore.OperatorIDReady() { + observabilityOptions = append(observabilityOptions, + observability.WithResourceAttributes( + observability.OperatorIDAttribute(operatorDataStore.GetOperatorID()), + ), + ) + } + observabilityShutdown, err = observability.Initialize( + cmd.Context(), + cmd.Parent().Short, + cmd.Parent().Version, + observabilityOptions..., + ) + if err != nil { + logger.Fatal("could not initialize observability metrics/traces", zap.Error(err)) + } + + // Emit baseline (zero) samples for sparse counters so PromQL increase()/rate() + // returns correct values across process restarts. See observability/metrics/baseline.go. + // Caveat: this only baselines the unlabeled time series; counters that emit with + // per-call attributes still produce one un-baselined series per attribute set on + // first increment — improving that is future work (per-attribute-set baselines). + metrics.EmitBaselines(cmd.Context()) + validatorProvider := nodeStorage.ValidatorStore().WithOperatorID(operatorDataStore.GetOperatorID) var validatorRegistrationSubmitter runner.ValidatorRegistrationSubmitter if !cfg.ExporterOptions.Enabled { diff --git a/eth/eventhandler/observability.go b/eth/eventhandler/observability.go index a53c240243..12a391c977 100644 --- a/eth/eventhandler/observability.go +++ b/eth/eventhandler/observability.go @@ -25,11 +25,12 @@ var ( metric.WithUnit("{event}"), metric.WithDescription("total number of successfully processed events(logs)"))) - eventsProcessFailureCounter = metrics.New( + // Sparse: only fires when contract event processing fails (rare). + eventsProcessFailureCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "events_failed"), metric.WithUnit("{event}"), - metric.WithDescription("total number of failures during event(log) processing"))) + metric.WithDescription("total number of failures during event(log) processing")))) lastProcessedBlockGauge = metrics.New( meter.Int64Gauge( diff --git a/eth/executionclient/observability.go b/eth/executionclient/observability.go index 1c7a370c5e..4afe283ec2 100644 --- a/eth/executionclient/observability.go +++ b/eth/executionclient/observability.go @@ -58,21 +58,22 @@ var ( metric.WithUnit("{block_number}"), metric.WithDescription("last processed block by execution client"))) - // MultiClient metrics - clientSwitchCounter = metrics.New( + // Sparse: only fires on multi-client failover (rare). + clientSwitchCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "client.switch"), - metric.WithDescription("number of times the execution client has been switched"))) + metric.WithDescription("number of times the execution client has been switched")))) multiClientMethodCallsCounter = metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "multi_client.method_calls"), metric.WithDescription("number of method calls to the multi client"))) - multiClientMethodErrorsCounter = metrics.New( + // Sparse-ish: tracks RPC error rate which is typically low. + multiClientMethodErrorsCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "multi_client.method_errors"), - metric.WithDescription("number of method call errors in the multi client"))) + metric.WithDescription("number of method call errors in the multi client")))) multiClientMethodDurationHistogram = metrics.New( meter.Float64Histogram( @@ -93,15 +94,17 @@ var ( metric.WithUnit("{clients}"), metric.WithDescription("number of clients in the multi client"))) - clientInitCounter = metrics.New( + // Sparse: fires only at startup/recovery (rare lifecycle event). + clientInitCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "client.init"), - metric.WithDescription("number of times a client was initialized"))) + metric.WithDescription("number of times a client was initialized")))) - bloomCheckCounter = metrics.New( + // Sparse: only fires during bloom cross-check recovery scenarios. + bloomCheckCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "bloom.checks"), - metric.WithDescription("number of bloom cross-check outcomes by type"))) + metric.WithDescription("number of bloom cross-check outcomes by type")))) ) func recordRequest( diff --git a/message/validation/observability.go b/message/validation/observability.go index 1bc72940e0..a4ed95453c 100644 --- a/message/validation/observability.go +++ b/message/validation/observability.go @@ -27,17 +27,18 @@ var ( metric.WithUnit("{message_validation}"), metric.WithDescription("total number of messages successfully validated and accepted"))) - messageValidationsIgnoredCounter = metrics.New( + // Possibly sparse (UNKNOWN from audit): depends on validation failure rate. + messageValidationsIgnoredCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "ignored"), metric.WithUnit("{message_validation}"), - metric.WithDescription("total number of messages that failed validation and were ignored"))) + metric.WithDescription("total number of messages that failed validation and were ignored")))) - messageValidationsRejectedCounter = metrics.New( + messageValidationsRejectedCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "rejected"), metric.WithUnit("{message_validation}"), - metric.WithDescription("total number of messages that failed validation and were rejected"))) + metric.WithDescription("total number of messages that failed validation and were rejected")))) messageValidationDurationHistogram = metrics.New( meter.Float64Histogram( diff --git a/network/discovery/observability.go b/network/discovery/observability.go index 1ff2725e4f..e0b5947271 100644 --- a/network/discovery/observability.go +++ b/network/discovery/observability.go @@ -48,11 +48,13 @@ var ( metric.WithUnit("{peer}"), metric.WithDescription("total number of peers discovered"))) - peerRejectionsCounter = metrics.New( + // Possibly sparse (UNKNOWN from audit): peer rejections during discovery may be rare + // depending on network topology — register conservatively. + peerRejectionsCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "peers.skipped"), metric.WithUnit("{peer}"), - metric.WithDescription("total number of peers skipped during discovery"))) + metric.WithDescription("total number of peers skipped during discovery")))) peerAcceptedCounter = metrics.New( meter.Int64Counter( diff --git a/network/peers/connections/observability.go b/network/peers/connections/observability.go index af7ce85cba..903867639e 100644 --- a/network/peers/connections/observability.go +++ b/network/peers/connections/observability.go @@ -19,23 +19,24 @@ const ( var ( meter = otel.Meter(observabilityComponentName) - connectedCounter = metrics.New( + // Sparse: per-connection lifecycle events on a steady-state node are infrequent. + connectedCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "connected"), metric.WithUnit("{connection}"), - metric.WithDescription("total number of connected peers"))) + metric.WithDescription("total number of connected peers")))) - disconnectedCounter = metrics.New( + disconnectedCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "disconnected"), metric.WithUnit("{connection}"), - metric.WithDescription("total number of disconnected peers"))) + metric.WithDescription("total number of disconnected peers")))) - filteredCounter = metrics.New( + filteredCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "filtered"), metric.WithUnit("{connection}"), - metric.WithDescription("total number of filtered connections"))) + metric.WithDescription("total number of filtered connections")))) ) func recordConnected(ctx context.Context, direction network.Direction) { diff --git a/network/streams/observability.go b/network/streams/observability.go index 892390980b..177b1abf17 100644 --- a/network/streams/observability.go +++ b/network/streams/observability.go @@ -42,11 +42,12 @@ var ( metric.WithUnit("{response}"), metric.WithDescription("total number of stream responses received(as response to initiated by us request)"))) - oversizedPayloadsCounter = metrics.New( + // Sparse: only fires when a peer sends an oversized payload (rare). + oversizedPayloadsCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "payloads.oversized"), metric.WithUnit("{payload}"), - metric.WithDescription("total number of oversized stream payloads rejected"))) + metric.WithDescription("total number of oversized stream payloads rejected")))) ) func protocolIDAttribute(id protocol.ID) attribute.KeyValue { diff --git a/observability/attributes.go b/observability/attributes.go index 661d093dda..2c93abcdf9 100644 --- a/observability/attributes.go +++ b/observability/attributes.go @@ -23,6 +23,24 @@ const ( RunnerRoleAttrKey = "ssv.runner.role" ) +// OperatorIDAttribute identifies the SSV operator this process is running on behalf of. +// Typically set as an OTel resource attribute via observability.WithResourceAttributes so +// every metric and trace emitted by the process is labeled automatically — see also +// cli/operator/node.go where this is wired up after operatorDataStore initialization. +func OperatorIDAttribute(id spectypes.OperatorID) attribute.KeyValue { + return attribute.KeyValue{ + Key: "ssv.operator_id", + Value: Uint64AttributeValue(uint64(id)), + } +} + +// BeaconClientAttribute identifies which configured beacon client (by address) produced +// the data being measured. Useful for diagnosing which beacon returned stale data, etc. +// Per-call attribute (not a resource attribute) since operators may run multiple beacons. +func BeaconClientAttribute(addr string) attribute.KeyValue { + return attribute.String("ssv.beacon.client", addr) +} + func BeaconRoleAttribute(role spectypes.BeaconRole) attribute.KeyValue { return attribute.String("ssv.beacon.role", role.String()) } diff --git a/observability/config.go b/observability/config.go index a38685e7ee..eaab3041db 100644 --- a/observability/config.go +++ b/observability/config.go @@ -1,5 +1,7 @@ package observability +import "go.opentelemetry.io/otel/attribute" + type ( tracesConfig struct { enabled bool @@ -9,15 +11,9 @@ type ( enabled bool } - loggerConfig struct { - enabled bool - level, levelFormat, format, filePath string - fileSize, fileBackups int - } - Config struct { - traces tracesConfig - metrics metricsConfig - logger loggerConfig + traces tracesConfig + metrics metricsConfig + resourceAttrs []attribute.KeyValue } ) diff --git a/observability/configurator.go b/observability/configurator.go index 1f7c5034c2..443fbd6609 100644 --- a/observability/configurator.go +++ b/observability/configurator.go @@ -32,13 +32,48 @@ func init() { model.NameValidationScheme = model.LegacyValidation // nolint: staticcheck } +// InitializeLogger configures the global zap logger. It must be called before Initialize, +// and is split from Initialize so the logger is available during early startup (before +// process-global facts like operator_id are known, which delays metric/trace provider +// initialization — see Initialize and WithResourceAttributes). +func InitializeLogger(level, levelFormat, format, filePath string, fileSize, fileBackups int) error { + err := log.SetGlobal( + level, + levelFormat, + format, + &log.LogFileOptions{ + FilePath: filePath, + MaxSize: fileSize, + MaxBackups: fileBackups, + }, + ) + if err != nil { + return fmt.Errorf("could not setup global logger: %w", err) + } + // Propagate the configured logger to observability sub-packages so they can log. + _ = initLogger(zap.L()) + return nil +} + +// Initialize configures the OTel metric and trace providers. The global zap logger must +// already be set up (see InitializeLogger); this function intentionally does not touch the +// logger, so that callers can defer Initialize until late-known facts like operator_id are +// available to pass via WithResourceAttributes. func Initialize(ctx context.Context, appName, appVersion string, options ...Option) (shutdown func(context.Context) error, err error) { var ( - localLogger = zap.NewNop() config Config shutdownFuncs []func(context.Context) error ) + for _, option := range options { + option(&config) + } + + // Derive a named logger for Initialize's own log messages. metrics/traces internal + // loggers are propagated by InitializeLogger (which must be called first); we don't + // repeat that here to avoid the surprising side effect of replacing them mid-startup. + localLogger := zap.L().Named(log.NameObservability) + shutdown = func(ctx context.Context) error { var joinedErr error localLogger.Info("shutting down observability stack") @@ -50,32 +85,8 @@ func Initialize(ctx context.Context, appName, appVersion string, options ...Opti return joinedErr } - for _, option := range options { - option(&config) - } - - if config.logger.enabled { - err = log.SetGlobal( - config.logger.level, - config.logger.levelFormat, - config.logger.format, - &log.LogFileOptions{ - FilePath: config.logger.filePath, - MaxSize: config.logger.fileSize, - MaxBackups: config.logger.fileBackups, - }, - ) - if err != nil { - return nil, fmt.Errorf("could not setup global logger: %w", err) - } - - localLogger = initLogger(zap.L()) - - localLogger.Info("global logger initialized") - } - localLogger.Info("building OTel resources") - resources, err := buildResources(appName, appVersion, localLogger) + resources, err := buildResources(appName, appVersion, config.resourceAttrs, localLogger) if err != nil { return nil, fmt.Errorf("could not build OTel resources: %w", err) } diff --git a/observability/metrics/baseline.go b/observability/metrics/baseline.go new file mode 100644 index 0000000000..07f5241dbb --- /dev/null +++ b/observability/metrics/baseline.go @@ -0,0 +1,60 @@ +package metrics + +import ( + "context" + "sync" + + "go.opentelemetry.io/otel/metric" +) + +// Background: PromQL `increase()` and `rate()` compute the delta between two samples in a +// counter's time series. If a counter is "sparse" (rarely incremented — e.g. error events +// or other rare conditions), it may have no baseline sample for some windows: the series +// starts from the first non-zero increment, and Prometheus has nothing to subtract from. +// After a process restart, this gets worse — the in-process counter starts at 0 and only +// emits a sample on the first increment, which looks to Prometheus like 0→N with no +// previous baseline, so `increase()` returns 0 instead of N. +// +// The fix is to emit `Add(ctx, 0)` once at startup (after the MeterProvider is installed) +// for each sparse counter, guaranteeing a baseline sample is present. +// +// This file provides a tiny registry so each package's observability.go can declare which +// of its counters are sparse, and a single `EmitBaselines` call at startup writes zeros +// for all of them. +// +// High-volume counters (per-message, per-attestation, per-slot, etc.) do not need this +// treatment — they always have recent samples for Prometheus to work from. + +var ( + sparseCountersMu sync.Mutex + sparseCounters []metric.Int64Counter +) + +// RegisterSparseCounter declares a counter as sparse (rarely incremented). Returns the +// passed counter unchanged so it can wrap an instrument declaration inline. The counter +// is recorded for baseline emission via EmitBaselines. +// +// Typical use, inside a package-level var block in an observability.go file: +// +// myErrorCounter = metrics.RegisterSparseCounter( +// metrics.New(meter.Int64Counter(observability.InstrumentName(ns, "my_errors"), ...))) +// +// Call EmitBaselines exactly once at startup, after observability.Initialize has set up +// the MeterProvider. +func RegisterSparseCounter(c metric.Int64Counter) metric.Int64Counter { + sparseCountersMu.Lock() + defer sparseCountersMu.Unlock() + sparseCounters = append(sparseCounters, c) + return c +} + +// EmitBaselines emits Add(ctx, 0) for every counter registered via RegisterSparseCounter, +// giving Prometheus a baseline sample for each. Call once at startup after the OTel +// MeterProvider is installed (i.e. after observability.Initialize completes). +func EmitBaselines(ctx context.Context) { + sparseCountersMu.Lock() + defer sparseCountersMu.Unlock() + for _, c := range sparseCounters { + c.Add(ctx, 0) + } +} diff --git a/observability/metrics/metric.go b/observability/metrics/metric.go index b652a5c76d..3977da6127 100644 --- a/observability/metrics/metric.go +++ b/observability/metrics/metric.go @@ -10,7 +10,10 @@ import ( var ( // logger is defined as global var here to keep package API as simple as possible (instead of returning error we log them with this logger in some places) - logger *zap.Logger + // Defaults to a no-op logger so that calls during package init (e.g. metrics.New + // reporting instrument creation errors) don't panic if InitLogger hasn't run yet. + // InitLogger replaces this with the configured global zap logger. + logger = zap.NewNop() SecondsHistogramBuckets = []float64{0, 0.001, 0.005, 0.01, 0.025, 0.05, 0.075, 0.1, 0.25, 0.5, 0.75, 1, 2.5, 5, 7.5, 10} ) diff --git a/observability/option.go b/observability/option.go index 6f0d8d7e34..fde968df60 100644 --- a/observability/option.go +++ b/observability/option.go @@ -1,7 +1,19 @@ package observability +import "go.opentelemetry.io/otel/attribute" + type Option func(*Config) +// WithResourceAttributes adds custom attributes to the OTel resource describing this +// process. Every metric and trace emitted by the SDK is automatically annotated with +// the resource attributes — useful for late-known process-global facts like operator_id, +// which is only available after the operator data store is initialized. +func WithResourceAttributes(attrs ...attribute.KeyValue) Option { + return func(cfg *Config) { + cfg.resourceAttrs = append(cfg.resourceAttrs, attrs...) + } +} + // WithMetrics enables OpenTelemetry metrics collection for the application. // When enabled, a Prometheus provider will be initialized. // This means Prometheus will scrape metrics from a specific HTTP endpoint, @@ -22,17 +34,3 @@ func WithTraces() Option { } } -// WithLogger configures the global application logger. -// It sets log level, format, output file settings, and enables the logger. -// If this option is not applied, a no-op logger will be used instead. -func WithLogger(level, levelFormat, format, filePath string, fileSize, fileBackups int) Option { - return func(cfg *Config) { - cfg.logger.enabled = true - cfg.logger.level = level - cfg.logger.levelFormat = levelFormat - cfg.logger.format = format - cfg.logger.filePath = filePath - cfg.logger.fileSize = fileSize - cfg.logger.fileBackups = fileBackups - } -} diff --git a/observability/resources.go b/observability/resources.go index 3347e665f2..14a030b139 100644 --- a/observability/resources.go +++ b/observability/resources.go @@ -4,12 +4,13 @@ import ( "fmt" "os" + "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/sdk/resource" semconv "go.opentelemetry.io/otel/semconv/v1.37.0" "go.uber.org/zap" ) -func buildResources(appName, appVersion string, logger *zap.Logger) (*resource.Resource, error) { +func buildResources(appName, appVersion string, extraAttrs []attribute.KeyValue, logger *zap.Logger) (*resource.Resource, error) { const defaultHostname = "unknown" hostName, err := os.Hostname() @@ -20,12 +21,19 @@ func buildResources(appName, appVersion string, logger *zap.Logger) (*resource.R hostName = defaultHostname } - const errMsg = "failed to merge OTeL Resources" - resources, err := resource.Merge(resource.Default(), resource.NewWithAttributes( - semconv.SchemaURL, + // Build the base attribute set, then append any caller-supplied extras (e.g. operator_id + // which is only known after the operator data store is initialized). + baseAttrs := []attribute.KeyValue{ semconv.ServiceName(appName), semconv.ServiceVersion(appVersion), semconv.HostName(hostName), + } + baseAttrs = append(baseAttrs, extraAttrs...) + + const errMsg = "failed to merge OTeL Resources" + resources, err := resource.Merge(resource.Default(), resource.NewWithAttributes( + semconv.SchemaURL, + baseAttrs..., )) if err != nil { return nil, fmt.Errorf("%s: %w", errMsg, err) diff --git a/observability/traces/trace.go b/observability/traces/trace.go index c907db4911..1fdc053241 100644 --- a/observability/traces/trace.go +++ b/observability/traces/trace.go @@ -11,8 +11,10 @@ import ( "go.uber.org/zap" ) -// logger is defined as global var here to keep package API as simple as possible (instead of returning error we log them with this logger in some places) -var logger *zap.Logger +// logger is defined as global var here to keep package API as simple as possible (instead of returning error we log them with this logger in some places). +// Defaults to a no-op logger so any logging before InitLogger runs doesn't panic on a +// nil pointer. InitLogger replaces this with the configured global zap logger. +var logger = zap.NewNop() const traceIDByteLen = 16 diff --git a/operator/validator/observability.go b/operator/validator/observability.go index 9c372aa820..b0c3e13c9d 100644 --- a/operator/validator/observability.go +++ b/operator/validator/observability.go @@ -47,22 +47,25 @@ var ( observability.InstrumentName(observabilityNamespace, "validators.per_status"), metric.WithDescription("total number of validators by status"))) - validatorsRemovedCounter = metrics.New( + // Sparse: validator lifecycle removals are rare. + validatorsRemovedCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "validators.removed"), metric.WithUnit("{validator}"), - metric.WithDescription("total number of validator errors"))) + metric.WithDescription("total number of validators removed")))) - validatorErrorsCounter = metrics.New( + // Sparse: validator-level errors are rare. + validatorErrorsCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "errors"), metric.WithUnit("{validator}"), - metric.WithDescription("total number of validator errors"))) - routerDroppedMessagesCounter = metrics.New( + metric.WithDescription("total number of validator errors")))) + // Sparse: only fires on message-router back-pressure or ctx cancellation. + routerDroppedMessagesCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "router.messages.dropped"), metric.WithUnit("{message}"), - metric.WithDescription("total number of router-dropped messages by reason"))) + metric.WithDescription("total number of router-dropped messages by reason")))) routerBufferFillGauge = metrics.New( meter.Int64Gauge( diff --git a/protocol/v2/qbft/instance/observability.go b/protocol/v2/qbft/instance/observability.go index 2bf2dcfcb9..0d1efd88cf 100644 --- a/protocol/v2/qbft/instance/observability.go +++ b/protocol/v2/qbft/instance/observability.go @@ -45,11 +45,12 @@ var ( metric.WithDescription("validator stage(proposal, prepare, commit) duration"), metric.WithExplicitBucketBoundaries(metrics.SecondsHistogramBuckets...))) - roundsChangedCounter = metrics.New( + // Sparse: QBFT round changes only happen on consensus failures/timeouts (rare). + roundsChangedCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "duty.rounds_changed"), metric.WithUnit("{change}"), - metric.WithDescription("number of round changes with their reasons"))) + metric.WithDescription("number of round changes with their reasons")))) ) func stageAttribute(stage stage) attribute.KeyValue { diff --git a/protocol/v2/ssv/runner/observability.go b/protocol/v2/ssv/runner/observability.go index e0d85d26ec..d93cb4c3bf 100644 --- a/protocol/v2/ssv/runner/observability.go +++ b/protocol/v2/ssv/runner/observability.go @@ -114,11 +114,12 @@ var ( metric.WithUnit("{submission}"), metric.WithDescription("number of duty submissions"))) - failedSubmissionCounter = metrics.New( + // Sparse: only fires when a duty submission fails (rare). + failedSubmissionCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "submissions.failed"), metric.WithUnit("{submission}"), - metric.WithDescription("total number of failed duty submissions"))) + metric.WithDescription("total number of failed duty submissions")))) ) func recordSuccessfulSubmission(ctx context.Context, count int64, epoch phase0.Epoch, role spectypes.BeaconRole) { From c2d8a077be6aa60a424288c86cdf1e16b9aa742f Mon Sep 17 00:00:00 2001 From: iurii Date: Tue, 26 May 2026 16:48:28 +0300 Subject: [PATCH 2/5] observability/metrics: per-attribute-set baselines for labeled counters MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Extends EmitBaselines so packages can pre-emit baselines for the specific attribute combinations they'll use at runtime — not just the unlabeled series. New RegisterLabeledBaseline takes a callback that the package implements to iterate its known label combinations and emit Add(ctx, 0, WithAttributes(...)) for each. Applied to the proposal_parent counters in beacon/goclient: after goclient.New populates the configured beacon clients, we register a baseline emitter that pre-creates the (counter, ssv.beacon.client) time series for each beacon. PromQL increase()/rate() now return correct values for per-beacon queries even after process restart. The unlabeled RegisterSparseCounter path still exists for counters whose labels aren't known at startup or that don't carry per-call attributes. Addresses feedback on ssvlabs/ssv-node-board#1069: restart-resilience must pre-register all expected label combinations at startup since the issue is missing baseline samples, not counter resets per se. --- beacon/goclient/goclient.go | 6 +++++ beacon/goclient/observability.go | 18 +++++++++++++ observability/metrics/baseline.go | 43 ++++++++++++++++++++++++++++--- 3 files changed, 63 insertions(+), 4 deletions(-) diff --git a/beacon/goclient/goclient.go b/beacon/goclient/goclient.go index de823542c1..1974e76c7d 100644 --- a/beacon/goclient/goclient.go +++ b/beacon/goclient/goclient.go @@ -212,6 +212,12 @@ func New(ctx context.Context, logger *zap.Logger, opt Options) (*GoClient, error } } + // Pre-register baselines for the proposal_parent counters across the configured + // beacon clients so that PromQL increase()/rate() return correct values per + // ssv.beacon.client label after restart. The registered function runs when + // metrics.EmitBaselines is called from startup (after observability.Initialize). + registerProposalParentBaselines(client.clients) + client.log.Debug("connecting") err := client.initMultiClient(ctx) diff --git a/beacon/goclient/observability.go b/beacon/goclient/observability.go index 8203a16d0a..4ce41ed686 100644 --- a/beacon/goclient/observability.go +++ b/beacon/goclient/observability.go @@ -141,6 +141,24 @@ var ( metric.WithDescription("proposal parent root did not match cached HeadEvent")))) ) +// registerProposalParentBaselines pre-emits Add(ctx, 0) for each (counter, beacon_client) +// combination so that PromQL increase()/rate() return correct values for per-client +// queries after process restart. Without this, each labeled time series starts at the +// first real increment with no prior sample, and Prometheus has nothing to compute a +// delta from. Configured beacon addresses are passed in because they're only known after +// GoClient construction. +func registerProposalParentBaselines(clients []Client) { + metrics.RegisterLabeledBaseline(func(ctx context.Context) { + for _, c := range clients { + attr := metric.WithAttributes(observability.BeaconClientAttribute(c.Address())) + proposalParentVerifyCounter.Add(ctx, 0, attr) + proposalParentMatchCounter.Add(ctx, 0, attr) + proposalParentCacheMissCounter.Add(ctx, 0, attr) + proposalParentMismatchCounter.Add(ctx, 0, attr) + } + }) +} + func recordRequest( ctx context.Context, logger *zap.Logger, diff --git a/observability/metrics/baseline.go b/observability/metrics/baseline.go index 07f5241dbb..4b03630d50 100644 --- a/observability/metrics/baseline.go +++ b/observability/metrics/baseline.go @@ -28,6 +28,9 @@ import ( var ( sparseCountersMu sync.Mutex sparseCounters []metric.Int64Counter + + labeledBaselinesMu sync.Mutex + labeledBaselineFns []func(context.Context) ) // RegisterSparseCounter declares a counter as sparse (rarely incremented). Returns the @@ -41,6 +44,12 @@ var ( // // Call EmitBaselines exactly once at startup, after observability.Initialize has set up // the MeterProvider. +// +// Note: this only baselines the unlabeled time series. Counters that emit with per-call +// attributes still produce one un-baselined series per attribute set on first labeled +// increment. For counters whose attribute combinations are bounded and known at startup +// (e.g. labeled by a fixed set of configured beacon addresses or validator roles), use +// RegisterLabeledBaseline to pre-emit baselines for each attribute combination. func RegisterSparseCounter(c metric.Int64Counter) metric.Int64Counter { sparseCountersMu.Lock() defer sparseCountersMu.Unlock() @@ -48,13 +57,39 @@ func RegisterSparseCounter(c metric.Int64Counter) metric.Int64Counter { return c } -// EmitBaselines emits Add(ctx, 0) for every counter registered via RegisterSparseCounter, -// giving Prometheus a baseline sample for each. Call once at startup after the OTel -// MeterProvider is installed (i.e. after observability.Initialize completes). +// RegisterLabeledBaseline lets a package contribute a custom baseline-emission function +// that knows the specific attribute combinations it will use at runtime. Useful when a +// counter is labeled by a bounded, runtime-known set of values (e.g. the addresses of +// configured beacon clients, the small set of validator roles). +// +// The registered function is invoked from EmitBaselines, after the OTel MeterProvider is +// installed. The function should iterate its known attribute combinations and emit +// Add(ctx, 0, WithAttributes(...)) for each, so PromQL increase()/rate() return correct +// values for per-label queries even after process restart. +func RegisterLabeledBaseline(fn func(context.Context)) { + labeledBaselinesMu.Lock() + defer labeledBaselinesMu.Unlock() + labeledBaselineFns = append(labeledBaselineFns, fn) +} + +// EmitBaselines emits Add(ctx, 0) for every counter registered via RegisterSparseCounter +// (the unlabeled series), then invokes every function registered via +// RegisterLabeledBaseline (which handle per-attribute-set baselines). Call once at startup +// after the OTel MeterProvider is installed (i.e. after observability.Initialize completes). func EmitBaselines(ctx context.Context) { sparseCountersMu.Lock() - defer sparseCountersMu.Unlock() for _, c := range sparseCounters { c.Add(ctx, 0) } + sparseCountersMu.Unlock() + + // Copy the slice under lock, then invoke without the lock — defensive in case any + // registered function indirectly triggers another registration. + labeledBaselinesMu.Lock() + fns := make([]func(context.Context), len(labeledBaselineFns)) + copy(fns, labeledBaselineFns) + labeledBaselinesMu.Unlock() + for _, fn := range fns { + fn(ctx) + } } From 6fc346d6370f0301c02a1549286af13c440f2a0f Mon Sep 17 00:00:00 2001 From: iurii Date: Thu, 28 May 2026 12:31:19 +0300 Subject: [PATCH 3/5] observability: address review feedback (tests, doc nits, shutdown refactor) Tests - observability/metrics/baseline_test.go: covers RegisterSparseCounter pass-through, EmitBaselines unlabeled-zero emission via an OTel manual reader, labeled-baseline fn invocation, the defensive-copy contract for re-entrant registration, and repeat-call idempotency. Tests snapshot the process-global registries so they isolate cleanly. - beacon/goclient/proposer_verify_test.go: covers verifyProposalParent slot==0 short-circuit, cache-miss/match silence, and that the mismatch log fires at Info with the new beacon_client field. cli/operator/node.go - Drop the early observabilityShutdown var and nil-check defer; declare it at the Initialize call site and register the shutdown defer only after a successful Initialize (Fatal earlier in startup os.Exits and has nothing to shut down). - Switch observabilityOptions to the idiomatic var declaration form. - Log an Info confirming observability init success, with metrics_enabled / traces_enabled / operator_id_label fields so misconfiguration is visible in startup logs. - Comment why OperatorIDReady() is intentionally false in exporter mode so future readers don't "fix" the missing label. observability/configurator.go - Drop misleading `_ =` on initLogger; expand InitializeLogger docstring with the symmetric note that Initialize does not re-propagate the logger. - Document that zap.L() inside Initialize returns the no-op global if InitializeLogger was never called. observability/metrics/baseline.go - Document that the registries are process-global and append-only, with the test-isolation caveat. - Document EmitBaselines as harmless-but-wasteful on repeat calls. beacon/goclient/proposer.go - Move the long trailing comment on beaconClient into a preceding block. - Expand the slot==0 guard comment to clarify production never reaches this branch; it is uint64-underflow defense for synthetic-slot tests. eth/executionclient/observability.go - Drop the "Sparse-ish" hedge on multiClientMethodErrorsCounter. --- beacon/goclient/proposer.go | 9 +- beacon/goclient/proposer_verify_test.go | 89 +++++++++++ cli/operator/node.go | 34 +++-- eth/executionclient/observability.go | 2 +- observability/configurator.go | 15 +- observability/metrics/baseline.go | 12 ++ observability/metrics/baseline_test.go | 192 ++++++++++++++++++++++++ 7 files changed, 331 insertions(+), 22 deletions(-) create mode 100644 beacon/goclient/proposer_verify_test.go create mode 100644 observability/metrics/baseline_test.go diff --git a/beacon/goclient/proposer.go b/beacon/goclient/proposer.go index fd0eee57a1..c1cb56cdca 100644 --- a/beacon/goclient/proposer.go +++ b/beacon/goclient/proposer.go @@ -99,7 +99,9 @@ func (gc *GoClient) GetBeaconBlock( copy(graffiti[:], graffitiBytes[:]) var beaconBlock *api.VersionedProposal - var beaconClient string // address of the BN that produced the selected proposal — used for metric labeling + // beaconClient is the address of the BN that produced the selected proposal — used + // for metric labeling so per-client staleness rates can be measured. + var beaconClient string var err error // For single client, use direct call to avoid multi-client overhead @@ -345,7 +347,10 @@ func (gc *GoClient) verifyProposalParent( beaconClient string, ) { if slot == 0 { - // Genesis has no parent to verify; also guards against uint64 underflow below. + // Guards against the slot-1 uint64 underflow below. In production this branch + // never fires (the slot ticker is well past 0 by the time GetBeaconBlock runs), + // but tests with synthetic zero slots can reach here. Genesis has no parent root + // to verify in any case. return } diff --git a/beacon/goclient/proposer_verify_test.go b/beacon/goclient/proposer_verify_test.go new file mode 100644 index 0000000000..8d6f9a4506 --- /dev/null +++ b/beacon/goclient/proposer_verify_test.go @@ -0,0 +1,89 @@ +package goclient + +import ( + "testing" + + "github.com/attestantio/go-eth2-client/spec" + "github.com/attestantio/go-eth2-client/spec/phase0" + "github.com/jellydator/ttlcache/v3" + spectestingutils "github.com/ssvlabs/ssv-spec/types/testingutils" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" +) + +const testBeaconClientAddr = "http://bn-test:5052" + +// newGoClientForVerifyTest builds a minimal *GoClient with only the fields required by +// verifyProposalParent. The observed core captures log entries the function emits so +// tests can assert on log fields without standing up a full client. +func newGoClientForVerifyTest(t *testing.T) (*GoClient, *observer.ObservedLogs) { + t.Helper() + core, observed := observer.New(zapcore.DebugLevel) + return &GoClient{ + log: zap.New(core), + headCache: ttlcache.New[phase0.Slot, phase0.Root](), + }, observed +} + +func TestVerifyProposalParent_Slot0_ShortCircuitsWithoutLog(t *testing.T) { + gc, observed := newGoClientForVerifyTest(t) + proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) + + // Must not panic on uint64 underflow (slot - 1 when slot==0) and must not emit any log. + gc.verifyProposalParent(t.Context(), gc.log, 0, proposal, testBeaconClientAddr) + + assert.Zero(t, observed.Len(), "slot==0 path must short-circuit before any log emission") +} + +func TestVerifyProposalParent_CacheMissIsSilent(t *testing.T) { + gc, observed := newGoClientForVerifyTest(t) + proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) + proposal.Electra.Block.Slot = 100 + + // headCache is empty, so the parent slot lookup misses. Cache miss is metric-only, + // no log entry should be emitted. + gc.verifyProposalParent(t.Context(), gc.log, proposal.Electra.Block.Slot, proposal, testBeaconClientAddr) + + assert.Zero(t, observed.Len(), "cache-miss path must not emit any log") +} + +func TestVerifyProposalParent_MatchIsSilent(t *testing.T) { + gc, observed := newGoClientForVerifyTest(t) + proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) + proposal.Electra.Block.Slot = 100 + + // Pre-seed the cache with the parent root that the proposal carries — this is the + // match path which is also metric-only. + gc.headCache.Set(proposal.Electra.Block.Slot-1, proposal.Electra.Block.ParentRoot, ttlcache.NoTTL) + + gc.verifyProposalParent(t.Context(), gc.log, proposal.Electra.Block.Slot, proposal, testBeaconClientAddr) + + assert.Zero(t, observed.Len(), "match path must not emit any log") +} + +func TestVerifyProposalParent_MismatchLogsBeaconClientField(t *testing.T) { + gc, observed := newGoClientForVerifyTest(t) + proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) + proposal.Electra.Block.Slot = 100 + + // Cache holds a different root for slot-1 than what the proposal references — + // triggers the mismatch path which logs at Info with the beacon_client field. + cachedRoot := phase0.Root{0xAA} + require.NotEqual(t, cachedRoot, proposal.Electra.Block.ParentRoot) + gc.headCache.Set(proposal.Electra.Block.Slot-1, cachedRoot, ttlcache.NoTTL) + + gc.verifyProposalParent(t.Context(), gc.log, proposal.Electra.Block.Slot, proposal, testBeaconClientAddr) + + require.Equal(t, 1, observed.Len(), "mismatch path must emit exactly one log entry") + entry := observed.All()[0] + assert.Equal(t, zapcore.InfoLevel, entry.Level, "mismatch log must be Info (was Warn pre-PR)") + assert.Equal(t, "proposal parent root mismatch detected", entry.Message) + + fields := entry.ContextMap() + beaconClient, ok := fields["beacon_client"] + require.True(t, ok, "mismatch log must include beacon_client field") + assert.Equal(t, testBeaconClientAddr, beaconClient) +} diff --git a/cli/operator/node.go b/cli/operator/node.go index 539bd2d39a..348e1865e9 100644 --- a/cli/operator/node.go +++ b/cli/operator/node.go @@ -166,7 +166,7 @@ var StartNodeCmd = &cobra.Command{ // OTel resource attributes — every emitted metric/trace is then automatically // labeled with the operator. Metrics emitted before that point are dropped, which // is an acceptable trade-off for accurate per-operator labeling. - observabilityOptions := []observability.Option{} + var observabilityOptions []observability.Option if cfg.MetricsAPIPort > 0 { observabilityOptions = append(observabilityOptions, observability.WithMetrics()) } @@ -174,18 +174,6 @@ var StartNodeCmd = &cobra.Command{ observabilityOptions = append(observabilityOptions, observability.WithTraces()) } - var observabilityShutdown func(context.Context) error - defer func() { - if observabilityShutdown == nil { - return // Initialize never ran (e.g. fatal before reaching it) - } - shutdownCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second) - defer cancel() - if err := observabilityShutdown(shutdownCtx); err != nil { - logger.Error("could not shutdown observability stack", zap.Error(err)) - } - }() - logger.Info(fmt.Sprintf("starting %v", commons.GetBuildData())) ssvNetworkConfig, err := setupSSVNetwork(logger) @@ -366,7 +354,9 @@ var StartNodeCmd = &cobra.Command{ // operator_id baked into the OTel resource attributes (only if the ID is ready — // new operators not yet registered on-chain will have ID=0 and we skip the label // rather than emit misleading metrics; the operator will need to restart after - // registration to pick up the correct ID in metric labels). + // registration to pick up the correct ID in metric labels). Note: in exporter + // mode OperatorIDReady() always returns false because exporters have no operator + // identity — that's intentional, do not "fix" by emitting a zero-valued label. if operatorDataStore.OperatorIDReady() { observabilityOptions = append(observabilityOptions, observability.WithResourceAttributes( @@ -374,7 +364,7 @@ var StartNodeCmd = &cobra.Command{ ), ) } - observabilityShutdown, err = observability.Initialize( + observabilityShutdown, err := observability.Initialize( cmd.Context(), cmd.Parent().Short, cmd.Parent().Version, @@ -383,6 +373,20 @@ var StartNodeCmd = &cobra.Command{ if err != nil { logger.Fatal("could not initialize observability metrics/traces", zap.Error(err)) } + // Register the shutdown defer only after a successful Initialize. Any earlier + // Fatal short-circuits via os.Exit before this point and has nothing to shut down. + defer func() { + shutdownCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + defer cancel() + if err := observabilityShutdown(shutdownCtx); err != nil { + logger.Error("could not shutdown observability stack", zap.Error(err)) + } + }() + logger.Info("observability stack initialized", + zap.Bool("metrics_enabled", cfg.MetricsAPIPort > 0), + zap.Bool("traces_enabled", cfg.EnableTraces), + zap.Bool("operator_id_label", operatorDataStore.OperatorIDReady()), + ) // Emit baseline (zero) samples for sparse counters so PromQL increase()/rate() // returns correct values across process restarts. See observability/metrics/baseline.go. diff --git a/eth/executionclient/observability.go b/eth/executionclient/observability.go index 4afe283ec2..df71e350d7 100644 --- a/eth/executionclient/observability.go +++ b/eth/executionclient/observability.go @@ -69,7 +69,7 @@ var ( observability.InstrumentName(observabilityNamespace, "multi_client.method_calls"), metric.WithDescription("number of method calls to the multi client"))) - // Sparse-ish: tracks RPC error rate which is typically low. + // Sparse: tracks RPC error rate which is typically low. multiClientMethodErrorsCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "multi_client.method_errors"), diff --git a/observability/configurator.go b/observability/configurator.go index 443fbd6609..f142455d55 100644 --- a/observability/configurator.go +++ b/observability/configurator.go @@ -32,10 +32,13 @@ func init() { model.NameValidationScheme = model.LegacyValidation // nolint: staticcheck } -// InitializeLogger configures the global zap logger. It must be called before Initialize, -// and is split from Initialize so the logger is available during early startup (before +// InitializeLogger configures the global zap logger and propagates it to the +// observability sub-packages (metrics, traces). It must be called before Initialize, and +// is split from Initialize so the logger is available during early startup (before // process-global facts like operator_id are known, which delays metric/trace provider -// initialization — see Initialize and WithResourceAttributes). +// initialization — see Initialize and WithResourceAttributes). Initialize intentionally +// does not re-propagate the logger so that calling it again mid-startup does not have the +// surprising side effect of replacing the metrics/traces internal loggers. func InitializeLogger(level, levelFormat, format, filePath string, fileSize, fileBackups int) error { err := log.SetGlobal( level, @@ -51,7 +54,8 @@ func InitializeLogger(level, levelFormat, format, filePath string, fileSize, fil return fmt.Errorf("could not setup global logger: %w", err) } // Propagate the configured logger to observability sub-packages so they can log. - _ = initLogger(zap.L()) + // initLogger returns the named logger but we don't need it here. + initLogger(zap.L()) return nil } @@ -72,6 +76,9 @@ func Initialize(ctx context.Context, appName, appVersion string, options ...Opti // Derive a named logger for Initialize's own log messages. metrics/traces internal // loggers are propagated by InitializeLogger (which must be called first); we don't // repeat that here to avoid the surprising side effect of replacing them mid-startup. + // If InitializeLogger was never called, zap.L() returns the no-op global and these + // messages are silently discarded — that's fine for tests but operators should always + // have called InitializeLogger before Initialize. localLogger := zap.L().Named(log.NameObservability) shutdown = func(ctx context.Context) error { diff --git a/observability/metrics/baseline.go b/observability/metrics/baseline.go index 4b03630d50..e9dd5a5513 100644 --- a/observability/metrics/baseline.go +++ b/observability/metrics/baseline.go @@ -24,6 +24,14 @@ import ( // // High-volume counters (per-message, per-attestation, per-slot, etc.) do not need this // treatment — they always have recent samples for Prometheus to work from. +// +// The registry is process-global and append-only: counters and labeled-baseline closures +// stay registered for the lifetime of the process. RegisterSparseCounter is typically +// called from package-level var initializers (once per process) so this is a non-issue in +// production; in tests that construct many objects whose constructors register baselines +// (e.g. goclient.New calling registerProposalParentBaselines), the registries grow +// unboundedly. This is harmless as long as tests do not call EmitBaselines — if a future +// test needs to, add a per-test reset hook here rather than working around it externally. var ( sparseCountersMu sync.Mutex @@ -76,6 +84,10 @@ func RegisterLabeledBaseline(fn func(context.Context)) { // (the unlabeled series), then invokes every function registered via // RegisterLabeledBaseline (which handle per-attribute-set baselines). Call once at startup // after the OTel MeterProvider is installed (i.e. after observability.Initialize completes). +// +// Calling EmitBaselines more than once is harmless — each extra invocation just emits +// another Add(ctx, 0), which does not change any counter's value — but it is wasted work +// and produces extra samples in the scrape window. Prefer the once-at-startup pattern. func EmitBaselines(ctx context.Context) { sparseCountersMu.Lock() for _, c := range sparseCounters { diff --git a/observability/metrics/baseline_test.go b/observability/metrics/baseline_test.go new file mode 100644 index 0000000000..772e09acb8 --- /dev/null +++ b/observability/metrics/baseline_test.go @@ -0,0 +1,192 @@ +package metrics + +import ( + "context" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/metric" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" +) + +// snapshotRegistries captures the current global registry state and restores it on test +// cleanup. RegisterSparseCounter and RegisterLabeledBaseline mutate process-global slices +// (see baseline.go), so tests must isolate themselves from each other. +func snapshotRegistries(t *testing.T) { + t.Helper() + sparseCountersMu.Lock() + savedSparse := append([]metric.Int64Counter(nil), sparseCounters...) + sparseCounters = nil + sparseCountersMu.Unlock() + + labeledBaselinesMu.Lock() + savedLabeled := make([]func(context.Context), len(labeledBaselineFns)) + copy(savedLabeled, labeledBaselineFns) + labeledBaselineFns = nil + labeledBaselinesMu.Unlock() + + t.Cleanup(func() { + sparseCountersMu.Lock() + sparseCounters = savedSparse + sparseCountersMu.Unlock() + labeledBaselinesMu.Lock() + labeledBaselineFns = savedLabeled + labeledBaselinesMu.Unlock() + }) +} + +// newTestMeter builds a MeterProvider with a manual reader for in-test metric collection. +func newTestMeter(t *testing.T) (metric.Meter, *sdkmetric.ManualReader) { + t.Helper() + reader := sdkmetric.NewManualReader() + provider := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + return provider.Meter("baseline_test"), reader +} + +// findCounterByName returns the metricdata.Sum[int64] for the named instrument from a +// collected ResourceMetrics, or fails the test. +func findCounterByName(t *testing.T, rm metricdata.ResourceMetrics, name string) metricdata.Sum[int64] { + t.Helper() + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + if m.Name == name { + sum, ok := m.Data.(metricdata.Sum[int64]) + require.True(t, ok, "metric %q is not a Sum[int64]", name) + return sum + } + } + } + t.Fatalf("counter %q not present in collected metrics", name) + return metricdata.Sum[int64]{} +} + +func TestRegisterSparseCounter_ReturnsSameCounter(t *testing.T) { + snapshotRegistries(t) + + meter, _ := newTestMeter(t) + c, err := meter.Int64Counter("test.sparse_pass_through") + require.NoError(t, err) + + out := RegisterSparseCounter(c) + assert.Same(t, c, out, "RegisterSparseCounter must return the same counter passed in") + + sparseCountersMu.Lock() + defer sparseCountersMu.Unlock() + require.Len(t, sparseCounters, 1) + assert.Same(t, c, sparseCounters[0]) +} + +func TestEmitBaselines_EmitsZeroSampleForSparseCounter(t *testing.T) { + snapshotRegistries(t) + + meter, reader := newTestMeter(t) + c, err := meter.Int64Counter("test.sparse_emits_zero") + require.NoError(t, err) + RegisterSparseCounter(c) + + // Before EmitBaselines the counter has never been touched — no data point should + // exist for the unlabeled series. + var beforeRM metricdata.ResourceMetrics + require.NoError(t, reader.Collect(t.Context(), &beforeRM)) + for _, sm := range beforeRM.ScopeMetrics { + for _, m := range sm.Metrics { + require.NotEqual(t, "test.sparse_emits_zero", m.Name, + "counter must not appear in collection before EmitBaselines") + } + } + + EmitBaselines(t.Context()) + + var afterRM metricdata.ResourceMetrics + require.NoError(t, reader.Collect(t.Context(), &afterRM)) + sum := findCounterByName(t, afterRM, "test.sparse_emits_zero") + require.Len(t, sum.DataPoints, 1, "expected exactly one unlabeled baseline sample") + assert.Equal(t, int64(0), sum.DataPoints[0].Value, "baseline sample must be zero") + assert.Equal(t, 0, sum.DataPoints[0].Attributes.Len(), "baseline sample must have no attributes") +} + +func TestEmitBaselines_InvokesRegisteredLabeledFunctions(t *testing.T) { + snapshotRegistries(t) + + meter, reader := newTestMeter(t) + c, err := meter.Int64Counter("test.labeled_emits_zero") + require.NoError(t, err) + + beaconAddrs := []string{"http://bn-a:5052", "http://bn-b:5052"} + RegisterLabeledBaseline(func(ctx context.Context) { + for _, addr := range beaconAddrs { + c.Add(ctx, 0, metric.WithAttributes(attribute.String("ssv.beacon.client", addr))) + } + }) + + EmitBaselines(t.Context()) + + var rm metricdata.ResourceMetrics + require.NoError(t, reader.Collect(t.Context(), &rm)) + sum := findCounterByName(t, rm, "test.labeled_emits_zero") + require.Len(t, sum.DataPoints, len(beaconAddrs), + "expected one labeled baseline sample per configured beacon address") + + gotAddrs := make(map[string]int64) + for _, dp := range sum.DataPoints { + v, ok := dp.Attributes.Value("ssv.beacon.client") + require.True(t, ok, "labeled baseline sample is missing ssv.beacon.client attribute") + gotAddrs[v.AsString()] = dp.Value + } + for _, addr := range beaconAddrs { + val, ok := gotAddrs[addr] + assert.True(t, ok, "no baseline sample for beacon %q", addr) + assert.Equal(t, int64(0), val, "baseline sample for %q must be zero", addr) + } +} + +// TestEmitBaselines_LabeledFunctionCanRegisterAnother locks the contract described by the +// "Copy the slice under lock, then invoke without the lock" comment in EmitBaselines. +// Without the defensive copy this would deadlock on labeledBaselinesMu. +func TestEmitBaselines_LabeledFunctionCanRegisterAnother(t *testing.T) { + snapshotRegistries(t) + + var outerRan, nestedRegistered bool + RegisterLabeledBaseline(func(ctx context.Context) { + outerRan = true + // Re-entrant registration: would deadlock if EmitBaselines held the lock while + // invoking registered fns. The nested fn must NOT run during this EmitBaselines + // call (it was registered after the slice snapshot was taken) — only the next. + RegisterLabeledBaseline(func(context.Context) { + nestedRegistered = true + }) + }) + + EmitBaselines(t.Context()) + assert.True(t, outerRan, "outer labeled baseline fn must run") + assert.False(t, nestedRegistered, "nested fn must not run during the same EmitBaselines") + + // Second call should pick up the nested fn. + EmitBaselines(t.Context()) + assert.True(t, nestedRegistered, "nested labeled baseline fn must run on the next EmitBaselines") +} + +// TestEmitBaselines_RepeatedCallsAddZeroEachTime documents that EmitBaselines is safe to +// call more than once (each invocation just emits another Add(0), which does not change +// the counter value). See the docstring caveat about preferring once-at-startup. +func TestEmitBaselines_RepeatedCallsAddZeroEachTime(t *testing.T) { + snapshotRegistries(t) + + meter, reader := newTestMeter(t) + c, err := meter.Int64Counter("test.sparse_repeated_calls") + require.NoError(t, err) + RegisterSparseCounter(c) + + EmitBaselines(t.Context()) + EmitBaselines(t.Context()) + EmitBaselines(t.Context()) + + var rm metricdata.ResourceMetrics + require.NoError(t, reader.Collect(t.Context(), &rm)) + sum := findCounterByName(t, rm, "test.sparse_repeated_calls") + require.Len(t, sum.DataPoints, 1, "all baseline emissions should fold into one unlabeled series") + assert.Equal(t, int64(0), sum.DataPoints[0].Value, "value must remain zero across repeated EmitBaselines calls") +} From 432685feab398b4c82cdb9b6b803feab23f9eb8e Mon Sep 17 00:00:00 2001 From: iurii Date: Thu, 28 May 2026 14:05:56 +0300 Subject: [PATCH 4/5] observability: address external review (CI lint + tests + doc nits) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CI lint failures - observability/option.go: drop trailing blank line at EOF (gofmt). - observability/resources.go: preallocate baseAttrs slice (prealloc). - observability/attributes.go: drop redundant uint64() cast on spectypes.OperatorID (which is `type OperatorID = uint64`) — matches the existing pattern in ValidatorProposerAttribute. Tests - observability/configurator_test.go: lock the InitializeLogger / Initialize contracts: InitializeLogger propagation into metrics; Initialize works without InitializeLogger (no-op fallback); Initialize does NOT replace metrics.logger (verified via sentinel + RecordUint64Value error trigger). The third test guards the "intentionally does not re-propagate" comment from silent regressions. - beacon/goclient/proposer_verify_metric_test.go: lock the metric-label contract — verifyProposalParent's three branches each fire the expected counter carrying ssv.beacon.client. Subtests share one OTel meter provider because the global delegating-meter only re-binds package-level instruments on the first SetMeterProvider call after package init; per-test providers don't compose. Code / comment edits - beacon/goclient/observability.go: document the invariant that the `clients` slice passed to registerProposalParentBaselines must be final at call time (the closure captures the slice header). - beacon/goclient/proposer.go: route the mismatch log's beacon_client field through the new fields.BeaconClient helper. - observability/log/fields/fields.go: add fields.BeaconClient helper and FieldBeaconClient constant, mirroring the ssv.beacon.client metric attribute (dotted OTel form vs snake_case log convention). - cli/operator/node.go: rename metrics_enabled / traces_enabled log fields to _configured (they reflect config, not runtime state); gate EmitBaselines on cfg.MetricsAPIPort > 0 to skip no-op iteration when metrics are disabled. - observability/metrics/baseline.go: explain the locking asymmetry in EmitBaselines — sparse-counters loop holds the lock during Add because Int64Counter.Add is a leaf and cannot reenter the registry; labeled-baselines path snapshots first because user-provided fns may. - network/peers/connections/observability.go, message/validation/observability.go: replace ambiguous "Sparse" / "Possibly sparse" comments with TODO(audit) markers — re-evaluate these classifications against production rates. Mis-classifying is harmless (Add(0) on a dense counter is a no-op for PromQL) but the registry is meant to document intent. --- beacon/goclient/observability.go | 5 + beacon/goclient/proposer.go | 2 +- .../goclient/proposer_verify_metric_test.go | 132 ++++++++++++++++++ cli/operator/node.go | 10 +- message/validation/observability.go | 5 +- network/peers/connections/observability.go | 7 +- observability/attributes.go | 2 +- observability/configurator_test.go | 110 +++++++++++++++ observability/log/fields/fields.go | 8 ++ observability/metrics/baseline.go | 10 +- observability/option.go | 1 - observability/resources.go | 6 +- 12 files changed, 286 insertions(+), 12 deletions(-) create mode 100644 beacon/goclient/proposer_verify_metric_test.go create mode 100644 observability/configurator_test.go diff --git a/beacon/goclient/observability.go b/beacon/goclient/observability.go index 4ce41ed686..8a6a6e6118 100644 --- a/beacon/goclient/observability.go +++ b/beacon/goclient/observability.go @@ -147,6 +147,11 @@ var ( // first real increment with no prior sample, and Prometheus has nothing to compute a // delta from. Configured beacon addresses are passed in because they're only known after // GoClient construction. +// +// Invariant: `clients` must be final at call time. The closure captures the slice header, +// so any later append to the same backing array (or a re-slice via append-that-reallocates) +// would not be visible here. Today this is satisfied because the caller in goclient.New +// finishes all addSingleClient calls before invoking registerProposalParentBaselines. func registerProposalParentBaselines(clients []Client) { metrics.RegisterLabeledBaseline(func(ctx context.Context) { for _, c := range clients { diff --git a/beacon/goclient/proposer.go b/beacon/goclient/proposer.go index c1cb56cdca..791cb5a6ed 100644 --- a/beacon/goclient/proposer.go +++ b/beacon/goclient/proposer.go @@ -387,7 +387,7 @@ func (gc *GoClient) verifyProposalParent( zap.Uint64("parent_slot", uint64(parentSlot)), zap.Stringer("expected_root", expectedRoot), zap.Stringer("got_root", parentRoot), - zap.String("beacon_client", beaconClient), + fields.BeaconClient(beaconClient), ) } diff --git a/beacon/goclient/proposer_verify_metric_test.go b/beacon/goclient/proposer_verify_metric_test.go new file mode 100644 index 0000000000..ad46305c12 --- /dev/null +++ b/beacon/goclient/proposer_verify_metric_test.go @@ -0,0 +1,132 @@ +package goclient + +import ( + "testing" + + "github.com/attestantio/go-eth2-client/spec" + "github.com/attestantio/go-eth2-client/spec/phase0" + "github.com/jellydator/ttlcache/v3" + spectestingutils "github.com/ssvlabs/ssv-spec/types/testingutils" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" + "go.uber.org/zap" +) + +// TestVerifyProposalParent_EmitsLabeledMetric verifies that each branch of +// verifyProposalParent fires the expected counter carrying the ssv.beacon.client attribute. +// +// All branches are exercised in one Test (with subtests) on purpose. OTel Go's global +// meter provider re-binds package-level instruments only on the first SetMeterProvider +// call after package init; subsequent provider swaps leave already-bound instruments +// pointed at the original target. Sharing a single provider across the subtests sidesteps +// that quirk. The provider is restored on cleanup so other tests in the package are +// unaffected. +func TestVerifyProposalParent_EmitsLabeledMetric(t *testing.T) { + reader := sdkmetric.NewManualReader() + provider := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + previous := otel.GetMeterProvider() + otel.SetMeterProvider(provider) + t.Cleanup(func() { + otel.SetMeterProvider(previous) + _ = provider.Shutdown(t.Context()) + }) + + // Each subtest collects the cumulative counter values seen so far and asserts the + // delta introduced by its own verifyProposalParent call. + type counterDelta struct { + name string + before int64 + want int64 + } + + collect := func() map[string]int64 { + var rm metricdata.ResourceMetrics + require.NoError(t, reader.Collect(t.Context(), &rm)) + out := make(map[string]int64) + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + sum, ok := m.Data.(metricdata.Sum[int64]) + if !ok { + continue + } + // Sum across all data points with the testBeaconClientAddr label. + for _, dp := range sum.DataPoints { + v, ok := dp.Attributes.Value("ssv.beacon.client") + if ok && v.AsString() == testBeaconClientAddr { + out[m.Name] += dp.Value + } + } + } + } + return out + } + + newGC := func() *GoClient { + return &GoClient{ + log: zap.NewNop(), + headCache: ttlcache.New[phase0.Slot, phase0.Root](), + } + } + + assertDeltas := func(t *testing.T, before map[string]int64, after map[string]int64, deltas []counterDelta) { + t.Helper() + for _, d := range deltas { + got := after[d.name] - before[d.name] + assert.Equal(t, d.want, got, + "counter %q delta: want +%d, got +%d (before=%d, after=%d)", + d.name, d.want, got, before[d.name], after[d.name]) + } + } + + t.Run("cache miss labels verify and cache_miss counters", func(t *testing.T) { + before := collect() + gc := newGC() + proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) + proposal.Electra.Block.Slot = 100 + + gc.verifyProposalParent(t.Context(), gc.log, proposal.Electra.Block.Slot, proposal, testBeaconClientAddr) + + after := collect() + assertDeltas(t, before, after, []counterDelta{ + {name: "ssv.cl.proposal.parent_verify", want: 1}, + {name: "ssv.cl.proposal.parent_cache_miss", want: 1}, + }) + }) + + t.Run("match labels verify and match counters", func(t *testing.T) { + before := collect() + gc := newGC() + proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) + proposal.Electra.Block.Slot = 100 + gc.headCache.Set(proposal.Electra.Block.Slot-1, proposal.Electra.Block.ParentRoot, ttlcache.NoTTL) + + gc.verifyProposalParent(t.Context(), gc.log, proposal.Electra.Block.Slot, proposal, testBeaconClientAddr) + + after := collect() + assertDeltas(t, before, after, []counterDelta{ + {name: "ssv.cl.proposal.parent_verify", want: 1}, + {name: "ssv.cl.proposal.parent_match", want: 1}, + }) + }) + + t.Run("mismatch labels verify and mismatch counters", func(t *testing.T) { + before := collect() + gc := newGC() + proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) + proposal.Electra.Block.Slot = 100 + cachedRoot := phase0.Root{0xAA} + require.NotEqual(t, cachedRoot, proposal.Electra.Block.ParentRoot) + gc.headCache.Set(proposal.Electra.Block.Slot-1, cachedRoot, ttlcache.NoTTL) + + gc.verifyProposalParent(t.Context(), gc.log, proposal.Electra.Block.Slot, proposal, testBeaconClientAddr) + + after := collect() + assertDeltas(t, before, after, []counterDelta{ + {name: "ssv.cl.proposal.parent_verify", want: 1}, + {name: "ssv.cl.proposal.parent_mismatch", want: 1}, + }) + }) +} diff --git a/cli/operator/node.go b/cli/operator/node.go index 348e1865e9..1edbf980ac 100644 --- a/cli/operator/node.go +++ b/cli/operator/node.go @@ -383,8 +383,8 @@ var StartNodeCmd = &cobra.Command{ } }() logger.Info("observability stack initialized", - zap.Bool("metrics_enabled", cfg.MetricsAPIPort > 0), - zap.Bool("traces_enabled", cfg.EnableTraces), + zap.Bool("metrics_configured", cfg.MetricsAPIPort > 0), + zap.Bool("traces_configured", cfg.EnableTraces), zap.Bool("operator_id_label", operatorDataStore.OperatorIDReady()), ) @@ -393,7 +393,11 @@ var StartNodeCmd = &cobra.Command{ // Caveat: this only baselines the unlabeled time series; counters that emit with // per-call attributes still produce one un-baselined series per attribute set on // first increment — improving that is future work (per-attribute-set baselines). - metrics.EmitBaselines(cmd.Context()) + // Gated on metrics being configured: when disabled the meter provider is no-op and + // the registered Add(0)/closures would just iterate to produce no-op work. + if cfg.MetricsAPIPort > 0 { + metrics.EmitBaselines(cmd.Context()) + } validatorProvider := nodeStorage.ValidatorStore().WithOperatorID(operatorDataStore.GetOperatorID) var validatorRegistrationSubmitter runner.ValidatorRegistrationSubmitter diff --git a/message/validation/observability.go b/message/validation/observability.go index a4ed95453c..2cab9ac012 100644 --- a/message/validation/observability.go +++ b/message/validation/observability.go @@ -27,13 +27,16 @@ var ( metric.WithUnit("{message_validation}"), metric.WithDescription("total number of messages successfully validated and accepted"))) - // Possibly sparse (UNKNOWN from audit): depends on validation failure rate. + // TODO(audit): classification uncertain — depends on validation failure rate which + // in turn depends on network health and version skew. Re-evaluate against production + // data. Mis-classifying as sparse is harmless for PromQL but should reflect intent. messageValidationsIgnoredCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "ignored"), metric.WithUnit("{message_validation}"), metric.WithDescription("total number of messages that failed validation and were ignored")))) + // TODO(audit): see note on messageValidationsIgnoredCounter — same caveat applies. messageValidationsRejectedCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "rejected"), diff --git a/network/peers/connections/observability.go b/network/peers/connections/observability.go index 903867639e..8927a8a77b 100644 --- a/network/peers/connections/observability.go +++ b/network/peers/connections/observability.go @@ -19,19 +19,24 @@ const ( var ( meter = otel.Meter(observabilityComponentName) - // Sparse: per-connection lifecycle events on a steady-state node are infrequent. + // TODO(audit): peer-connection lifecycle events on a node with dozens of peers may + // not be sparse in practice (peer churn, discovery surges). Re-evaluate classification + // against production rates. Mis-classifying as sparse is harmless (Add(0) on a dense + // counter is a no-op for PromQL), but the intent should be accurate. connectedCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "connected"), metric.WithUnit("{connection}"), metric.WithDescription("total number of connected peers")))) + // TODO(audit): see note on connectedCounter — same caveat applies. disconnectedCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "disconnected"), metric.WithUnit("{connection}"), metric.WithDescription("total number of disconnected peers")))) + // TODO(audit): see note on connectedCounter — same caveat applies. filteredCounter = metrics.RegisterSparseCounter(metrics.New( meter.Int64Counter( observability.InstrumentName(observabilityNamespace, "filtered"), diff --git a/observability/attributes.go b/observability/attributes.go index 2c93abcdf9..c199fa5d4d 100644 --- a/observability/attributes.go +++ b/observability/attributes.go @@ -30,7 +30,7 @@ const ( func OperatorIDAttribute(id spectypes.OperatorID) attribute.KeyValue { return attribute.KeyValue{ Key: "ssv.operator_id", - Value: Uint64AttributeValue(uint64(id)), + Value: Uint64AttributeValue(id), } } diff --git a/observability/configurator_test.go b/observability/configurator_test.go new file mode 100644 index 0000000000..72cb6e18ba --- /dev/null +++ b/observability/configurator_test.go @@ -0,0 +1,110 @@ +package observability_test + +import ( + "context" + "math" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel/metric" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" + + "github.com/ssvlabs/ssv/observability" + "github.com/ssvlabs/ssv/observability/metrics" +) + +// installSentinelMetricsLogger swaps metrics.logger to a sentinel observed logger and +// arranges restoration on test completion. Returns the observed logs handle so the test +// can assert what (if anything) was emitted through metrics.logger during the test. +// +// We snapshot only by re-installing a no-op on cleanup — the metrics package doesn't +// expose its current logger, but tests that need restoration are themselves the ones +// installing a sentinel, so resetting to no-op is sufficient for isolation. If this +// becomes a pattern, expose a public metrics.Logger() getter. +func installSentinelMetricsLogger(t *testing.T) *observer.ObservedLogs { + t.Helper() + core, observed := observer.New(zapcore.DebugLevel) + metrics.InitLogger(zap.New(core)) + t.Cleanup(func() { metrics.InitLogger(zap.NewNop()) }) + return observed +} + +// restoreGlobalLogger captures zap.L() before mutations (e.g. via InitializeLogger) and +// restores it in cleanup so test ordering doesn't affect subsequent tests. +func restoreGlobalLogger(t *testing.T) { + t.Helper() + original := zap.L() + t.Cleanup(func() { zap.ReplaceGlobals(original) }) +} + +func TestInitializeLogger_Succeeds(t *testing.T) { + restoreGlobalLogger(t) + t.Cleanup(func() { metrics.InitLogger(zap.NewNop()) }) + + err := observability.InitializeLogger("info", "lowercase", "console", "", 0, 0) + require.NoError(t, err) + + // Sanity: zap.L() now produces a real logger rather than the no-op global. + assert.NotEqual(t, zap.NewNop(), zap.L(), "InitializeLogger must replace the global logger") +} + +func TestInitializeLogger_PropagatesToMetricsPackage(t *testing.T) { + restoreGlobalLogger(t) + t.Cleanup(func() { metrics.InitLogger(zap.NewNop()) }) + + // Pre-condition: install a sentinel into metrics so we can detect propagation + // overwriting it. After InitializeLogger runs, the sentinel will be replaced with the + // named global logger — we just need to observe that the package's logger field is + // no longer our sentinel (i.e. InitializeLogger called metrics.InitLogger). + sentinelObserved := installSentinelMetricsLogger(t) + + err := observability.InitializeLogger("info", "lowercase", "console", "", 0, 0) + require.NoError(t, err) + + // Trigger a log via the metrics package logger. If propagation happened, the + // sentinel core no longer receives it — it goes to the new global instead. + metrics.RecordUint64Value(t.Context(), uint64(math.MaxInt64)+1, noopRecordF) + assert.Zero(t, sentinelObserved.Len(), + "InitializeLogger must propagate to metrics.logger (sentinel should no longer receive)") +} + +func TestInitialize_WorksWithoutInitializeLogger(t *testing.T) { + // No InitializeLogger call: Initialize's localLogger falls back to zap.L() which may + // be a no-op or whatever global was last set. Either way, Initialize must not panic + // and must return a usable shutdown func. + shutdown, err := observability.Initialize(t.Context(), "test-app", "test-version") + require.NoError(t, err) + require.NotNil(t, shutdown) + require.NoError(t, shutdown(t.Context())) +} + +// TestInitialize_DoesNotReplaceMetricsLogger locks the contract documented at +// observability/configurator.go: Initialize intentionally does not re-propagate the +// logger, so calling it (e.g. mid-startup after deferred init) does not have the +// surprising side effect of replacing the metrics/traces internal loggers. +func TestInitialize_DoesNotReplaceMetricsLogger(t *testing.T) { + restoreGlobalLogger(t) + + // Install a sentinel directly into the metrics package logger. Observable logs that + // land in the sentinel core prove the package is still using it after Initialize. + sentinelObserved := installSentinelMetricsLogger(t) + + shutdown, err := observability.Initialize(t.Context(), "test-app", "test-version") + require.NoError(t, err) + t.Cleanup(func() { _ = shutdown(t.Context()) }) + + // Trigger an error log via the metrics package logger — value > MaxInt64 hits the + // "value exceeds int64 range" log path in RecordUint64Value. + metrics.RecordUint64Value(t.Context(), uint64(math.MaxInt64)+1, noopRecordF) + + require.Equal(t, 1, sentinelObserved.Len(), + "Initialize must not replace metrics.logger (sentinel should still receive)") + entry := sentinelObserved.All()[0] + assert.Equal(t, zapcore.ErrorLevel, entry.Level) + assert.Contains(t, entry.Message, "value exceeds int64 range") +} + +func noopRecordF(_ context.Context, _ int64, _ ...metric.RecordOption) {} diff --git a/observability/log/fields/fields.go b/observability/log/fields/fields.go index e547bebf1e..ab443b7a34 100644 --- a/observability/log/fields/fields.go +++ b/observability/log/fields/fields.go @@ -67,6 +67,7 @@ const ( FieldPrivKey = "privkey" FieldProtocolID = "protocol_id" FieldPubKey = "pubkey" + FieldBeaconClient = "beacon_client" FieldBeaconRole = "beacon_role" FieldRunnerRole = "runner_role" FieldSlot = "slot" @@ -117,6 +118,13 @@ func Address(val string) zapcore.Field { return zap.String(FieldAddress, val) } +// BeaconClient is the address of a configured beacon client. Mirrors the metric attribute +// observability.BeaconClientAttribute (which uses the OTel-conventional dotted key +// `ssv.beacon.client`); this helper provides the equivalent snake-case key for log fields. +func BeaconClient(addr string) zapcore.Field { + return zap.String(FieldBeaconClient, addr) +} + func Addresses(vals []string) zapcore.Field { return zap.Strings(FieldAddresses, vals) } diff --git a/observability/metrics/baseline.go b/observability/metrics/baseline.go index e9dd5a5513..0eb9468f12 100644 --- a/observability/metrics/baseline.go +++ b/observability/metrics/baseline.go @@ -89,14 +89,20 @@ func RegisterLabeledBaseline(fn func(context.Context)) { // another Add(ctx, 0), which does not change any counter's value — but it is wasted work // and produces extra samples in the scrape window. Prefer the once-at-startup pattern. func EmitBaselines(ctx context.Context) { + // The sparse-counters loop holds the lock during Add(ctx, 0). This is safe because + // metric.Int64Counter.Add is a leaf operation in the OTel SDK — it does not call back + // into user code and so cannot re-enter RegisterSparseCounter. If a future counter + // implementation grows callbacks (e.g. observable instruments with user callbacks), + // switch to the snapshot-then-invoke pattern used for labeled baselines below. sparseCountersMu.Lock() for _, c := range sparseCounters { c.Add(ctx, 0) } sparseCountersMu.Unlock() - // Copy the slice under lock, then invoke without the lock — defensive in case any - // registered function indirectly triggers another registration. + // Copy the slice under lock, then invoke without the lock — defensive because the + // registered functions are user-provided and may indirectly trigger another + // RegisterLabeledBaseline (which would deadlock if we held the lock while invoking). labeledBaselinesMu.Lock() fns := make([]func(context.Context), len(labeledBaselineFns)) copy(fns, labeledBaselineFns) diff --git a/observability/option.go b/observability/option.go index fde968df60..14520e36b9 100644 --- a/observability/option.go +++ b/observability/option.go @@ -33,4 +33,3 @@ func WithTraces() Option { cfg.traces.enabled = true } } - diff --git a/observability/resources.go b/observability/resources.go index 14a030b139..fe855d7bc1 100644 --- a/observability/resources.go +++ b/observability/resources.go @@ -23,11 +23,13 @@ func buildResources(appName, appVersion string, extraAttrs []attribute.KeyValue, // Build the base attribute set, then append any caller-supplied extras (e.g. operator_id // which is only known after the operator data store is initialized). - baseAttrs := []attribute.KeyValue{ + const baseAttrCount = 3 + baseAttrs := make([]attribute.KeyValue, 0, baseAttrCount+len(extraAttrs)) + baseAttrs = append(baseAttrs, semconv.ServiceName(appName), semconv.ServiceVersion(appVersion), semconv.HostName(hostName), - } + ) baseAttrs = append(baseAttrs, extraAttrs...) const errMsg = "failed to merge OTeL Resources" From cc34c77c522329527fedd58344e9842593328c31 Mon Sep 17 00:00:00 2001 From: iurii Date: Thu, 28 May 2026 14:24:35 +0300 Subject: [PATCH 5/5] observability, beacon/goclient: address own cleanup notes MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit observability/metrics, observability/traces - Add Logger() *zap.Logger getter symmetric with InitLogger. Primary use is letting tests capture-and-restore the package logger around mutations rather than blindly resetting to no-op. observability/configurator_test.go - installSentinelMetricsLogger now captures the original metrics.Logger() and restores it on cleanup (was: reset to zap.NewNop, which lost any pre-existing state). - New restoreMetricsLogger helper for tests that call InitializeLogger (which mutates metrics.logger as a side effect) but don't install a sentinel themselves. - TestInitializeLogger_PropagatesToMetricsPackage no longer duplicates the metrics-logger cleanup — installSentinelMetricsLogger handles it. beacon/goclient/proposer_test.go - createProposalResponseSafe now SSZ-deep-clones the spec-testing fixture (TestingBlockContentsElectra / TestingBlindedBeaconBlockElectra) before mutating Slot / FeeRecipient. Those package-level singletons were being mutated in place on every call, leaking state across every test in the binary that read from the same fixture. The fix is preventive — no test has been observed to be affected today. beacon/goclient/proposer_verify_test.go, beacon/goclient/proposer_verify_metric_test.go - Drop `proposal.Electra.Block.Slot = 100` mutations from all subtests. Tests now use whatever default Slot the fixture provides (ForkEpochPraterElectra) — they only need slot > 0 and a consistent parent root, both of which the default satisfies. - Add explanatory comment block documenting why mutation is avoided. --- beacon/goclient/proposer_test.go | 35 ++++++++++--------- .../goclient/proposer_verify_metric_test.go | 6 ++-- beacon/goclient/proposer_verify_test.go | 10 ++++-- observability/configurator_test.go | 27 ++++++++------ observability/metrics/metric.go | 6 ++++ observability/traces/trace.go | 6 ++++ 6 files changed, 57 insertions(+), 33 deletions(-) diff --git a/beacon/goclient/proposer_test.go b/beacon/goclient/proposer_test.go index adf02efb16..12dd66e57d 100644 --- a/beacon/goclient/proposer_test.go +++ b/beacon/goclient/proposer_test.go @@ -14,6 +14,7 @@ import ( "time" eth2apiv1 "github.com/attestantio/go-eth2-client/api/v1" + apiv1electra "github.com/attestantio/go-eth2-client/api/v1/electra" "github.com/attestantio/go-eth2-client/spec" "github.com/attestantio/go-eth2-client/spec/bellatrix" "github.com/attestantio/go-eth2-client/spec/phase0" @@ -128,37 +129,37 @@ func createProposalBeaconServer(t *testing.T, options beaconProposalServerOption return server, serverGotRequests } -// Create a safe proposal response using ssv-spec utilities (called once during server setup) +// createProposalResponseSafe builds a JSON-encoded beacon proposal response with the +// requested slot + fee recipient. It deep-clones the shared spec-testing fixture before +// mutating: TestingBeaconBlockV / TestingBlindedBeaconBlockV return wrappers whose inner +// *electra.BlockContents / *electra.BlindedBeaconBlock fields point at package-level +// singletons (TestingBlockContentsElectra, TestingBlindedBeaconBlockElectra). Mutating +// those directly leaks state across every test in the binary; SSZ round-trip gives us a +// per-call independent copy. func createProposalResponseSafe(slot phase0.Slot, feeRecipient bellatrix.ExecutionAddress, blinded bool) []byte { if blinded { - // Get a blinded block from ssv-spec testing utilities - versionedBlinded := spectestingutils.TestingBlindedBeaconBlockV(spec.DataVersionElectra) - block := versionedBlinded.ElectraBlinded + shared := spectestingutils.TestingBlindedBeaconBlockV(spec.DataVersionElectra).ElectraBlinded + sszBytes, _ := shared.MarshalSSZ() + block := new(apiv1electra.BlindedBeaconBlock) + _ = block.UnmarshalSSZ(sszBytes) - // Modify the fields we need for our test block.Slot = slot block.Body.ExecutionPayloadHeader.FeeRecipient = feeRecipient - // Wrap in response structure - response := map[string]any{ - "data": block, - } + response := map[string]any{"data": block} data, _ := json.Marshal(response) return data } - // Get a regular block from ssv-spec testing utilities - versioned := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) - blockContents := versioned.Electra + shared := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra).Electra + sszBytes, _ := shared.MarshalSSZ() + blockContents := new(apiv1electra.BlockContents) + _ = blockContents.UnmarshalSSZ(sszBytes) - // Modify the fields we need for our test blockContents.Block.Slot = slot blockContents.Block.Body.ExecutionPayload.FeeRecipient = feeRecipient - // Wrap in response structure - response := map[string]any{ - "data": blockContents, - } + response := map[string]any{"data": blockContents} data, _ := json.Marshal(response) return data } diff --git a/beacon/goclient/proposer_verify_metric_test.go b/beacon/goclient/proposer_verify_metric_test.go index ad46305c12..e2f0bc7717 100644 --- a/beacon/goclient/proposer_verify_metric_test.go +++ b/beacon/goclient/proposer_verify_metric_test.go @@ -81,11 +81,13 @@ func TestVerifyProposalParent_EmitsLabeledMetric(t *testing.T) { } } + // Subtests do not mutate proposal.Electra.Block.Slot — see proposer_verify_test.go + // for the rationale (spec-testing fixture is a shared singleton). + t.Run("cache miss labels verify and cache_miss counters", func(t *testing.T) { before := collect() gc := newGC() proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) - proposal.Electra.Block.Slot = 100 gc.verifyProposalParent(t.Context(), gc.log, proposal.Electra.Block.Slot, proposal, testBeaconClientAddr) @@ -100,7 +102,6 @@ func TestVerifyProposalParent_EmitsLabeledMetric(t *testing.T) { before := collect() gc := newGC() proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) - proposal.Electra.Block.Slot = 100 gc.headCache.Set(proposal.Electra.Block.Slot-1, proposal.Electra.Block.ParentRoot, ttlcache.NoTTL) gc.verifyProposalParent(t.Context(), gc.log, proposal.Electra.Block.Slot, proposal, testBeaconClientAddr) @@ -116,7 +117,6 @@ func TestVerifyProposalParent_EmitsLabeledMetric(t *testing.T) { before := collect() gc := newGC() proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) - proposal.Electra.Block.Slot = 100 cachedRoot := phase0.Root{0xAA} require.NotEqual(t, cachedRoot, proposal.Electra.Block.ParentRoot) gc.headCache.Set(proposal.Electra.Block.Slot-1, cachedRoot, ttlcache.NoTTL) diff --git a/beacon/goclient/proposer_verify_test.go b/beacon/goclient/proposer_verify_test.go index 8d6f9a4506..00cfd2f20d 100644 --- a/beacon/goclient/proposer_verify_test.go +++ b/beacon/goclient/proposer_verify_test.go @@ -38,10 +38,16 @@ func TestVerifyProposalParent_Slot0_ShortCircuitsWithoutLog(t *testing.T) { assert.Zero(t, observed.Len(), "slot==0 path must short-circuit before any log emission") } +// The remaining tests use whatever default slot is set in the spec-testing fixture +// (TestingBlockContentsElectra.Block.Slot, currently ForkEpochPraterElectra). Tests do +// not mutate the fixture — TestingBeaconBlockV returns a fresh wrapper but its .Electra +// field points at a shared package-level singleton, so any field assignment would leak +// across the test binary. We accept whatever Slot the fixture provides and derive +// downstream values (parent slot, expected parent root) from it. + func TestVerifyProposalParent_CacheMissIsSilent(t *testing.T) { gc, observed := newGoClientForVerifyTest(t) proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) - proposal.Electra.Block.Slot = 100 // headCache is empty, so the parent slot lookup misses. Cache miss is metric-only, // no log entry should be emitted. @@ -53,7 +59,6 @@ func TestVerifyProposalParent_CacheMissIsSilent(t *testing.T) { func TestVerifyProposalParent_MatchIsSilent(t *testing.T) { gc, observed := newGoClientForVerifyTest(t) proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) - proposal.Electra.Block.Slot = 100 // Pre-seed the cache with the parent root that the proposal carries — this is the // match path which is also metric-only. @@ -67,7 +72,6 @@ func TestVerifyProposalParent_MatchIsSilent(t *testing.T) { func TestVerifyProposalParent_MismatchLogsBeaconClientField(t *testing.T) { gc, observed := newGoClientForVerifyTest(t) proposal := spectestingutils.TestingBeaconBlockV(spec.DataVersionElectra) - proposal.Electra.Block.Slot = 100 // Cache holds a different root for slot-1 than what the proposal references — // triggers the mismatch path which logs at Info with the beacon_client field. diff --git a/observability/configurator_test.go b/observability/configurator_test.go index 72cb6e18ba..fa5cc48d5c 100644 --- a/observability/configurator_test.go +++ b/observability/configurator_test.go @@ -17,18 +17,15 @@ import ( ) // installSentinelMetricsLogger swaps metrics.logger to a sentinel observed logger and -// arranges restoration on test completion. Returns the observed logs handle so the test -// can assert what (if anything) was emitted through metrics.logger during the test. -// -// We snapshot only by re-installing a no-op on cleanup — the metrics package doesn't -// expose its current logger, but tests that need restoration are themselves the ones -// installing a sentinel, so resetting to no-op is sufficient for isolation. If this -// becomes a pattern, expose a public metrics.Logger() getter. +// arranges restoration to the originally-installed logger on test completion. Returns +// the observed logs handle so the test can assert what (if anything) was emitted through +// metrics.logger during the test. func installSentinelMetricsLogger(t *testing.T) *observer.ObservedLogs { t.Helper() + original := metrics.Logger() core, observed := observer.New(zapcore.DebugLevel) metrics.InitLogger(zap.New(core)) - t.Cleanup(func() { metrics.InitLogger(zap.NewNop()) }) + t.Cleanup(func() { metrics.InitLogger(original) }) return observed } @@ -40,9 +37,18 @@ func restoreGlobalLogger(t *testing.T) { t.Cleanup(func() { zap.ReplaceGlobals(original) }) } +// restoreMetricsLogger captures metrics.Logger() before mutations and restores it on +// cleanup. Use this alongside restoreGlobalLogger in any test that calls InitializeLogger +// (which mutates metrics.logger as a side effect). +func restoreMetricsLogger(t *testing.T) { + t.Helper() + original := metrics.Logger() + t.Cleanup(func() { metrics.InitLogger(original) }) +} + func TestInitializeLogger_Succeeds(t *testing.T) { restoreGlobalLogger(t) - t.Cleanup(func() { metrics.InitLogger(zap.NewNop()) }) + restoreMetricsLogger(t) err := observability.InitializeLogger("info", "lowercase", "console", "", 0, 0) require.NoError(t, err) @@ -53,7 +59,8 @@ func TestInitializeLogger_Succeeds(t *testing.T) { func TestInitializeLogger_PropagatesToMetricsPackage(t *testing.T) { restoreGlobalLogger(t) - t.Cleanup(func() { metrics.InitLogger(zap.NewNop()) }) + // restoreMetricsLogger is implicit in installSentinelMetricsLogger's cleanup, which + // captures-and-restores the original logger. // Pre-condition: install a sentinel into metrics so we can detect propagation // overwriting it. After InitializeLogger runs, the sentinel will be replaced with the diff --git a/observability/metrics/metric.go b/observability/metrics/metric.go index 3977da6127..374d280c17 100644 --- a/observability/metrics/metric.go +++ b/observability/metrics/metric.go @@ -21,6 +21,12 @@ func InitLogger(l *zap.Logger) { logger = l } +// Logger returns the package-level logger. Symmetric with InitLogger; primarily useful +// for tests that need to save and restore the logger around mutations. +func Logger() *zap.Logger { + return logger +} + func New[T any](metric T, err error) T { if err != nil { logger.Error("failed to instantiate metric", zap.Error(err)) diff --git a/observability/traces/trace.go b/observability/traces/trace.go index 1fdc053241..ed048493ba 100644 --- a/observability/traces/trace.go +++ b/observability/traces/trace.go @@ -25,6 +25,12 @@ func InitLogger(l *zap.Logger) { logger = l } +// Logger returns the package-level logger. Symmetric with InitLogger; primarily useful +// for tests that need to save and restore the logger around mutations. +func Logger() *zap.Logger { + return logger +} + // DutyIDFromContext retrieves the duty ID string from the context if present. func DutyIDFromContext(ctx context.Context) (string, bool) { dutyID, ok := ctx.Value(dutyIDKey{}).(string)