From 57349285b41f01f36352f76bb695dc66d97f1288 Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Fri, 28 Aug 2026 23:54:59 +0200 Subject: [PATCH] body-drain: add -role server|client|both and -header-timeout Lets each side run out of fds in its own process; document ulimit -Hn (Go raises soft limit to hard) and Linux hang vs macOS RST difference. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01GbnJj9ZqEx9nUvzkjdwfMq --- 99-experiments/body-drain/README.md | 39 ++++- 99-experiments/body-drain/main.go | 214 +++++++++++++++++++++------- 2 files changed, 197 insertions(+), 56 deletions(-) diff --git a/99-experiments/body-drain/README.md b/99-experiments/body-drain/README.md index d3f4c69..68e2e20 100644 --- a/99-experiments/body-drain/README.md +++ b/99-experiments/body-drain/README.md @@ -6,9 +6,46 @@ 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 ``` +## Two processes: watch each side run out of fds on its own + +In one process the client and server share one fd limit and each leaked +request costs *two* fds (client socket + accepted server socket). The server +usually loses first — `accept` fails with `too many open files`, its accept +loop retries with backoff forever, and the client silently hangs waiting for +headers on a connection nobody will ever accept. Realistic, but confusing. So +split them: + +``` +# terminal 1 +go run ./99-experiments/body-drain -role server + +# terminal 2 — client is the one out of fds +ulimit -Hn 64; ulimit -Sn 64 +go run ./99-experiments/body-drain -role client -mode leak -n 200 +# request 60 failed: dial tcp 127.0.0.1:8099: socket: too many open files +``` + +Now swap: limit the *server* terminal instead. It logs +`http: Accept error: accept tcp ...: too many open files; retrying in 5ms`, +while the client (unlimited) either hangs (Linux — pass `-header-timeout 3s` +to turn that into `timeout awaiting response headers`) or gets +`read: connection reset by peer` (macOS). + +Which error string you see tells you which side is exhausted: + +| error | who ran out | +|---|---| +| `dial tcp ...: socket: too many open files` | the client (this process) | +| `http: Accept error: accept ...: too many open files` | the server | +| `timeout awaiting response headers` / `connection reset by peer` | the client is fine; the *server* can't accept | + +Note on `ulimit`: since Go 1.19 the runtime raises the soft `RLIMIT_NOFILE` +to the hard limit at startup, so lowering only the soft limit does nothing. +bash's plain `ulimit -n 64` sets both; zsh's sets only the soft one, hence +the explicit `-Hn`. + ## What it does A local `httptest.Server` returns a 1 MiB body and counts accepted TCP diff --git a/99-experiments/body-drain/main.go b/99-experiments/body-drain/main.go index bd5eb22..faba84f 100644 --- a/99-experiments/body-drain/main.go +++ b/99-experiments/body-drain/main.go @@ -1,6 +1,6 @@ // 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 +// A 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: // @@ -15,25 +15,46 @@ // 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) +// Roles (so you can watch each side fail on its own, with its own fd limit): // -// 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 +// both — server + client in one process (default) +// server — only serve on -addr, print connection stats every second, Ctrl-C to stop +// client — only run the client against -url +// +// Run in one process: +// +// go run ./99-experiments/body-drain -mode all +// +// Run as two processes (two terminals): +// +// go run ./99-experiments/body-drain -role server +// ulimit -Hn 64; ulimit -Sn 64; go run ./99-experiments/body-drain -role client -mode leak -n 200 +// +// (Lower the HARD limit too: since Go 1.19 the runtime raises the soft +// RLIMIT_NOFILE to the hard limit at startup. bash's `ulimit -n 64` sets both; +// zsh's sets only the soft one.) +// +// With the client alone at 64 fds you'll see the CLIENT die: +// +// dial tcp 127.0.0.1:8099: socket: too many open files +// +// With the limit on the SERVER terminal instead, the SERVER logs +// "accept: too many open files" and the client either hangs waiting for +// headers (Linux — use -header-timeout 3s) or gets "connection reset by +// peer" (macOS). package main import ( "context" + "errors" "flag" "fmt" "io" "net" "net/http" - "net/http/httptest" "net/http/httptrace" "os" + "os/signal" "runtime" "sync/atomic" "time" @@ -49,40 +70,95 @@ const ( modeLeak mode = "leak" ) -// countingServer wraps httptest.Server and counts accepted connections. +// ---- server ---- + +// countingServer is an http.Server that counts accepted connections. type countingServer struct { - *httptest.Server + srv *http.Server + ln net.Listener 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) - } +func (s *countingServer) URL() string { return "http://" + s.ln.Addr().String() } + +// newCountingServer listens on addr ("127.0.0.1:0" = random port) and starts serving. +func newCountingServer(addr string) (*countingServer, error) { + ln, err := net.Listen("tcp", addr) + if err != nil { + return nil, err } - s.Start() - return s + payload := make([]byte, bodySize) + s := &countingServer{ln: ln} + s.srv = &http.Server{ + Handler: 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. + 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) + } + }, + } + go s.srv.Serve(ln) + return s, nil } -// run performs n GETs in the given mode and reports what it observed. -func run(m mode, n int, url string) { +// close force-closes everything. In leak mode the handlers are STILL BLOCKED +// in Write(): the kernel socket buffers filled up because nobody on the +// client side is reading the 1 MiB body. A graceful Shutdown would wait for +// them forever — that's the server-side symptom of a client leak: goroutines +// and memory pinned per stuck connection. So we use Close(), not Shutdown(). +func (s *countingServer) close() { s.srv.Close() } + +func (s *countingServer) report() { + fmt.Printf(" server new conns : %d (ideal: 1)\n", s.newConns.Load()) + fmt.Printf(" server active conns: %d (ideal after cleanup: 0)\n", s.activeConns.Load()) +} + +// serveForever runs the server role: serve until Ctrl-C, printing stats each second. +func serveForever(addr string) { + s, err := newCountingServer(addr) + if err != nil { + fmt.Fprintln(os.Stderr, "listen:", err) + os.Exit(1) + } + fmt.Printf("serving on %s (point the client at it with -url %s)\n", s.URL(), s.URL()) + + ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt) + defer stop() + tick := time.NewTicker(time.Second) + defer tick.Stop() + for { + select { + case <-ctx.Done(): + fmt.Println("\nshutting down") + s.close() + return + case <-tick.C: + fmt.Printf("%s new=%d active=%d goroutines=%d\n", + time.Now().Format("15:04:05"), s.newConns.Load(), s.activeConns.Load(), runtime.NumGoroutine()) + } + } +} + +// ---- client ---- + +// runClient performs n GETs in the given mode and reports what it observed. +func runClient(m mode, n int, url string, headerTimeout time.Duration) { // Fresh transport per run so runs don't share a pool. Cloning keeps sane defaults. tr := http.DefaultTransport.(*http.Transport).Clone() tr.MaxIdleConnsPerHost = 10 + // Without this, a request whose connection the server can't accept (server + // out of fds) blocks forever waiting for headers. + tr.ResponseHeaderTimeout = headerTimeout // 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). @@ -102,6 +178,7 @@ func run(m mode, n int, url string) { goroutinesBefore := runtime.NumGoroutine() start := time.Now() + done := 0 for i := 0; i < n; i++ { req, err := http.NewRequestWithContext(httptrace.WithClientTrace(context.Background(), trace), http.MethodGet, url, nil) if err != nil { @@ -109,10 +186,18 @@ func run(m mode, n int, url string) { } resp, err := client.Do(req) if err != nil { + // This is where `leak` eventually dies. Which error you get tells + // you which side ran out of fds: + // dial tcp ...: socket: too many open files → THIS process (client) + // timeout awaiting response headers → the server can't accept (it's out of fds) fmt.Printf(" request %d failed: %v\n", i, err) - // This is where `leak` eventually dies with "socket: too many open files". + var ne net.Error + if errors.As(err, &ne) && ne.Timeout() { + fmt.Println(" (timeout: the server probably can't accept — check its log for 'accept4: too many open files')") + } break } + done++ switch m { case modeDrain: @@ -130,7 +215,7 @@ func run(m mode, n int, url string) { time.Sleep(50 * time.Millisecond) goroutinesAfter := runtime.NumGoroutine() - fmt.Printf(" requests : %d in %v\n", n, elapsed.Round(time.Millisecond)) + fmt.Printf(" requests : %d/%d ok in %v\n", done, 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) @@ -143,8 +228,12 @@ func run(m mode, n int, url string) { } func main() { - modeFlag := flag.String("mode", "all", "drain | close | leak | all") - n := flag.Int("n", 20, "number of requests per mode") + role := flag.String("role", "both", "both | server | client") + addr := flag.String("addr", "127.0.0.1:8099", "server: address to listen on") + url := flag.String("url", "http://127.0.0.1:8099", "client: server URL to hit") + modeFlag := flag.String("mode", "all", "client: drain | close | leak | all") + n := flag.Int("n", 20, "client: number of requests per mode") + headerTimeout := flag.Duration("header-timeout", 0, "client: ResponseHeaderTimeout (0 = none; try 3s when the server is the one out of fds)") flag.Parse() modes := []mode{modeDrain, modeClose, modeLeak} @@ -152,25 +241,40 @@ func main() { 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() - } + switch *role { + case "server": + serveForever(*addr) - 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'") + case "client": + for _, m := range modes { + fmt.Printf("== mode=%s (client only, target %s) ==\n", m, *url) + runClient(m, *n, *url, *headerTimeout) + fmt.Println() + } + if len(modes) == 1 && modes[0] == modeLeak { + fmt.Fprintln(os.Stderr, "tip: rerun with `ulimit -n 64` and -n 200 to watch the client hit 'too many open files'") + } + + case "both": + for _, m := range modes { + srv, err := newCountingServer("127.0.0.1:0") + if err != nil { + fmt.Fprintln(os.Stderr, "listen:", err) + os.Exit(1) + } + fmt.Printf("== mode=%s ==\n", m) + runClient(m, *n, srv.URL(), *headerTimeout) + time.Sleep(50 * time.Millisecond) + srv.report() + fmt.Println() + srv.close() + } + if len(modes) == 1 && modes[0] == modeLeak { + fmt.Fprintln(os.Stderr, "tip: in one process both sides share the fd limit and the SERVER usually hits it first (accept4 error) while the client hangs. Use -role server / -role client in two terminals to see each side fail alone.") + } + + default: + fmt.Fprintf(os.Stderr, "unknown -role %q\n", *role) + os.Exit(2) } -} \ No newline at end of file +}