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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01GbnJj9ZqEx9nUvzkjdwfMq
This commit is contained in:
@@ -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 all
|
||||||
go run ./99-experiments/body-drain -mode leak -n 200
|
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
|
## What it does
|
||||||
|
|
||||||
A local `httptest.Server` returns a 1 MiB body and counts accepted TCP
|
A local `httptest.Server` returns a 1 MiB body and counts accepted TCP
|
||||||
|
|||||||
@@ -1,6 +1,6 @@
|
|||||||
// Experiment — what happens when you don't drain/close an HTTP response body
|
// 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
|
// accepts. The client performs N sequential GETs against it in one of three
|
||||||
// modes and we observe:
|
// modes and we observe:
|
||||||
//
|
//
|
||||||
@@ -15,25 +15,46 @@
|
|||||||
// close — body.Close() only → connection thrown away, new dial every time
|
// close — body.Close() only → connection thrown away, new dial every time
|
||||||
// leak — neither → connection AND 2 goroutines AND 1 fd leaked per request
|
// leak — neither → connection AND 2 goroutines AND 1 fd leaked per request
|
||||||
//
|
//
|
||||||
// Run: go run ./99-experiments/body-drain -mode drain
|
// Roles (so you can watch each side fail on its own, with its own fd limit):
|
||||||
// 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:
|
// both — server + client in one process (default)
|
||||||
// ulimit -n 64 && go run ./99-experiments/body-drain -mode leak -n 200
|
// 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
|
package main
|
||||||
|
|
||||||
import (
|
import (
|
||||||
"context"
|
"context"
|
||||||
|
"errors"
|
||||||
"flag"
|
"flag"
|
||||||
"fmt"
|
"fmt"
|
||||||
"io"
|
"io"
|
||||||
"net"
|
"net"
|
||||||
"net/http"
|
"net/http"
|
||||||
"net/http/httptest"
|
|
||||||
"net/http/httptrace"
|
"net/http/httptrace"
|
||||||
"os"
|
"os"
|
||||||
|
"os/signal"
|
||||||
"runtime"
|
"runtime"
|
||||||
"sync/atomic"
|
"sync/atomic"
|
||||||
"time"
|
"time"
|
||||||
@@ -49,23 +70,34 @@ const (
|
|||||||
modeLeak mode = "leak"
|
modeLeak mode = "leak"
|
||||||
)
|
)
|
||||||
|
|
||||||
// countingServer wraps httptest.Server and counts accepted connections.
|
// ---- server ----
|
||||||
|
|
||||||
|
// countingServer is an http.Server that counts accepted connections.
|
||||||
type countingServer struct {
|
type countingServer struct {
|
||||||
*httptest.Server
|
srv *http.Server
|
||||||
|
ln net.Listener
|
||||||
newConns atomic.Int64
|
newConns atomic.Int64
|
||||||
activeConns atomic.Int64
|
activeConns atomic.Int64
|
||||||
}
|
}
|
||||||
|
|
||||||
func newCountingServer() *countingServer {
|
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
|
||||||
|
}
|
||||||
payload := make([]byte, bodySize)
|
payload := make([]byte, bodySize)
|
||||||
s := &countingServer{}
|
s := &countingServer{ln: ln}
|
||||||
s.Server = httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
s.srv = &http.Server{
|
||||||
|
Handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||||
w.Header().Set("Content-Length", fmt.Sprint(bodySize))
|
w.Header().Set("Content-Length", fmt.Sprint(bodySize))
|
||||||
w.WriteHeader(http.StatusOK)
|
w.WriteHeader(http.StatusOK)
|
||||||
w.Write(payload)
|
w.Write(payload)
|
||||||
}))
|
}),
|
||||||
// ConnState is the server-side hook that lets us see the connection lifecycle.
|
// ConnState is the server-side hook that lets us see the connection lifecycle.
|
||||||
s.Config.ConnState = func(c net.Conn, st http.ConnState) {
|
ConnState: func(c net.Conn, st http.ConnState) {
|
||||||
switch st {
|
switch st {
|
||||||
case http.StateNew:
|
case http.StateNew:
|
||||||
s.newConns.Add(1)
|
s.newConns.Add(1)
|
||||||
@@ -73,16 +105,60 @@ func newCountingServer() *countingServer {
|
|||||||
case http.StateClosed, http.StateHijacked:
|
case http.StateClosed, http.StateHijacked:
|
||||||
s.activeConns.Add(-1)
|
s.activeConns.Add(-1)
|
||||||
}
|
}
|
||||||
|
},
|
||||||
}
|
}
|
||||||
s.Start()
|
go s.srv.Serve(ln)
|
||||||
return s
|
return s, nil
|
||||||
}
|
}
|
||||||
|
|
||||||
// run performs n GETs in the given mode and reports what it observed.
|
// close force-closes everything. In leak mode the handlers are STILL BLOCKED
|
||||||
func run(m mode, n int, url string) {
|
// 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.
|
// Fresh transport per run so runs don't share a pool. Cloning keeps sane defaults.
|
||||||
tr := http.DefaultTransport.(*http.Transport).Clone()
|
tr := http.DefaultTransport.(*http.Transport).Clone()
|
||||||
tr.MaxIdleConnsPerHost = 10
|
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
|
// 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
|
// force-closed when the timer fires, which hides the leak (try adding one
|
||||||
// and watch the goroutine count drop after the timeout).
|
// and watch the goroutine count drop after the timeout).
|
||||||
@@ -102,6 +178,7 @@ func run(m mode, n int, url string) {
|
|||||||
goroutinesBefore := runtime.NumGoroutine()
|
goroutinesBefore := runtime.NumGoroutine()
|
||||||
start := time.Now()
|
start := time.Now()
|
||||||
|
|
||||||
|
done := 0
|
||||||
for i := 0; i < n; i++ {
|
for i := 0; i < n; i++ {
|
||||||
req, err := http.NewRequestWithContext(httptrace.WithClientTrace(context.Background(), trace), http.MethodGet, url, nil)
|
req, err := http.NewRequestWithContext(httptrace.WithClientTrace(context.Background(), trace), http.MethodGet, url, nil)
|
||||||
if err != nil {
|
if err != nil {
|
||||||
@@ -109,10 +186,18 @@ func run(m mode, n int, url string) {
|
|||||||
}
|
}
|
||||||
resp, err := client.Do(req)
|
resp, err := client.Do(req)
|
||||||
if err != nil {
|
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)
|
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
|
break
|
||||||
}
|
}
|
||||||
|
done++
|
||||||
|
|
||||||
switch m {
|
switch m {
|
||||||
case modeDrain:
|
case modeDrain:
|
||||||
@@ -130,7 +215,7 @@ func run(m mode, n int, url string) {
|
|||||||
time.Sleep(50 * time.Millisecond)
|
time.Sleep(50 * time.Millisecond)
|
||||||
goroutinesAfter := runtime.NumGoroutine()
|
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(" httptrace GotConn : reused=%d fresh=%d\n", reused, fresh)
|
||||||
fmt.Printf(" goroutines : before=%d after=%d (delta %+d)\n",
|
fmt.Printf(" goroutines : before=%d after=%d (delta %+d)\n",
|
||||||
goroutinesBefore, goroutinesAfter, goroutinesAfter-goroutinesBefore)
|
goroutinesBefore, goroutinesAfter, goroutinesAfter-goroutinesBefore)
|
||||||
@@ -143,8 +228,12 @@ func run(m mode, n int, url string) {
|
|||||||
}
|
}
|
||||||
|
|
||||||
func main() {
|
func main() {
|
||||||
modeFlag := flag.String("mode", "all", "drain | close | leak | all")
|
role := flag.String("role", "both", "both | server | client")
|
||||||
n := flag.Int("n", 20, "number of requests per mode")
|
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()
|
flag.Parse()
|
||||||
|
|
||||||
modes := []mode{modeDrain, modeClose, modeLeak}
|
modes := []mode{modeDrain, modeClose, modeLeak}
|
||||||
@@ -152,25 +241,40 @@ func main() {
|
|||||||
modes = []mode{mode(*modeFlag)}
|
modes = []mode{mode(*modeFlag)}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
switch *role {
|
||||||
|
case "server":
|
||||||
|
serveForever(*addr)
|
||||||
|
|
||||||
|
case "client":
|
||||||
for _, m := range modes {
|
for _, m := range modes {
|
||||||
srv := newCountingServer()
|
fmt.Printf("== mode=%s (client only, target %s) ==\n", m, *url)
|
||||||
fmt.Printf("== mode=%s ==\n", m)
|
runClient(m, *n, *url, *headerTimeout)
|
||||||
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()
|
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
|
if len(modes) == 1 && modes[0] == modeLeak {
|
||||||
// reading the 1 MiB body. srv.Close() waits for active conns and would
|
fmt.Fprintln(os.Stderr, "tip: rerun with `ulimit -n 64` and -n 200 to watch the client hit 'too many open files'")
|
||||||
// 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()
|
|
||||||
}
|
}
|
||||||
|
|
||||||
|
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 {
|
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'")
|
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)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
Reference in New Issue
Block a user