使用 Go 的 net/http/httptrace 追踪 HTTP 请求

# 使用 Go 的 net/http/httptrace 追踪 HTTP 请求 来源：https://blainsmith.com/articles/httptrace-with-go/ \[主页 (https://blainsmith.com/)\] \[随笔 (https://blainsmith.com/essays)\] \[文章 (https://blainsmith.com/articles)\] \[项目 (https://blainsmith.com/projects)\] \[现在 (https://blainsmith.com/now)\] \[简历 (https://blainsmith.com/resume)\] \[演讲 (https://blainsmith.com/talks)\] 2026年5月26日 `net/http/httptrace` (https://pkg.go.dev/net/http/httptrace) 自 Go 1.7 起就被包含在标准库中，但我接触的大多数 Go 开发者从未使用过它。它暴露了出站 HTTP 请求中你通常无法从传输层外部看到的各个阶段的钩子：DNS 解析、连接获取、TLS 握手、字节发送到线路的时刻、首个响应字节返回的时刻。 有趣的地方在于它的接入方式。`http.Client` 上没有 `Tracer` 接口，也没有需要注册的中间件。你将一个 `ClientTrace` (https://pkg.go.dev/net/http/httptrace#ClientTrace) 附加到 `context.Context` (https://pkg.go.dev/context#Context) 上，传输层会在关键节点通过 `httptrace.ContextClientTrace` (https://pkg.go.dev/net/http/httptrace#ContextClientTrace) 将其取出。我想先探讨这个设计选择，因为它解释了该包如何与标准库的其他部分组合，然后会用它构建两个东西：一个类似 `curl --trace` 的命令行工具，以及一个可复用的 `http.RoundTripper`，用于记录每个请求的时序。 ## 为什么用 Context，而不是接口 请求追踪的直观设计是定义一个 `Tracer` 接口，给 `http.Client` 或 `http.Transport` 添加一个 `Tracer` 字段，然后在传输层内部调用其方法。这大致是大多数语言处理此问题的方式。 Go 的标准库并非如此。相反，`httptrace.WithClientTrace` (https://pkg.go.dev/net/http/httptrace#WithClientTrace) 返回一个新的 context，其中携带了一个 `*ClientTrace`；你通过 `req.WithContext(ctx)` 将这个 context 附加到请求上，然后传输层在关键节点通过 `httptrace.ContextClientTrace` (https://pkg.go.dev/net/http/httptrace#ContextClientTrace) 将 trace 取出。 ```go 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) ``` 这很不寻常，但好处很大。trace 随请求一起传递，因此任何转发 context 的中间件都会自动传播 trace。客户端上没有共享的可变状态，因此来自同一个 `http.Client` 的并发请求可以携带不同的 trace。而且，如果没有人附加 trace，传输层会完全忽略它，因此未使用时的成本只是一个 nil 检查。 `ClientTrace` 本身是一个由可选函数字段组成的结构体： ```go type ClientTrace struct { GetConn func(hostPort string) GotConn func(GotConnInfo) PutIdleConn func(err error) GotFirstResponseByte func() Got100Continue func() Got1xxResponse func(code int, header textproto.MIMEHeader) error DNSStart func(DNSStartInfo) DNSDone func(DNSDoneInfo) ConnectStart func(network, addr string) ConnectDone func(network, addr string, err error) TLSHandshakeStart func() TLSHandshakeDone func(tls.ConnectionState, error) WroteHeaderField func(key string, value []string) WroteHeaders func() Wait100Continue func() WroteRequest func(WroteRequestInfo) } ``` 你只需设置你关心的字段。未设置的字段为 nil，会被跳过。这也是该包能够添加新钩子而不破坏任何现有代码的原因——现有代码只需将新字段留为 nil 即可。 ## 构建一个 curl --trace 风格的命令行工具 首先值得构建的是一个命令行工具，它接受一个 URL 并打印出类似 `curl -w` 的时序分解，但拥有 `httptrace` 所暴露的细粒度。关键在于在每个钩子中记录时间戳，并计算相对于开始时间的持续时间。 ```go package main import ( "context" "crypto/tls" "fmt" "net/http" "net/http/httptrace" "os" "time" ) 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 } func (t *timings) elapsed(at time.Time) time.Duration { return at.Sub(t.start) } ``` 为此构建的 `ClientTrace` 是机械性的——在每个钩子中捕获 `time.Now()`： ```go 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() }, } } ``` main 函数将其组装起来并打印分解结果： ```go 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)) } ``` 针对任何 URL 运行它，输出会告诉你时间花在了哪里。缓慢的 DNS 查找、缓慢的 TLS 握手、或者服务器花很长时间生成第一个字节，都会在分解中作为单独的一行显示。无需代理，无需 APM 代理，也无需在依赖图中引入任何检测库。 有几个要点需要知道。`DNSStart` 和 `DNSDone` 只在 Go 的解析器执行查找时触发——如果地址已经在内核的 DNS 缓存中，或者你直接传入了 IP，这些钩子将保持静默。`TLSHandshakeStart` 和 `TLSHandshakeDone` 只在 HTTPS 上触发。`GotConn` 无论连接是新建的还是复用的都会触发，并且 `GotConnInfo` (https://pkg.go.dev/net/http/httptrace#GotConnInfo) 结构体有一个 `Reused` 字段告诉你具体是哪种情况。 ## 构建一个 RoundTripper 一次性的命令行工具很有用，但大多数时候你希望某个 `http.Client` 发出的每个请求都能自动被追踪。这正是 `http.RoundTripper` (https://pkg.go.dev/net/http#RoundTripper) 的用途。包装默认的传输层，在委派给底层之前将 trace 附加到 context 上，并在请求完成时记录结果。 ```go 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 } ``` 使用起来很简单： ```go 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") ``` 这里有一个微妙之处容易让人掉坑。如果调用者已经在请求的 context 上附加了 `ClientTrace`，再次调用 `httptrace.WithClientTrace` 并不会替换它——而是会组合。`ContextClientTrace` 返回最近附加的 trace，但两个钩子都会触发。对于 `RoundTripper` 来说，这通常就是你想要的行为：调用者的 trace 被保留，你的 trace 与之并行运行。如果你想替换现有的 trace，你需要自己检查 context。 另一个需要知道的事情是，`RoundTrip` 在读取响应头时返回，而不是在消费响应体时。这里的 `t.done` 测量的是 TTFB 加上头读取的时间，而不是包括响应体在内的总请求时间。要获得包含响应体传输的总时间，可以将 `res.Body` 包装在一个在 `Close` 时记录 `time.Now()` 的读取器中： ```go type timedBody struct { io.ReadCloser onClose func() } func (tb *timedBody) Close() error { tb.onClose() return tb.ReadCloser.Close() } // ... 在 RoundTrip 内部，调用 base.RoundTrip 之后： res.Body = &timedBody{ ReadCloser: res.Body, onClose: func() { t.done = time.Now() }, } ``` 现在，`t.done` 会在调用者完成读取响应体并关闭它时被设置，这正是总请求持续时间所需要的。 ## 连接复用 `httptrace` 揭示的最有用的事情之一是你的客户端是否实际上在复用连接。传递给 `GotConn` 的 `GotConnInfo` (https://pkg.go.dev/net/http/httptrace#GotConnInfo) 结构体包含 `Reused bool` 和 `WasIdle bool` 字段。如果你重复调用同一个主机，而 `Reused` 每次都返回 `false`，那么你的代码中有些东西阻止了连接池化——通常是因为每个请求都创建了独立的 `http.Client`，或者响应体从未关闭。 将其添加到 trace 中只需要一个字段： ```go 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()) } }, ``` 这通常是需要数据包捕获才能验证的事情。 ## 结论 `net/http/httptrace` 是一个小型的 API：一个用于附加 trace 的函数，一个用于获取它的函数，以及一个钩子结构体。基于 context 的设计意味着它可以与标准库中任何已经使用 `context.Context` 的代码组合，而标准库中大多数代码都是如此。这里展示的命令行工具和 `RoundTripper` 足够短小，可以投入任何项目，作为调试慢速 HTTP 调用的起点，而无需引入分布式追踪或 APM 代理。 如果你觉得这些追踪信息有用，你可能会对 https://probes.dev 感兴趣，因为我们在 Limeleaf 正在构建这样一个工具，用这些详细信息来监控网站和 API。快去看看吧！