moby/vendor/github.com/go-openapi/runtime/client/httptrace.go

// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers
// SPDX-License-Identifier: Apache-2.0

package client

import (
	"context"
	"crypto/tls"
	"fmt"
	"io"
	"net/http/httptrace"
	"strings"
	"sync"
	"time"

	"github.com/go-openapi/runtime/logger"
)

// traceSession owns the per-request state for [Runtime.Trace].
//
// It tracks the t=0 anchor for the connection phase, accumulates
// per-phase timestamps (for the trailing summary), and emits each
// event to the runtime logger as it fires. One session per
// SubmitContext call.
type traceSession struct {
	logger logger.Logger
	method string
	url    string

	// tlsCfg points at the *tls.Config of the http.Transport that
	// will run the request, when introspectable (i.e. the transport
	// is an *http.Transport). Used by the TLS diagnostic mode to
	// cross-check user configuration against what the handshake
	// actually attempted. Nil when the transport is custom and
	// the config cannot be reached.
	tlsCfg *tls.Config

	mu      sync.Mutex
	start   time.Time
	last    time.Time // last printed event, for relative-dt rendering
	phases  phaseTimings
	gotConn httptrace.GotConnInfo
	tlsDone tlsResult

	dnsStartAt          time.Time
	connectStartAt      time.Time
	tlsHandshakeStartAt time.Time
	wait100StartAt      time.Time
	gotConnAt           time.Time
	wroteHeadersAt      time.Time
	wroteRequestAt      time.Time
	ttfbAt              time.Time

	statusCode int
	rtError    error
}

// phaseTimings holds the per-phase durations for the trailing
// summary line. Zero values mean "phase did not occur" (e.g. no
// DNS lookup on a reused conn, no TLS on http://).
type phaseTimings struct {
	dns  time.Duration
	dial time.Duration
	tls  time.Duration
	ttfb time.Duration // time from GotConn to first response byte
}

// tlsResult captures whatever we learned from TLSHandshakeDone.
// On the happy path err is nil and state is fully populated; on
// failure state may be partial (and is what the TLS diagnostic
// mode in httptrace_tls.go works from).
type tlsResult struct {
	state tls.ConnectionState
	err   error
	done  bool
}

const tracePrefix = "[trace] "

// staleIdleThreshold is the idle duration above which a reused
// pooled connection earns a HEADS-UP annotation. Per-runtime
// configurability is deferred to v2; 30s matches the issue #336
// territory (typical NAT idle timeouts start in the 60–350s
// range, so a 30s reuse is already in "could be stale" zone).
const staleIdleThreshold = 30 * time.Second

// newTraceSession allocates a session and pre-renders the opening
// line (method + url). The session is not yet attached to a
// context — that's the caller's responsibility via session.attach.
//
// tlsCfg may be nil; when non-nil it is used by the TLS diagnostic
// mode to cross-check user-configured constraints (MinVersion,
// CipherSuites, custom RootCAs) against handshake failures.
func newTraceSession(log logger.Logger, method, url string, tlsCfg *tls.Config) *traceSession {
	s := &traceSession{
		logger: log,
		method: method,
		url:    url,
		tlsCfg: tlsCfg,
		start:  time.Now(),
	}
	s.last = s.start
	s.emitf("%s %s", method, url)
	return s
}

// attach installs the session's ClientTrace on ctx and returns the
// derived context. Callers pass the returned context to
// http.Client.Do (typically by setting it on req via
// req.WithContext) so the transport fires the hooks.
func (s *traceSession) attach(ctx context.Context) context.Context {
	return httptrace.WithClientTrace(ctx, s.clientTrace())
}

// clientTrace wires every httptrace hook to the corresponding
// session method. Each callback is responsible for its own
// locking; the stdlib does not serialize trace callbacks.
func (s *traceSession) clientTrace() *httptrace.ClientTrace {
	return &httptrace.ClientTrace{
		GetConn:              s.onGetConn,
		GotConn:              s.onGotConn,
		PutIdleConn:          s.onPutIdleConn,
		GotFirstResponseByte: s.onGotFirstResponseByte,
		Got100Continue:       s.onGot100Continue,
		DNSStart:             s.onDNSStart,
		DNSDone:              s.onDNSDone,
		ConnectStart:         s.onConnectStart,
		ConnectDone:          s.onConnectDone,
		TLSHandshakeStart:    s.onTLSHandshakeStart,
		TLSHandshakeDone:     s.onTLSHandshakeDone,
		WroteHeaders:         s.onWroteHeaders,
		Wait100Continue:      s.onWait100Continue,
		WroteRequest:         s.onWroteRequest,
	}
}

// ---------------------------------------------------------------
// Phase callbacks (stdlib httptrace hooks)
// ---------------------------------------------------------------

func (s *traceSession) onGetConn(hostPort string) {
	s.emitTf("GetConn(%s)", hostPort)
}

func (s *traceSession) onGotConn(info httptrace.GotConnInfo) {
	s.mu.Lock()
	s.gotConn = info
	s.gotConnAt = time.Now()
	s.mu.Unlock()

	if info.Reused {
		s.emitTf("GotConn(reused=true, idle=%t, idle-time=%s)",
			info.WasIdle, info.IdleTime.Round(time.Millisecond))
	} else {
		s.emitTf("GotConn(reused=false)")
	}

	if isStaleIdleReuse(info) {
		s.emitf("# HEADS-UP: reused idle connection (idle for %s).",
			info.IdleTime.Round(time.Second))
		s.emitf("# If this request fails with EOF/connection reset, the server")
		s.emitf("# or an in-path NAT may have dropped the conn silently.")
	}
}

// isStaleIdleReuse reports whether a GotConn info indicates the
// connection came from the idle pool after sitting idle for
// longer than [staleIdleThreshold]. This is the issue #336
// pattern: long-idle pooled conns are the ones most likely to be
// dead by the time the next request tries to use them.
func isStaleIdleReuse(info httptrace.GotConnInfo) bool {
	return info.Reused && info.WasIdle && info.IdleTime > staleIdleThreshold
}

func (s *traceSession) onPutIdleConn(err error) {
	if err != nil {
		s.emitTf("PutIdleConn(err=%v)", err)
		return
	}
	s.emitTf("PutIdleConn")
}

func (s *traceSession) onGotFirstResponseByte() {
	s.mu.Lock()
	s.ttfbAt = time.Now()
	if !s.gotConnAt.IsZero() {
		s.phases.ttfb = s.ttfbAt.Sub(s.gotConnAt)
	}
	s.mu.Unlock()
	s.emitTf("GotFirstResponseByte (TTFB)")
}

func (s *traceSession) onGot100Continue() {
	s.emitTf("Got100Continue")
}

func (s *traceSession) onDNSStart(info httptrace.DNSStartInfo) {
	s.mu.Lock()
	s.dnsStartAt = time.Now()
	s.mu.Unlock()
	s.emitTf("DNSStart(host=%s)", info.Host)
}

func (s *traceSession) onDNSDone(info httptrace.DNSDoneInfo) {
	s.mu.Lock()
	if !s.dnsStartAt.IsZero() {
		s.phases.dns = time.Since(s.dnsStartAt)
	}
	s.mu.Unlock()

	addrs := make([]string, 0, len(info.Addrs))
	for _, a := range info.Addrs {
		addrs = append(addrs, a.String())
	}
	if info.Err != nil {
		s.emitTf("DNSDone(err=%v, addrs=[%s], coalesced=%t)",
			info.Err, strings.Join(addrs, " "), info.Coalesced)
		return
	}
	s.emitTf("DNSDone(addrs=[%s], coalesced=%t)",
		strings.Join(addrs, " "), info.Coalesced)
}

func (s *traceSession) onConnectStart(network, addr string) {
	s.mu.Lock()
	s.connectStartAt = time.Now()
	s.mu.Unlock()
	s.emitTf("ConnectStart(%s %s)", network, addr)
}

func (s *traceSession) onConnectDone(network, addr string, err error) {
	s.mu.Lock()
	if !s.connectStartAt.IsZero() {
		s.phases.dial = time.Since(s.connectStartAt)
	}
	s.mu.Unlock()

	if err != nil {
		s.emitTf("ConnectDone(%s %s, err=%v)", network, addr, err)
		return
	}
	s.emitTf("ConnectDone(%s %s)", network, addr)
}

func (s *traceSession) onTLSHandshakeStart() {
	s.mu.Lock()
	s.tlsHandshakeStartAt = time.Now()
	s.mu.Unlock()
	s.emitTf("TLSHandshakeStart")
}

func (s *traceSession) onTLSHandshakeDone(state tls.ConnectionState, err error) {
	s.mu.Lock()
	if !s.tlsHandshakeStartAt.IsZero() {
		s.phases.tls = time.Since(s.tlsHandshakeStartAt)
	}
	s.tlsDone = tlsResult{state: state, err: err, done: true}
	s.mu.Unlock()

	if err != nil {
		s.emitTf("TLSHandshakeDone(err=%v)", err)
		s.emitTLSDiagnostic(state, err)
		return
	}
	s.emitTf("TLSHandshakeDone(tls=%s, cipher=%s, server=%s%s)",
		tlsVersionName(state.Version),
		tls.CipherSuiteName(state.CipherSuite),
		state.ServerName,
		certExpiryFragment(state),
	)
}

func (s *traceSession) onWroteHeaders() {
	s.mu.Lock()
	s.wroteHeadersAt = time.Now()
	s.mu.Unlock()
	s.emitTf("WroteHeaders")
}

func (s *traceSession) onWait100Continue() {
	s.mu.Lock()
	s.wait100StartAt = time.Now()
	s.mu.Unlock()
	s.emitTf("Wait100Continue")
}

func (s *traceSession) onWroteRequest(info httptrace.WroteRequestInfo) {
	s.mu.Lock()
	s.wroteRequestAt = time.Now()
	s.mu.Unlock()

	if info.Err != nil {
		s.emitTf("WroteRequest(err=%v)", info.Err)
		return
	}
	s.emitTf("WroteRequest")
}

// ---------------------------------------------------------------
// Body wrapping
// ---------------------------------------------------------------

// bodySide identifies which direction an instrumented body is on.
type bodySide string

const (
	bodySend bodySide = "Sent"
	bodyRecv bodySide = "Received"
)

// instrumentedBody wraps an [io.ReadCloser] and emits a
// BodyChunk{Sent,Received} trace event per Read call. Tracks the
// inter-read delay in `dt` so users can see streaming-body
// cadence.
//
// Read granularity: bytes returned by the underlying body, not
// HTTP/1.1 chunked-framing units. For wire-level chunking, use
// [Runtime.Debug] instead.
//
// Concurrency: a single body is read from a single goroutine in
// practice (http.Transport for request bodies, the application
// for response bodies), so no internal locking is needed beyond
// what the underlying ReadCloser provides.
type instrumentedBody struct {
	wrapped io.ReadCloser
	sess    *traceSession
	side    bodySide
	last    time.Time
}

func (b *instrumentedBody) Read(p []byte) (int, error) {
	n, err := b.wrapped.Read(p)
	if n > 0 {
		first := b.last.IsZero()
		var dt time.Duration
		if !first {
			dt = time.Since(b.last)
		}
		b.last = time.Now()
		b.sess.onBodyChunk(b.side, n, dt, first)
	}
	return n, err
}

func (b *instrumentedBody) Close() error {
	return b.wrapped.Close()
}

// wrapRequestBody returns an instrumented wrapper around the
// outgoing request body, or the original body if nil (which is
// the common case for GET requests). The wrapper observes
// Transport-side reads, so BodyChunkSent events appear between
// WroteHeaders and WroteRequest in the trace timeline.
func (s *traceSession) wrapRequestBody(body io.ReadCloser) io.ReadCloser {
	if body == nil {
		return nil
	}
	return &instrumentedBody{wrapped: body, sess: s, side: bodySend}
}

// wrapResponseBody returns an instrumented wrapper around the
// incoming response body. Stacks cleanly above
// [KeepAliveTransport]'s drain-on-close behavior.
func (s *traceSession) wrapResponseBody(body io.ReadCloser) io.ReadCloser {
	if body == nil {
		return nil
	}
	return &instrumentedBody{wrapped: body, sess: s, side: bodyRecv}
}

// onBodyChunk renders a single BodyChunk{Sent,Received} event.
// dt is the duration since the previous Read on the same body and
// is meaningful only when `first` is false. The first chunk has no
// preceding read, so the dt= field is suppressed; every subsequent
// chunk emits dt= unconditionally — even when the measured value
// rounds to zero (common on Windows, where the system clock
// resolution is coarser than a fast loopback read loop).
func (s *traceSession) onBodyChunk(side bodySide, n int, dt time.Duration, first bool) {
	if first {
		s.emitTf("BodyChunk%s(n=%d)", side, n)
		return
	}
	s.emitTf("BodyChunk%s(n=%d, dt=%s)", side, n, round(dt))
}

// ---------------------------------------------------------------
// Submit-level lifecycle hooks (called from SubmitContext)
// ---------------------------------------------------------------

// onRoundTripError is called by SubmitContext when http.Client.Do
// returns an error. It records the error for the summary line.
func (s *traceSession) onRoundTripError(err error) {
	s.mu.Lock()
	s.rtError = err
	s.mu.Unlock()
	s.emitTf("! error: %v", err)
}

// onResponse is called when http.Client.Do returns successfully.
// It records the status code for the summary line.
func (s *traceSession) onResponse(statusCode int) {
	s.mu.Lock()
	s.statusCode = statusCode
	s.mu.Unlock()
}

// finish renders the trailing single-line summary and is called
// by SubmitContext after the response body has been consumed (or
// on error path, after the error was recorded). When a round-trip
// error happened on a stale-idle reused connection, a tail block
// flags the issue #336 pattern explicitly.
func (s *traceSession) finish() {
	s.mu.Lock()
	defer s.mu.Unlock()

	total := time.Since(s.start)
	var b strings.Builder
	fmt.Fprintf(&b, "Summary: %s — ", s.method)
	if s.rtError != nil {
		fmt.Fprintf(&b, "FAILED (%v)", s.rtError)
	} else {
		fmt.Fprintf(&b, "%d", s.statusCode)
	}
	if s.phases.dns > 0 {
		fmt.Fprintf(&b, ", dns=%s", round(s.phases.dns))
	}
	if s.phases.dial > 0 {
		fmt.Fprintf(&b, ", dial=%s", round(s.phases.dial))
	}
	if s.phases.tls > 0 {
		fmt.Fprintf(&b, ", tls=%s", round(s.phases.tls))
	}
	if s.phases.ttfb > 0 {
		fmt.Fprintf(&b, ", ttfb=%s", round(s.phases.ttfb))
	}
	fmt.Fprintf(&b, ", total=%s", round(total))

	s.emitRaw(b.String())

	// issue #336 tail annotation: a round-trip failure on a
	// stale-idle reused conn is the canonical pattern.
	if s.rtError != nil && isStaleIdleReuse(s.gotConn) {
		s.emitf("# FAILED on a reused idle conn (%s idle).",
			s.gotConn.IdleTime.Round(time.Second))
		s.emitf("# Silently closed the conn while it sat in the idle pool.")
		s.emitf("# Consider lowering http.Transport.IdleConnTimeout to evict")
		s.emitf("# pooled conns before the NAT/server side does.")
	}
}

// ---------------------------------------------------------------
// Emission helpers
// ---------------------------------------------------------------

// emitf prints a plain event line (no t= timestamp). Used for the
// opening line and the summary.
func (s *traceSession) emitf(format string, args ...any) {
	s.logger.Debugf(tracePrefix+format, args...)
}

// emitRaw is like emitf but takes an already-rendered string. Used
// by finish() which builds its line via strings.Builder.
func (s *traceSession) emitRaw(line string) {
	s.logger.Debugf("%s", tracePrefix+line)
}

// emitTf prints a phase event with a cumulative t=... offset from
// the session start.
func (s *traceSession) emitTf(format string, args ...any) {
	t := round(time.Since(s.start))
	msg := fmt.Sprintf(format, args...)
	s.logger.Debugf(tracePrefix+"%s (t=%s)", msg, t)
}

// traceRoundUnit is the rounding granularity for >=1ms durations
// rendered in trace output. 100µs keeps lines readable while
// preserving enough resolution to spot millisecond-scale phase
// differences.
const traceRoundUnit = 100 * time.Microsecond

// round trims durations for human-readable trace output.
// Sub-millisecond durations round to 1µs (preserves visibility on
// fast loopback servers); >=1ms durations round to [traceRoundUnit].
func round(d time.Duration) time.Duration {
	if d <= 0 {
		return 0
	}
	if d < time.Millisecond {
		return d.Round(time.Microsecond)
	}
	return d.Round(traceRoundUnit)
}

// ---------------------------------------------------------------
// TLS rendering helpers
// ---------------------------------------------------------------

func tlsVersionName(v uint16) string {
	switch v {
	case tls.VersionTLS10:
		return "1.0"
	case tls.VersionTLS11:
		return "1.1"
	case tls.VersionTLS12:
		return "1.2"
	case tls.VersionTLS13:
		return "1.3"
	default:
		return fmt.Sprintf("0x%04x", v)
	}
}

// certExpiryFragment renders ", expires=YYYY-MM-DD" for the leaf
// cert when available, or an empty string otherwise.
func certExpiryFragment(state tls.ConnectionState) string {
	if len(state.PeerCertificates) == 0 {
		return ""
	}
	return ", expires=" + state.PeerCertificates[0].NotAfter.UTC().Format("2006-01-02")
}