Middleware, Timeouts and Graceful Shutdown

You deploy at the wrong moment and the process exits with four requests mid-flight. Two clients get connection resets, one gets a truncated JSON body and parses it as a syntax error, and the fourth had already written a row to the database that nobody will hear about. The same deploy also turned up a second problem you had not noticed: a client that opens a connection and sends a request header one byte at a time can hold one of your goroutines for as long as it likes, because the default HTTP server has no timeouts.

Both of those are configuration and structure, not algorithm, and both are the kind of thing that stays broken for a year. What follows is the middleware shape that makes handlers composable, the timeout settings that actually cancel work, and a shutdown that finishes what it started.

Middleware is a function that takes a handler and returns one

There is no middleware interface in net/http. The pattern is a function type you write yourself:

type Middleware func(http.Handler) http.Handler

// Chain applies middleware so the first argument is the outermost layer.
func Chain(h http.Handler, mw ...Middleware) http.Handler {
	for i := len(mw) - 1; i >= 0; i-- {
		h = mw[i](h)
	}
	return h
}

The loop runs backwards so the call site reads in the order you think about it. Chain(mux, recoverPanic, requestID, requestLog) means a panic in any handler is caught, request ids exist, and every request is logged, with recoverPanic as the outermost layer. That last part is not cosmetic: a middleware that can panic must have another one outside it, or the panic reaches the server and the client sees a closed connection instead of a 500.

What each layer can see comes directly from where it sits. Everything before next.ServeHTTP runs on the way in, in outer-to-inner order; everything after runs on the way out, inner-to-outer. Run four layers around a small handler and the ordering is the whole lesson:

requestID: assigning req-56000
logging: -> GET /tea
handler: sees request id "req-56000"
logging: <- 418 in 10µs (id="req-56000")
requestID: req-56000 done
client got 418 "brewing\n"

Read the indentation off the arrows. The request id is assigned before logging starts because the id layer is outside, so the log line can include it. The status is known only after the handler returned, so the arrow-out line has it and the arrow-in line cannot. Any middleware that wants to add a response header has to set it before calling next, which is why the id appears in the response.

The status is hidden from the layer outside, so wrap the writer

A logging middleware that only has http.ResponseWriter cannot tell a 404 from a 200, because ResponseWriter has no method that reports the status. The fix is a struct that embeds the writer and remembers the code:

type statusRecorder struct {
	http.ResponseWriter
	status int
	wrote  bool
}

func (r *statusRecorder) WriteHeader(code int) {
	if !r.wrote {
		r.status, r.wrote = code, true
		r.ResponseWriter.WriteHeader(code)
	}
}

func (r *statusRecorder) Write(b []byte) (int, error) {
	if !r.wrote {
		r.status, r.wrote = http.StatusOK, true
	}
	return r.ResponseWriter.Write(b)
}

Embedding rather than storing the writer in a named field is the reason this is safe. Promoted methods still satisfy the interfaces, so Flush and Hijack reach the real writer underneath. A wrapper with a plain w http.ResponseWriter field hides both, and the handler that calls http.NewResponseController(w).Flush() then gets an error matching http.ErrNotSupported with no obvious cause.

Middleware cannot see what happens after it returns either. Once next.ServeHTTP is done and the panics are recovered, the response is on the wire, and a middleware that wants to change the status has already lost its chance. Anything that has to decide the outcome belongs inside the handler; the layer outside records it.

Only one of the timeout knobs cancels your handler

Four things in this stack can stop a slow request, and they do not do the same thing. Getting this wrong produces a service where requests "time out" and the work carries on anyway.

http.TimeoutHandler is itself a handler wrapper. Wire it around a mux and make two handlers, one that respects the context and one that sleeps through it:

srv := &http.Server{
	Addr:    "127.0.0.1:8082",
	Handler: http.TimeoutHandler(mux, 300*time.Millisecond, "upstream too slow\n"),
}

$ time curl -i http://127.0.0.1:8082/respectful
HTTP/1.1 503 Service Unavailable
Content-Length: 18

upstream too slow

real	0m0.315s

# server log
respectful: returned after 301ms with err=context deadline exceeded

The client got a 503 in 315 milliseconds and the handler returned at almost exactly the same moment, because the wrapper's context carried context.DeadlineExceeded into the handler and the select took it. The timeout is real work stopped, not a client hung up on.

Now the handler that waits out its sleep instead of selecting on the context:

$ curl -o /dev/null -w '%{http_code} after %{time_total}s\n' http://127.0.0.1:8082/stubborn
503 after 0.302s

# log immediately after the client returned
13:01:01 listening on 127.0.0.1:8082

# log two seconds later
13:01:03 stubborn: finished its work anyway (1 total)

Same 503 to the client, and the work ran to completion anyway, holding whatever connection or lock it had. TimeoutHandler can cancel a context but it cannot cancel a function. A handler that does not check ctx.Done() is not interruptible, and no amount of wrapping changes that.

Which to use comes down to who owns the response. TimeoutHandler owns it: on expiry it writes a 503 with your message and discards anything the handler wrote. A context deadline inside the handler leaves the response to the handler, which is what you want when the failure has a better status than 503. Using both is legitimate: a handler-level deadline for the fine-grained case, and a TimeoutHandler as the backstop that guarantees every response has a status.

The default server has no timeouts at all

http.Server with only Addr and Handler set has zero values for all four timeout fields, and zero means no limit. A client that connects, sends GET / HTTP/1.1\r\n and then one header byte every few seconds will hold a goroutine and a file descriptor for as long as it wants. Enough of those and the server is unavailable without a single request having completed.

header dribbled over 3s to a server with NO ReadHeaderTimeout (port 8086):
  server replied "HTTP/1.1 200 OK" after 3.008s
header dribbled over 3s to a server with ReadHeaderTimeout 500ms (port 8085):
  server replied "HTTP/1.1 400 Bad Request" after 501ms

The first server accepted the request after the client finished dribbling, three seconds after it connected. The second cut the connection off at half a second with a 400, and the goroutine was free. That is ReadHeaderTimeout: 500 * time.Millisecond doing its only job, and it is the setting to add first because it is the one that costs nothing: a legitimate client has already sent its headers.

srv := &http.Server{
	Addr:              "127.0.0.1:8090",
	Handler:           routes(),
	ReadHeaderTimeout: 5 * time.Second,
	ReadTimeout:       15 * time.Second,
	WriteTimeout:      15 * time.Second,
	IdleTimeout:       60 * time.Second,
}

The other three are judgement calls and they interact. WriteTimeout starts when the request headers have been read, so it covers the handler's whole working time plus the response write; set it lower than your slowest legitimate handler and you will truncate responses that were about to succeed. IdleTimeout is how long a keep-alive connection may sit between requests, and leaving it at zero lets an idle client hold a connection forever, which is a smaller version of the same problem.

And the hint that WriteTimeout is a connection setting rather than a request setting is what a handler sees when it finishes after the deadline:

13:01:01 write: handler started
13:01:03 write: write succeeded
13:01:03 write: context error is <nil>

The handler ran for two seconds against a 300 millisecond WriteTimeout, its write reported no error, and its context was never cancelled. The client had received an empty reply before the handler finished. WriteTimeout is a connection setting that does not cancel the handler's context, so if you want the handler to stop, put a deadline on the context where the work happens.

Shutdown drains; Close does not

Server.Shutdown closes the listeners first and then waits for active connections to become idle. Because the listener closes immediately, new connections are refused while the requests already in progress finish normally. That difference is the whole point, and it is visible in one run: a request started before the signal, and a curl issued half a second after it.

13:01:03.524706 signal received: 1 request(s) in flight
13:01:03.524818 serve loop returned ErrServerClosed
13:01:05.957123 GET /slow -> 200 in 3.001s id=req-0003
13:01:06.203579 shutdown clean after 2.679s, 0 in flight

$ curl -m 2 http://127.0.0.1:8090/fast      # issued during the drain
curl: (7) Failed to connect to 127.0.0.1 port 8090 after 0 ms

$ curl -o /dev/null -w '%{http_code} in %{time_total}s\n' http://127.0.0.1:8090/slow
200 in 3.004190s                                # started before the signal

The in-flight request got its full 200, the new one could not connect, and the process exited zero 2.7 seconds after the signal. The wiring that produces this is short:

ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)
defer stop()
<-ctx.Done()
stop() // restore default handling so a second signal kills the process

shutdownCtx, cancel := context.WithTimeout(context.Background(), drain)
defer cancel()

if err := srv.Shutdown(shutdownCtx); err != nil {
	log.Printf("shutdown gave up: %v", err)
	os.Exit(1)
}

signal.NotifyContext gives you a context that is cancelled by the signal, which means the wait is a plain channel receive and reads like the rest of the module. Calling stop() straight after is deliberate: it unregisters the handler, so a second Ctrl-C terminates the process instead of being swallowed while you wait for a drain that is not going to finish.

The Shutdown context is the other half of the decision. A drain with no deadline waits forever, and a drain with a deadline that is too short cuts off exactly the requests you were trying to save:

$ DRAIN=1s ./bin/graceful
13:01:22.312237 signal received: shutting down with 1 request(s) in flight
13:01:22.312410 serve loop returned ErrServerClosed
13:01:23.313424 shutdown did not finish cleanly: context deadline exceeded

$ curl ... http://127.0.0.1:8083/slow
curl: (52) Empty reply from server

One second of drain against a three second handler is worse than no drain at all: the client gets an empty reply rather than a connection error, which some clients report as a parse failure. Pick the drain budget from the slowest thing you are willing to finish, and count the segments, because during a rolling deploy the drain is also how long the load balancer has to notice you are gone.

Two things Shutdown does not wait for. Hijacked connections, which includes WebSockets, are not tracked, and RegisterOnShutdown is the hook for telling those clients to go away. And a handler that never returns holds the drain until the deadline, which is why the context discipline above is what makes shutdown bounded.

The signal also propagates into requests. A client that disconnects mid-response cancels r.Context(), which is why the handler above stops within a millisecond of the client leaving:

13:01:01.085209 slow: start (in flight: 1)
13:01:01.890244 slow: gave up: context canceled
13:01:01.890300 GET /slow -> 499 in 805ms id=req-0002

curl -m 0.8 gave up, the handler stopped 805 milliseconds in rather than running its full three seconds, and the middleware logged it like any other request. The 499 is not a standard status code; it is the convention for a client that closed the request, and it makes the log distinguish "the client left" from "we were too slow".

func requestLog(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		start := time.Now()
		rec := &statusRecorder{ResponseWriter: w, status: http.StatusOK}
		next.ServeHTTP(rec, r)
		id, _ := r.Context().Value(requestIDKey).(string)
		log.Printf("%s %s -> %d in %v id=%s", r.Method, r.URL.Path,
			rec.status, time.Since(start).Round(time.Millisecond), id)
	})
}