Add request logging middleware

README.md

@@ -26,6 +26,8 @@ variable.
 | GET    | `/{code}`  | Redirect to the original URL             |
 | GET    | `/healthz` | Health check                             |
 
+All requests are logged with their method, path, status code, and latency.
+
 Example:
 
 ```sh

internal/shortener/handler.go

@@ -24,7 +24,7 @@ func NewHandler(svc *Service) http.Handler {
 	mux.HandleFunc("GET /healthz", func(w http.ResponseWriter, _ *http.Request) {
 		w.WriteHeader(http.StatusOK)
 	})
-	return mux
+	return LoggingMiddleware(mux)
 }
 
 func handleShorten(svc *Service) http.HandlerFunc {

internal/shortener/middleware.go

@@ -0,0 +1,30 @@
+package shortener
+
+import (
+	"log"
+	"net/http"
+	"time"
+)
+
+// statusRecorder wraps http.ResponseWriter to capture the status code written
+// to the response.
+type statusRecorder struct {
+	http.ResponseWriter
+	status int
+}
+
+func (r *statusRecorder) WriteHeader(code int) {
+	r.status = code
+	r.ResponseWriter.WriteHeader(code)
+}
+
+// LoggingMiddleware logs the method, path, status code, and duration of each
+// request.
+func LoggingMiddleware(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)
+		log.Printf("%s %s %d %s", r.Method, r.URL.Path, rec.status, time.Since(start))
+	})
+}

internal/shortener/middleware_test.go

@@ -0,0 +1,45 @@
+package shortener
+
+import (
+	"net/http"
+	"net/http/httptest"
+	"testing"
+)
+
+func TestLoggingMiddlewarePassesThrough(t *testing.T) {
+	called := false
+	next := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
+		called = true
+		w.WriteHeader(http.StatusTeapot)
+		w.Write([]byte("ok"))
+	})
+
+	rec := httptest.NewRecorder()
+	req := httptest.NewRequest(http.MethodGet, "/anything", nil)
+
+	LoggingMiddleware(next).ServeHTTP(rec, req)
+
+	if !called {
+		t.Fatal("next handler was not called")
+	}
+	if rec.Code != http.StatusTeapot {
+		t.Errorf("status = %d, want %d", rec.Code, http.StatusTeapot)
+	}
+	if rec.Body.String() != "ok" {
+		t.Errorf("body = %q, want %q", rec.Body.String(), "ok")
+	}
+}
+
+func TestStatusRecorderCapturesCode(t *testing.T) {
+	rec := httptest.NewRecorder()
+	sr := &statusRecorder{ResponseWriter: rec, status: http.StatusOK}
+
+	sr.WriteHeader(http.StatusNotFound)
+
+	if sr.status != http.StatusNotFound {
+		t.Errorf("recorded status = %d, want %d", sr.status, http.StatusNotFound)
+	}
+	if rec.Code != http.StatusNotFound {
+		t.Errorf("underlying status = %d, want %d", rec.Code, http.StatusNotFound)
+	}
+}