CRE-4405: Add gateway request tracing

Add httptrace metrics to network/httpclient used by the Gateway

Author: cedric-cordenier

core/cmd/shell.go

@@ -51,6 +51,7 @@ import (
 	"github.com/smartcontractkit/chainlink/v2/core/services/ccv/ccvcommon"
 	"github.com/smartcontractkit/chainlink/v2/core/services/chainlink"
 	"github.com/smartcontractkit/chainlink/v2/core/services/cre"
+	gatewaynetwork "github.com/smartcontractkit/chainlink/v2/core/services/gateway/network"
 	"github.com/smartcontractkit/chainlink/v2/core/services/keystore"
 	"github.com/smartcontractkit/chainlink/v2/core/services/llo"
 	"github.com/smartcontractkit/chainlink/v2/core/services/llo/retirement"
@@ -80,6 +81,7 @@ func metricViews() []sdkmetric.View {
 		ccvcommon.MetricViews(),
 		ocr3beholderwrapper.MetricViews(),
 		ocr3_1beholderwrapper.MetricViews(),
+		gatewaynetwork.HTTPClientMetricViews(),
 	)
 }
 

core/services/gateway/network/httpclient.go

@@ -8,6 +8,7 @@ import (
 	"io"
 	"maps"
 	"net/http"
+	"net/http/httptrace"
 	"slices"
 	"strings"
 
@@ -169,9 +170,10 @@ func responseHeadersFromNetHeader(h http.Header) (map[string]string, map[string]
 }
 
 type httpClient struct {
-	client *safeurl.WrappedClient
-	config HTTPClientConfig
-	lggr   logger.Logger
+	client  *safeurl.WrappedClient
+	config  HTTPClientConfig
+	lggr    logger.Logger
+	metrics *httpClientMetrics
 }
 
 // NewHTTPClient creates a new NewHTTPClient
@@ -196,10 +198,16 @@ func NewHTTPClient(config HTTPClientConfig, lggr logger.Logger) (HTTPClient, err
 		SetCheckRedirect(disableRedirects).
 		Build()
 
+	metrics, err := newHTTPClientMetrics()
+	if err != nil {
+		return nil, err
+	}
+
 	return &httpClient{
-		config: config,
-		client: safeurl.Client(safeConfig),
-		lggr:   lggr,
+		config:  config,
+		client:  safeurl.Client(safeConfig),
+		lggr:    lggr,
+		metrics: metrics,
 	}, nil
 }
 
@@ -297,8 +305,13 @@ func (c *httpClient) Send(ctx context.Context, req HTTPRequest) (*HTTPResponse,
 	timeoutCtx, cancel := context.WithTimeout(ctx, to)
 	defer cancel()
 
+	requestStart := time.Now()
+	trace, traceState := newClientTrace(ctx, req.Method, requestStart, c.metrics)
+	timeoutCtx = httptrace.WithClientTrace(timeoutCtx, trace)
+
 	r, err := http.NewRequestWithContext(timeoutCtx, req.Method, req.URL, bytes.NewBuffer(req.Body))
 	if err != nil {
+		c.metrics.recordTotal(ctx, req.Method, 0, false, false, time.Since(requestStart))
 		return nil, err
 	}
 	for k, values := range requestToNetHeader(req) {
@@ -309,6 +322,7 @@ func (c *httpClient) Send(ctx context.Context, req HTTPRequest) (*HTTPResponse,
 
 	resp, err := c.client.Do(r)
 	if err != nil {
+		c.metrics.recordTotal(ctx, req.Method, 0, false, traceState.connReused.Load(), time.Since(requestStart))
 		if isBlockedRequest(err) {
 			c.lggr.Warnw("HTTP request blocked", "err", err)
 			return nil, fmt.Errorf("%w: %w", ErrBlockedRequest, err)
@@ -324,10 +338,13 @@ func (c *httpClient) Send(ctx context.Context, req HTTPRequest) (*HTTPResponse,
 	reader := http.MaxBytesReader(nil, resp.Body, int64(n))
 	body, err := io.ReadAll(reader)
 	if err != nil {
+		c.metrics.recordTotal(ctx, req.Method, resp.StatusCode, false, traceState.connReused.Load(), time.Since(requestStart))
 		c.lggr.Errorw("failed to read HTTP response body", "err", err)
 		return nil, errors.Join(err, ErrHTTPRead)
 	}
 
+	c.metrics.recordTotal(ctx, req.Method, resp.StatusCode, true, traceState.connReused.Load(), time.Since(requestStart))
+
 	headers, multiHeaders := responseHeadersFromNetHeader(resp.Header)
 	c.lggr.Debugw("received HTTP response", "statusCode", resp.StatusCode)
 	return &HTTPResponse{

core/services/gateway/network/httpclient_metrics.go

@@ -0,0 +1,81 @@
+package network
+
+import (
+	"context"
+	"fmt"
+	"strconv"
+	"time"
+
+	"github.com/prometheus/client_golang/prometheus"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/metric"
+	sdkmetric "go.opentelemetry.io/otel/sdk/metric"
+
+	"github.com/smartcontractkit/chainlink-common/pkg/beholder"
+)
+
+// TracePhase identifies a phase of the HTTP client request lifecycle as
+// observed via net/http/httptrace.
+type TracePhase string
+
+const (
+	PhaseGetConn         TracePhase = "get_conn"
+	PhaseDNSLookup       TracePhase = "dns_lookup"
+	PhaseTCPConnect      TracePhase = "tcp_connect"
+	PhaseTLSHandshake    TracePhase = "tls_handshake"
+	PhaseWroteRequest    TracePhase = "wrote_request"
+	PhaseTimeToFirstByte TracePhase = "time_to_first_byte"
+	PhaseTotal           TracePhase = "total"
+)
+
+type httpClientMetrics struct {
+	phaseDuration metric.Int64Histogram
+}
+
+func newHTTPClientMetrics() (*httpClientMetrics, error) {
+	phaseDuration, err := beholder.GetMeter().Int64Histogram(
+		"platform_gateway_http_client_phase_duration_ms",
+		metric.WithUnit("ms"),
+		metric.WithDescription("HTTP client request phase duration observed via httptrace. The count of phase=total observations is the request count, partitioned by method, statusCode, success, and connectionReused."),
+	)
+	if err != nil {
+		return nil, fmt.Errorf("failed to create platform_gateway_http_client_phase_duration_ms histogram: %w", err)
+	}
+
+	return &httpClientMetrics{
+		phaseDuration: phaseDuration,
+	}, nil
+}
+
+func (m *httpClientMetrics) recordPhase(ctx context.Context, method string, phase TracePhase, d time.Duration) {
+	m.phaseDuration.Record(ctx, d.Milliseconds(), metric.WithAttributes(
+		attribute.String("method", method),
+		attribute.String("phase", string(phase)),
+	))
+}
+
+// recordTotal records the total request lifetime with the result attributes.
+// The histogram's count for phase=total doubles as the request counter.
+func (m *httpClientMetrics) recordTotal(ctx context.Context, method string, statusCode int, success, connReused bool, d time.Duration) {
+	m.phaseDuration.Record(ctx, d.Milliseconds(), metric.WithAttributes(
+		attribute.String("method", method),
+		attribute.String("phase", string(PhaseTotal)),
+		attribute.String("statusCode", strconv.Itoa(statusCode)),
+		attribute.String("success", strconv.FormatBool(success)),
+		attribute.String("connectionReused", strconv.FormatBool(connReused)),
+	))
+}
+
+// HTTPClientMetricViews returns histogram bucket definitions for the HTTP client trace metrics.
+// Due to the OTEL specification, all histogram buckets must be defined when the beholder client is created.
+func HTTPClientMetricViews() []sdkmetric.View {
+	return []sdkmetric.View{
+		sdkmetric.NewView(
+			sdkmetric.Instrument{Name: "platform_gateway_http_client_phase_duration_ms"},
+			sdkmetric.Stream{Aggregation: sdkmetric.AggregationExplicitBucketHistogram{
+				// 1, 2, 4, 8, 16, 32, 64, 128, 256, 512, 1024, 2048, 4096, 8192, 16384, 32768 (ms)
+				Boundaries: prometheus.ExponentialBuckets(1, 2, 16),
+			}},
+		),
+	}
+}

core/services/gateway/network/httpclient_metrics_test.go

@@ -0,0 +1,48 @@
+package network
+
+import (
+	"context"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/require"
+)
+
+func TestNewHTTPClientMetrics(t *testing.T) {
+	m, err := newHTTPClientMetrics()
+	require.NoError(t, err)
+	require.NotNil(t, m)
+}
+
+func TestHTTPClientMetrics_RecordPhase(t *testing.T) {
+	m, err := newHTTPClientMetrics()
+	require.NoError(t, err)
+
+	ctx := context.Background()
+	for _, phase := range []TracePhase{
+		PhaseGetConn,
+		PhaseDNSLookup,
+		PhaseTCPConnect,
+		PhaseTLSHandshake,
+		PhaseWroteRequest,
+		PhaseTimeToFirstByte,
+		PhaseTotal,
+	} {
+		m.recordPhase(ctx, "GET", phase, 25*time.Millisecond)
+	}
+}
+
+func TestHTTPClientMetrics_RecordTotal(t *testing.T) {
+	m, err := newHTTPClientMetrics()
+	require.NoError(t, err)
+
+	ctx := context.Background()
+	m.recordTotal(ctx, "GET", 200, true, false, 25*time.Millisecond)
+	m.recordTotal(ctx, "POST", 500, true, true, 100*time.Millisecond)
+	m.recordTotal(ctx, "GET", 0, false, false, 5*time.Millisecond)
+}
+
+func TestHTTPClientMetricViews(t *testing.T) {
+	views := HTTPClientMetricViews()
+	require.Len(t, views, 1)
+}

core/services/gateway/network/httpclient_trace.go

@@ -0,0 +1,79 @@
+package network
+
+import (
+	"context"
+	"crypto/tls"
+	"net/http/httptrace"
+	"sync/atomic"
+	"time"
+)
+
+// requestTrace holds out-of-band signals captured during a single HTTP request
+// so the caller can include them in the final request metric.
+type requestTrace struct {
+	connReused atomic.Bool
+}
+
+// newClientTrace returns an httptrace.ClientTrace that records per-phase
+// durations on m, along with a requestTrace exposing connection reuse.
+//
+// httptrace may invoke callbacks concurrently so each phase keeps its own atomic start timestamp.
+func newClientTrace(ctx context.Context, method string, requestStart time.Time, m *httpClientMetrics) (*httptrace.ClientTrace, *requestTrace) {
+	rt := &requestTrace{}
+
+	var (
+		getConnStart atomic.Pointer[time.Time]
+		dnsStart     atomic.Pointer[time.Time]
+		connectStart atomic.Pointer[time.Time]
+		tlsStart     atomic.Pointer[time.Time]
+	)
+
+	storeNow := func(p *atomic.Pointer[time.Time]) {
+		now := time.Now()
+		p.Store(&now)
+	}
+
+	recordPhase := func(start *atomic.Pointer[time.Time], phase TracePhase) {
+		s := start.Load()
+		if s == nil {
+			return
+		}
+		m.recordPhase(ctx, method, phase, time.Since(*s))
+	}
+
+	return &httptrace.ClientTrace{
+		GetConn: func(string) {
+			storeNow(&getConnStart)
+		},
+		GotConn: func(info httptrace.GotConnInfo) {
+			recordPhase(&getConnStart, PhaseGetConn)
+			if info.Reused {
+				rt.connReused.Store(true)
+			}
+		},
+		DNSStart: func(httptrace.DNSStartInfo) {
+			storeNow(&dnsStart)
+		},
+		DNSDone: func(httptrace.DNSDoneInfo) {
+			recordPhase(&dnsStart, PhaseDNSLookup)
+		},
+		ConnectStart: func(string, string) {
+			storeNow(&connectStart)
+		},
+		ConnectDone: func(string, string, error) {
+			recordPhase(&connectStart, PhaseTCPConnect)
+		},
+		TLSHandshakeStart: func() {
+			storeNow(&tlsStart)
+		},
+		TLSHandshakeDone: func(tls.ConnectionState, error) {
+			recordPhase(&tlsStart, PhaseTLSHandshake)
+		},
+		WroteRequest: func(httptrace.WroteRequestInfo) {
+			m.recordPhase(ctx, method, PhaseWroteRequest, time.Since(requestStart))
+		},
+		GotFirstResponseByte: func() {
+			m.recordPhase(ctx, method, PhaseTimeToFirstByte, time.Since(requestStart))
+		},
+	}, rt
+}