feat(verifier): policy endpoint latency histogram

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.

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.
 

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

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...))
+}

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) {
+}

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

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))
+}

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)
 }

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) {
+}