This lesson's interactive features are locked, please to keep using them

Request Context

"I wish the ring had never come to me."
– Frodo Baggins

A powerful quote. But what if he said that when he first saw Gandalf in the Shire instead of, "You're late!"?

That would be confusing. What ring is he talking about? Gandalf would be missing context.

HTTP Requests

For HTTP servers, much of the context to log should be related to the specific HTTP request being served. Some good ideas include:

Number of bytes in the request body
Information about the authenticated user (if any)
Response code (200, 404, etc.)
Number of bytes in the response body
Response duration
Request User-Agent header
Request Content-Type header
Presence of relevant cookies in the request
Response Content-Type header

Don't run out and log everything in every app, but add fields as they become useful.

Logging Response Duration

Let's start with an easy one: response duration.

Record request start time, then subtract when the response finishes.

func requestLogger(logger *slog.Logger) func(http.Handler) http.Handler {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			start := time.Now()
			next.ServeHTTP(w, r)

			logger.Info("Served request",
				/* ... other fields ... */
				slog.Duration("duration", time.Since(start)),
			)
		})
	}
}

Logging Request Metadata

We can use a similar trick for request body size:

type spyReadCloser struct {
	io.ReadCloser
	bytesRead int
}

func (r *spyReadCloser) Read(p []byte) (int, error) {
	n, err := r.ReadCloser.Read(p)
	r.bytesRead += n
	return n, err
}

Replace the request body with our spy wrapper:

func requestLogger(logger *slog.Logger) func(http.Handler) http.Handler {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			spyReader := &spyReadCloser{ReadCloser: r.Body}
			r.Body = spyReader
			next.ServeHTTP(w, r)

			logger.Info("Served request",
				/* ... other fields ... */
				slog.Int("request_body_bytes", spyReader.bytesRead),
			)
		})
	}
}

Logging Response Metadata

The default http.ResponseWriter provided by the standard library doesn't let us inspect the HTTP status sent, the number of bytes sent, or much else, really. However, because it's an interface, it gives us all the flexibility we need to implement our own version that does. Let's consider a simple example:

type spyResponseWriter struct {
	http.ResponseWriter
	bytesWritten int
	statusCode   int
}

func (w *spyResponseWriter) Write(p []byte) (int, error) {
	if w.statusCode == 0 {
		w.statusCode = http.StatusOK
	}
	n, err := w.ResponseWriter.Write(p)
	w.bytesWritten += n
	return n, err
}

func (w *spyResponseWriter) WriteHeader(statusCode int) {
	w.statusCode = statusCode
	w.ResponseWriter.WriteHeader(statusCode)
}

This wrapper delegates to an existing http.ResponseWriter while tracking bytes written and status code. We can use it to enrich response logging:

func requestLogger(logger *slog.Logger) func(http.Handler) http.Handler {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			spyWriter := &spyResponseWriter{ResponseWriter: w}
			next.ServeHTTP(spyWriter, r)

			logger.Info("Served request",
				/* ... other fields ... */
				slog.Int("response_status", spyWriter.statusCode),
				slog.Int("response_body_bytes", spyWriter.bytesWritten),
			)
		})
	}
}

Assignment

Add request and response metadata to the "Served request" log entry.

Update your requestLogger middleware to include:

duration – the time elapsed between receiving the request and finishing the response, using time.Since.
request_body_bytes – the number of bytes read from the request body, using a spyReadCloser wrapper as shown above.
response_status – the HTTP status code sent to the client, using a spyResponseWriter wrapper as shown above.
response_body_bytes – the number of bytes written to the response body, also tracked by spyResponseWriter.

Rebuild your app with -ldflags, then run it with ENV and LINKO_LOG_FILE set:

go build \
  -ldflags "-X boot.dev/linko/internal/build.GitSHA=$(git rev-parse HEAD) -X boot.dev/linko/internal/build.BuildTime=$(date -u '+%Y-%m-%dT%H:%M:%SZ')" \
  -o linko &&
LINKO_LOG_FILE=linko.access.log ENV=development ./linko

Run and submit the CLI tests from the root of the Linko repo.