net/http: add GODEBUG=httpdebug setting for structured HTTP debug logging
The http2debug GODEBUG setting has proven valuable for debugging
HTTP/2 issues, but there is no equivalent for HTTP/1. The transport
had a hardcoded const debugRoundTrip = false that required
recompiling the standard library to use.
This change adds a unified GODEBUG=httpdebug setting that enables
structured debug logging for HTTP/1 client and server using log/slog.
The setting controls verbosity: level 1 logs connection events,
level 2 adds request and response events, and level 3 adds headers.
Sensitive headers (Authorization, Cookie, Set-Cookie,
Proxy-Authorization) are redacted by default; set httpdebugredact=0
to disable redaction.
The httpdebug and http2debug settings are orthogonal: httpdebug
controls slog-based structured logging, while http2debug controls
the existing unstructured log.Printf output. Adding slog-based
logging to net/http/internal/http2 for levels 1-3 and HTTP/2 frame
logging at level 4 are planned as follow-up work.
Fixes #18733
diff --git a/doc/godebug.md b/doc/godebug.md
index 4935d64..e285632 100644
--- a/doc/godebug.md
+++ b/doc/godebug.md
@@ -170,6 +170,12 @@
labels acquire sensitive information that shouldn't be made available in
tracebacks.
+Go 1.27 added the [`httpdebug` and `httpdebugredact` settings](/pkg/net/http/#hdr-HTTP_Debug_Logging)
+for structured HTTP debug logging using log/slog. The `httpdebug` setting
+controls the verbosity level (1=connections, 2=requests, 3=headers).
+The `httpdebugredact` setting controls whether sensitive headers are redacted
+(default is enabled; set to 0 to disable). There is no plan to remove these settings.
+
### Go 1.26
Go 1.26 added a new `httpcookiemaxnum` setting that controls the maximum number
@@ -534,7 +540,7 @@
Go 1.6 introduced transparent support for HTTP/2,
controlled by the [`http2client`, `http2server`, and `http2debug` settings](/pkg/net/http/#hdr-HTTP_2).
-There is no plan to remove these settings.
+There is no plan to remove the `http2client`, `http2server`, and `http2debug` settings.
### Go 1.5
diff --git a/src/internal/godebugs/table.go b/src/internal/godebugs/table.go
index 7ddfad1..9614fd8 100644
--- a/src/internal/godebugs/table.go
+++ b/src/internal/godebugs/table.go
@@ -44,6 +44,8 @@
{Name: "http2debug", Package: "net/http", Opaque: true},
{Name: "http2server", Package: "net/http"},
{Name: "httpcookiemaxnum", Package: "net/http", Changed: 24, Old: "0"},
+ {Name: "httpdebug", Package: "net/http", Opaque: true},
+ {Name: "httpdebugredact", Package: "net/http", Opaque: true},
{Name: "httplaxcontentlength", Package: "net/http", Changed: 22, Old: "1"},
{Name: "httpmuxgo121", Package: "net/http", Changed: 22, Old: "1"},
{Name: "httpservecontentkeepheaders", Package: "net/http", Changed: 23, Old: "1"},
diff --git a/src/net/http/doc.go b/src/net/http/doc.go
index e50cf5f..e9a4eea 100644
--- a/src/net/http/doc.go
+++ b/src/net/http/doc.go
@@ -102,6 +102,32 @@
GODEBUG=http2debug=1 # enable verbose HTTP/2 debug logs
GODEBUG=http2debug=2 # ... even more verbose, with frame dumps
+The http2debug setting uses unstructured log.Printf output and controls
+only HTTP/2. The httpdebug and http2debug settings are orthogonal:
+httpdebug produces slog-based structured output, while http2debug
+produces existing unstructured log.Printf output. Both can be enabled
+simultaneously.
+
+The httpdebug setting (see below) provides structured logging via
+log/slog for HTTP client and server operations. It currently covers
+HTTP/1 client and server operations; slog-based logging for HTTP/2
+will be added in a future release.
+
+# HTTP Debug Logging
+
+The httpdebug GODEBUG setting enables structured debug logging for
+HTTP client and server operations using [log/slog]. The setting
+controls the verbosity level:
+
+ GODEBUG=httpdebug=1 # log connection events (open/close)
+ GODEBUG=httpdebug=2 # also log request/response events
+ GODEBUG=httpdebug=3 # also log request/response headers
+
+By default, sensitive headers (Authorization, Cookie, Set-Cookie,
+Proxy-Authorization) are redacted in log output. To disable redaction:
+
+ GODEBUG=httpdebugredact=0
+
The "omithttp2" build tag may be used to disable the HTTP/2 implementation
contained in the http package.
*/
diff --git a/src/net/http/httpdebug.go b/src/net/http/httpdebug.go
new file mode 100644
index 0000000..36526e0
--- /dev/null
+++ b/src/net/http/httpdebug.go
@@ -0,0 +1,263 @@
+// Copyright 2026 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package http
+
+import (
+ "context"
+ "crypto/tls"
+ "internal/godebug"
+ "log/slog"
+ "net"
+ "slices"
+ "strconv"
+ "strings"
+ "sync/atomic"
+)
+
+// httpdebug controls the verbosity of HTTP debug logging.
+//
+// The level is set by the GODEBUG=httpdebug=N setting:
+//
+// - httpdebug=1: Log connection events (open/close).
+// - httpdebug=2: Also log request/response events.
+// - httpdebug=3: Also log request/response headers.
+//
+// The GODEBUG=httpdebugredact setting controls whether sensitive
+// headers (Authorization, Cookie, Set-Cookie, Proxy-Authorization)
+// are redacted in log output. By default, redaction is enabled.
+// Set httpdebugredact=0 to disable redaction.
+var (
+ httpdebugSetting = godebug.New("httpdebug")
+ httpdebugredactSetting = godebug.New("httpdebugredact")
+)
+
+// httpDebugLevel returns the current httpdebug level.
+// The parsed integer result is cached to avoid repeated strconv.Atoi
+// calls on the hot path. The cache is invalidated when the underlying
+// GODEBUG string value changes.
+func httpDebugLevel() int {
+ v := httpdebugSetting.Value()
+ if v == "" {
+ return 0
+ }
+ if c := httpDebugCachedLevel.Load(); c != nil && c.raw == v {
+ return c.level
+ }
+ n, err := strconv.Atoi(v)
+ if err != nil || n <= 0 {
+ n = 0
+ }
+ httpDebugCachedLevel.Store(&httpDebugLevelCache{raw: v, level: n})
+ return n
+}
+
+type httpDebugLevelCache struct {
+ raw string
+ level int
+}
+
+var httpDebugCachedLevel atomic.Pointer[httpDebugLevelCache]
+
+// httpDebugRedact reports whether sensitive headers should be redacted.
+// It reads the GODEBUG setting on each call.
+func httpDebugRedact() bool {
+ return httpdebugredactSetting.Value() != "0"
+}
+
+// httpDebugLogConnections reports whether connection events should be logged.
+func httpDebugLogConnections() bool { return httpDebugLevel() >= 1 }
+
+// httpDebugLogRequests reports whether request/response events should be logged.
+func httpDebugLogRequests() bool { return httpDebugLevel() >= 2 }
+
+// httpDebugLogHeaders reports whether request/response headers should be logged.
+func httpDebugLogHeaders() bool { return httpDebugLevel() >= 3 }
+
+// Atomic counters for assigning unique IDs to connections and requests.
+var (
+ httpDebugNextConnID atomic.Int64
+ httpDebugNextReqID atomic.Int64
+)
+
+// httpDebugNewConnID returns the next unique connection ID.
+func httpDebugNewConnID() int64 {
+ return httpDebugNextConnID.Add(1)
+}
+
+// httpDebugNewReqID returns the next unique request ID.
+func httpDebugNewReqID() int64 {
+ return httpDebugNextReqID.Add(1)
+}
+
+// sensitiveHeaders is the set of headers that are redacted by default.
+var sensitiveHeaders = map[string]bool{
+ "Authorization": true,
+ "Cookie": true,
+ "Set-Cookie": true,
+ "Proxy-Authorization": true,
+}
+
+// httpDebugLogf logs a debug message with structured attributes.
+func httpDebugLogf(msg string, attrs ...slog.Attr) {
+ slog.LogAttrs(context.Background(), slog.LevelDebug, msg, attrs...)
+}
+
+// httpDebugHeaderAttrs returns a slog Group attribute for HTTP headers.
+// Sensitive headers are redacted unless httpdebugredact=0.
+// Headers are sorted by key for deterministic output.
+func httpDebugHeaderAttrs(name string, h Header) slog.Attr {
+ // Collect and sort header keys for deterministic output.
+ keys := make([]string, 0, len(h))
+ for key := range h {
+ keys = append(keys, key)
+ }
+ slices.Sort(keys)
+
+ redact := httpDebugRedact()
+ attrs := make([]any, 0, len(keys))
+ for _, key := range keys {
+ vals := h[key]
+ value := strings.Join(vals, ", ")
+ if redact && sensitiveHeaders[key] {
+ value = "[REDACTED]"
+ }
+ attrs = append(attrs, slog.String(key, value))
+ }
+ return slog.Group(name, attrs...)
+}
+
+// httpDebugConnAttrs returns common slog attributes for a connection.
+func httpDebugConnAttrs(connID int64, localAddr, remoteAddr net.Addr, tlsState *tls.ConnectionState) []slog.Attr {
+ attrs := []slog.Attr{
+ slog.Int64("conn_id", connID),
+ }
+ if localAddr != nil {
+ attrs = append(attrs, slog.String("local_addr", localAddr.String()))
+ }
+ if remoteAddr != nil {
+ attrs = append(attrs, slog.String("remote_addr", remoteAddr.String()))
+ }
+ if tlsState != nil {
+ attrs = append(attrs, slog.Bool("tls", true))
+ } else {
+ attrs = append(attrs, slog.Bool("tls", false))
+ }
+ return attrs
+}
+
+// httpDebugReqAttrs returns common slog attributes for a request.
+func httpDebugReqAttrs(connID, reqID int64, method, uri, proto, host string) []slog.Attr {
+ return []slog.Attr{
+ slog.Int64("conn_id", connID),
+ slog.Int64("req_id", reqID),
+ slog.String("method", method),
+ slog.String("url", uri),
+ slog.String("proto", proto),
+ slog.String("host", host),
+ }
+}
+
+// httpDebugRespAttrs returns common slog attributes for a response.
+func httpDebugRespAttrs(connID, reqID int64, status int, proto string) []slog.Attr {
+ return []slog.Attr{
+ slog.Int64("conn_id", connID),
+ slog.Int64("req_id", reqID),
+ slog.Int("status", status),
+ slog.String("proto", proto),
+ }
+}
+
+// httpDebugLogConn logs a connection event.
+func httpDebugLogConn(event string, connID int64, localAddr, remoteAddr net.Addr, tlsState *tls.ConnectionState) {
+ if !httpDebugLogConnections() {
+ return
+ }
+ httpDebugLogf(event, httpDebugConnAttrs(connID, localAddr, remoteAddr, tlsState)...)
+}
+
+// httpDebugLogConnClose logs a connection close event with a reason.
+func httpDebugLogConnClose(event string, connID int64, localAddr, remoteAddr net.Addr, reason string) {
+ if !httpDebugLogConnections() {
+ return
+ }
+ attrs := []slog.Attr{
+ slog.Int64("conn_id", connID),
+ }
+ if localAddr != nil {
+ attrs = append(attrs, slog.String("local_addr", localAddr.String()))
+ }
+ if remoteAddr != nil {
+ attrs = append(attrs, slog.String("remote_addr", remoteAddr.String()))
+ }
+ attrs = append(attrs, slog.String("reason", reason))
+ httpDebugLogf(event, attrs...)
+}
+
+// httpDebugLogReq logs a request event.
+func httpDebugLogReq(event string, connID, reqID int64, method, uri, proto, host string, h Header) {
+ level := httpDebugLevel()
+ if level < 2 {
+ return
+ }
+ attrs := httpDebugReqAttrs(connID, reqID, method, uri, proto, host)
+ if level >= 3 && h != nil {
+ attrs = append(attrs, httpDebugHeaderAttrs("header", h))
+ }
+ httpDebugLogf(event, attrs...)
+}
+
+// httpDebugLogResp logs a response event.
+func httpDebugLogResp(event string, connID, reqID int64, status int, proto string, h Header) {
+ level := httpDebugLevel()
+ if level < 2 {
+ return
+ }
+ attrs := httpDebugRespAttrs(connID, reqID, status, proto)
+ if level >= 3 && h != nil {
+ attrs = append(attrs, httpDebugHeaderAttrs("header", h))
+ }
+ httpDebugLogf(event, attrs...)
+}
+
+// Event name constants for HTTP debug logging.
+// Using constants avoids allocating a new string on each call.
+const (
+ httpDebugClientConnOpened = "http.client.connection_opened"
+ httpDebugClientConnClosed = "http.client.connection_closed"
+ httpDebugClientReqSent = "http.client.request_sent"
+ httpDebugClientRespRecvd = "http.client.response_received"
+ httpDebugServerConnOpened = "http.server.connection_opened"
+ httpDebugServerConnClosed = "http.server.connection_closed"
+ httpDebugServerReqRecvd = "http.server.request_received"
+ httpDebugServerRespSent = "http.server.response_sent"
+)
+
+// httpDebugConnEvent returns the event name for a connection event.
+func httpDebugConnEvent(side, event string) string {
+ switch side + "." + event {
+ case "client.connection_opened":
+ return httpDebugClientConnOpened
+ case "client.connection_closed":
+ return httpDebugClientConnClosed
+ case "server.connection_opened":
+ return httpDebugServerConnOpened
+ case "server.connection_closed":
+ return httpDebugServerConnClosed
+ }
+ return "http." + side + "." + event
+}
+
+// httpDebugLogConnOpen assigns a new connection ID and logs the connection_opened event.
+func httpDebugLogConnOpen(side string, c net.Conn, tlsState *tls.ConnectionState) int64 {
+ connID := httpDebugNewConnID()
+ httpDebugLogConn(
+ httpDebugConnEvent(side, "connection_opened"),
+ connID,
+ c.LocalAddr(),
+ c.RemoteAddr(),
+ tlsState,
+ )
+ return connID
+}
diff --git a/src/net/http/httpdebug_test.go b/src/net/http/httpdebug_test.go
new file mode 100644
index 0000000..7e3d945
--- /dev/null
+++ b/src/net/http/httpdebug_test.go
@@ -0,0 +1,530 @@
+// Copyright 2026 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package http_test
+
+import (
+ "bytes"
+ "fmt"
+ "log/slog"
+ . "net/http"
+ "sort"
+ "strings"
+ "sync"
+ "testing"
+)
+
+// setupHTTPDebugLogger sets up a slog handler that writes to a buffer
+// and returns the buffer and a restore function.
+func setupHTTPDebugLogger(t testing.TB) *bytes.Buffer {
+ t.Helper()
+ var buf bytes.Buffer
+ handler := slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug})
+ oldLogger := slog.Default()
+ slog.SetDefault(slog.New(handler))
+ t.Cleanup(func() { slog.SetDefault(oldLogger) })
+ return &buf
+}
+
+func TestHTTPDebugLevel1Connections(t *testing.T) {
+ // Level 1: connection events only.
+ t.Setenv("GODEBUG", "httpdebug=1")
+
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+
+ // Close idle client connections to trigger connection_closed events.
+ cst.tr.CloseIdleConnections()
+
+ output := buf.String()
+ if !strings.Contains(output, "http.client.connection_opened") {
+ t.Errorf("expected client connection_opened log, got:\n%s", output)
+ }
+ if !strings.Contains(output, "http.server.connection_opened") {
+ t.Errorf("expected server connection_opened log, got:\n%s", output)
+ }
+ if !strings.Contains(output, "conn_id=") {
+ t.Errorf("expected conn_id field, got:\n%s", output)
+ }
+ if !strings.Contains(output, "tls=") {
+ t.Errorf("expected tls field, got:\n%s", output)
+ }
+ if !strings.Contains(output, "local_addr=") {
+ t.Errorf("expected local_addr field, got:\n%s", output)
+ }
+ if !strings.Contains(output, "remote_addr=") {
+ t.Errorf("expected remote_addr field, got:\n%s", output)
+ }
+ // Level 1 should NOT log requests.
+ if strings.Contains(output, "request_sent") || strings.Contains(output, "request_received") {
+ t.Errorf("level 1 should not log requests, got:\n%s", output)
+ }
+}
+
+func TestHTTPDebugLevel1ConnectionClosed(t *testing.T) {
+ // Level 1: verify connection_closed events.
+ t.Setenv("GODEBUG", "httpdebug=1")
+
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+
+ // Close idle client connections to trigger connection_closed events.
+ cst.tr.CloseIdleConnections()
+
+ output := buf.String()
+ if !strings.Contains(output, "http.client.connection_closed") {
+ t.Errorf("expected client connection_closed log, got:\n%s", output)
+ }
+ // connection_closed should include address information.
+ if !strings.Contains(output, "local_addr=") {
+ t.Errorf("expected local_addr field in connection_closed log, got:\n%s", output)
+ }
+ if !strings.Contains(output, "remote_addr=") {
+ t.Errorf("expected remote_addr field in connection_closed log, got:\n%s", output)
+ }
+}
+
+func TestHTTPDebugLevel2Requests(t *testing.T) {
+ // Level 2: connection + request/response events.
+ t.Setenv("GODEBUG", "httpdebug=2")
+
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+
+ output := buf.String()
+ if !strings.Contains(output, "http.client.request_sent") {
+ t.Errorf("expected client request_sent log, got:\n%s", output)
+ }
+ if !strings.Contains(output, "http.client.response_received") {
+ t.Errorf("expected client response_received log, got:\n%s", output)
+ }
+ if !strings.Contains(output, "http.server.request_received") {
+ t.Errorf("expected server request_received log, got:\n%s", output)
+ }
+ if !strings.Contains(output, "http.server.response_sent") {
+ t.Errorf("expected server response_sent log, got:\n%s", output)
+ }
+ // Verify proto and host fields are present.
+ if !strings.Contains(output, "proto=") {
+ t.Errorf("expected proto field in request/response logs, got:\n%s", output)
+ }
+ if !strings.Contains(output, "host=") {
+ t.Errorf("expected host field in request logs, got:\n%s", output)
+ }
+ // Verify req_id field is present.
+ if !strings.Contains(output, "req_id=") {
+ t.Errorf("expected req_id field in request/response logs, got:\n%s", output)
+ }
+ // Verify status field is present.
+ if !strings.Contains(output, "status=200") {
+ t.Errorf("expected status=200 in response logs, got:\n%s", output)
+ }
+ // Level 2 should NOT log headers.
+ if strings.Contains(output, "header.") {
+ t.Errorf("level 2 should not log headers, got:\n%s", output)
+ }
+}
+
+func TestHTTPDebugLevel3Headers(t *testing.T) {
+ // Level 3: also log headers.
+ t.Setenv("GODEBUG", "httpdebug=3")
+
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.Header().Set("X-Test", "hello")
+ w.WriteHeader(200)
+ }))
+
+ req, _ := NewRequest("GET", cst.ts.URL, nil)
+ req.Header.Set("X-Custom", "world")
+ resp, err := cst.c.Do(req)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+
+ output := buf.String()
+ if !strings.Contains(output, "header.") {
+ t.Errorf("level 3 should log headers, got:\n%s", output)
+ }
+}
+
+func TestHTTPDebugRedaction(t *testing.T) {
+ // Level 3 with redaction enabled (default).
+ t.Setenv("GODEBUG", "httpdebug=3")
+
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ req, _ := NewRequest("GET", cst.ts.URL, nil)
+ req.Header.Set("Authorization", "Bearer secret-token")
+ req.Header.Set("Cookie", "session=abc123")
+ resp, err := cst.c.Do(req)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+
+ output := buf.String()
+ if strings.Contains(output, "secret-token") {
+ t.Errorf("Authorization header should be redacted, got:\n%s", output)
+ }
+ if strings.Contains(output, "abc123") {
+ t.Errorf("Cookie header should be redacted, got:\n%s", output)
+ }
+ if !strings.Contains(output, "[REDACTED]") {
+ t.Errorf("expected [REDACTED] in output, got:\n%s", output)
+ }
+}
+
+func TestHTTPDebugRedactionDisabled(t *testing.T) {
+ // Level 3 with redaction disabled.
+ t.Setenv("GODEBUG", "httpdebug=3,httpdebugredact=0")
+
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ req, _ := NewRequest("GET", cst.ts.URL, nil)
+ req.Header.Set("Authorization", "Bearer secret-token")
+ resp, err := cst.c.Do(req)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+
+ output := buf.String()
+ if !strings.Contains(output, "secret-token") {
+ t.Errorf("Authorization header should NOT be redacted when httpdebugredact=0, got:\n%s", output)
+ }
+}
+
+func TestHTTPDebugDisabled(t *testing.T) {
+ // No httpdebug setting: no debug logging.
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+
+ output := buf.String()
+ if strings.Contains(output, "http.client") || strings.Contains(output, "http.server") {
+ t.Errorf("no httpdebug setting should not produce any httpdebug logs, got:\n%s", output)
+ }
+}
+
+func TestHTTPDebugLevel2HTTPS(t *testing.T) {
+ // Verify httpdebug works with HTTPS connections and reports tls=true.
+ t.Setenv("GODEBUG", "httpdebug=2")
+
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, https1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+
+ output := buf.String()
+ // Both client and server connection_opened should be logged.
+ if !strings.Contains(output, "http.client.connection_opened") {
+ t.Errorf("expected client connection_opened log in HTTPS mode, got:\n%s", output)
+ }
+ if !strings.Contains(output, "http.server.connection_opened") {
+ t.Errorf("expected server connection_opened log in HTTPS mode, got:\n%s", output)
+ }
+ // TLS connections should report tls=true.
+ if !strings.Contains(output, "tls=true") {
+ t.Errorf("expected tls=true in HTTPS connection_opened log, got:\n%s", output)
+ }
+ // Request/response events should also be logged.
+ if !strings.Contains(output, "http.client.request_sent") {
+ t.Errorf("expected client request_sent log in HTTPS mode, got:\n%s", output)
+ }
+ if !strings.Contains(output, "http.server.request_received") {
+ t.Errorf("expected server request_received log in HTTPS mode, got:\n%s", output)
+ }
+}
+
+func TestHTTPDebugServerConnectionClosed(t *testing.T) {
+ // Verify server connection_closed events are logged.
+ t.Setenv("GODEBUG", "httpdebug=1")
+
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.Header().Set("Connection", "close")
+ w.WriteHeader(200)
+ }))
+
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+
+ // Wait for server to finish processing.
+ cst.tr.CloseIdleConnections()
+
+ output := buf.String()
+ if !strings.Contains(output, "http.server.connection_closed") {
+ t.Errorf("expected server connection_closed log, got:\n%s", output)
+ }
+ // The handler sets "Connection: close", so the server should report
+ // reason="connection not reusable" when the connection is closed.
+ if !strings.Contains(output, `reason="connection not reusable"`) {
+ t.Errorf("expected reason=\"connection not reusable\" in server connection_closed log, got:\n%s", output)
+ }
+ // connection_closed should include address information.
+ if !strings.Contains(output, "local_addr=") {
+ t.Errorf("expected local_addr field in server connection_closed log, got:\n%s", output)
+ }
+ if !strings.Contains(output, "remote_addr=") {
+ t.Errorf("expected remote_addr field in server connection_closed log, got:\n%s", output)
+ }
+}
+
+func TestHTTPDebugHTTP2NoLog(t *testing.T) {
+ // Verify httpdebug does not crash or produce incorrect logs in HTTP/2 mode.
+ //
+ // httpdebug and http2debug are orthogonal: httpdebug controls structured
+ // slog-based logging for HTTP/1 connections, while http2debug controls
+ // the existing unstructured log.Printf output for HTTP/2.
+ //
+ // HTTP/2 connections are handled by TLSNextProto before the httpdebug
+ // logging code in conn.serve runs, and the client uses http2Transport
+ // which has a separate code path. Adding slog-based logging to
+ // net/http/internal/http2 is planned as a follow-up.
+ t.Setenv("GODEBUG", "httpdebug=2")
+
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http2Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+
+ // HTTP/2 mode should not produce any httpdebug slog output,
+ // since the HTTP/2 code paths are not yet instrumented.
+ output := buf.String()
+ if strings.Contains(output, "http.client") || strings.Contains(output, "http.server") {
+ t.Errorf("HTTP/2 mode should not produce httpdebug slog logs (not yet instrumented), got:\n%s", output)
+ }
+}
+
+func TestHTTPDebugRedactionAllSensitiveHeaders(t *testing.T) {
+ // Verify all four sensitive headers are redacted: Authorization,
+ // Cookie, Set-Cookie, Proxy-Authorization.
+ t.Setenv("GODEBUG", "httpdebug=3")
+
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.Header().Set("Set-Cookie", "session=secret-session-value")
+ w.WriteHeader(200)
+ }))
+
+ req, _ := NewRequest("GET", cst.ts.URL, nil)
+ req.Header.Set("Authorization", "Bearer secret-auth-token")
+ req.Header.Set("Cookie", "id=secret-cookie-value")
+ req.Header.Set("Proxy-Authorization", "Basic secret-proxy-cred")
+ resp, err := cst.c.Do(req)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+
+ output := buf.String()
+ for _, secret := range []string{
+ "secret-auth-token",
+ "secret-cookie-value",
+ "secret-proxy-cred",
+ "secret-session-value",
+ } {
+ if strings.Contains(output, secret) {
+ t.Errorf("sensitive value %q should be redacted, got:\n%s", secret, output)
+ }
+ }
+ if !strings.Contains(output, "[REDACTED]") {
+ t.Errorf("expected [REDACTED] in output, got:\n%s", output)
+ }
+}
+
+func TestHTTPDebugConcurrentUniqueIDs(t *testing.T) {
+ // Verify conn_id and req_id are unique under concurrent requests.
+ t.Setenv("GODEBUG", "httpdebug=2")
+
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ const numRequests = 10
+ var wg sync.WaitGroup
+ wg.Add(numRequests)
+ for i := 0; i < numRequests; i++ {
+ go func() {
+ defer wg.Done()
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Error(err)
+ return
+ }
+ resp.Body.Close()
+ }()
+ }
+ wg.Wait()
+
+ // Close idle connections to flush all logs.
+ cst.tr.CloseIdleConnections()
+
+ output := buf.String()
+
+ // Extract all req_id values from the log output and verify uniqueness.
+ var reqIDs []string
+ for _, line := range strings.Split(output, "\n") {
+ for _, field := range strings.Fields(line) {
+ if strings.HasPrefix(field, "req_id=") {
+ reqIDs = append(reqIDs, field)
+ }
+ }
+ }
+ if len(reqIDs) == 0 {
+ t.Fatal("expected req_id fields in concurrent request logs, got none")
+ }
+
+ // Each request should produce a unique req_id on the client side
+ // (request_sent) and server side (request_received). Collect
+ // client-side req_ids by pairing with request_sent lines.
+ var clientReqIDs []string
+ for _, line := range strings.Split(output, "\n") {
+ if strings.Contains(line, "http.client.request_sent") {
+ for _, field := range strings.Fields(line) {
+ if strings.HasPrefix(field, "req_id=") {
+ clientReqIDs = append(clientReqIDs, field)
+ }
+ }
+ }
+ }
+ sort.Strings(clientReqIDs)
+ for i := 1; i < len(clientReqIDs); i++ {
+ if clientReqIDs[i] == clientReqIDs[i-1] {
+ t.Errorf("duplicate client req_id found: %s", clientReqIDs[i])
+ }
+ }
+}
+
+func BenchmarkHTTPDebugDisabled(b *testing.B) {
+ // Benchmark with httpdebug disabled (default) to measure zero overhead.
+ b.ReportAllocs()
+
+ setupHTTPDebugLogger(b)
+
+ cst := newClientServerTest(b, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ b.ResetTimer()
+ for i := 0; i < b.N; i++ {
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ b.Fatal(err)
+ }
+ resp.Body.Close()
+ }
+}
+
+func BenchmarkHTTPDebugLevel2(b *testing.B) {
+ // Benchmark with httpdebug=2 to measure the cost of request/response logging.
+ b.Setenv("GODEBUG", "httpdebug=2")
+ b.ReportAllocs()
+
+ setupHTTPDebugLogger(b)
+
+ cst := newClientServerTest(b, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ b.ResetTimer()
+ for i := 0; i < b.N; i++ {
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ b.Fatal(err)
+ }
+ resp.Body.Close()
+ }
+}
+
+func BenchmarkHTTPDebugLevel3(b *testing.B) {
+ // Benchmark with httpdebug=3 to measure the cost of header logging.
+ b.Setenv("GODEBUG", "httpdebug=3")
+ b.ReportAllocs()
+
+ setupHTTPDebugLogger(b)
+
+ cst := newClientServerTest(b, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.Header().Set("X-Test", "value")
+ w.WriteHeader(200)
+ }))
+
+ b.ResetTimer()
+ for i := 0; i < b.N; i++ {
+ req, _ := NewRequest("GET", cst.ts.URL, nil)
+ req.Header.Set("X-Custom", fmt.Sprintf("bench-%d", i))
+ resp, err := cst.c.Do(req)
+ if err != nil {
+ b.Fatal(err)
+ }
+ resp.Body.Close()
+ }
+}
diff --git a/src/net/http/server.go b/src/net/http/server.go
index c25e83b..cae8c64 100644
--- a/src/net/http/server.go
+++ b/src/net/http/server.go
@@ -306,6 +306,14 @@
// by a Handler with the Hijacker interface.
// It is guarded by mu.
hijackedv bool
+
+ // debugConnID is the unique connection ID for httpdebug logging.
+ debugConnID int64
+
+ // debugCloseReason records why the connection was closed, for httpdebug logging.
+ // It is set at various points during serve(); later assignments intentionally
+ // override earlier ones to reflect the most specific reason for closing.
+ debugCloseReason string
}
func (c *conn) hijacked() bool {
@@ -1777,6 +1785,13 @@
// Close the connection.
func (c *conn) close() {
+ if c.debugConnID != 0 {
+ reason := c.debugCloseReason
+ if reason == "" {
+ reason = "closed"
+ }
+ httpDebugLogConnClose(httpDebugServerConnClosed, c.debugConnID, c.rwc.LocalAddr(), c.rwc.RemoteAddr(), reason)
+ }
c.finalFlush()
c.rwc.Close()
}
@@ -1931,6 +1946,7 @@
buf := make([]byte, size)
buf = buf[:runtime.Stack(buf, false)]
c.server.logf("http: panic serving %v: %v\n%s", c.remoteAddr, err, buf)
+ c.debugCloseReason = "panic"
}
if inFlightResponse != nil {
inFlightResponse.cancelCtx()
@@ -1998,6 +2014,11 @@
}
}
+ // Log connection_opened after TLS handshake so the tls field is accurate.
+ if httpDebugLogConnections() {
+ c.debugConnID = httpDebugLogConnOpen("server", c.rwc, c.tlsState)
+ }
+
ctx, cancelCtx := context.WithCancel(ctx)
c.cancelCtx = cancelCtx
defer cancelCtx()
@@ -2023,9 +2044,11 @@
c.setState(c.rwc, StateActive, runHooks)
}
if c.server.shuttingDown() {
+ c.debugCloseReason = "server shutdown"
return
}
if err != nil {
+ c.debugCloseReason = "read error"
const errorHeaders = "\r\nContent-Type: text/plain; charset=utf-8\r\nConnection: close\r\n\r\n"
switch {
@@ -2068,6 +2091,17 @@
// Expect 100 Continue support
req := w.req
+
+ var debugReqID int64
+ if httpDebugLogRequests() {
+ debugReqID = httpDebugNewReqID()
+ httpDebugLogReq(httpDebugServerReqRecvd,
+ c.debugConnID, debugReqID,
+ req.Method, req.RequestURI,
+ req.Proto, req.Host,
+ req.Header)
+ }
+
if req.expectsContinue() {
if req.ProtoAtLeast(1, 1) && req.ContentLength != 0 {
// Wrap the Body reader with one that replies on the connection
@@ -2098,13 +2132,34 @@
serverHandler{c.server}.ServeHTTP(w, w.req)
inFlightResponse = nil
w.cancelCtx()
+
if c.hijacked() {
c.r.releaseConn()
return
}
w.finishRequest()
+
+ // Log response_sent after finishRequest flushes the response
+ // to the network, so the event reflects that the response has
+ // actually been sent to the client.
+ if debugReqID != 0 {
+ status := w.status
+ if status == 0 {
+ // If the handler never called WriteHeader, the
+ // server implicitly sends a 200 status code.
+ // Report 200 in the debug log to match what the
+ // client will observe.
+ status = 200
+ }
+ httpDebugLogResp(httpDebugServerRespSent,
+ c.debugConnID, debugReqID,
+ status, req.Proto,
+ w.handlerHeader)
+ }
+
c.rwc.SetWriteDeadline(time.Time{})
if !w.shouldReuseConnection() {
+ c.debugCloseReason = "connection not reusable"
if w.requestBodyLimitHit || w.closedRequestBodyEarly() {
c.closeWriteAndWait()
}
@@ -2118,6 +2173,7 @@
// to the user without "Connection: close" and
// they might think they can send another
// request, but such is life with HTTP/1.1.
+ c.debugCloseReason = "server shutdown"
return
}
@@ -2132,6 +2188,7 @@
// ReadTimeout from starting until the first bytes of the next request
// have been received.
if _, err := c.bufr.Peek(4); err != nil {
+ c.debugCloseReason = "idle"
return
}
diff --git a/src/net/http/transport.go b/src/net/http/transport.go
index b7f68e6..72a9791 100644
--- a/src/net/http/transport.go
+++ b/src/net/http/transport.go
@@ -2051,6 +2051,10 @@
pconn.br = bufio.NewReaderSize(pconn, t.readBufferSize())
pconn.bw = bufio.NewWriterSize(persistConnWriter{pconn}, t.writeBufferSize())
+ if httpDebugLogConnections() {
+ pconn.debugConnID = httpDebugLogConnOpen("client", pconn.conn, pconn.tlsState)
+ }
+
go pconn.readLoop()
go pconn.writeLoop()
return pconn, nil
@@ -2178,6 +2182,7 @@
t *Transport
cacheKey connectMethodKey
conn net.Conn
+ debugConnID int64 // unique connection ID for httpdebug logging
tlsState *tls.ConnectionState
br *bufio.Reader // from conn
bw *bufio.Writer // to conn
@@ -2961,7 +2966,10 @@
gone := make(chan struct{})
defer close(gone)
- const debugRoundTrip = false
+ var debugReqID int64
+ if httpDebugLogRequests() {
+ debugReqID = httpDebugNewReqID()
+ }
// Write the request concurrently with waiting for a response,
// in case the server decides to reply before reading our full
@@ -2983,12 +2991,15 @@
if (re.res == nil) == (re.err == nil) {
panic(fmt.Sprintf("internal error: exactly one of res or err should be set; nil=%v", re.res == nil))
}
- if debugRoundTrip {
- req.logf("resc recv: %p, %T/%#v", re.res, re.err, re.err)
- }
if re.err != nil {
return nil, pc.mapRoundTripError(req, startBytesWritten, re.err)
}
+ if debugReqID != 0 {
+ httpDebugLogResp(httpDebugClientRespRecvd,
+ pc.debugConnID, debugReqID,
+ re.res.StatusCode, re.res.Proto,
+ re.res.Header)
+ }
return re.res, nil
}
@@ -2999,17 +3010,21 @@
testHookWaitResLoop()
select {
case err := <-writeErrCh:
- if debugRoundTrip {
- req.logf("writeErrCh recv: %T/%#v", err, err)
- }
if err != nil {
pc.close(fmt.Errorf("write error: %w", err))
return nil, pc.mapRoundTripError(req, startBytesWritten, err)
}
+ if debugReqID != 0 {
+ // Log request_sent after the write succeeds, so the event
+ // reflects a request that was actually sent on the wire.
+ // If the write fails, no request_sent event is emitted.
+ httpDebugLogReq(httpDebugClientReqSent,
+ pc.debugConnID, debugReqID,
+ req.Method, req.URL.RequestURI(),
+ req.Proto, req.URL.Host,
+ req.Header)
+ }
if d := pc.t.ResponseHeaderTimeout; d > 0 {
- if debugRoundTrip {
- req.logf("starting timer for %v", d)
- }
timer := time.NewTimer(d)
defer timer.Stop() // prevent leaks
respHeaderTimer = timer.C
@@ -3023,14 +3038,8 @@
return handleResponse(re)
default:
}
- if debugRoundTrip {
- req.logf("closech recv: %T %#v", pc.closed, pc.closed)
- }
return nil, pc.mapRoundTripError(req, startBytesWritten, pc.closed)
case <-respHeaderTimer:
- if debugRoundTrip {
- req.logf("timeout waiting for response headers.")
- }
pc.close(errTimeout)
return nil, errTimeout
case re := <-resc:
@@ -3083,6 +3092,14 @@
panic("nil error")
}
if pc.closed == nil {
+ if pc.debugConnID != 0 {
+ var localAddr, remoteAddr net.Addr
+ if pc.conn != nil {
+ localAddr = pc.conn.LocalAddr()
+ remoteAddr = pc.conn.RemoteAddr()
+ }
+ httpDebugLogConnClose(httpDebugClientConnClosed, pc.debugConnID, localAddr, remoteAddr, err.Error())
+ }
pc.closed = err
pc.t.decConnsPerHost(pc.cacheKey)
// Close HTTP/1 (pc.alt == nil) connection.
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Fixes #18733(Left some preliminary comments for now, will take a deeper look in the coming days.)
Thanks for working on this!
nit: if there is still follow-up work planned, just use `For #18733` so the bug isn't automatically closed? Unless you plan / have already created a new bug.
// sensitiveHeaders is the set of headers that are redacted by default.
var sensitiveHeaders = map[string]bool{
"Authorization": true,
"Cookie": true,
"Set-Cookie": true,
"Proxy-Authorization": true,
}Worth noting that we have a list of sensitive headers that we strip on redirect to a different domain: https://cs.opensource.google/go/go/+/master:src/net/http/client.go;l=817-819;drc=33e66cfb0406b27ce11229a4ebd944c4cb20006f.
For consistency, it's probably nice to just refactor that out into a common variable and reuse it in both instances?
if redact && sensitiveHeaders[key] {Someone might set their headers like so:
```
// No automatic canonicalization from req.Header.Set per usual.
req.Header["authorization"] = []string{"sensitive"}
```
In which case, the redaction won't work. Probably nice to play it safe and also redact non-canonicalized headers?
switch side + "." + event {nit: How about something like the following?
```
if side == "client" {
switch event {
case "connection_opened": return httpDebugClientConnOpened
case "connection_closed": return httpDebugClientConnClosed
}
} else if side == "server" {
switch event {
case "connection_opened": return httpDebugServerConnOpened
case "connection_closed": return httpDebugServerConnClosed
}
}
```
I think this does not make the code that much dirtier, but we get to avoid string concat (and therefore, allocation).
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Patch Set 2:
Thanks for the review, Nicholas! All four comments addressed:
(1) COMMIT_MSG: Changed `Fixes #18733` to `For #18733` since HTTP/2 slog coverage (levels 1-3) and frame logging (level 4) are planned as follow-up work.
(2) sensitiveHeaders (L100): Added a comment explaining the relationship with the redirect strip list in client.go. The lists differ intentionally — client.go also strips authentication *challenge* headers (Www-Authenticate, Cookie2, Proxy-Authenticate), while httpdebug only redacts headers carrying *credentials*. Happy to refactor into a shared variable if you feel strongly, but the different semantics made me lean toward keeping them separate with a cross-reference comment.
(3) Non-canonical header keys (L123): Good catch! Changed the redaction check to use `sensitiveHeaders[CanonicalHeaderKey(key)]` so that `req.Header["authorization"]` is also redacted.
(4) httpDebugConnEvent (L239): Refactored to use nested `if`/`switch` as suggested, avoiding the string concatenation allocation.
(Left some preliminary comments for now, will take a deeper look in the coming days.)
Thanks for working on this!
nit: if there is still follow-up work planned, just use `For #18733` so the bug isn't automatically closed? Unless you plan / have already created a new bug.
Done. Changed to `For #18733` since HTTP/2 slog coverage (levels 1-3) and frame logging (level 4) are planned as follow-up work.
// sensitiveHeaders is the set of headers that are redacted by default.
var sensitiveHeaders = map[string]bool{
"Authorization": true,
"Cookie": true,
"Set-Cookie": true,
"Proxy-Authorization": true,
}Worth noting that we have a list of sensitive headers that we strip on redirect to a different domain: https://cs.opensource.google/go/go/+/master:src/net/http/client.go;l=817-819;drc=33e66cfb0406b27ce11229a4ebd944c4cb20006f.
For consistency, it's probably nice to just refactor that out into a common variable and reuse it in both instances?
Good point. The two lists differ intentionally — client.go also strips authentication *challenge* headers (Www-Authenticate, Cookie2, Proxy-Authenticate), while httpdebug only redacts headers carrying *credentials*. I've added a cross-reference comment explaining the relationship and the rationale for the difference. Happy to refactor into a shared variable if you'd prefer, though.
Someone might set their headers like so:
```
// No automatic canonicalization from req.Header.Set per usual.
req.Header["authorization"] = []string{"sensitive"}
```In which case, the redaction won't work. Probably nice to play it safe and also redact non-canonicalized headers?
Good catch! Changed to `sensitiveHeaders[CanonicalHeaderKey(key)]` so that non-canonical keys like `req.Header["authorization"]` are also redacted.
nit: How about something like the following?
```
if side == "client" {
switch event {
case "connection_opened": return httpDebugClientConnOpened
case "connection_closed": return httpDebugClientConnClosed
}
} else if side == "server" {
switch event {
case "connection_opened": return httpDebugServerConnOpened
case "connection_closed": return httpDebugServerConnClosed
}
}
```I think this does not make the code that much dirtier, but we get to avoid string concat (and therefore, allocation).
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Thanks! Sorry for the delay in reviewing.
}This seems fine, but I wonder if it'd be simpler and perform as well if we skipped the Atoi entirely:
```
switch httpdebugsetting.Value() {
case "1":
return 1
case "2":
return 2
case "3"
return 3
case "4"
return 4 // no additional effect today, but future-proofing
}
```
slog.LogAttrs(context.Background(), slog.LevelDebug, msg, attrs...)Currently, setting `GODEBUG=httpdebug=2` produces no output on its own, because the default slog logger doesn't log events logged at LevelDebug.
Maybe this should log at LevelInfo?
(The fact that we have two different log level controls here is a bit confusing; I'm going to ask a local slog expert if they have any opinion on what we should be doing.)
slices.Sort(keys)This could be:
```
keys := slices.Sorted(maps.Keys(h))
```
...but better would be to avoid creating a transient slice here. We can just make the slice of slog.Attr and sort it:
```
attrs := make([]slog.Attr, len(h))
for k, v := range h {
// ...
attrs = append(attrs, slog.String(k, v))
}
slices.SortFunc(attrs, func(a, b slog.Attr) int {
return cmp.Compare(a.Key, b.Key)
})
return slog.GroupAttrs(name, attrs...)
```
attrs = append(attrs, slog.String(key, value))Is there a reason to prefer
```
slog.String(key, strings.Join(vals, ","))
```
over
```
slog.Group(key, vals...)
```
?
I can see arguments for either, not sure which is preferable.
httpDebugLogf(event, httpDebugConnAttrs(connID, localAddr, remoteAddr, tlsState)...)We should skip expensive slog event creation when the slog logging level excludes the event. We can check `slog.Default().Enabled(level)` before creating the event.
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Thanks for the review, Damien! Addressed all five inline comments in PS3. PTAL.
This seems fine, but I wonder if it'd be simpler and perform as well if we skipped the Atoi entirely:
```
switch httpdebugsetting.Value() {
case "1":
return 1
case "2":
return 2
case "3"
return 3
case "4"
return 4 // no additional effect today, but future-proofing
}
```
Done. Replaced the strconv.Atoi path with a plain switch on "1"/"2"/"3"/"4" and
removed the atomic cache (httpDebugLevelCache and httpDebugCachedLevel) along
with the strconv import. Level 4 is kept as a no-op placeholder so the set of
accepted values stays stable when HTTP/2 frame logging is added later.
slog.LogAttrs(context.Background(), slog.LevelDebug, msg, attrs...)Currently, setting `GODEBUG=httpdebug=2` produces no output on its own, because the default slog logger doesn't log events logged at LevelDebug.
Maybe this should log at LevelInfo?
(The fact that we have two different log level controls here is a bit confusing; I'm going to ask a local slog expert if they have any opinion on what we should be doing.)
Done. Introduced a package-level constant
const httpDebugLogLevel = slog.LevelInfo
and routed every LogAttrs call through it. This way GODEBUG=httpdebug=N
produces visible output with the default slog handler without requiring the
user to install a custom handler with a lower threshold. Happy to revisit if
your slog expert has a different recommendation.
This could be:
```
keys := slices.Sorted(maps.Keys(h))
```...but better would be to avoid creating a transient slice here. We can just make the slice of slog.Attr and sort it:
```
attrs := make([]slog.Attr, len(h))
for k, v := range h {
// ...
attrs = append(attrs, slog.String(k, v))
}
slices.SortFunc(attrs, func(a, b slog.Attr) int {
return cmp.Compare(a.Key, b.Key)
})
return slog.GroupAttrs(name, attrs...)
```
Done. Rewrote as you suggested: build []slog.Attr directly, sort in place with
slices.SortFunc + cmp.Compare, and return slog.GroupAttrs(name, attrs...).
No more transient []string keys, and the type-safe GroupAttrs replaces the
any-typed Group call.
Is there a reason to prefer
```
slog.String(key, strings.Join(vals, ","))
```over
```
slog.Group(key, vals...)
```?
I can see arguments for either, not sure which is preferable.
Kept strings.Join for now. A few reasons:
1. slog.Group's variadic expects alternating key/value pairs, so
slog.Group(key, vals...) wouldn't compile as written. The closest
equivalent would be emitting one slog.String per value, which under
JSONHandler produces an object with duplicated keys — legal JSON but
awkward to consume and inconsistent with typical slog output.
2. RFC 7230 §3.2.2 explicitly allows multiple field-values of the same
header to be combined with a comma, so the joined form matches the
wire convention readers will expect in debug output.
3. Under TextHandler / logfmt, each header already renders as a single
key=value line, which I think is the most readable form for humans
scanning the log.
4. Set-Cookie is the one header where folding isn't spec-compliant at
the protocol level, but since this is debug display rather than
protocol re-emission, the joined form is still unambiguous for
readers.
Happy to switch if you or the slog expert prefer the grouped form; it'd be
a one-line change.
httpDebugLogf(event, httpDebugConnAttrs(connID, localAddr, remoteAddr, tlsState)...)We should skip expensive slog event creation when the slog logging level excludes the event. We can check `slog.Default().Enabled(level)` before creating the event.
Done. Added
func httpDebugLogEnabled() bool {
return slog.Default().Enabled(context.Background(), httpDebugLogLevel)
}and used it as an additional guard in all four entry points — httpDebugLogConn,
httpDebugLogConnClose, httpDebugLogReq, httpDebugLogResp — so attribute
construction (including Header iteration/sorting and redaction) is skipped
whenever either the GODEBUG level or the slog handler threshold would drop
the event.
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
slog.LogAttrs(context.Background(), httpDebugLogLevel, msg, attrs...)Sorry for the delay in reviewing; I've been trying to figure out what the right way to connect the httpdebug log level with slog is. I think I've got a reasonable approach, but if you see a better one please let me know.
The core problem here is that we've got two different ways of specifying what is being logged:
This is confusing. If we log at `slog.LevelDebug`, then log messages aren't printed unless the user adjusts the slog logging level. (In which case, why do we have `GODEBUG=httpdebug=N`, since the user can just adjust the logging level?) But if we log at `slog.LevelInfo`, then it's confusing that we're putting debug logs into a non-debug level.
I think that:
1) We should switch this CL to use a net/http-internal `slog.Logger` rather than `slog.Default()`.
2) `GODEBUG=httpdebug=N` sets the level for this logger to `-N`. We log connection events at level `-1`, request/response at `-2`, and so on. This gets the exact same behavior as today.
3) As a followup proposal (which I'm happy to file), we add a way for the user to set the `slog.Logger` used by `net/http`. Users who want to consume log events programmatically or change the logging to, say, JSON, can use this to do so.
This gives us `GODEBUG=httpdebug=N` and log events printed to stdout in the short term (should be in Go 1.27), and in the longer term (Go 1.28 with luck) we also have the ability to use a custom logger.
How does that sound?
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
net/http: add GODEBUG=httpdebug setting for structured HTTP debug logging
diff --git a/src/net/http/export_test.go b/src/net/http/export_test.go
index b499769..7ec8961 100644
--- a/src/net/http/export_test.go
+++ b/src/net/http/export_test.go
@@ -10,6 +10,7 @@
import (
"context"
"fmt"
+ "log/slog"
"net"
"net/url"
"slices"
@@ -311,3 +312,33 @@
})
rstAvoidanceDelay = d
}
+
+// SetHTTPDebugLogHandler replaces the net/http internal httpdebug
+// [slog.Handler] with one that wraps h. The minimum level is still
+// controlled by the GODEBUG=httpdebug setting, so h is wrapped with a
+// [slog.HandlerOptions.Level] of the internal level variable. The
+// original logger is restored when the test ends.
+func SetHTTPDebugLogHandler(t testing.TB, h func() slog.Handler) {
+ t.Helper()
+ // Prime the logger so any earlier lazy init has already run.
+ httpDebugLoggerInit()
+ prev := httpDebugLogger.Load()
+ httpDebugLogger.Store(slog.New(h()))
+ t.Cleanup(func() {
+ httpDebugLogger.Store(prev)
+ })
+}
+
+// HTTPDebugLevelVar returns the internal [slog.LevelVar] controlling
+// the httpdebug logger. Tests can read it to verify the GODEBUG
+// setting was translated correctly.
+func HTTPDebugLevelVar() *slog.LevelVar {
+ return httpDebugLevelVar
+}
+
+// HTTPDebugEnabled reports whether an httpdebug event at the given
+// slog level would be emitted. It is exported for use by tests that
+// need to force a re-read of the GODEBUG=httpdebug setting.
+func HTTPDebugEnabled(level slog.Level) bool {
+ return httpDebugEnabled(level)
+}
diff --git a/src/net/http/httpdebug.go b/src/net/http/httpdebug.go
new file mode 100644
index 0000000..f2367db
--- /dev/null
+++ b/src/net/http/httpdebug.go
@@ -0,0 +1,318 @@
+// Copyright 2026 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package http
+
+import (
+ "cmp"
+ "context"
+ "crypto/tls"
+ "internal/godebug"
+ "log/slog"
+ "net"
+ "os"
+ "slices"
+ "strings"
+ "sync"
+ "sync/atomic"
+)
+
+// httpdebug controls the verbosity of HTTP debug logging.
+//
+// The level is set by the GODEBUG=httpdebug=N setting:
+//
+// - httpdebug=1: Log connection events (open/close).
+// - httpdebug=2: Also log request/response events.
+// - httpdebug=3: Also log request/response headers.
+//
+// The GODEBUG=httpdebugredact setting controls whether sensitive
+// headers (Authorization, Cookie, Set-Cookie, Proxy-Authorization)
+// are redacted in log output. By default, redaction is enabled.
+// Set httpdebugredact=0 to disable redaction.
+var (
+ httpdebugSetting = godebug.New("httpdebug")
+ httpdebugredactSetting = godebug.New("httpdebugredact")
+)
+
+// httpDebugLog levels.
+//
+// The httpdebug GODEBUG setting controls a net/http internal [slog.Logger]
+// whose minimum level is set to the negative of the GODEBUG value:
+// httpdebug=N enables events logged at [slog.Level](-N) or higher.
+// Connection events are logged at level -1, request/response events
+// at level -2, and headers at level -3. Using negative levels keeps
+// httpdebug events strictly below [slog.LevelDebug] (-4) so they do
+// not interfere with application logging when the net/http logger
+// is replaced with a user-supplied one in the future.
+const (
+ httpDebugLevelConn slog.Level = -1
+ httpDebugLevelReq slog.Level = -2
+ httpDebugLevelHeader slog.Level = -3
+ httpDebugLevelReserve slog.Level = -4 // reserved for HTTP/2 frame logging
+)
+
+// httpDebugLevelVar is the dynamic minimum level of [httpDebugLogger].
+// It is updated from the httpdebug GODEBUG setting when the setting
+// changes (see httpDebugUpdateLevel).
+var httpDebugLevelVar = new(slog.LevelVar)
+
+// httpDebugLogger is the [slog.Logger] used for httpdebug output.
+// Its handler writes to stderr, and its minimum level is controlled
+// by httpDebugLevelVar. Using a dedicated logger (rather than
+// [slog.Default]) decouples httpdebug from application logging: the
+// GODEBUG setting alone determines whether events are emitted.
+var httpDebugLogger atomic.Pointer[slog.Logger]
+
+// httpDebugDefaultHandler returns the default handler used by
+// httpDebugLogger when no test handler has been installed.
+var httpDebugDefaultHandler = sync.OnceValue(func() slog.Handler {
+ // Use a very low level threshold so the handler accepts all httpdebug
+ // events. The GODEBUG setting (via httpDebugLevelVar) is the sole
+ // gate that controls whether events are emitted.
+ return slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: slog.Level(-16)})
+})
+
+// httpDebugLoggerInit is called on first use to install the default
+// logger. It also primes the level from the current GODEBUG value.
+var httpDebugLoggerInit = sync.OnceFunc(func() {
+ httpDebugUpdateLevel()
+ if httpDebugLogger.Load() == nil {
+ httpDebugLogger.CompareAndSwap(nil, slog.New(httpDebugDefaultHandler()))
+ }
+})
+
+// httpDebugUpdateLevel reads the current GODEBUG=httpdebug setting
+// and updates httpDebugLevelVar. It is safe to call concurrently.
+func httpDebugUpdateLevel() {
+ switch httpdebugSetting.Value() {
+ case "1":
+ httpDebugLevelVar.Set(httpDebugLevelConn)
+ case "2":
+ httpDebugLevelVar.Set(httpDebugLevelReq)
+ case "3":
+ httpDebugLevelVar.Set(httpDebugLevelHeader)
+ case "4":
+ httpDebugLevelVar.Set(httpDebugLevelReserve)
+ default:
+ // Any other value (including unset, "0", or an unparseable
+ // string) disables logging. slog.LevelInfo (0) is higher
+ // than all httpdebug event levels, which are negative.
+ httpDebugLevelVar.Set(slog.LevelInfo)
+ }
+}
+
+// httpDebugEnabled reports whether events at level would be emitted
+// by the httpdebug logger. The GODEBUG=httpdebug setting is the sole
+// gate: an event at level l is enabled when httpDebugLevelVar.Level() <= l.
+// This is cheap to call: it is a single atomic load followed by a comparison.
+func httpDebugEnabled(level slog.Level) bool {
+ httpDebugLoggerInit()
+ httpDebugUpdateLevel()
+ return httpDebugLevelVar.Level() <= level
+}
+
+// httpDebugLogConnections reports whether connection events should be logged.
+func httpDebugLogConnections() bool { return httpDebugEnabled(httpDebugLevelConn) }
+
+// httpDebugLogRequests reports whether request/response events should be logged.
+func httpDebugLogRequests() bool { return httpDebugEnabled(httpDebugLevelReq) }
+
+// httpDebugRedact reports whether sensitive headers should be redacted.
+// It reads the GODEBUG setting on each call.
+func httpDebugRedact() bool {
+ return httpdebugredactSetting.Value() != "0"
+}
+
+// Atomic counters for assigning unique IDs to connections and requests.
+var (
+ httpDebugNextConnID atomic.Int64
+ httpDebugNextReqID atomic.Int64
+)
+
+// httpDebugNewConnID returns the next unique connection ID.
+func httpDebugNewConnID() int64 {
+ return httpDebugNextConnID.Add(1)
+}
+
+// httpDebugNewReqID returns the next unique request ID.
+func httpDebugNewReqID() int64 {
+ return httpDebugNextReqID.Add(1)
+}
+
+// sensitiveHeaders is the set of headers whose values contain credentials
+// and are redacted by default in httpdebug output. The keys must be in
+// canonical form (see [CanonicalHeaderKey]).
+//
+// This list is intentionally a subset of the headers stripped on redirect
+// in client.go (which also includes Www-Authenticate, Cookie2, and
+// Proxy-Authenticate). Those additional headers carry authentication
+// challenges rather than credentials, so they are not redacted here.
+var sensitiveHeaders = map[string]bool{
+ "Authorization": true,
+ "Cookie": true,
+ "Set-Cookie": true,
+ "Proxy-Authorization": true,
+}
+
+// httpDebugLogf logs a debug message with structured attributes at the
+// given slog level on the httpdebug logger.
+func httpDebugLogf(level slog.Level, msg string, attrs ...slog.Attr) {
+ httpDebugLogger.Load().LogAttrs(context.Background(), level, msg, attrs...)
+}
+
+// httpDebugHeaderAttrs returns a slog Group attribute for HTTP headers.
+// Sensitive headers are redacted unless httpdebugredact=0.
+// Headers are sorted by key for deterministic output.
+func httpDebugHeaderAttrs(name string, h Header) slog.Attr {
+ redact := httpDebugRedact()
+ attrs := make([]slog.Attr, 0, len(h))
+ for key, vals := range h {
+ value := strings.Join(vals, ", ")
+ if redact && sensitiveHeaders[CanonicalHeaderKey(key)] {
+ value = "[REDACTED]"
+ }
+ attrs = append(attrs, slog.String(key, value))
+ }
+ slices.SortFunc(attrs, func(a, b slog.Attr) int {
+ return cmp.Compare(a.Key, b.Key)
+ })
+ return slog.GroupAttrs(name, attrs...)
+ if !httpDebugEnabled(httpDebugLevelConn) {
+ return
+ }
+ httpDebugLogf(httpDebugLevelConn, event, httpDebugConnAttrs(connID, localAddr, remoteAddr, tlsState)...)
+}
+
+// httpDebugLogConnClose logs a connection close event with a reason.
+func httpDebugLogConnClose(event string, connID int64, localAddr, remoteAddr net.Addr, reason string) {
+ if !httpDebugEnabled(httpDebugLevelConn) {
+ return
+ }
+ attrs := []slog.Attr{
+ slog.Int64("conn_id", connID),
+ }
+ if localAddr != nil {
+ attrs = append(attrs, slog.String("local_addr", localAddr.String()))
+ }
+ if remoteAddr != nil {
+ attrs = append(attrs, slog.String("remote_addr", remoteAddr.String()))
+ }
+ attrs = append(attrs, slog.String("reason", reason))
+ httpDebugLogf(httpDebugLevelConn, event, attrs...)
+}
+
+// httpDebugLogReq logs a request event.
+func httpDebugLogReq(event string, connID, reqID int64, method, uri, proto, host string, h Header) {
+ if !httpDebugEnabled(httpDebugLevelReq) {
+ return
+ }
+ attrs := httpDebugReqAttrs(connID, reqID, method, uri, proto, host)
+ if h != nil && httpDebugEnabled(httpDebugLevelHeader) {
+ attrs = append(attrs, httpDebugHeaderAttrs("header", h))
+ }
+ httpDebugLogf(httpDebugLevelReq, event, attrs...)
+}
+
+// httpDebugLogResp logs a response event.
+func httpDebugLogResp(event string, connID, reqID int64, status int, proto string, h Header) {
+ if !httpDebugEnabled(httpDebugLevelReq) {
+ return
+ }
+ attrs := httpDebugRespAttrs(connID, reqID, status, proto)
+ if h != nil && httpDebugEnabled(httpDebugLevelHeader) {
+ attrs = append(attrs, httpDebugHeaderAttrs("header", h))
+ }
+ httpDebugLogf(httpDebugLevelReq, event, attrs...)
+}
+
+// Event name constants for HTTP debug logging.
+// Using constants avoids allocating a new string on each call.
+const (
+ httpDebugClientConnOpened = "http.client.connection_opened"
+ httpDebugClientConnClosed = "http.client.connection_closed"
+ httpDebugClientReqSent = "http.client.request_sent"
+ httpDebugClientRespRecvd = "http.client.response_received"
+ httpDebugServerConnOpened = "http.server.connection_opened"
+ httpDebugServerConnClosed = "http.server.connection_closed"
+ httpDebugServerReqRecvd = "http.server.request_received"
+ httpDebugServerRespSent = "http.server.response_sent"
+)
+
+// httpDebugConnEvent returns the event name for a connection event.
+func httpDebugConnEvent(side, event string) string {
+ if side == "client" {
+ switch event {
+ case "connection_opened":
+ return httpDebugClientConnOpened
+ case "connection_closed":
+ return httpDebugClientConnClosed
+ }
+ } else if side == "server" {
+ switch event {
+ case "connection_opened":
+ return httpDebugServerConnOpened
+ case "connection_closed":
+ return httpDebugServerConnClosed
+ }
+ }
+ return "http." + side + "." + event
+}
+
+// httpDebugLogConnOpen assigns a new connection ID and logs the connection_opened event.
+func httpDebugLogConnOpen(side string, c net.Conn, tlsState *tls.ConnectionState) int64 {
+ connID := httpDebugNewConnID()
+ httpDebugLogConn(
+ httpDebugConnEvent(side, "connection_opened"),
+ connID,
+ c.LocalAddr(),
+ c.RemoteAddr(),
+ tlsState,
+ )
+ return connID
+}
diff --git a/src/net/http/httpdebug_test.go b/src/net/http/httpdebug_test.go
new file mode 100644
index 0000000..9e3e2d8
--- /dev/null
+++ b/src/net/http/httpdebug_test.go
@@ -0,0 +1,751 @@
+// Copyright 2026 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package http_test
+
+import (
+ "bytes"
+ "fmt"
+ "log/slog"
+ . "net/http"
+ "sort"
+ "strings"
+ "sync"
+ "testing"
+)
+
+// setupHTTPDebugLogger installs a test slog handler that writes to a
+// buffer and returns the buffer. The handler accepts any level, so
+// events emitted by httpdebug (which uses negative slog levels
+// controlled by the GODEBUG=httpdebug setting) are captured.
+func setupHTTPDebugLogger(t testing.TB) *bytes.Buffer {
+ t.Helper()
+ var buf bytes.Buffer
+ SetHTTPDebugLogHandler(t, func() slog.Handler {
+ return slog.NewTextHandler(&buf, &slog.HandlerOptions{
+ // LevelDebug-16 is below httpdebug's most verbose level (-3),
+ // so the handler lets all httpdebug events through and the
+ // GODEBUG setting alone controls what is emitted.
+ Level: slog.Level(-16),
+ })
+ })
+// TestHTTPDebugDynamicLevelChange verifies that changing the
+// GODEBUG=httpdebug setting at runtime takes effect immediately on
+// subsequent requests, without requiring a process restart. This is a
+// direct consequence of the PS4 design: httpDebugEnabled re-reads the
+// GODEBUG value on every call via httpDebugUpdateLevel.
+func TestHTTPDebugDynamicLevelChange(t *testing.T) {
+ buf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ // Start with httpdebug disabled.
+ t.Setenv("GODEBUG", "")
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+ if strings.Contains(buf.String(), "http.client") {
+ t.Errorf("unexpected httpdebug output while disabled:\n%s", buf.String())
+ }
+
+ // Flip to level 2 at runtime; the next request should be logged.
+ buf.Reset()
+ t.Setenv("GODEBUG", "httpdebug=2")
+ resp, err = cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+ if !strings.Contains(buf.String(), "http.client.request_sent") {
+ t.Errorf("expected request_sent after switching to httpdebug=2, got:\n%s", buf.String())
+ }
+
+ // Flip back to disabled; the next request must produce no output.
+ buf.Reset()
+ t.Setenv("GODEBUG", "")
+ resp, err = cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+ if strings.Contains(buf.String(), "http.client") {
+ t.Errorf("httpdebug output should stop after disabling, got:\n%s", buf.String())
+ }
+}
+
+// TestHTTPDebugIndependentOfSlogDefault verifies that httpdebug uses
+// its own internal slog.Logger and is not affected by the level or
+// output of [slog.Default]. This guarantees that applications which
+// configure slog.Default to filter out low-level events still receive
+// httpdebug output when GODEBUG=httpdebug is set, and conversely that
+// httpdebug events do not leak into an application's production logs.
+func TestHTTPDebugIndependentOfSlogDefault(t *testing.T) {
+ t.Setenv("GODEBUG", "httpdebug=2")
+
+ // Install a slog.Default that discards everything below LevelError
+ // and writes to a separate buffer. If httpdebug were routed through
+ // slog.Default, its events (at negative levels) would be silently
+ // dropped and defaultBuf would remain empty — but so would httpdebug's
+ // own buffer, which is not what we want to assert. Instead, we use
+ // LevelError to ensure slog.Default would drop httpdebug events if
+ // they were ever routed there.
+ var defaultBuf bytes.Buffer
+ defaultHandler := slog.NewTextHandler(&defaultBuf, &slog.HandlerOptions{Level: slog.LevelError})
+ prevDefault := slog.Default()
+ slog.SetDefault(slog.New(defaultHandler))
+ t.Cleanup(func() { slog.SetDefault(prevDefault) })
+
+ // Install the httpdebug test handler (writes to its own buffer).
+ httpdebugBuf := setupHTTPDebugLogger(t)
+
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+
+ if !strings.Contains(httpdebugBuf.String(), "http.client.request_sent") {
+ t.Errorf("httpdebug should emit events regardless of slog.Default level, got:\n%s", httpdebugBuf.String())
+ }
+ // slog.Default must not have received any httpdebug events.
+ if strings.Contains(defaultBuf.String(), "http.client") ||
+ strings.Contains(defaultBuf.String(), "http.server") {
+ t.Errorf("httpdebug events leaked into slog.Default, got:\n%s", defaultBuf.String())
+ }
+}
+
+// TestHTTPDebugLevel4Reserved verifies that httpdebug=4 is accepted
+// without panicking and lowers the internal level threshold. Level 4
+// is currently reserved for HTTP/2 frame logging in a future CL and
+// has no additional user-visible effect today, but the GODEBUG value
+// must still be recognized and mapped to slog.Level(-4).
+func TestHTTPDebugLevel4Reserved(t *testing.T) {
+ t.Setenv("GODEBUG", "httpdebug=4")
+ // Trigger an update via a cheap Enabled check.
+ if !HTTPDebugEnabled(slog.Level(-4)) {
+ t.Errorf("httpdebug=4 should enable events at slog.Level(-4)")
+ }
+ if got, want := HTTPDebugLevelVar().Level(), slog.Level(-4); got != want {
+ t.Errorf("httpdebug=4: level var = %v, want %v", got, want)
+ }
+ // Level 4 must behave at least as a superset of level 3 (header events
+ // are still logged).
+ buf := setupHTTPDebugLogger(t)
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+ if !strings.Contains(buf.String(), "header.") {
+ t.Errorf("httpdebug=4 should still log headers, got:\n%s", buf.String())
+ }
+}
+
+// TestHTTPDebugLevelMapping verifies the GODEBUG-to-slog.Level mapping
+// that underpins the PS4 design, and that emitted records carry the
+// expected negative levels. These values are part of the externally
+// observable behavior (users may filter by level in a future handler-
+// replacement API), so the test pins them down.
+func TestHTTPDebugLevelMapping(t *testing.T) {
+ cases := []struct {
+ godebug string
+ want slog.Level
+ }{
+ {"", slog.LevelInfo}, // disabled
+ {"httpdebug=0", slog.LevelInfo},
+ {"httpdebug=1", slog.Level(-1)},
+ {"httpdebug=2", slog.Level(-2)},
+ {"httpdebug=3", slog.Level(-3)},
+ {"httpdebug=4", slog.Level(-4)},
+ {"httpdebug=bogus", slog.LevelInfo},
+ }
+ for _, c := range cases {
+ t.Run(c.godebug, func(t *testing.T) {
+ t.Setenv("GODEBUG", c.godebug)
+ // Force an update through a no-op Enabled call.
+ HTTPDebugEnabled(slog.Level(-4))
+ if got := HTTPDebugLevelVar().Level(); got != c.want {
+ t.Errorf("GODEBUG=%q: level var = %v, want %v", c.godebug, got, c.want)
+ }
+ })
+ }
+
+ // Additionally verify that emitted records carry the expected levels
+ // by inspecting the text-handler output for "level=DEBUG+3" (== -1),
+ // "level=DEBUG+2" (== -2), "level=DEBUG+1" (== -3).
+ t.Setenv("GODEBUG", "httpdebug=3")
+ buf := setupHTTPDebugLogger(t)
+ cst := newClientServerTest(t, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ t.Fatal(err)
+ }
+ resp.Body.Close()
+ cst.tr.CloseIdleConnections()
+
+ out := buf.String()
+ // slog's text handler prints slog.Level(-1) as "DEBUG+3",
+ // slog.Level(-2) as "DEBUG+2", and slog.Level(-3) as "DEBUG+1".
+ // (See (Level).String in log/slog.)
+ for _, want := range []struct {
+ event string
+ level string
+ }{
+ {"http.client.connection_opened", "level=DEBUG+3"},
+ {"http.client.request_sent", "level=DEBUG+2"},
+ } {
+ // Find the line for the event and check it carries the right level.
+ var found bool
+ for _, line := range strings.Split(out, "\n") {
+ if strings.Contains(line, "msg="+want.event) {
+ found = true
+ if !strings.Contains(line, want.level) {
+ t.Errorf("%s line missing %s:\n%s", want.event, want.level, line)
+ }
+ break
+ }
+ }
+ if !found {
+ t.Errorf("no line for event %s in output:\n%s", want.event, out)
+ }
+ }
+}
+
+func BenchmarkHTTPDebugDisabled(b *testing.B) {
+ // Benchmark with httpdebug disabled (default) to measure zero overhead.
+ b.ReportAllocs()
+
+ setupHTTPDebugLogger(b)
+
+ cst := newClientServerTest(b, http1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+ w.WriteHeader(200)
+ }))
+
+ b.ResetTimer()
+ for i := 0; i < b.N; i++ {
+ resp, err := cst.c.Get(cst.ts.URL)
+ if err != nil {
+ b.Fatal(err)
+ }
+ resp.Body.Close()
+ }
+}
+
+func BenchmarkHTTPDebugLevel1(b *testing.B) {
+ // Benchmark with httpdebug=1 to measure the cost of connection logging.
+ b.Setenv("GODEBUG", "httpdebug=1")
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
slog.LogAttrs(context.Background(), httpDebugLogLevel, msg, attrs...)Sorry for the delay in reviewing; I've been trying to figure out what the right way to connect the httpdebug log level with slog is. I think I've got a reasonable approach, but if you see a better one please let me know.
The core problem here is that we've got two different ways of specifying what is being logged:
- `GODEBUG=httpdebug=N` essentially sets the HTTP debug logging level.
- `slog.Default`'`s level *also* sets a logging level.
This is confusing. If we log at `slog.LevelDebug`, then log messages aren't printed unless the user adjusts the slog logging level. (In which case, why do we have `GODEBUG=httpdebug=N`, since the user can just adjust the logging level?) But if we log at `slog.LevelInfo`, then it's confusing that we're putting debug logs into a non-debug level.
I think that:
1) We should switch this CL to use a net/http-internal `slog.Logger` rather than `slog.Default()`.
2) `GODEBUG=httpdebug=N` sets the level for this logger to `-N`. We log connection events at level `-1`, request/response at `-2`, and so on. This gets the exact same behavior as today.
3) As a followup proposal (which I'm happy to file), we add a way for the user to set the `slog.Logger` used by `net/http`. Users who want to consume log events programmatically or change the logging to, say, JSON, can use this to do so.This gives us `GODEBUG=httpdebug=N` and log events printed to stdout in the short term (should be in Go 1.27), and in the longer term (Go 1.28 with luck) we also have the ability to use a custom logger.
How does that sound?
Thanks for the detailed guidance, Damien. PS4 implements the approach:
- Added a package-private slog.Logger in net/http that writes JSON to stderr
with a LevelVar, decoupled from slog.Default().
- GODEBUG=httpdebug=N sets the logger level to -N (httpdebug=1 → Level(-1)
for connection events, =2 → Level(-2) for requests, =3 → Level(-3) for
headers). GODEBUG is now the single source of truth; there's no way to
enable debug logging except via GODEBUG.
- httpdebug.Value() checks are kept on the hot paths so we still avoid work
when debugging is off.
- Tests cover dynamic GODEBUG changes, independence from slog.Default, and
level=4 being accepted as a future-compatible no-op.
PTAL.
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |