better request logging middleware

README.md

@@ -262,7 +262,21 @@ type Unmarshaler interface {
 }
 ```
 
+## Logging
+
+An "event" field in log lines will represent a "verb" in the context of the logging line. So: event describes the type 
+of occurrence in this log record, not a universal taxonomy across all services.
+
+| Layer             | Example event                                 | Meaning           |
+| ----------------- | --------------------------------------------- | ----------------- |
+| HTTP middleware   | `start`, `end`                                | Request lifecycle |
+| Database client   | `query`, `commit`, `rollback`, `pool_acquire` | DB operations     |
+| Background worker | `started`, `completed`, `failed`              | Job lifecycle     |
+| Cache layer       | `hit`, `miss`                                 | Cache result      |
+| Message queue     | `consume`, `ack`, `nack`                      | Queue actions     |
+
+
 ## Additional Resources
 
 - https://betterstack.com/community/guides/scaling-go/postgresql-pgx-golang/ 
-- https://betterstack.com/community/guides/scaling-go/golang-testify/
+- https://betterstack.com/community/guides/scaling-go/golang-testify/

cmd/api/middleware.go

@@ -1,8 +1,14 @@
 package main
 
 import (
+	"context"
 	"fmt"
+	"log/slog"
 	"net/http"
+	"time"
+
+	"git.runcible.io/learning/pulley/internal/logging"
+	"github.com/google/uuid"
 )
 
 // recoverPanic provides middleware for recovering from panics in the same goroutine that
@@ -29,8 +35,18 @@ func (app *application) recoverPanic(next http.Handler) http.Handler {
 	})
 }
 
+// RequestLoggingMiddleware
+// So this was my first crack at a request logging middleware. Originally I intended a LoggerFromContext function would
+// extract this prebuilt logger from the context at each layer it is passed to, but on futher examination I think it
+// would repeat information that is superfluous to that context of logging. Take for example if I use this in the Database Model
+// Service why does it matter what http.method was used in the http.Handler. The only important thing in that context would be
+// the Request ID that triggered the Database call.
 func (app *application) RquestLoggingMiddleware(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		requestId := r.Header.Get("X-Request-Id")
+		if requestId == "" {
+			requestId = uuid.New().String()
+		}
 
 		var (
 			ip     = r.RemoteAddr
@@ -38,7 +54,92 @@ func (app *application) RquestLoggingMiddleware(next http.Handler) http.Handler
 			method = r.Method
 			uri    = r.URL.RequestURI()
 		)
-		app.logger.Info("recieved request", "ip", ip, "proto", proto, "method", method, "uri", uri)
-		next.ServeHTTP(w, r)
+
+		reqLogger := slog.Default().With(
+			// TODO figure out if there is more
+			slog.Group("http",
+				slog.String("request_id", requestId),
+				slog.String("ip", ip),
+				slog.String("proto", proto),
+				slog.String("method", method),
+				slog.String("uri", uri),
+			),
+		)
+		ctx := context.WithValue(r.Context(), logging.CtxKeyLogger, reqLogger)
+		ctx = context.WithValue(ctx, logging.CtxKeyTraceID, requestId)
+		w.Header().Set("X-Request-Id", requestId)
+		reqLogger.Info("Recieved a request")
+		next.ServeHTTP(w, r.WithContext(ctx))
+	})
+}
+
+// See https://blog.questionable.services/article/guide-logging-middleware-go/
+
+// responseWriter is a minimal wrapper for http.ResponseWriter that allows the
+// written HTTP status code to be captured for logging.
+type responseWriter struct {
+	http.ResponseWriter
+	status      int
+	wroteHeader bool
+}
+
+func wrapResponseWriter(w http.ResponseWriter) *responseWriter {
+	return &responseWriter{ResponseWriter: w}
+}
+
+func (rw *responseWriter) Status() int {
+	return rw.status
+}
+
+func (rw *responseWriter) WriteHeader(code int) {
+	if rw.wroteHeader {
+		return
+	}
+
+	rw.status = code
+	rw.ResponseWriter.WriteHeader(code)
+	rw.wroteHeader = true
+	return
+}
+
+func (app *application) BetterRequestLoggingMiddleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		requestId := r.Header.Get("X-Request-Id")
+		if requestId == "" {
+			requestId = uuid.New().String()
+		}
+
+		var (
+			ip     = r.RemoteAddr
+			proto  = r.Proto
+			method = r.Method
+			uri    = r.URL.RequestURI()
+		)
+
+		reqLogger := slog.Default().With(
+			slog.String("correlation_id", requestId),
+		)
+
+		httpBaseGroup := func(kv ...any) slog.Attr {
+			return slog.Group("http",
+				append([]any{
+					slog.String("request_id", requestId),
+					slog.String("ip", ip),
+					slog.String("proto", proto),
+					slog.String("method", method),
+					slog.String("uri", uri),
+				}, kv...)...,
+			)
+		}
+
+		ctx := context.WithValue(r.Context(), logging.CtxKeyLogger, reqLogger)
+		ctx = context.WithValue(ctx, logging.CtxKeyTraceID, requestId)
+		w.Header().Set("X-Request-Id", requestId)
+		start := time.Now()
+		wrapped := wrapResponseWriter(w)
+		reqLogger.Info("Recieved a new request", slog.String("event", "start"), httpBaseGroup())
+		next.ServeHTTP(wrapped, r.WithContext(ctx))
+		reqLogger.Info("Completed request", slog.String("event", "end"), httpBaseGroup(slog.Int("status", wrapped.status), slog.Int64("duration_ms", time.Since(start).Milliseconds())))
+
 	})
 }

cmd/api/routes.go

@@ -30,5 +30,7 @@ func (app *application) routes() http.Handler {
 	router.HandlerFunc(http.MethodDelete, "/v1/movies/:id", app.deleteMovieHandler)
 
 	// middleware
-	return app.recoverPanic(app.RquestLoggingMiddleware(router))
+	// Wrapping recoverPanic with RequestMiddle ware since recoverPanic will write a 500
+	// status code that we cannot capture otherwise
+	return app.BetterRequestLoggingMiddleware(app.recoverPanic(router))
 }

go.mod

@@ -11,6 +11,7 @@ require (
 )
 
 require (
+	github.com/google/uuid v1.6.0 // indirect
 	github.com/hashicorp/errwrap v1.1.0 // indirect
 	github.com/hashicorp/go-multierror v1.1.1 // indirect
 	github.com/jackc/pgerrcode v0.0.0-20220416144525-469b46aa5efa // indirect

go.sum

@@ -5,6 +5,8 @@ github.com/golang-migrate/migrate v3.5.4+incompatible h1:R7OzwvCJTCgwapPCiX6DyBi
 github.com/golang-migrate/migrate v3.5.4+incompatible/go.mod h1:IsVUlFN5puWOmXrqjgGUfIRIbU7mr8oNBE2tyERd9Wk=
 github.com/golang-migrate/migrate/v4 v4.18.3 h1:EYGkoOsvgHHfm5U/naS1RP/6PL/Xv3S4B/swMiAmDLs=
 github.com/golang-migrate/migrate/v4 v4.18.3/go.mod h1:99BKpIi6ruaaXRM1A77eqZ+FWPQ3cfRa+ZVy5bmWMaY=
+github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0=
+github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
 github.com/hashicorp/errwrap v1.0.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4=
 github.com/hashicorp/errwrap v1.1.0 h1:OxrOeh75EUXMY8TBjag2fzXGZ40LB6IKw45YeGUDY2I=
 github.com/hashicorp/errwrap v1.1.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4=

internal/data/movies.go

@@ -52,6 +52,8 @@ func (m MovieModel) Get(ctx context.Context, id int64) (*Movie, error) {
 		return nil, ErrRecordNotFound
 	}
 
+	panic("OMG!")
+
 	query := `
 		SELECT id, created_at, title, year, runtime, genres, version
 		FROM movies