better request logging middleware

NOTES.md

@@ -62,4 +62,12 @@ curl -w '\nTime: %{time_total}s \n' localhost:5002/v1/movies/4
 }
 
 Time: 8.009385s
+```
+
+## Timeout a Curl Request
+
+We can timeout our curl request like so
+
+```bash
+curl --max-time 2 localhost:5002/v1/movies/4
 ```

README.md

@@ -260,4 +260,23 @@ If we want to perform some kind of custom decoding for our type, this can be don
 type Unmarshaler interface {
     UnmarshalJSON([]byte) error
 }
-```
+```
+
+## 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/

cmd/api/handlers.go

@@ -242,6 +242,20 @@ func (app *application) deleteMovieHandler(w http.ResponseWriter, r *http.Reques
 	}
 }
 
+func (app *application) listMoviesHandler(w http.ResponseWriter, r *http.Request) {
+	qparams := r.URL.Query()
+	if len(qparams) != 0 {
+		app.logger.Debug("query params", "qp", qparams)
+	}
+
+	movies, err := app.models.Movies.List(r.Context())
+	if err != nil {
+		app.serverErrorResponse(w, r, err)
+		return
+	}
+	app.writeJSON(w, 200, envelope{"movies": movies}, nil)
+}
+
 func (app *application) healthCheckHandler(w http.ResponseWriter, r *http.Request) {
 	// JSON has to be double quoted. FYI you would never really do this
 	// js := `{"status": "available", "environment": %q, "version": %q}`

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
@@ -28,3 +34,112 @@ func (app *application) recoverPanic(next http.Handler) http.Handler {
 		next.ServeHTTP(w, r)
 	})
 }
+
+// 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
+			proto  = r.Proto
+			method = r.Method
+			uri    = r.URL.RequestURI()
+		)
+
+		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

@@ -23,11 +23,14 @@ func (app *application) routes() http.Handler {
 	router.MethodNotAllowed = http.HandlerFunc(app.methodNotAllowedResponse)
 
 	router.HandlerFunc(http.MethodGet, "/v1/healthcheck", app.healthCheckHandler)
+	router.HandlerFunc(http.MethodGet, "/v1/movies", app.listMoviesHandler)
 	router.HandlerFunc(http.MethodPost, "/v1/movies", app.createMovieHandler)
 	router.HandlerFunc(http.MethodGet, "/v1/movies/:id", app.getMovieHandler)
 	router.HandlerFunc(http.MethodPatch, "/v1/movies/:id", app.updateMovieHandler)
 	router.HandlerFunc(http.MethodDelete, "/v1/movies/:id", app.deleteMovieHandler)
 
 	// middleware
-	return app.recoverPanic(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/config/config.go

@@ -1,6 +1,10 @@
 package config
 
-import "github.com/kelseyhightower/envconfig"
+import (
+	"flag"
+
+	"github.com/kelseyhightower/envconfig"
+)
 
 type ServiceConfig struct {
 	LogLevel    string `default:"INFO"`
@@ -12,5 +16,13 @@ type ServiceConfig struct {
 func GetServiceConfig() ServiceConfig {
 	var sc ServiceConfig
 	envconfig.MustProcess("PULLEY", &sc)
+
+	// Flag overrides
+	port := flag.Int("port", sc.Port, "Service port. Default: '5002'")
+	logLevel := flag.String("log-level", sc.LogLevel, "Logging level Default:'INFO'")
+	flag.Parse()
+	sc.Port = *port
+	sc.LogLevel = *logLevel
+
 	return sc
 }

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
@@ -167,3 +169,41 @@ func (m MovieModel) Delete(ctx context.Context, id int64) (err error) {
 
 	return nil
 }
+
+func (m MovieModel) List(ctx context.Context) ([]*Movie, error) {
+
+	query := `
+		SELECT id, created_at, title, year, runtime, genres, version
+		FROM movies
+		ORDER BY id ASC
+		`
+	rows, err := m.pool.Query(ctx, query)
+	if err != nil {
+		return nil, err
+	}
+	defer rows.Close()
+
+	var movies []*Movie
+	for rows.Next() {
+		var movie Movie
+		err := rows.Scan(
+			&movie.ID,
+			&movie.CreatedAt,
+			&movie.Title,
+			&movie.Year,
+			&movie.Runtime,
+			&movie.Genres,
+			&movie.Version,
+		)
+		if err != nil {
+			return nil, err
+		}
+		movies = append(movies, &movie)
+	}
+	err = rows.Err()
+	if err != nil {
+		return nil, err
+	}
+
+	return movies, nil
+}

internal/logging/logging.go

@@ -1,11 +1,20 @@
 package logging
 
 import (
+	"context"
 	"io"
 	"log/slog"
 	"strings"
 )
 
+type CtxKey int
+
+const (
+	_ CtxKey = iota
+	CtxKeyLogger
+	CtxKeyTraceID
+)
+
 func parseLogLevel(levelStr string) slog.Level {
 	switch strings.ToUpper(levelStr) {
 	case "DEBUG":
@@ -34,3 +43,13 @@ func InitLogging(level string, w io.Writer, addSource bool) *slog.Logger {
 	slog.SetDefault(logger)
 	return logger
 }
+
+func LoggerFromCtx(ctx context.Context) *slog.Logger {
+	// context doesn't enforce type when context.WithValue(ctx, ctxKeyLogger, logger) is used
+	// it is stored as empty interface. So use type assertion .(*slog.Logger) to retrieve the
+	// value
+	if l, ok := ctx.Value(CtxKeyLogger).(*slog.Logger); ok && l != nil {
+		return l
+	}
+	return slog.Default()
+}

internal/logging/logging_test.go

@@ -2,6 +2,7 @@ package logging
 
 import (
 	"bytes"
+	"context"
 	"log/slog"
 	"testing"
 
@@ -63,3 +64,24 @@ func TestInitLogging(t *testing.T) {
 	assert.StringContains(t, content, msg)
 
 }
+
+func TestLoggerFromCtx(t *testing.T) {
+	defaultLogger := slog.Default()
+	subLogger := defaultLogger.With("testLogger", "this is a test")
+
+	t.Run("test logger returned is default", func(t *testing.T) {
+		assert.Equal(t, LoggerFromCtx(context.TODO()), defaultLogger)
+	})
+
+	t.Run("test logger returns saved logger", func(t *testing.T) {
+		assert.Equal(t, LoggerFromCtx(context.WithValue(context.TODO(), CtxKeyLogger, subLogger)), subLogger)
+	})
+
+	t.Run("test default logger when nil", func(t *testing.T) {
+		assert.Equal(t, LoggerFromCtx(context.WithValue(context.TODO(), CtxKeyLogger, nil)), defaultLogger)
+	})
+
+	t.Run("test default logger when wrong type", func(t *testing.T) {
+		assert.Equal(t, LoggerFromCtx(context.WithValue(context.TODO(), CtxKeyLogger, "bad type")), defaultLogger)
+	})
+}