One Request, All the Way Down

One request, from the byte arriving on the socket to the last log line, through the machinery pages 07 and 08 assembled. Following it end to end shows which layer owns what, and it shows the deadline the request carries and how that gets spent.

The trace

POST /items HTTP/1.1
Host: api.example.com
Content-Type: application/json
X-Request-ID: abc123

{"name":"seed-bolt","quantity":17}

1. The server accepts

http.Server reads the request line and headers, builds an *http.Request, and creates the request context from the server’s base context, which the reference implementation constructs like this:

// Request contexts inherit the values of the application context but not
// its cancelation: canceling the application context triggers a graceful
// shutdown, and in-flight requests must be allowed to complete within the
// shutdown grace period instead of being canceled immediately.
baseCtx := context.WithoutCancel(ctx)

Without WithoutCancel, cancelling the application context on SIGTERM would cancel every in-flight request instantly. Graceful shutdown would drain nothing, because every request it was draining would abort the moment the drain started.

So the request context is cancelled by the client disconnecting, by the request timeout, or by the handler returning. It is not cancelled by shutdown. Values set on the application context, the way a request reaches things wired at startup, still pass through.

ReadHeaderTimeout bounds this step. A client that opens a connection and sends headers slowly is disconnected after a minute rather than holding a goroutine indefinitely.

2. The body cap

http.MaxBytesHandler, outermost, from page 08. A request whose body exceeds the limit is refused with 413 and the connection is closed, before the logger has buffered anything.

3. Trace ID and the per-request logger

reqID := traceid.FromHTTPRequestHeader(r, traceIDHeaderName, "")
if reqID == "" {
	reqID = rnd.UUIDv7().String()
}

ctx := r.Context()
ctx = libhttputil.WithRequestTime(ctx, reqTime)
ctx = traceid.NewContext(ctx, reqID)

abc123 came in the header, it passes validation, and it is used. A request with no valid trace ID gets a fresh UUIDv7, which sorts by creation time, so trace IDs generated by this service are roughly ordered by when they were issued.

The context gains the trace ID, so every log record in this request carries it, and the request time, so the response can report its own duration without the handler measuring anything.

Then a logger is derived for this request:

reqLogger := logger.With(
	slog.String(traceid.DefaultLogKey, reqID),
	slog.Time("request_time", reqTime),
	slog.String("request_method", r.Method),
	slog.String("request_path", r.URL.Path),
	slog.String("request_query", redactFn([]byte(r.URL.RawQuery))),
	slog.String("request_remote_address", r.RemoteAddr),
	slog.String("request_uri", redactRequestURI(r.RequestURI, redactFn)),
	slog.String("request_user_agent", r.UserAgent()),
	slog.String("request_x_forwarded_for", r.Header.Get("X-Forwarded-For")),
)

The query string is redacted, because ?api_key=... is a real pattern and it would otherwise be logged verbatim. request_uri is redacted from the ? onward, keeping the path readable.

The source comment says why:

// Derive a per-request logger from the shared one. The captured logger
// must never be reassigned, otherwise concurrent requests would race on
// it and cross-attribute log fields.

logger is the shared one, captured once when the middleware was built. reqLogger is a new value per request. Assigning back to logger would mean two concurrent requests writing to the same variable, and the visible symptom is one request’s trace ID appearing on another’s log lines. Page 02’s rule about shared state, in the place it is easiest to break.

4. The timeout starts

http.TimeoutHandler with the configured request timeout, 60 seconds by default. This is where the budget begins, and the rest of this page is about it.

5. Instrumentation

return m.InstrumentHandler(args.Path, next.ServeHTTP)

Starts a timer, and on the way out records the duration and the status against the route pattern. Wrapping the handler rather than the router, for the cardinality reason from page 08.

6. Routing

httprouter matches POST /items. No match is a 404 through the not-found handler, a wrong method is a 405 through the method-not-allowed handler, and both carry the same middleware chain, so both produce a log line and a metric.

7. The handler

func (h *HTTPHandlerPublic) handleGenUID(w http.ResponseWriter, r *http.Request) {
	h.httpres.SendJSON(r.Context(), w, http.StatusOK, h.rnd.UUIDv7().String())
}

The shipped example is one line, and the shape is visible in it: take the context from the request, do the work, hand the result to the response writer. Page 15 puts a real body in it.

8. The response

SendJSON does three things in an order that matters, in the writeJSON helper it shares with SendJSONType and SendProblem:

body, err := json.Marshal(data)
if err != nil {
	hr.logger.With(slog.Any("error", err)).ErrorContext(ctx, logName)
	hr.SendStatus(ctx, w, http.StatusInternalServerError)

	return
}

defer hr.logResponse(ctx, statusCode, logKeyResponseDataObject, data)

writeHeaders(w, statusCode, contentType)

_, err = w.Write(append(body, '\n'))

Marshal fully into memory. Only then write the status and headers. Then write the bytes. contentType is what separates the three callers, logName names the one that failed in the log entry.

That is the answer to the problem from page 02, where the status cannot be taken back once the first byte is out. json.NewEncoder(w).Encode(v) streams, so a value that fails to marshal halfway through has already sent a 200 and a partial body. Buffering first means a marshal failure produces a clean 500 with a complete body.

The cost is memory proportional to the response: the right trade for a JSON API and the wrong one for a large export. An endpoint streaming a hundred megabytes should encode straight to the writer and accept that it cannot change its mind.

writeHeaders also sets the headers nobody remembers to set:

h.Del("Content-Length")
h.Set("Cache-Control", "no-cache, no-store, must-revalidate")
h.Set("Pragma", "no-cache")
h.Set("Expires", "0")
h.Set("X-Content-Type-Options", "nosniff")
h.Set(HeaderContentType, contentType)
w.WriteHeader(statusCode)

X-Content-Type-Options: nosniff stops a browser guessing at the content type, the defence against a JSON response containing attacker-controlled text being interpreted as HTML. The Content-Length deletion is a smaller trap: a caller who set it before delegating almost certainly set a value that does not match this body, and net/http responds to that mismatch by truncating the response.

The no-cache set is a default, and page 16 replaces it for read endpoints that should be cached, because caching an item list for thirty seconds is often correct.

9. Two log lines

logResponse writes one:

attrs := []slog.Attr{
	slog.Int("response_code", statusCode),
	slog.String("response_message", StatusText(statusCode)),
	slog.Any("response_status", Status(statusCode)),
	slog.Time("response_time", resTime),
	slog.Duration("response_duration", resTime.Sub(reqTime)),
	slog.Any(dataKey, data),
}

response_duration comes from the request time put into the context in step 3, so the handler measures nothing. StatusText is httputil’s own, and falls back to the RFC 9110 status class name where http.StatusText returns an empty string, so a non-standard code such as 499 logs Client Error rather than nothing.

The level follows the status: 5xx at error, 4xx at warning, everything else at debug. Combined with the per-level metric counter from page 06, a spike in 5xx responses is a metric before it is a log query.

There is a cost. At 4xx and 5xx the response payload is logged in full, at a level that is on in production, so an endpoint that echoes user input in its error messages puts that input in the logs. That is one more reason for page 15’s rule that a validation error names the offending field without repeating what the client sent.

The guard above it is worth copying:

if !hr.logger.Enabled(ctx, level) {
	return
}

Timestamps, durations, a trace ID lookup and a payload reference are all built only if the record will actually be emitted. On the 2xx-at-info path, almost every request, that work is skipped entirely.

Then the middleware writes the second line, on the way out, with response_code and response_size taken from the wrapped writer. Two records per request, both carrying the same trace ID, one describing what arrived and one describing what left.

The response writer wrapper

To record the status, the logging middleware substitutes its own writer:

rw := libhttputil.NewResponseWriterWrapper(w)

next.ServeHTTP(rw, r.WithContext(ctx))

status := rw.Status()
if status == 0 {
	// The handler never called WriteHeader: net/http sends an implicit 200.
	status = http.StatusOK
}

Page 02 noted the danger in wrapping a ResponseWriter: a naive wrapper satisfies only http.ResponseWriter and silently discards every optional interface the original implemented. This one forwards http.Flusher, http.Hijacker, http.Pusher, io.ReaderFrom and http.ResponseController through Unwrap.

io.ReaderFrom is the one with a measurable cost. Without it, io.Copy to the response writer loses the kernel-level sendfile path and copies through userspace buffers.

http.CloseNotifier is deliberately not forwarded. It is deprecated, and r.Context() is the replacement.

The timeout budget

This thread runs through the next three pages. The 60-second request timeout is a budget rather than a property of the server alone, and the handler spends it.

Take a create that does three things: a lookup, a check against an upstream catalogue, and the insert. Give each its own independent 30-second timeout, a normal-looking configuration.

Worst case, the handler works for 90 seconds. TimeoutHandler gave up at 60 and already sent a 503, and the client either saw it or disconnected earlier. For the remaining 30 seconds the service holds a database connection and an upstream connection on behalf of nobody. Under load, that arithmetic fills a connection pool.

Deriving from what is left

Every call takes a context derived from the request’s, rather than one built from context.Background().

func (s *Service) Create(ctx context.Context, p CreateParams) (*Item, error) {
	// Inherits the request deadline. Shortens it, never extends it.
	qctx, cancel := context.WithTimeout(ctx, 2*time.Second)
	defer cancel()

	err := s.store.Create(qctx, it)
	if err != nil {
		return nil, fmt.Errorf("create item: %w", err)
	}
	// ...
}

context.WithTimeout fires on whichever deadline is nearer. If the request has 50 seconds left, this call gets 2. If it has 1 second left, this call gets 1. The budget shrinks as it goes down the stack and never grows.

Reading what is left, when you need to:

if deadline, ok := ctx.Deadline(); ok {
	remaining := time.Until(deadline)
	// ...
}

Useful for deciding whether to attempt a retry at all. Page 11 uses it: a retry that cannot finish before the budget expires should not be started.

Where the budget is spent

The sum of the parts should be comfortably under the whole, with room for the work between them. A client timeout longer than the request budget is a timeout that never fires, which means the configured value is decorative and the real behaviour is whatever TimeoutHandler does.

What ignoring it looks like

A handler that ignores the context finishes its work and writes to a ResponseWriter that TimeoutHandler already abandoned. The write goes nowhere. The database work happened, the row was inserted, the client got a 503 and will probably retry, and the retry either duplicates the row or collides with it.

Page 15’s section on idempotency keys exists because of exactly that sequence.

What survives shutdown

Shutdown starts. http.Server.Shutdown stops accepting new connections and waits for in-flight requests, and the request context is unaffected, per the WithoutCancel at the top of this page.

So a request in flight when SIGTERM arrives runs to completion, bounded by the server’s shutdown timeout from page 05. A request that arrives after shutdown began is refused at the connection level. A request still running when the shutdown timeout expires is cut off mid-flight, its connection closed, and whatever it had already written to the database stays written.

Size the timeouts against that last case. A shutdown timeout shorter than the request timeout means a normal deploy can cut off a request that was going to succeed.

Next: The Envelope Argument, on the shape of what step 8 wrote.