Request Logging and Correlation IDs
Log one line per HTTP request with middleware, and carry an id that ties that request to every service it touches.
func logging(next http.Handler) http.HandlerOne log line per request, written after the request finishes, is the single most useful thing a web service produces. It records what was asked, what was answered, and how long it took. The place to write it is middleware: a function that wraps a handler, does work before and after, and returns a handler of the same shape.
Capturing the status
The status code is written by the inner handler, and http.ResponseWriter offers no way to read it back. So the middleware passes a small wrapper struct that embeds the real ResponseWriter and overrides WriteHeader to remember the code. Start the remembered value at 200, because a handler that only calls Write never calls WriteHeader and still returns 200.
Correlation IDs
One click may touch an API, a worker and a database. A correlation id is a short random string created at the first service to see the request and passed to every other one, so a single search retrieves the whole story. Read it from the X-Request-Id header; if it is absent, generate one with rand.Text() from crypto/rand, added in Go 1.24. Put it in the request's context so handlers can log it, echo it in the response header so a client can quote it in a bug report, and set the same header on every outbound call.
What trips people up
Logging in several layers. One line per request, with fields, beats four lines that each know part of it.
Example
package main
import (
"log/slog"
"net/http"
"net/http/httptest"
"os"
)
// statusWriter remembers the code the handler wrote, which the middleware
// needs after the handler has already returned.
type statusWriter struct {
http.ResponseWriter
status int
}
func (w *statusWriter) WriteHeader(code int) {
w.status = code
w.ResponseWriter.WriteHeader(code)
}
func logging(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
id := r.Header.Get("X-Request-Id") // "" when the header is absent
if id == "" {
id = "local-1" // real code: rand.Text() from crypto/rand
}
w.Header().Set("X-Request-Id", id) // let the caller see it too
// 200 is the status a handler gets if it never calls WriteHeader.
sw := &statusWriter{ResponseWriter: w, status: http.StatusOK}
next.ServeHTTP(sw, r)
slog.Info("request", "method", r.Method, "path", r.URL.Path,
"status", sw.status, "request_id", id)
})
}
func main() {
// Drop the time field so the printed line is identical on every run.
drop := func(groups []string, a slog.Attr) slog.Attr {
if a.Key == slog.TimeKey {
return slog.Attr{}
}
return a
}
slog.SetDefault(slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{ReplaceAttr: drop})))
h := logging(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
w.WriteHeader(http.StatusCreated)
}))
// Stand in for a real request: curl -X POST -H 'X-Request-Id: abc123' /orders
req := httptest.NewRequest(http.MethodPost, "/orders", nil)
req.Header.Set("X-Request-Id", "abc123")
h.ServeHTTP(httptest.NewRecorder(), req)
}
// Output:
// level=INFO msg=request method=POST path=/orders status=201 request_id=abc123
When to use it
- Answer "what happened to the request that failed at 14:02" with one search instead of reading four services' logs side by side.
- Return the request id in a response header so support can paste it into a ticket.
- Find the slowest endpoint by percentile from the duration field rather than by guesswork.
More examples
Putting the id in the context so handlers can use it
Without this, only the middleware knows the id, and the deep error that actually explains a failure cannot be linked to the request line. The key is an unexported empty struct rather than a string so that two packages using the name "request_id" cannot overwrite each other. A typed getter keeps the assertion in one place.
// An unexported struct type as the key means no other package can collide
// with it, and nobody can read the value without going through RequestID.
type requestIDKey struct{}
func withRequestID(ctx context.Context, id string) context.Context {
return context.WithValue(ctx, requestIDKey{}, id)
}
// RequestID returns the id for this request, or "" outside a request.
func RequestID(ctx context.Context) string {
id, _ := ctx.Value(requestIDKey{}).(string) // "" if absent or wrong type
return id
}
// Inside the middleware, replace the request with one carrying the id:
// next.ServeHTTP(sw, r.WithContext(withRequestID(r.Context(), id)))
func handler(w http.ResponseWriter, r *http.Request) {
slog.ErrorContext(r.Context(), "could not reserve stock",
"request_id", RequestID(r.Context()), "sku", "A-11")
}Passing the id to the next service
The stock service reads X-Request-Id in its own logging middleware, finds it set, and reuses it instead of generating a new one. Searching one id in the aggregator now returns both services' lines in order. Do this once in a shared http.RoundTripper rather than in every call site, so no outbound request can forget.
// A correlation id is only worth having if it survives a network hop.
func fetchStock(ctx context.Context, client *http.Client, sku string) (int, error) {
req, err := http.NewRequestWithContext(ctx, http.MethodGet,
"http://stock.internal/levels/"+sku, nil)
if err != nil {
return 0, err
}
if id := RequestID(ctx); id != "" {
req.Header.Set("X-Request-Id", id) // the other service logs the same id
}
resp, err := client.Do(req)
if err != nil {
return 0, fmt.Errorf("stock service: %w", err)
}
defer resp.Body.Close()
// ... decode the body
return 0, nil
}Timing, and the size of the response
Duration as a number in its own field is what lets the aggregator compute a 99th percentile per path; a duration glued into the message text cannot be summed or sorted. Record it as milliseconds or as nanoseconds consistently across services, and never mix the two under one field name.
// bytes written and elapsed time are the two fields you miss first when
// diagnosing a slow endpoint.
func (w *statusWriter) Write(b []byte) (int, error) {
n, err := w.ResponseWriter.Write(b)
w.bytes += n
return n, err
}
// In the middleware:
start := time.Now()
next.ServeHTTP(sw, r)
slog.InfoContext(r.Context(), "request",
"method", r.Method,
"path", r.URL.Path,
"status", sw.status,
"bytes", sw.bytes,
"duration_ms", time.Since(start).Milliseconds(),
"request_id", RequestID(r.Context()),
)
Discussion