Tracing HTTP Requests with Go's net/http/httptrace - Blain Smith

net/http/httptrace has been in the standard library since Go 1.7 and most Go developers I talk to have never used it. It exposes hooks for the points in an outgoing HTTP request that you usually cannot see from outside the transport: DNS resolution, connection acquisition, TLS handshake, the moment bytes go on the wire, the moment the first response byte comes back.

The interesting part is how it plugs in. There is no Tracer interface on http.Client, no middleware to register. You attach a ClientTrace to a context.Context and the transport pulls it back out via httptrace.ContextClientTrace at the points where it matters. I want to walk through that design choice first because it explains how the package composes with the rest of the stdlib, then build two things with it: a curl --trace-style CLI and a reusable http.RoundTripper that logs timings for every request.

Why Context, Not an Interface

The obvious design for request tracing would be to define a Tracer interface, add a Tracer field to http.Client or http.Transport, and call methods on it from inside the transport. That is roughly how most languages handle this.

Go's standard library does not work that way. Instead, httptrace.WithClientTrace returns a new context carrying a *ClientTrace, you attach that context to your request with req.WithContext(ctx), and the transport pulls the trace back out via httptrace.ContextClientTrace at the points where it matters.

trace := &httptrace.ClientTrace{<br>DNSStart: func(info httptrace.DNSStartInfo) {<br>fmt.Printf("DNS start: %s\n", info.Host)<br>},<br>DNSDone: func(info httptrace.DNSDoneInfo) {<br>fmt.Printf("DNS done: %v\n", info.Addrs)<br>},

ctx := httptrace.WithClientTrace(context.Background(), trace)<br>req, _ := http.NewRequestWithContext(ctx, http.MethodGet, "https://example.com", nil)<br>http.DefaultClient.Do(req)<br>This is unusual but it pays off. The trace travels with the request, so any middleware that forwards the context propagates tracing for free. Nothing on the client is shared mutable state, so concurrent requests from the same http.Client can carry different traces. And the transport ignores the trace entirely if no one attached one, so the cost when unused is a nil check.

ClientTrace itself is a struct of optional function fields:

type ClientTrace struct {<br>GetConn func(hostPort string)<br>GotConn func(GotConnInfo)<br>PutIdleConn func(err error)<br>GotFirstResponseByte func()<br>Got100Continue func()<br>Got1xxResponse func(code int, header textproto.MIMEHeader) error<br>DNSStart func(DNSStartInfo)<br>DNSDone func(DNSDoneInfo)<br>ConnectStart func(network, addr string)<br>ConnectDone func(network, addr string, err error)<br>TLSHandshakeStart func()<br>TLSHandshakeDone func(tls.ConnectionState, error)<br>WroteHeaderField func(key string, value []string)<br>WroteHeaders func()<br>Wait100Continue func()<br>WroteRequest func(WroteRequestInfo)<br>You set only the fields you care about. Unset fields are nil and skipped. This is also why the package can add new hooks without breaking anyone - existing code just leaves the new field nil.

Building a curl --trace

The first thing worth building is a CLI that takes a URL and prints a timing breakdown like curl -w does, but with the granularity httptrace exposes. The trick is recording timestamps in each hook and computing durations relative to a start time.

package main

import (<br>"context"<br>"crypto/tls"<br>"fmt"<br>"net/http"<br>"net/http/httptrace"<br>"os"<br>"time"

type timings struct {<br>start time.Time<br>dnsStart time.Time<br>dnsDone time.Time<br>connectStart time.Time<br>connectDone time.Time<br>tlsStart time.Time<br>tlsDone time.Time<br>gotConn time.Time<br>firstByte time.Time<br>done time.Time

func (t *timings) elapsed(at time.Time) time.Duration {<br>return at.Sub(t.start)<br>The ClientTrace for this is mechanical - capture time.Now() in each hook:

func newTrace(t *timings) *httptrace.ClientTrace {<br>return &httptrace.ClientTrace{<br>DNSStart: func(_ httptrace.DNSStartInfo) {<br>t.dnsStart = time.Now()<br>},<br>DNSDone: func(_ httptrace.DNSDoneInfo) {<br>t.dnsDone = time.Now()<br>},<br>ConnectStart: func(_, _ string) {<br>t.connectStart = time.Now()<br>},<br>ConnectDone: func(_, _ string, _ error) {<br>t.connectDone = time.Now()<br>},<br>TLSHandshakeStart: func() {<br>t.tlsStart = time.Now()<br>},<br>TLSHandshakeDone: func(_ tls.ConnectionState, _ error) {<br>t.tlsDone = time.Now()<br>},<br>GotConn: func(_ httptrace.GotConnInfo) {<br>t.gotConn = time.Now()<br>},<br>GotFirstResponseByte: func() {<br>t.firstByte = time.Now()<br>},<br>And the main function wires it up and prints the breakdown:

func main() {<br>url := os.Args[1]

t := &timings{start: time.Now()}<br>trace := newTrace(t)

ctx := httptrace.WithClientTrace(context.Background(), trace)<br>req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil)<br>if err != nil {<br>fmt.Fprintln(os.Stderr, err)<br>os.Exit(1)

res, err := http.DefaultClient.Do(req)<br>if err != nil {<br>fmt.Fprintln(os.Stderr, err)<br>os.Exit(1)<br>res.Body.Close()<br>t.done = time.Now()

fmt.Printf("DNS lookup: %v\n",...