diff --git a/internal/transport/http/middleware/logger.go b/internal/transport/http/middleware/logger.go new file mode 100644 index 0000000..dac3362 --- /dev/null +++ b/internal/transport/http/middleware/logger.go @@ -0,0 +1,51 @@ +package middleware + +import ( + "log/slog" + "net/http" + "time" +) + +// statusRecorder wraps http.ResponseWriter to capture the response status +// code so the Logger middleware can include it in the structured log line. +// +// The default status is initialised to http.StatusOK because net/http +// implicitly emits a 200 when a handler writes a body without calling +// WriteHeader explicitly; mirroring that behaviour keeps logs accurate. +type statusRecorder struct { + http.ResponseWriter + status int +} + +// WriteHeader records the status code before delegating to the wrapped +// ResponseWriter so the original response semantics are preserved. +func (s *statusRecorder) WriteHeader(code int) { + s.status = code + s.ResponseWriter.WriteHeader(code) +} + +// Logger returns HTTP middleware that emits a single structured log line +// per request once the downstream handler has finished. The line includes +// method, path, response status, elapsed duration in milliseconds, and the +// request ID (if RequestID middleware is mounted upstream). +// +// The middleware is intentionally placed *inside* RequestID so the +// generated identifier is available via context; placing it outside would +// log an empty request_id. +func Logger(log *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() + rec := &statusRecorder{ResponseWriter: w, status: http.StatusOK} + next.ServeHTTP(rec, r) + ctx := r.Context() + log.LogAttrs(ctx, slog.LevelInfo, "http", + slog.String("method", r.Method), + slog.String("path", r.URL.Path), + slog.Int("status", rec.status), + slog.Int64("duration_ms", time.Since(start).Milliseconds()), + slog.String("request_id", RequestIDFromContext(ctx)), + ) + }) + } +} diff --git a/internal/transport/http/middleware/logger_test.go b/internal/transport/http/middleware/logger_test.go new file mode 100644 index 0000000..4770bc9 --- /dev/null +++ b/internal/transport/http/middleware/logger_test.go @@ -0,0 +1,48 @@ +package middleware + +import ( + "bytes" + "encoding/json" + "log/slog" + "net/http" + "net/http/httptest" + "testing" + + "github.com/stretchr/testify/require" +) + +func TestLogger_LogsRequest(t *testing.T) { + var buf bytes.Buffer + log := slog.New(slog.NewJSONHandler(&buf, nil)) + + chain := RequestID(Logger(log)(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusNoContent) + }))) + + rec := httptest.NewRecorder() + chain.ServeHTTP(rec, httptest.NewRequest("GET", "/x", nil)) + + var line map[string]any + require.NoError(t, json.Unmarshal(buf.Bytes(), &line)) + require.Equal(t, "http", line["msg"]) + require.Equal(t, "/x", line["path"]) + require.Equal(t, "GET", line["method"]) + require.EqualValues(t, http.StatusNoContent, line["status"]) + require.NotEmpty(t, line["request_id"]) +} + +func TestLogger_DefaultStatus200(t *testing.T) { + var buf bytes.Buffer + log := slog.New(slog.NewJSONHandler(&buf, nil)) + + h := Logger(log)(http.HandlerFunc(func(_ http.ResponseWriter, _ *http.Request) { + // Handler writes nothing — status should default to 200. + })) + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest("GET", "/y", nil)) + + var line map[string]any + require.NoError(t, json.Unmarshal(buf.Bytes(), &line)) + require.EqualValues(t, http.StatusOK, line["status"]) +}