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 b81ab95e79..8a6a6e6118 100644 --- a/beacon/goclient/observability.go +++ b/beacon/goclient/observability.go @@ -70,68 +70,100 @@ 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")))) ) +// 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. +// +// 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 { + 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/beacon/goclient/proposer.go b/beacon/goclient/proposer.go index a072c476f0..791cb5a6ed 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,29 @@ func (gc *GoClient) GetBeaconBlock( copy(graffiti[:], graffitiBytes[:]) var beaconBlock *api.VersionedProposal + // 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 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 +180,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 +285,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 +315,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 +337,26 @@ 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 { + // 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 + } + + clientAttr := metric.WithAttributes(observability.BeaconClientAttribute(beaconClient)) + + proposalParentVerifyCounter.Add(ctx, 1, clientAttr) parentRoot, err := proposal.ParentRoot() if err != nil { @@ -344,22 +368,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), + fields.BeaconClient(beaconClient), ) } 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 new file mode 100644 index 0000000000..e2f0bc7717 --- /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]) + } + } + + // 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) + + 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) + 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) + 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/beacon/goclient/proposer_verify_test.go b/beacon/goclient/proposer_verify_test.go new file mode 100644 index 0000000000..00cfd2f20d --- /dev/null +++ b/beacon/goclient/proposer_verify_test.go @@ -0,0 +1,93 @@ +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") +} + +// 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) + + // 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) + + // 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) + + // 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 c3df393f1f..1edbf980ac 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. + var observabilityOptions []observability.Option if cfg.MetricsAPIPort > 0 { observabilityOptions = append(observabilityOptions, observability.WithMetrics()) } @@ -164,26 +174,6 @@ 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) - - 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(fmt.Sprintf("starting %v", commons.GetBuildData())) ssvNetworkConfig, err := setupSSVNetwork(logger) @@ -359,6 +349,56 @@ 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). 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( + 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)) + } + // 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_configured", cfg.MetricsAPIPort > 0), + zap.Bool("traces_configured", 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. + // 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). + // 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 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..df71e350d7 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: 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..2cab9ac012 100644 --- a/message/validation/observability.go +++ b/message/validation/observability.go @@ -27,17 +27,21 @@ var ( metric.WithUnit("{message_validation}"), metric.WithDescription("total number of messages successfully validated and accepted"))) - messageValidationsIgnoredCounter = metrics.New( + // 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"))) + metric.WithDescription("total number of messages that failed validation and were ignored")))) - messageValidationsRejectedCounter = metrics.New( + // TODO(audit): see note on messageValidationsIgnoredCounter — same caveat applies. + 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..8927a8a77b 100644 --- a/network/peers/connections/observability.go +++ b/network/peers/connections/observability.go @@ -19,23 +19,29 @@ const ( var ( meter = otel.Meter(observabilityComponentName) - connectedCounter = metrics.New( + // 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"))) + metric.WithDescription("total number of connected peers")))) - disconnectedCounter = metrics.New( + // 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"))) + metric.WithDescription("total number of disconnected peers")))) - filteredCounter = metrics.New( + // TODO(audit): see note on connectedCounter — same caveat applies. + 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..c199fa5d4d 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(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..f142455d55 100644 --- a/observability/configurator.go +++ b/observability/configurator.go @@ -32,13 +32,55 @@ func init() { model.NameValidationScheme = model.LegacyValidation // nolint: staticcheck } +// 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). 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, + 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 returns the named logger but we don't need it here. + 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. + // 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 { var joinedErr error localLogger.Info("shutting down observability stack") @@ -50,32 +92,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/configurator_test.go b/observability/configurator_test.go new file mode 100644 index 0000000000..fa5cc48d5c --- /dev/null +++ b/observability/configurator_test.go @@ -0,0 +1,117 @@ +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 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(original) }) + 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) }) +} + +// 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) + restoreMetricsLogger(t) + + 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) + // 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 + // 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 new file mode 100644 index 0000000000..0eb9468f12 --- /dev/null +++ b/observability/metrics/baseline.go @@ -0,0 +1,113 @@ +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. +// +// 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 + sparseCounters []metric.Int64Counter + + labeledBaselinesMu sync.Mutex + labeledBaselineFns []func(context.Context) +) + +// 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. +// +// 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() + sparseCounters = append(sparseCounters, c) + return c +} + +// 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). +// +// 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) { + // 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 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) + labeledBaselinesMu.Unlock() + for _, fn := range fns { + fn(ctx) + } +} 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") +} diff --git a/observability/metrics/metric.go b/observability/metrics/metric.go index b652a5c76d..374d280c17 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} ) @@ -18,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/option.go b/observability/option.go index 6f0d8d7e34..14520e36b9 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, @@ -21,18 +33,3 @@ func WithTraces() Option { cfg.traces.enabled = true } } - -// 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..fe855d7bc1 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,21 @@ 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). + 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" + 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..ed048493ba 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 @@ -23,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) 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) {