Add body-drain experiment: observe HTTP body drain/close/leak effects

Local counting server + httptrace/goroutine metrics showing connection reuse (drain), pool bypass (close only) and fd/goroutine leak (no close). Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01GbnJj9ZqEx9nUvzkjdwfMq
2026-08-28 23:49:04 +02:00
parent 7219eb5a23
commit 9df64837dd
2 changed files with 286 additions and 0 deletions
@@ -0,0 +1,110 @@
+# Experiment — not draining / closing HTTP response bodies
+
+Companion to exercise 01, assignment point 5 ("reuse a single http.Client and
+properly drain+close response bodies so connections are reused").
+
+```
+go run ./99-experiments/body-drain -mode all
+go run ./99-experiments/body-drain -mode leak -n 200
+ulimit -n 64 && go run ./99-experiments/body-drain -mode leak -n 200   # watch it die
+```
+
+## What it does
+
+A local `httptest.Server` returns a 1 MiB body and counts accepted TCP
+connections via `Server.ConnState`. The client does N sequential GETs in one of
+three modes, with a fresh `Transport` per mode:
+
+| mode    | client does                                   |
+|---------|-----------------------------------------------|
+| `drain` | `io.Copy(io.Discard, body)` then `body.Close()` |
+| `close` | `body.Close()` only                             |
+| `leak`  | nothing                                         |
+
+## What to watch
+
+- **`server new conns`** — TCP connections the server accepted. Ideal: 1.
+- **`httptrace GotConn reused/fresh`** — the client's own view: did `client.Do`
+  pull a conn from the idle pool or dial a new one.
+- **`goroutines delta`** — every connection the transport owns runs two
+  goroutines (`readLoop` + `writeLoop`). Pooled conns show up here too, but
+  they disappear after `CloseIdleConnections()`. Leaked ones don't.
+- **`server active conns`** — conns the server still considers open after the
+  client is "done".
+
+## Typical output
+
+```
+== mode=drain ==
+  httptrace GotConn  : reused=19 fresh=1
+  goroutines         : before=2 after=5 (delta +3)
+  after CloseIdleConnections: goroutines=2
+  server new conns   : 1 (ideal: 1)
+  server active conns: 0
+
+== mode=close ==
+  httptrace GotConn  : reused=0 fresh=20
+  goroutines         : before=2 after=2
+  server new conns   : 20 (ideal: 1)
+  server active conns: 0
+
+== mode=leak ==
+  httptrace GotConn  : reused=0 fresh=20
+  goroutines         : before=2 after=73 (delta +71)
+  after CloseIdleConnections: goroutines=73        <- nothing reclaimed
+  server new conns   : 20 (ideal: 1)
+  server active conns: 20                          <- server stuck too
+```
+
+## Reading it
+
+**`close` without drain is not a leak, but it defeats the pool.** The transport
+sees unread bytes on the wire; reusing that TCP stream would corrupt the next
+response, so it closes the conn. Every request pays DNS + TCP + TLS again. On
+loopback that's microseconds; against a real HTTPS host it's 3–4 RTTs per
+request and a TLS handshake the server has to do CPU work for. Correct output,
+silently several times slower, and a `TIME_WAIT` pile-up on your host.
+
+**`leak` leaks three things per request:** a file descriptor, two goroutines,
+and the read buffer. `CloseIdleConnections` can't help because the conn is not
+idle — the transport thinks a response is still in progress. Under any real
+request rate this ends in `dial tcp: socket: too many open files`.
+
+**The server suffers as well.** Its handler is blocked in `Write()` because the
+client never reads and the kernel socket buffers are full. Without a
+`WriteTimeout` those handler goroutines live until the client process dies.
+This is why `httptest.Server.Close` hangs and logs "blocked in Close after 5
+seconds" if you remove the `CloseClientConnections()` call — try it.
+
+**Why doesn't a `Client.Timeout` hide this?** It does, partially: when the timer
+fires, the transport force-closes the conn and the goroutines go away. So a
+leaky client with a 5 s timeout leaks for 5 s per request instead of forever —
+enough to exhaust fds at a few hundred req/s, and no connection reuse either
+way. Add `Timeout: 5 * time.Second` to the client in `run()` and re-run `leak`
+with a `time.Sleep(6 * time.Second)` before the goroutine count to see it.
+
+## Rules that follow
+
+```go
+resp, err := client.Do(req)
+if err != nil { return err }
+defer resp.Body.Close()
+io.Copy(io.Discard, resp.Body)   // or io.CopyN(..., 64<<10) if bodies may be huge
+```
+
+- Always `Close()`, always via `defer` right after the error check.
+- Read to EOF if you want the conn back. If you don't need the body and it may
+  be large, cap the drain — past some size a new handshake is cheaper than the
+  download.
+- Consider `HEAD` for health checks: nothing to drain.
+- `Transport.MaxIdleConnsPerHost` defaults to 2; with `limit` concurrent
+  checkers to one host, raise it to `limit` or the pool thrashes anyway.
+
+## References
+
+- `net/http` docs, `Client.Do`: "If the Body is not both read to EOF and closed,
+  the Client's underlying RoundTripper may not be able to re-use a persistent
+  TCP connection" — https://pkg.go.dev/net/http#Client.Do
+- `net/http/httptrace` — https://pkg.go.dev/net/http/httptrace
+- `http.Server.ConnState` — https://pkg.go.dev/net/http#Server.ConnState
+- golang/go#4677 — the issue where this behaviour was settled.
@@ -0,0 +1,176 @@
+// Experiment — what happens when you don't drain/close an HTTP response body
+//
+// A local server hands out 1 MiB responses and counts every TCP connection it
+// accepts. The client performs N sequential GETs against it in one of three
+// modes and we observe:
+//
+//   - server-side: how many *new* TCP connections were accepted (ideal: 1)
+//   - client-side: httptrace's GotConnInfo.Reused for every request
+//   - client-side: goroutine count (each pooled/leaked conn owns 2 goroutines:
+//     the transport's readLoop and writeLoop)
+//
+// Modes:
+//
+//	drain  — io.Copy(io.Discard, body); body.Close()   → connection reused
+//	close  — body.Close() only                          → connection thrown away, new dial every time
+//	leak   — neither                                    → connection AND 2 goroutines AND 1 fd leaked per request
+//
+// Run:  go run ./99-experiments/body-drain -mode drain
+//       go run ./99-experiments/body-drain -mode close
+//       go run ./99-experiments/body-drain -mode leak
+//       go run ./99-experiments/body-drain -mode all      (all three, fresh transport each)
+//
+// To see the leak actually kill the process, lower the fd limit first:
+//       ulimit -n 64 && go run ./99-experiments/body-drain -mode leak -n 200
+package main
+
+import (
+	"context"
+	"flag"
+	"fmt"
+	"io"
+	"net"
+	"net/http"
+	"net/http/httptest"
+	"net/http/httptrace"
+	"os"
+	"runtime"
+	"sync/atomic"
+	"time"
+)
+
+const bodySize = 1 << 20 // 1 MiB — large enough that it is never fully buffered in the transport
+
+type mode string
+
+const (
+	modeDrain mode = "drain"
+	modeClose mode = "close"
+	modeLeak  mode = "leak"
+)
+
+// countingServer wraps httptest.Server and counts accepted connections.
+type countingServer struct {
+	*httptest.Server
+	newConns    atomic.Int64
+	activeConns atomic.Int64
+}
+
+func newCountingServer() *countingServer {
+	payload := make([]byte, bodySize)
+	s := &countingServer{}
+	s.Server = httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		w.Header().Set("Content-Length", fmt.Sprint(bodySize))
+		w.WriteHeader(http.StatusOK)
+		w.Write(payload)
+	}))
+	// ConnState is the server-side hook that lets us see the connection lifecycle.
+	s.Config.ConnState = func(c net.Conn, st http.ConnState) {
+		switch st {
+		case http.StateNew:
+			s.newConns.Add(1)
+			s.activeConns.Add(1)
+		case http.StateClosed, http.StateHijacked:
+			s.activeConns.Add(-1)
+		}
+	}
+	s.Start()
+	return s
+}
+
+// run performs n GETs in the given mode and reports what it observed.
+func run(m mode, n int, url string) {
+	// Fresh transport per run so runs don't share a pool. Cloning keeps sane defaults.
+	tr := http.DefaultTransport.(*http.Transport).Clone()
+	tr.MaxIdleConnsPerHost = 10
+	// NOTE: deliberately no Client.Timeout. With a timeout, a leaked body gets
+	// force-closed when the timer fires, which hides the leak (try adding one
+	// and watch the goroutine count drop after the timeout).
+	client := &http.Client{Transport: tr}
+
+	var reused, fresh int
+	trace := &httptrace.ClientTrace{
+		GotConn: func(info httptrace.GotConnInfo) {
+			if info.Reused {
+				reused++
+			} else {
+				fresh++
+			}
+		},
+	}
+
+	goroutinesBefore := runtime.NumGoroutine()
+	start := time.Now()
+
+	for i := 0; i < n; i++ {
+		req, err := http.NewRequestWithContext(httptrace.WithClientTrace(context.Background(), trace), http.MethodGet, url, nil)
+		if err != nil {
+			panic(err)
+		}
+		resp, err := client.Do(req)
+		if err != nil {
+			fmt.Printf("  request %d failed: %v\n", i, err)
+			// This is where `leak` eventually dies with "socket: too many open files".
+			break
+		}
+
+		switch m {
+		case modeDrain:
+			io.Copy(io.Discard, resp.Body)
+			resp.Body.Close()
+		case modeClose:
+			resp.Body.Close()
+		case modeLeak:
+			// nothing — the body, the conn, its fd and its 2 goroutines are now orphaned
+		}
+	}
+
+	elapsed := time.Since(start)
+	// Give the transport a moment to settle bookkeeping (put conn back to idle etc.).
+	time.Sleep(50 * time.Millisecond)
+	goroutinesAfter := runtime.NumGoroutine()
+
+	fmt.Printf("  requests           : %d in %v\n", n, elapsed.Round(time.Millisecond))
+	fmt.Printf("  httptrace GotConn  : reused=%d fresh=%d\n", reused, fresh)
+	fmt.Printf("  goroutines         : before=%d after=%d (delta %+d)\n",
+		goroutinesBefore, goroutinesAfter, goroutinesAfter-goroutinesBefore)
+
+	// Closing idle conns cleans up whatever the transport still *knows* about.
+	// Leaked bodies are not idle, so they survive this — that's the point.
+	tr.CloseIdleConnections()
+	time.Sleep(50 * time.Millisecond)
+	fmt.Printf("  after CloseIdleConnections: goroutines=%d\n", runtime.NumGoroutine())
+}
+
+func main() {
+	modeFlag := flag.String("mode", "all", "drain | close | leak | all")
+	n := flag.Int("n", 20, "number of requests per mode")
+	flag.Parse()
+
+	modes := []mode{modeDrain, modeClose, modeLeak}
+	if *modeFlag != "all" {
+		modes = []mode{mode(*modeFlag)}
+	}
+
+	for _, m := range modes {
+		srv := newCountingServer()
+		fmt.Printf("== mode=%s ==\n", m)
+		run(m, *n, srv.URL)
+		time.Sleep(50 * time.Millisecond)
+		fmt.Printf("  server new conns   : %d (ideal: 1)\n", srv.newConns.Load())
+		fmt.Printf("  server active conns: %d (ideal after cleanup: 0)\n", srv.activeConns.Load())
+		fmt.Println()
+		// In leak mode the server's handlers are STILL BLOCKED in Write(): the
+		// kernel socket buffers filled up because nobody on the client side is
+		// reading the 1 MiB body. srv.Close() waits for active conns and would
+		// hang forever (it logs "blocked in Close after 5 seconds" and lists
+		// them). That's the server-side symptom of a client leak: goroutines
+		// and memory pinned per stuck connection. Force-close them first.
+		srv.CloseClientConnections()
+		srv.Close()
+	}
+
+	if len(modes) == 1 && modes[0] == modeLeak {
+		fmt.Fprintln(os.Stderr, "tip: rerun with `ulimit -n 64` and -n 200 to watch it hit 'too many open files'")
+	}
+}