diff --git a/README.md b/README.md index 9278b8f..47715f9 100644 --- a/README.md +++ b/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/ \ No newline at end of file +- https://betterstack.com/community/guides/scaling-go/golang-testify/ diff --git a/cmd/api/middleware.go b/cmd/api/middleware.go index 9c8088b..d88c0e9 100644 --- a/cmd/api/middleware.go +++ b/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()))) + }) } diff --git a/cmd/api/routes.go b/cmd/api/routes.go index 0ec0b46..52d6c78 100644 --- a/cmd/api/routes.go +++ b/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)) } diff --git a/go.mod b/go.mod index 10326ff..e4ec207 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index bd86198..68fdd21 100644 --- a/go.sum +++ b/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= diff --git a/internal/data/movies.go b/internal/data/movies.go index 4167240..7d638b0 100644 --- a/internal/data/movies.go +++ b/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