diff --git a/changelog/2026-09-05_policy_endpoint_latency_histogram.md b/changelog/2026-09-05_policy_endpoint_latency_histogram.md new file mode 100644 index 000000000..242571a0e --- /dev/null +++ b/changelog/2026-09-05_policy_endpoint_latency_histogram.md @@ -0,0 +1,55 @@ +# Policy endpoint latency histogram + +## Executive Summary + +- `verifier_policy_http_request_duration_seconds` times each call to the operator's policy + endpoint, labeled with the same `policy_passed` / `policy_rejected` / `policy_unavailable` + vocabulary the stage's transition counter uses, so the two read side by side. A `policy_skipped` + task makes no call and never appears. +- The outcome counters only count. An endpoint drifting from 200ms to 4s is invisible on them + until it crosses `request_timeout` and starts failing; this histogram shows it while messages + are still passing. +- Buckets run 1ms to 15s. 15s is `policy.MaxRequestTimeout`, the largest per-call timeout an + operator may configure, so a call that runs to the ceiling lands in a real bucket rather than + `+Inf`. +- `vtypes.MetricLabeler` gains `RecordPolicyHTTPRequestDuration`. See Breaking Changes. + +## AI Adapter Index + +| Symbol | Kind | Search | Location | Section | +|---|---|---|---|---| +| `vtypes.MetricLabeler.RecordPolicyHTTPRequestDuration` | added | `RecordPolicyHTTPRequestDuration\(` | `verifier/pkg/vtypes/interfaces.go:220` | [#the-interface-method](#the-interface-method) | +| `monitoring.VerifierMetricLabeler.RecordPolicyHTTPRequestDuration` | added | `policyHTTPRequestDurationSeconds` | `verifier/pkg/monitoring/metrics.go:965` | [#the-histogram](#the-histogram) | +| `policy.callOutcome` | added | `func callOutcome\(` | `verifier/pkg/policy/gate.go:213` | [#the-histogram](#the-histogram) | + +## Breaking Changes + +`vtypes.MetricLabeler` gains one method, `RecordPolicyHTTPRequestDuration`. The interface is +exported, so an implementation outside this repo stops compiling until it adds the method. + +All five implementations in this repo are updated: `monitoring.VerifierMetricLabeler`, +`monitoring.FakeVerifierMetricLabeler`, `testutil.NoopMetricLabeler`, the generated +`mocks.MockMetricLabeler`, and the test noop in `verifier/pkg/helpers_test.go`. The alternative +shape, an optional interface picked up by type assertion, was not taken: `MetricLabeler` is a +single flat surface of ~25 recording methods with one production implementation, and splitting the +newest one out would leave the caller branching on whether metrics exist for a path where they +always do. + +## The histogram + +`GatedVerifier.evaluateAll` times each `checker.Evaluate` call and records it against the message's +labels. `callOutcome` maps the call to its label: an error is `policy_unavailable`, a FAIL verdict +is `policy_rejected`, anything else is `policy_passed`. An error wins over whatever verdict came +back with it, since a verdict that arrived with an error is not one the gate acts on. + +The instrument is registered in `InitMetrics` and its buckets in `MetricViews`. The top boundary +is named as a literal rather than imported from `policy.MaxRequestTimeout`: `verifier/pkg/policy` +already depends on `verifier/pkg/monitoring`, so the import would cycle. + +## The interface method + +The method takes the outcome as a string rather than a typed enum, matching +`IncrementMessageTransition` next to it. The doc comment names the +`monitoring.MessageTransitionOutcomePolicy*` constants as the vocabulary, and +`TestGatedVerifier_RecordsEndpointLatencyPerOutcome` pins the three the gate actually emits, so a +label renamed on the counter and not here would fail rather than silently split a dashboard. diff --git a/verifier/docs/policy_hook.md b/verifier/docs/policy_hook.md index a87b6e0f3..1595b9487 100644 --- a/verifier/docs/policy_hook.md +++ b/verifier/docs/policy_hook.md @@ -346,6 +346,13 @@ the node's own error, so it lands on the message-failure counter under whatever maps to, not under a policy class. Failures from the endpoint itself are classified as `policy_rejected` or `policy_endpoint_error`. +Endpoint latency is a separate histogram, `verifier_policy_http_request_duration_seconds`, labeled +with the same `policy_passed` / `policy_rejected` / `policy_unavailable` outcome vocabulary (a +skipped task makes no call, so it never appears here). The outcome counters only count; an +endpoint that is slow but not yet timing out shows up here first. Buckets run from 1ms to 15s, +the largest `request_timeout` an operator may configure, so a call that runs to the ceiling still +lands in a bucket. + A rising `policy_skipped` says something upstream is feeding the verifier messages it cannot sign. It is not a policy problem and paging on it as one would be wrong. diff --git a/verifier/internal/mocks/mock_MetricLabeler.go b/verifier/internal/mocks/mock_MetricLabeler.go index a242288fc..e81396c68 100644 --- a/verifier/internal/mocks/mock_MetricLabeler.go +++ b/verifier/internal/mocks/mock_MetricLabeler.go @@ -806,6 +806,41 @@ func (_c *MockMetricLabeler_RecordOldestMessageAge_Call) RunAndReturn(run func(c return _c } +// RecordPolicyHTTPRequestDuration provides a mock function with given fields: ctx, outcome, duration +func (_m *MockMetricLabeler) RecordPolicyHTTPRequestDuration(ctx context.Context, outcome string, duration time.Duration) { + _m.Called(ctx, outcome, duration) +} + +// MockMetricLabeler_RecordPolicyHTTPRequestDuration_Call is a *mock.Call that shadows Run/Return methods with type explicit version for method 'RecordPolicyHTTPRequestDuration' +type MockMetricLabeler_RecordPolicyHTTPRequestDuration_Call struct { + *mock.Call +} + +// RecordPolicyHTTPRequestDuration is a helper method to define mock.On call +// - ctx context.Context +// - outcome string +// - duration time.Duration +func (_e *MockMetricLabeler_Expecter) RecordPolicyHTTPRequestDuration(ctx interface{}, outcome interface{}, duration interface{}) *MockMetricLabeler_RecordPolicyHTTPRequestDuration_Call { + return &MockMetricLabeler_RecordPolicyHTTPRequestDuration_Call{Call: _e.mock.On("RecordPolicyHTTPRequestDuration", ctx, outcome, duration)} +} + +func (_c *MockMetricLabeler_RecordPolicyHTTPRequestDuration_Call) Run(run func(ctx context.Context, outcome string, duration time.Duration)) *MockMetricLabeler_RecordPolicyHTTPRequestDuration_Call { + _c.Call.Run(func(args mock.Arguments) { + run(args[0].(context.Context), args[1].(string), args[2].(time.Duration)) + }) + return _c +} + +func (_c *MockMetricLabeler_RecordPolicyHTTPRequestDuration_Call) Return() *MockMetricLabeler_RecordPolicyHTTPRequestDuration_Call { + _c.Call.Return() + return _c +} + +func (_c *MockMetricLabeler_RecordPolicyHTTPRequestDuration_Call) RunAndReturn(run func(context.Context, string, time.Duration)) *MockMetricLabeler_RecordPolicyHTTPRequestDuration_Call { + _c.Run(run) + return _c +} + // RecordReorgTrackedSeqNums provides a mock function with given fields: ctx, count func (_m *MockMetricLabeler) RecordReorgTrackedSeqNums(ctx context.Context, count int64) { _m.Called(ctx, count) diff --git a/verifier/pkg/helpers_test.go b/verifier/pkg/helpers_test.go index 857d4bbf5..47904f4fe 100644 --- a/verifier/pkg/helpers_test.go +++ b/verifier/pkg/helpers_test.go @@ -192,6 +192,9 @@ func (m *noopMetricLabeler) RecordTokenHTTPRequest(context.Context, string, stri func (m *noopMetricLabeler) RecordTokenHTTPCooldownSeconds(context.Context, string, time.Duration) { } +func (m *noopMetricLabeler) RecordPolicyHTTPRequestDuration(context.Context, string, time.Duration) { +} + // TestVerifier keeps track of all processed messages for testing. type TestVerifier struct { processedTasks []VerificationTask diff --git a/verifier/pkg/monitoring/metrics.go b/verifier/pkg/monitoring/metrics.go index 8c088e51c..e5d42ab85 100644 --- a/verifier/pkg/monitoring/metrics.go +++ b/verifier/pkg/monitoring/metrics.go @@ -165,6 +165,9 @@ type VerifierMetrics struct { tokenHTTPRequestDurationSeconds metric.Float64Histogram tokenHTTPRateLimitedTotal metric.Int64Counter tokenHTTPCooldownSeconds metric.Float64Gauge + + // Policy Hook Metrics (outbound policy endpoint) + policyHTTPRequestDurationSeconds metric.Float64Histogram } // InitMetrics initializes all verifier metrics. @@ -528,6 +531,16 @@ func InitMetrics() (*VerifierMetrics, error) { return nil, fmt.Errorf("failed to register token http cooldown gauge: %w", err) } + // Policy Hook Metrics (outbound policy endpoint) + vm.policyHTTPRequestDurationSeconds, err = beholder.GetMeter().Float64Histogram( + "verifier_policy_http_request_duration_seconds", + metric.WithDescription("Duration of outbound policy hook HTTP requests"), + metric.WithUnit("seconds"), + ) + if err != nil { + return nil, fmt.Errorf("failed to register policy http request duration histogram: %w", err) + } + return vm, nil } @@ -591,6 +604,16 @@ func MetricViews() []sdkmetric.View { Boundaries: []float64{0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10}, }}, ), + // Policy HTTP Request Duration. The top boundary is the largest per-call timeout an + // operator may configure (policy.MaxRequestTimeout, 15s), so a call that runs to the + // ceiling lands in a real bucket instead of +Inf. Named here rather than imported: + // verifier/pkg/policy already depends on this package. + sdkmetric.NewView( + sdkmetric.Instrument{Name: "verifier_policy_http_request_duration_seconds"}, + sdkmetric.Stream{Aggregation: sdkmetric.AggregationExplicitBucketHistogram{ + Boundaries: []float64{0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 15}, + }}, + ), } } @@ -938,3 +961,9 @@ func (v *VerifierMetricLabeler) RecordTokenHTTPCooldownSeconds(ctx context.Conte otelLabels = append(otelLabels, attribute.String("provider", provider)) v.vm.tokenHTTPCooldownSeconds.Record(ctx, cooldown.Seconds(), metric.WithAttributes(otelLabels...)) } + +func (v *VerifierMetricLabeler) RecordPolicyHTTPRequestDuration(ctx context.Context, outcome string, duration time.Duration) { + otelLabels := beholder.OtelAttributes(v.Labels).AsStringAttributes() + otelLabels = append(otelLabels, attribute.String("outcome", outcome)) + v.vm.policyHTTPRequestDurationSeconds.Record(ctx, duration.Seconds(), metric.WithAttributes(otelLabels...)) +} diff --git a/verifier/pkg/monitoring/monitoring.go b/verifier/pkg/monitoring/monitoring.go index 961956f24..1af1b0471 100644 --- a/verifier/pkg/monitoring/monitoring.go +++ b/verifier/pkg/monitoring/monitoring.go @@ -234,3 +234,6 @@ func (f *FakeVerifierMetricLabeler) RecordTokenHTTPRequest(context.Context, stri func (f *FakeVerifierMetricLabeler) RecordTokenHTTPCooldownSeconds(context.Context, string, time.Duration) { } + +func (f *FakeVerifierMetricLabeler) RecordPolicyHTTPRequestDuration(context.Context, string, time.Duration) { +} diff --git a/verifier/pkg/policy/gate.go b/verifier/pkg/policy/gate.go index 1177aa584..01b673691 100644 --- a/verifier/pkg/policy/gate.go +++ b/verifier/pkg/policy/gate.go @@ -197,7 +197,9 @@ func (g *GatedVerifier) evaluateAll(ctx context.Context, tasks []vtypes.Verifica defer func() { <-sem }() req := NewEvaluateRequest(g.verifierID, &tasks[index]) + start := time.Now() verdict, err := g.checker.Evaluate(ctx, req) + g.messageMetrics(tasks[index].Message).RecordPolicyHTTPRequestDuration(ctx, callOutcome(verdict, err), time.Since(start)) out[index] = evaluation{verdict: verdict, err: err} }(i) } @@ -206,6 +208,19 @@ func (g *GatedVerifier) evaluateAll(ctx context.Context, tasks []vtypes.Verifica return out } +// callOutcome classifies one endpoint call for the duration histogram in the same vocabulary the +// stage's transition counter uses, so the two can be read side by side. +func callOutcome(verdict Verdict, err error) string { + switch { + case err != nil: + return monitoring.MessageTransitionOutcomePolicyUnavailable + case verdict.Decision == DecisionFail: + return monitoring.MessageTransitionOutcomePolicyRejected + default: + return monitoring.MessageTransitionOutcomePolicyPassed + } +} + // rejectedResult turns a FAIL into a permanent verification error. The task verifier fails the // queue job, so the message is never signed, never written to an aggregator, and never // auto-executed. Recovery is an operator replay: reschedule the archived job with the verifier diff --git a/verifier/pkg/policy/gate_metrics_test.go b/verifier/pkg/policy/gate_metrics_test.go new file mode 100644 index 000000000..c28b5298c --- /dev/null +++ b/verifier/pkg/policy/gate_metrics_test.go @@ -0,0 +1,139 @@ +package policy + +import ( + "context" + "errors" + "sort" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/smartcontractkit/chainlink-ccv/verifier/pkg/monitoring" + vtypes "github.com/smartcontractkit/chainlink-ccv/verifier/pkg/vtypes" + "github.com/smartcontractkit/chainlink-common/pkg/logger" +) + +// policyDurationCall is one RecordPolicyHTTPRequestDuration the gate made. +type policyDurationCall struct { + outcome string + duration time.Duration +} + +// durationSpy captures the policy duration calls the fake labeler discards. Everything else +// comes from the fake, so the spy does not have to track the whole MetricLabeler surface. +type durationSpy struct { + *monitoring.FakeVerifierMetricLabeler + + mu sync.Mutex + calls []policyDurationCall +} + +// With returns the spy rather than the embedded fake, which would drop the override. +func (s *durationSpy) With(...string) vtypes.MetricLabeler { return s } + +func (s *durationSpy) RecordPolicyHTTPRequestDuration(_ context.Context, outcome string, duration time.Duration) { + s.mu.Lock() + defer s.mu.Unlock() + s.calls = append(s.calls, policyDurationCall{outcome: outcome, duration: duration}) +} + +func (s *durationSpy) recorded() []policyDurationCall { + s.mu.Lock() + defer s.mu.Unlock() + return append([]policyDurationCall(nil), s.calls...) +} + +// outcomes returns the recorded outcome labels, sorted so a concurrent batch compares stably. +func (s *durationSpy) outcomes() []string { + calls := s.recorded() + out := make([]string, 0, len(calls)) + for _, c := range calls { + out = append(out, c.outcome) + } + sort.Strings(out) + return out +} + +// spyMonitoring serves the duration spy in place of the fake labeler. +type spyMonitoring struct { + *monitoring.FakeVerifierMonitoring + spy *durationSpy +} + +func (m *spyMonitoring) Metrics() vtypes.MetricLabeler { return m.spy } + +func newSpyMonitoring() *spyMonitoring { + fake := monitoring.NewFakeVerifierMonitoring() + return &spyMonitoring{ + FakeVerifierMonitoring: fake, + spy: &durationSpy{FakeVerifierMetricLabeler: fake.Fake}, + } +} + +func newGateWithMonitoring(t *testing.T, checker Checker, inner vtypes.Verifier, mon vtypes.Monitoring) *GatedVerifier { + t.Helper() + + gate, err := NewGatedVerifier( + logger.Test(t), "committee-verifier-1", inner, checker, mon, time.Second) + require.NoError(t, err) + return gate +} + +// The histogram's label vocabulary is what a dashboard joins against the stage's transition +// counter, so a PASS, a FAIL, and an endpoint error have to land on the same three outcome +// strings the counter uses. +func TestGatedVerifier_RecordsEndpointLatencyPerOutcome(t *testing.T) { + checker := &stubChecker{ + verdicts: map[string]Verdict{ + msgID(1): {Decision: DecisionPass}, + msgID(2): {Decision: DecisionFail, Reason: "sanctioned"}, + }, + errs: map[string]error{msgID(3): errors.New("endpoint down")}, + } + mon := newSpyMonitoring() + + results := newGateWithMonitoring(t, checker, &stubVerifier{}, mon).VerifyMessages( + t.Context(), + []vtypes.VerificationTask{newTask(msgID(1)), newTask(msgID(2)), newTask(msgID(3))}, + ) + require.Len(t, results, 3) + + assert.Equal(t, []string{ + monitoring.MessageTransitionOutcomePolicyPassed, + monitoring.MessageTransitionOutcomePolicyRejected, + monitoring.MessageTransitionOutcomePolicyUnavailable, + }, mon.spy.outcomes(), "one call per message, labeled by its verdict") + + for _, call := range mon.spy.recorded() { + assert.Positive(t, call.duration, "a recorded call must carry the time it took") + } +} + +// A task the verifier rejects before signing never reaches the endpoint, so it must not land in +// the latency histogram. Counting it would report a call that was never made. +func TestGatedVerifier_SkippedTaskRecordsNoEndpointLatency(t *testing.T) { + checker := &stubChecker{} + inner := &validatingVerifier{invalid: map[string]error{msgID(1): errors.New("unsignable")}} + mon := newSpyMonitoring() + + results := newGateWithMonitoring(t, checker, inner, mon).VerifyMessages( + t.Context(), []vtypes.VerificationTask{newTask(msgID(1)), newTask(msgID(2))}) + require.Len(t, results, 2) + + assert.Equal(t, []string{monitoring.MessageTransitionOutcomePolicyPassed}, mon.spy.outcomes(), + "only the evaluated task is timed") + assert.Equal(t, []string{msgID(2)}, checker.callsMade(), "a skipped task must not be called") +} + +func TestCallOutcome(t *testing.T) { + assert.Equal(t, monitoring.MessageTransitionOutcomePolicyUnavailable, + callOutcome(Verdict{Decision: DecisionPass}, errors.New("boom")), + "an error wins over whatever verdict came back with it") + assert.Equal(t, monitoring.MessageTransitionOutcomePolicyRejected, + callOutcome(Verdict{Decision: DecisionFail}, nil)) + assert.Equal(t, monitoring.MessageTransitionOutcomePolicyPassed, + callOutcome(Verdict{Decision: DecisionPass}, nil)) +} diff --git a/verifier/pkg/vtypes/interfaces.go b/verifier/pkg/vtypes/interfaces.go index 05c864a29..a37ab7a5c 100644 --- a/verifier/pkg/vtypes/interfaces.go +++ b/verifier/pkg/vtypes/interfaces.go @@ -209,4 +209,13 @@ type MetricLabeler interface { // RecordTokenHTTPCooldownSeconds records how long until the outbound attestation // API cools down (0 if not currently cooling down). RecordTokenHTTPCooldownSeconds(ctx context.Context, provider string, cooldown time.Duration) + + // Policy hook (outbound policy endpoint) metrics + + // RecordPolicyHTTPRequestDuration records how long one call to the operator's policy + // endpoint took. outcome is one of the monitoring.MessageTransitionOutcomePolicy* constants + // the stage's transition counter uses; policy_skipped never occurs here because a skipped + // task makes no call. A slow endpoint that is not yet timing out is invisible on the + // outcome counters, which is what this histogram is for. + RecordPolicyHTTPRequestDuration(ctx context.Context, outcome string, duration time.Duration) } diff --git a/verifier/testutil/metric_labeler.go b/verifier/testutil/metric_labeler.go index cb2404cf2..cc8c254fb 100644 --- a/verifier/testutil/metric_labeler.go +++ b/verifier/testutil/metric_labeler.go @@ -82,3 +82,6 @@ func (n *NoopMetricLabeler) RecordTokenHTTPRequest(_ context.Context, _, _, _ st func (n *NoopMetricLabeler) RecordTokenHTTPCooldownSeconds(_ context.Context, _ string, _ time.Duration) { } + +func (n *NoopMetricLabeler) RecordPolicyHTTPRequestDuration(_ context.Context, _ string, _ time.Duration) { +}