diff --git a/docs/content/docs.md b/docs/content/docs.md index ef1faa341..6971d3513 100644 --- a/docs/content/docs.md +++ b/docs/content/docs.md @@ -3296,6 +3296,15 @@ The available flags are: failed transactions only. On its own `--dump errors` dumps the headers. This lets you capture first-failure diagnostics without the noise of dumping every transaction. May contain sensitive info. +- `trace` logs connection level events for each HTTP transaction using Go's + `net/http/httptrace` - DNS resolution, TCP connect, TLS handshake (including + the negotiated TLS version, cipher, ALPN protocol and server certificate), + connection reuse, request write and time to first response byte. Each line is + tagged with the time elapsed since the start of the transaction so you can see + where the time goes. This is complementary to the other dump flags: it shows + how the connection behaved rather than what was sent, so it is useful for + debugging connectivity, DNS, TLS, proxy and keep-alive problems. It does not + dump headers or bodies - combine it with `headers` or `bodies` for that. ## Filtering diff --git a/fs/dump.go b/fs/dump.go index 234f32214..10be1ad33 100644 --- a/fs/dump.go +++ b/fs/dump.go @@ -16,6 +16,7 @@ const ( DumpMapper DumpCurl DumpErrors + DumpTrace ) type dumpChoices struct{} @@ -33,6 +34,7 @@ func (dumpChoices) Choices() []BitsChoicesInfo { {uint64(DumpMapper), "mapper"}, {uint64(DumpCurl), "curl"}, {uint64(DumpErrors), "errors"}, + {uint64(DumpTrace), "trace"}, } } diff --git a/fs/fshttp/dump_test.go b/fs/fshttp/dump_test.go index c0f60d499..fd3ee9ad6 100644 --- a/fs/fshttp/dump_test.go +++ b/fs/fshttp/dump_test.go @@ -142,3 +142,67 @@ func TestDumpErrors(t *testing.T) { curl500 := run(t, fs.DumpErrors|fs.DumpCurl, "/500") assert.Contains(t, curl500, "curl") } + +// TestDumpTrace checks that --dump trace logs the connection level +// httptrace events without dumping the request or response bodies. +func TestDumpTrace(t *testing.T) { + handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte("response body\n")) + }) + + // run makes count requests to srv reusing the same client with the + // trace dump flag set and returns the captured log output. + run := func(t *testing.T, srv *httptest.Server, count int) string { + capture := &captureBuf{} + fs.SetLogger(slog.NewTextHandler(capture, &slog.HandlerOptions{Level: slog.LevelDebug})) + defer fs.SetLogger(slog.NewTextHandler(io.Discard, nil)) + + // The dump logging is emitted at Debug level and filtered + // against the global config, so set that up for the test. + ci := fs.GetConfig(context.Background()) + oldDump, oldLevel, oldInsecure := ci.Dump, ci.LogLevel, ci.InsecureSkipVerify + ci.Dump = fs.DumpTrace + ci.LogLevel = fs.LogLevelDebug + ci.InsecureSkipVerify = true + defer func() { + ci.Dump, ci.LogLevel, ci.InsecureSkipVerify = oldDump, oldLevel, oldInsecure + }() + ResetTransport() + defer ResetTransport() + + client := NewClientCustom(context.Background(), nil) + for range count { + req, err := http.NewRequest("GET", srv.URL, strings.NewReader("request body\n")) + require.NoError(t, err) + resp, err := client.Do(req) + require.NoError(t, err) + _, _ = io.Copy(io.Discard, resp.Body) + _ = resp.Body.Close() + } + return capture.String() + } + + t.Run("HTTP", func(t *testing.T) { + srv := httptest.NewServer(handler) + defer srv.Close() + out := run(t, srv, 2) + // Connection level events should be traced + assert.Contains(t, out, "HTTP TRACE") + assert.Contains(t, out, "Connected to") + assert.Contains(t, out, "Wrote request") + assert.Contains(t, out, "First response byte") + // The second request should reuse the keep-alive connection + assert.Contains(t, out, "reused=true") + // trace on its own does not dump the request/response or bodies + assert.NotContains(t, out, "HTTP REQUEST") + assert.NotContains(t, out, "response body") + }) + + t.Run("HTTPS", func(t *testing.T) { + srv := httptest.NewTLSServer(handler) + defer srv.Close() + out := run(t, srv, 1) + assert.Contains(t, out, "TLS handshake done") + }) +} diff --git a/fs/fshttp/http.go b/fs/fshttp/http.go index 44a02c2a7..67465a892 100644 --- a/fs/fshttp/http.go +++ b/fs/fshttp/http.go @@ -12,7 +12,9 @@ import ( "net" "net/http" "net/http/cookiejar" + "net/http/httptrace" "net/http/httputil" + "net/textproto" "net/url" "os" "slices" @@ -490,6 +492,105 @@ func isRetryableResponse(resp *http.Response, err error) bool { return resp.StatusCode == 429 || resp.StatusCode >= 500 } +// newClientTrace returns an httptrace.ClientTrace which logs the +// connection level events for req - DNS resolution, TCP connect, TLS +// handshake, connection reuse, request write and time to first byte. +// +// Each line is tagged with the req pointer so it can be correlated with +// the HTTP REQUEST/RESPONSE dumps, and prefixed with the time elapsed +// since the round trip started so the timing of each phase is visible. +// +// This is complementary to the other dump flags: it shows how the +// connection behaved rather than what was sent, so it is useful for +// debugging connectivity, DNS, TLS, proxy and keep-alive problems. +func newClientTrace(req *http.Request) *httptrace.ClientTrace { + start := time.Now() + tracef := func(format string, args ...any) { + fs.Debugf(nil, "HTTP TRACE (req %p) %9.3fms: %s", req, float64(time.Since(start))/float64(time.Millisecond), fmt.Sprintf(format, args...)) + } + return &httptrace.ClientTrace{ + GetConn: func(hostPort string) { + tracef("Getting connection for %s", hostPort) + }, + GotConn: func(info httptrace.GotConnInfo) { + local, remote := "?", "?" + if info.Conn != nil { + local = info.Conn.LocalAddr().String() + remote = info.Conn.RemoteAddr().String() + } + tracef("Got connection %s -> %s (reused=%v, wasIdle=%v, idleTime=%v)", local, remote, info.Reused, info.WasIdle, info.IdleTime) + }, + PutIdleConn: func(err error) { + if err != nil { + tracef("Connection not returned to idle pool: %v", err) + } else { + tracef("Connection returned to idle pool") + } + }, + GotFirstResponseByte: func() { + tracef("First response byte") + }, + Got100Continue: func() { + tracef("Got 100 Continue") + }, + Got1xxResponse: func(code int, header textproto.MIMEHeader) error { + tracef("Got 1xx response %d", code) + return nil + }, + DNSStart: func(info httptrace.DNSStartInfo) { + tracef("Looking up host %q", info.Host) + }, + DNSDone: func(info httptrace.DNSDoneInfo) { + if info.Err != nil { + tracef("DNS lookup failed: %v", info.Err) + return + } + addrs := make([]string, len(info.Addrs)) + for i := range info.Addrs { + addrs[i] = info.Addrs[i].String() + } + tracef("DNS lookup gave %v (coalesced=%v)", addrs, info.Coalesced) + }, + ConnectStart: func(network, addr string) { + tracef("Connecting to %s:%s", network, addr) + }, + ConnectDone: func(network, addr string, err error) { + if err != nil { + tracef("Connect to %s:%s failed: %v", network, addr, err) + } else { + tracef("Connected to %s:%s", network, addr) + } + }, + TLSHandshakeStart: func() { + tracef("TLS handshake starting") + }, + TLSHandshakeDone: func(state tls.ConnectionState, err error) { + if err != nil { + tracef("TLS handshake failed: %v", err) + return + } + tracef("TLS handshake done: %s %s, alpn=%q, serverName=%q", tls.VersionName(state.Version), tls.CipherSuiteName(state.CipherSuite), state.NegotiatedProtocol, state.ServerName) + if len(state.PeerCertificates) > 0 { + leaf := state.PeerCertificates[0] + tracef("TLS peer certificate: subject=%q issuer=%q notAfter=%v dnsNames=%v", leaf.Subject, leaf.Issuer, leaf.NotAfter.Format(time.RFC3339), leaf.DNSNames) + } + }, + WroteHeaders: func() { + tracef("Wrote request headers") + }, + Wait100Continue: func() { + tracef("Waiting for 100 Continue before writing request body") + }, + WroteRequest: func(info httptrace.WroteRequestInfo) { + if info.Err != nil { + tracef("Writing request failed: %v", info.Err) + } else { + tracef("Wrote request") + } + }, + } +} + // RoundTrip implements the RoundTripper interface. func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error) { // Check if certificates are being used and the certificates are expired @@ -561,8 +662,17 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error } } } + // Attach an httptrace to log connection level events if required. + // This is done here, after the request dump above, so that + // DumpRequestOut's internal round trip does not trigger the trace. + // The original req is passed to newClientTrace so the trace lines + // share the same req pointer as the HTTP REQUEST/RESPONSE dumps. + traceReq := req + if t.dump&fs.DumpTrace != 0 { + traceReq = req.WithContext(httptrace.WithClientTrace(req.Context(), newClientTrace(req))) + } // Do round trip - resp, err = t.Transport.RoundTrip(req) + resp, err = t.Transport.RoundTrip(traceReq) // Dump response, and the request too if we deferred it for --dump errors if wantDump && (!onError || isRetryableResponse(resp, err)) { logMutex.Lock()