Go's httptrace: Debug HTTP Requests Without APM Agents

The Context-Based Design

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

The design choice is unusual. There is no Tracer interface on http.Client or http.Transport. Instead, you attach a *httptrace.ClientTrace to a context.Context via httptrace.WithClientTrace, and the transport pulls it back out via httptrace.ContextClientTrace at the relevant points.

trace := &httptrace.ClientTrace{
    DNSStart: func(info httptrace.DNSStartInfo) {
        fmt.Printf("DNS start: %s\n", info.Host)
    },
    DNSDone: func(info httptrace.DNSDoneInfo) {
        fmt.Printf("DNS done: %v\n", info.Addrs)
    },
}
ctx := httptrace.WithClientTrace(context.Background(), trace)
req, _ := http.NewRequestWithContext(ctx, http.MethodGet, "https://example.com", nil)
http.DefaultClient.Do(req)

This pays off in three ways. First, the trace travels with the request, so any middleware that forwards the context propagates tracing for free. Second, nothing on the client is shared mutable state, so concurrent requests from the same http.Client can carry different traces. Third, the transport ignores the trace entirely if no one attached one — the cost when unused is a single nil check.

ClientTrace itself is a struct of optional function fields. You set only the fields you care about; unset fields are nil and skipped. This allows the package to add new hooks without breaking existing code.

Building a curl --trace CLI

The first project is a CLI that prints a timing breakdown for any URL, similar to curl -w but with the granularity httptrace exposes.

Define a timings struct to record timestamps:

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

Create the trace by capturing time.Now() in each hook:

func newTrace(t *timings) *httptrace.ClientTrace {
    return &httptrace.ClientTrace{
        DNSStart: func(_ httptrace.DNSStartInfo) {
            t.dnsStart = time.Now()
        },
        DNSDone: func(_ httptrace.DNSDoneInfo) {
            t.dnsDone = time.Now()
        },
        ConnectStart: func(_, _ string) {
            t.connectStart = time.Now()
        },
        ConnectDone: func(_, _ string, _ error) {
            t.connectDone = time.Now()
        },
        TLSHandshakeStart: func() {
            t.tlsStart = time.Now()
        },
        TLSHandshakeDone: func(_ tls.ConnectionState, _ error) {
            t.tlsDone = time.Now()
        },
        GotConn: func(_ httptrace.GotConnInfo) {
            t.gotConn = time.Now()
        },
        GotFirstResponseByte: func() {
            t.firstByte = time.Now()
        },
    }
}

Wire it together in main:

func main() {
    url := os.Args[1]
    t := &timings{start: time.Now()}
    trace := newTrace(t)
    ctx := httptrace.WithClientTrace(context.Background(), trace)
    req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil)
    if err != nil {
        fmt.Fprintln(os.Stderr, err)
        os.Exit(1)
    }
    res, err := http.DefaultClient.Do(req)
    if err != nil {
        fmt.Fprintln(os.Stderr, err)
        os.Exit(1)
    }
    res.Body.Close()
    t.done = time.Now()

    fmt.Printf("DNS lookup:       %v\n", t.dnsDone.Sub(t.dnsStart))
    fmt.Printf("TCP connect:      %v\n", t.connectDone.Sub(t.connectStart))
    fmt.Printf("TLS handshake:    %v\n", t.tlsDone.Sub(t.tlsStart))
    fmt.Printf("Server processing: %v\n", t.firstByte.Sub(t.gotConn))
    fmt.Printf("Content transfer: %v\n", t.done.Sub(t.firstByte))
    fmt.Printf("Total:            %v\n", t.done.Sub(t.start))
}

Run it against any URL and the output tells you where the time went. Slow DNS? Slow TLS? Server taking long to produce the first byte? Each shows up on its own line. No proxy, no APM agent, no instrumentation library in the dependency graph.

A few caveats: DNSStart and DNSDone only fire if Go's resolver does the lookup — if the address is already in the kernel's DNS cache or you passed an IP directly, the hooks stay quiet. TLSHandshakeStart and TLSHandshakeDone only fire on HTTPS. GotConn fires whether the connection was new or reused, and the GotConnInfo struct has a Reused field.

Building a RoundTripper

A one-shot CLI is useful, but most of the time you want every request through a given http.Client traced automatically. That's what http.RoundTripper is for. Wrap the default transport, attach a trace to the context before delegating, and log the result when the request finishes.

type TracingTransport struct {
    Base http.RoundTripper
    Log  func(req *http.Request, t *timings)
}

func (tt *TracingTransport) RoundTrip(req *http.Request) (*http.Response, error) {
    base := tt.Base
    if base == nil {
        base = http.DefaultTransport
    }
    t := &timings{start: time.Now()}
    trace := newTrace(t)
    req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace))
    res, err := base.RoundTrip(req)
    t.done = time.Now()
    if tt.Log != nil {
        tt.Log(req, t)
    }
    return res, err
}

Usage:

client := &http.Client{
    Transport: &TracingTransport{
        Log: func(req *http.Request, t *timings) {
            log.Printf("%s %s dns=%v tls=%v ttfb=%v total=%v",
                req.Method, req.URL,
                t.dnsDone.Sub(t.dnsStart),
                t.tlsDone.Sub(t.tlsStart),
                t.firstByte.Sub(t.gotConn),
                t.done.Sub(t.start),
            )
        },
    },
}
client.Get("https://example.com")

One subtlety: if the caller already attached a ClientTrace to the request's context, calling httptrace.WithClientTrace again composes rather than replaces. ContextClientTrace returns the most recently attached trace, but hooks from both fire. For a RoundTripper this is usually what you want — the caller's tracing is preserved and yours runs alongside it. If you need to replace the existing trace, inspect the context yourself.

Another important detail: RoundTrip returns when the response headers are read, not when the body is consumed. t.done above measures TTFB plus header read, not total request time including body. For total time including body transfer, wrap res.Body in a reader that records time.Now() on Close:

type timedBody struct {
    io.ReadCloser
    onClose func()
}

func (tb *timedBody) Close() error {
    tb.onClose()
    return tb.ReadCloser.Close()
}

// inside RoundTrip, after base.RoundTrip:
res.Body = &timedBody{
    ReadCloser: res.Body,
    onClose:    func() { t.done = time.Now() },
}

Now t.done is set when the caller finishes reading the body and closes it — the true total request duration.

Connection Reuse

One of the most useful things httptrace reveals is whether your client is actually reusing connections. The GotConnInfo struct includes Reused and WasIdle fields. If you make repeated calls to the same host and Reused is false every time, something is preventing pooling — usually a per-request http.Client or a response body that never gets closed.

Add it to the trace:

GotConn: func(info httptrace.GotConnInfo) {
    t.gotConn = time.Now()
    if info.Reused {
        log.Printf("connection reused (idle for %v)", info.IdleTime)
    } else {
        log.Printf("new connection to %s", info.Conn.RemoteAddr())
    }
},

This is the kind of thing you would otherwise need a packet capture to verify.

Conclusion

net/http/httptrace is a small surface: one function to attach a trace, one to retrieve it, and a struct of hooks. The context-based design composes with anything in the stdlib that already threads context.Context through. The CLI and RoundTripper shown here are short enough to drop into any project as a starting point for debugging slow HTTP calls before reaching for distributed tracing or an APM agent.