From 9df64837ddcbeafe525f12f95cc99f6080d3c6d1 Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Fri, 28 Aug 2026 23:49:04 +0200 Subject: [PATCH] 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 Claude-Session: https://claude.ai/code/session_01GbnJj9ZqEx9nUvzkjdwfMq --- 99-experiments/body-drain/README.md | 110 +++++++++++++++++ 99-experiments/body-drain/main.go | 176 ++++++++++++++++++++++++++++ 2 files changed, 286 insertions(+) create mode 100644 99-experiments/body-drain/README.md create mode 100644 99-experiments/body-drain/main.go diff --git a/99-experiments/body-drain/README.md b/99-experiments/body-drain/README.md new file mode 100644 index 0000000..d3f4c69 --- /dev/null +++ b/99-experiments/body-drain/README.md @@ -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. \ No newline at end of file diff --git a/99-experiments/body-drain/main.go b/99-experiments/body-drain/main.go new file mode 100644 index 0000000..bd5eb22 --- /dev/null +++ b/99-experiments/body-drain/main.go @@ -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'") + } +} \ No newline at end of file