Chapter 17 — Debugging the lifecycle: browser DevTools, curl, OpenSSL, packet capture, and logs

Build it in Go (30 min) — curl -w you can extend

Go's net/http/httptrace package calls you back at every phase of a request. httptrace turns those callbacks into a timing breakdown, and then prints the response headers that reveal the path (CDN, cache, protocol upgrades). With -n it sends several requests on one client, so you can watch connection reuse:

// httptrace: `curl -w` in Go -- time every phase of an HTTPS request and show
// what the response says about caches, servers, and protocols on the way.
//
//	go run ./httptrace https://example.com/
//	go run ./httptrace -n 3 https://www.cloudflare.com/     # watch connection reuse
package main

import (
	"crypto/tls"
	"flag"
	"fmt"
	"io"
	"net/http"
	"net/http/httptrace"
	"os"
	"strings"
	"time"
)

func main() {
	n := flag.Int("n", 1, "number of sequential requests (shows connection reuse)")
	flag.Parse()
	if flag.NArg() != 1 {
		fmt.Println("usage: httptrace [-n N] URL")
		os.Exit(2)
	}
	client := &http.Client{Timeout: 15 * time.Second} // one client = one connection pool
	for i := 1; i <= *n; i++ {
		if err := trace(client, flag.Arg(0), i); err != nil {
			fmt.Println("error:", err)
			os.Exit(1)
		}
	}
}

func trace(client *http.Client, url string, i int) error {
	var start, dnsStart, dnsDone, connStart, connDone, tlsStart, tlsDone, gotConn, wrote, firstByte time.Time
	var reused bool
	var remote string
	var tlsState *tls.ConnectionState

	ct := &httptrace.ClientTrace{
		DNSStart:          func(httptrace.DNSStartInfo) { dnsStart = time.Now() },
		DNSDone:           func(httptrace.DNSDoneInfo) { dnsDone = time.Now() },
		ConnectStart:      func(_, _ string) { connStart = time.Now() },
		ConnectDone:       func(_, addr string, _ error) { connDone, remote = time.Now(), addr },
		TLSHandshakeStart: func() { tlsStart = time.Now() },
		TLSHandshakeDone: func(s tls.ConnectionState, _ error) {
			tlsDone, tlsState = time.Now(), &s
		},
		GotConn: func(info httptrace.GotConnInfo) {
			gotConn, reused = time.Now(), info.Reused
			if remote == "" {
				remote = info.Conn.RemoteAddr().String()
			}
		},
		WroteRequest:         func(httptrace.WroteRequestInfo) { wrote = time.Now() },
		GotFirstResponseByte: func() { firstByte = time.Now() },
	}

	req, err := http.NewRequest("GET", url, nil)
	if err != nil {
		return err
	}
	req = req.WithContext(httptrace.WithClientTrace(req.Context(), ct))

	start = time.Now()
	resp, err := client.Do(req)
	if err != nil {
		return err
	}
	body, _ := io.Copy(io.Discard, resp.Body)
	resp.Body.Close()
	end := time.Now()

	ms := func(a, b time.Time) string {
		if a.IsZero() || b.IsZero() {
			return "     -   "
		}
		return fmt.Sprintf("%7.1fms", float64(b.Sub(a).Microseconds())/1000)
	}
	fmt.Printf("request #%d  %s  %s  reused=%v  remote=%s\n", i, resp.Proto, resp.Status, reused, remote)
	fmt.Printf("  dns       %s\n", ms(dnsStart, dnsDone))
	fmt.Printf("  tcp       %s\n", ms(connStart, connDone))
	fmt.Printf("  tls       %s", ms(tlsStart, tlsDone))
	if tlsState != nil {
		fmt.Printf("   %s, ALPN=%q, resumed=%v", tls.VersionName(tlsState.Version), tlsState.NegotiatedProtocol, tlsState.DidResume)
	}
	fmt.Println()
	fmt.Printf("  got conn  %s  (time to a usable connection)\n", ms(start, gotConn))
	fmt.Printf("  ttfb      %s  (request written -> first byte: server think time + 1 RTT)\n", ms(wrote, firstByte))
	fmt.Printf("  download  %s  (%d bytes)\n", ms(firstByte, end), body)
	fmt.Printf("  total     %s\n", ms(start, end))

	// What the headers reveal about the path.
	for _, h := range []string{"Server", "Via", "Age", "Cache-Control", "CF-Cache-Status", "X-Cache",
		"Alt-Svc", "Strict-Transport-Security", "Server-Timing", "Content-Encoding"} {
		if v := resp.Header.Get(h); v != "" {
			fmt.Printf("  %-26s %s\n", h+":", strings.TrimSpace(v))
		}
	}
	fmt.Println()
	return nil
}

$ go run ./httptrace -n 2 https://example.com/
request #1  HTTP/2.0  200 OK  reused=false  remote=104.20.23.154:443
  dns          30.2ms
  tcp          19.5ms
  tls        1108.8ms   TLS 1.3, ALPN="h2", resumed=false
  got conn   1159.5ms  (time to a usable connection)
  ttfb         63.5ms  (request written -> first byte: server think time + 1 RTT)
  download      0.1ms  (577 bytes)
  total      1223.3ms
  Server:                    cloudflare
  Age:                       1345
  CF-Cache-Status:           HIT
  Alt-Svc:                   h3=":443"; ma=86400

request #2  HTTP/2.0  200 OK  reused=true  remote=104.20.23.154:443
  dns            -
  tcp            -
  tls            -
  got conn      0.0ms  (time to a usable connection)
  ttfb         53.2ms  (request written -> first byte: server think time + 1 RTT)
  total        53.6ms

Read it like an incident responder:

• The TLS phase took 1,109 ms while TCP took 19.5 ms. One RTT was about 20 ms, so a TLS 1.3 handshake should take about 20 ms too. Something stalled: packet loss during the handshake, a busy TLS terminator, or a retransmitted large certificate flight. Run it again. If it's consistent, capture packets; if it's rare, it's a tail-latency problem worth graphing.
• Request #2 skipped DNS, TCP, and TLS entirely (reused=true) and finished in 54 ms instead of 1,223 ms. Connection reuse is the cheapest performance fix there is.
• CF-Cache-Status: HIT with Age: 1345: the CDN answered from a copy about 22 minutes old, so the 63 ms TTFB never touched the origin.
• ttfb ≈ server time + 1 RTT. Subtract the TCP time (≈1 RTT) from TTFB to estimate how long the server or edge spent thinking.

Exercises:

1. Point it at your own service and at the same service through your CDN. Which phases move?
2. Add -resolve host:ip (use a custom DialContext, as the TCP/IP guide's tcpinfo lab does) to test one specific backend or POP.
3. Print the Server-Timing header if present, and add it to your own service: Server-Timing: db;dur=53, render;dur=12. It shows up in browser DevTools too.
4. Run -n 20 and print p50/p99 of each phase. One slow handshake in 20 is a finding.