logging update with context

cmd/main.go

@@ -3,25 +3,24 @@ package main
 import (
 	"database/sql"
 	"log"
-	"log/slog"
 	"net/http"
-	"os"
 
+	"gitea.michaelthomson.dev/mthomson/habits/internal/logging"
 	"gitea.michaelthomson.dev/mthomson/habits/internal/middleware"
 	"gitea.michaelthomson.dev/mthomson/habits/internal/migrate"
 	todohandler "gitea.michaelthomson.dev/mthomson/habits/internal/todo/handler"
 	todorepository "gitea.michaelthomson.dev/mthomson/habits/internal/todo/repository/postgres"
 	todoservice "gitea.michaelthomson.dev/mthomson/habits/internal/todo/service"
 	_ "github.com/jackc/pgx/v5/stdlib"
-	_ "github.com/mattn/go-sqlite3"
 )
 
 func main() {
 	// create logger
-	httpLogger := slog.New(slog.NewTextHandler(os.Stdout, nil))
+	logger := logging.NewLogger()
 
 	// create middlewares
-	loggingMiddleware := middleware.LoggingMiddleware(httpLogger)
+	contextMiddleware := middleware.ContextMiddleware(logger)
+	loggingMiddleware := middleware.LoggingMiddleware(logger)
 
 	// create db pool
 	postgresUrl := "postgres://todo:password@localhost:5432/todo"
@@ -35,19 +34,19 @@ func main() {
 	migrate.Migrate(db)
 
 	// create repos
-	todoRepository := todorepository.NewPostgresTodoRepository(db)
+	todoRepository := todorepository.NewPostgresTodoRepository(logger, db)
 
 	// create services
-	todoService := todoservice.NewTodoService(todoRepository)
+	todoService := todoservice.NewTodoService(logger, todoRepository)
 
 	// create mux
 	mux := http.NewServeMux()
 
 	// register handlers
-	mux.Handle("GET /todo/{id}", loggingMiddleware(todohandler.HandleTodoGet(todoService)))
+	mux.Handle("GET /todo/{id}", contextMiddleware(loggingMiddleware(todohandler.HandleTodoGet(logger, todoService))))
-	mux.Handle("POST /todo", loggingMiddleware(todohandler.HandleTodoCreate(todoService)))
+	mux.Handle("POST /todo", contextMiddleware(loggingMiddleware(todohandler.HandleTodoCreate(logger, todoService))))
-	mux.Handle("DELETE /todo/{id}", loggingMiddleware(todohandler.HandleTodoDelete(todoService)))
+	mux.Handle("DELETE /todo/{id}", contextMiddleware(loggingMiddleware(todohandler.HandleTodoDelete(logger, todoService))))
-	mux.Handle("PUT /todo/{id}", loggingMiddleware(todohandler.HandleTodoUpdate(todoService)))
+	mux.Handle("PUT /todo/{id}", contextMiddleware(loggingMiddleware(todohandler.HandleTodoUpdate(logger, todoService))))
 
 	// create server
 	server := &http.Server{

internal/logging/logging.go

@@ -0,0 +1,26 @@
+package logging
+
+import (
+	"context"
+	"log/slog"
+	"os"
+)
+
+type ContextHandler struct {
+	slog.Handler
+}
+
+func (h *ContextHandler) Handle(ctx context.Context, r slog.Record) error  {
+	if requestID, ok := ctx.Value("trace_id").(string); ok {
+        r.AddAttrs(slog.String("trace_id", requestID))
+    }
+    return h.Handler.Handle(ctx, r)
+}
+
+func NewLogger() *slog.Logger {
+    baseHandler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{AddSource: false})
+    customHandler := &ContextHandler{Handler: baseHandler}
+    logger := slog.New(customHandler)
+
+	return logger
+}

internal/middleware/context.go

@@ -0,0 +1,21 @@
+package middleware
+
+import (
+	"context"
+	"log/slog"
+	"net/http"
+
+	"github.com/google/uuid"
+)
+
+func ContextMiddleware(logger *slog.Logger) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			traceid := uuid.NewString()
+			ctx := context.WithValue(r.Context(), "trace_id", traceid)
+			newReq := r.WithContext(ctx)
+
+			next.ServeHTTP(w, newReq)
+		})
+	}
+}

internal/middleware/logging.go

@@ -1,23 +1,39 @@
 package middleware
 
 import (
-	"context"
 	"log/slog"
 	"net/http"
 )
 
+type LoggingResponseWriter struct {
+	http.ResponseWriter
+	statusCode int
+}
+
+func NewLoggingResponseWriter(w http.ResponseWriter) *LoggingResponseWriter {
+	return &LoggingResponseWriter{w, http.StatusOK}
+}
+
+func (lrw *LoggingResponseWriter) WriteHeader(code int) {
+	lrw.statusCode = code
+	lrw.ResponseWriter.WriteHeader(code)
+}
+
 func LoggingMiddleware(logger *slog.Logger) func(http.Handler) http.Handler {
 	return func(next http.Handler) http.Handler {
 		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-			logger.LogAttrs(
+			logger.InfoContext(r.Context(), "Incoming request",
-				context.Background(),
-				slog.LevelInfo,
-				"Incoming request",
 				slog.String("method", r.Method),
 				slog.String("path", r.URL.String()),
 			)
 
-			next.ServeHTTP(w, r)
+			lrw := NewLoggingResponseWriter(w)
+			next.ServeHTTP(lrw, r)
+
+			logger.InfoContext(r.Context(), "Sent response",
+				slog.Int("code", lrw.statusCode),
+				slog.String("message", http.StatusText(lrw.statusCode)),
+			)
 		})
 	}
 }

internal/todo/handler/create.go

@@ -3,6 +3,7 @@ package handler
 import (
 	"encoding/json"
 	"fmt"
+	"log/slog"
 	"net/http"
 
 	"gitea.michaelthomson.dev/mthomson/habits/internal/todo/service"
@@ -27,19 +28,21 @@ func CreateTodoResponseFromTodo(todo service.Todo) CreateTodoResponse {
 	return CreateTodoResponse{Id: todo.Id, Name: todo.Name, Done: todo.Done}
 }
 
-func HandleTodoCreate(todoService TodoCreater) http.HandlerFunc {
+func HandleTodoCreate(logger *slog.Logger, todoService TodoCreater) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
+		ctx := r.Context()
 		createTodoRequest := CreateTodoRequest{}
 		decoder := json.NewDecoder(r.Body)
 		decoder.DisallowUnknownFields()
 		err := decoder.Decode(&createTodoRequest)
 
 		if err != nil {
+			logger.ErrorContext(ctx, err.Error())
 			http.Error(w, "", http.StatusBadRequest)
 			return
 		}
 
-		todo, err := todoService.CreateTodo(TodoFromCreateTodoRequest(createTodoRequest))
+		todo, err := todoService.CreateTodo(ctx, TodoFromCreateTodoRequest(createTodoRequest))
 
 		if err != nil {
 			if err == service.ErrNotFound {
@@ -47,6 +50,7 @@ func HandleTodoCreate(todoService TodoCreater) http.HandlerFunc {
 				return
 			}
 
+			logger.ErrorContext(ctx, err.Error())
 			http.Error(w, "", http.StatusInternalServerError)
 			return
 		}
@@ -60,6 +64,7 @@ func HandleTodoCreate(todoService TodoCreater) http.HandlerFunc {
 		err = json.NewEncoder(w).Encode(response)
 
 		if err != nil {
+			logger.ErrorContext(ctx, err.Error())
 			http.Error(w, "", http.StatusInternalServerError)
 			return
 		}

internal/todo/handler/delete.go

@@ -1,24 +1,27 @@
 package handler
 
 import (
+	"log/slog"
 	"net/http"
 	"strconv"
 
 	"gitea.michaelthomson.dev/mthomson/habits/internal/todo/service"
 )
 
-func HandleTodoDelete(todoService TodoDeleter) http.HandlerFunc {
+func HandleTodoDelete(logger *slog.Logger, todoService TodoDeleter) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
+		ctx := r.Context()
 		idString := r.PathValue("id")
 
 		id, err := strconv.ParseInt(idString, 10, 64)
 
 		if err != nil {
+			slog.ErrorContext(ctx, err.Error())
 			http.Error(w, "", http.StatusBadRequest)
 			return
 		}
 
-		err = todoService.DeleteTodo(id)
+		err = todoService.DeleteTodo(ctx, id)
 
 		if err != nil {
 			if err == service.ErrNotFound {
@@ -26,6 +29,7 @@ func HandleTodoDelete(todoService TodoDeleter) http.HandlerFunc {
 				return
 			}
 
+			slog.ErrorContext(ctx, err.Error())
 			http.Error(w, "", http.StatusInternalServerError)
 			return
 		}

internal/todo/handler/get.go

@@ -2,6 +2,7 @@ package handler
 
 import (
 	"encoding/json"
+	"log/slog"
 	"net/http"
 	"strconv"
 
@@ -18,18 +19,20 @@ func GetTodoResponseFromTodo(todo service.Todo) GetTodoResponse {
 	return GetTodoResponse{Id: todo.Id, Name: todo.Name, Done: todo.Done}
 }
 
-func HandleTodoGet(todoService TodoGetter) http.HandlerFunc {
+func HandleTodoGet(logger *slog.Logger, todoService TodoGetter) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
+		ctx := r.Context()
 		idString := r.PathValue("id")
 
 		id, err := strconv.ParseInt(idString, 10, 64)
 
 		if err != nil {
+			logger.ErrorContext(ctx, err.Error())
 			http.Error(w, "", http.StatusBadRequest)
 			return
 		}
 
-		todo, err := todoService.GetTodo(id)
+		todo, err := todoService.GetTodo(ctx, id)
 
 		if err != nil {
 			if err == service.ErrNotFound {
@@ -37,6 +40,7 @@ func HandleTodoGet(todoService TodoGetter) http.HandlerFunc {
 				return
 			}
 
+			logger.ErrorContext(ctx, err.Error())
 			http.Error(w, "", http.StatusInternalServerError)
 			return
 		}
@@ -49,6 +53,7 @@ func HandleTodoGet(todoService TodoGetter) http.HandlerFunc {
 		err = json.NewEncoder(w).Encode(response)
 
 		if err != nil {
+			logger.ErrorContext(ctx, err.Error())
 			http.Error(w, "", http.StatusInternalServerError)
 			return
 		}

internal/todo/handler/handler.go

@@ -1,21 +1,23 @@
 package handler
 
 import (
+	"context"
+
 	"gitea.michaelthomson.dev/mthomson/habits/internal/todo/service"
 )
 
 type TodoGetter interface {
-	GetTodo(id int64) (service.Todo, error)
+	GetTodo(ctx context.Context, id int64) (service.Todo, error)
 }
 
 type TodoCreater interface {
-	CreateTodo(todo service.Todo) (service.Todo, error)
+	CreateTodo(ctx context.Context, todo service.Todo) (service.Todo, error)
 }
 
 type TodoDeleter interface {
-	DeleteTodo(id int64) error
+	DeleteTodo(ctx context.Context, id int64) error
 }
 
 type TodoUpdater interface {
-	UpdateTodo(todo service.Todo) error
+	UpdateTodo(ctx context.Context, todo service.Todo) error
 }

internal/todo/handler/update.go

@@ -2,6 +2,7 @@ package handler
 
 import (
 	"encoding/json"
+	"log/slog"
 	"net/http"
 	"strconv"
 
@@ -17,14 +18,16 @@ func TodoFromUpdateTodoRequest(todo UpdateTodoRequest, id int64) service.Todo {
 	return service.Todo{Id: id, Name: todo.Name, Done: todo.Done}
 }
 
-func HandleTodoUpdate(todoService TodoUpdater) http.HandlerFunc {
+func HandleTodoUpdate(logger *slog.Logger, todoService TodoUpdater) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
+		ctx := r.Context()
 		updateTodoRequest := UpdateTodoRequest{}
 		decoder := json.NewDecoder(r.Body)
 		decoder.DisallowUnknownFields()
 		err := decoder.Decode(&updateTodoRequest)
 
 		if err != nil {
+			logger.ErrorContext(ctx, err.Error())
 			http.Error(w, "", http.StatusBadRequest)
 			return
 		}
@@ -34,11 +37,12 @@ func HandleTodoUpdate(todoService TodoUpdater) http.HandlerFunc {
 		id, err := strconv.ParseInt(idString, 10, 64)
 
 		if err != nil {
+			logger.ErrorContext(ctx, err.Error())
 			http.Error(w, "", http.StatusBadRequest)
 			return
 		}
 
-		err = todoService.UpdateTodo(TodoFromUpdateTodoRequest(updateTodoRequest, id))
+		err = todoService.UpdateTodo(ctx, TodoFromUpdateTodoRequest(updateTodoRequest, id))
 
 		if err != nil {
 			if err == service.ErrNotFound {
@@ -46,6 +50,7 @@ func HandleTodoUpdate(todoService TodoUpdater) http.HandlerFunc {
 				return
 			}
 
+			logger.ErrorContext(ctx, err.Error())
 			http.Error(w, "", http.StatusInternalServerError)
 			return
 		}

internal/todo/repository/postgres/postgres.go

@@ -2,16 +2,19 @@ package postgres
 
 import (
 	"database/sql"
+	"log/slog"
 
 	"gitea.michaelthomson.dev/mthomson/habits/internal/todo/repository"
 )
 
 type PostgresTodoRepository struct {
+	logger *slog.Logger
 	db *sql.DB
 }
 
-func NewPostgresTodoRepository(db *sql.DB) *PostgresTodoRepository {
+func NewPostgresTodoRepository(logger *slog.Logger, db *sql.DB) *PostgresTodoRepository {
 	return &PostgresTodoRepository{
+		logger: logger,
 		db: db,
 	}
 }

internal/todo/service/service.go

@@ -1,8 +1,9 @@
 package service
 
 import (
+	"context"
 	"errors"
-	"log"
+	"log/slog"
 
 	"gitea.michaelthomson.dev/mthomson/habits/internal/todo/repository"
 )
@@ -41,14 +42,18 @@ type TodoRepository interface {
 }
 
 type TodoService struct {
+	logger *slog.Logger
 	repo TodoRepository
 }
 
-func NewTodoService(todoRepo TodoRepository) *TodoService {
+func NewTodoService(logger *slog.Logger, todoRepo TodoRepository) *TodoService {
-	return &TodoService{todoRepo}
+	return &TodoService{
+		logger: logger,
+		repo: todoRepo,
+	}
 }
 
-func (s *TodoService) GetTodo(id int64) (Todo, error) {
+func (s *TodoService) GetTodo(ctx context.Context, id int64) (Todo, error) {
 	todo, err := s.repo.GetById(id)
 
 	if err != nil {
@@ -56,36 +61,41 @@ func (s *TodoService) GetTodo(id int64) (Todo, error) {
 			return Todo{}, ErrNotFound
 		}
 
+		s.logger.ErrorContext(ctx, err.Error())
 		return Todo{}, err
 	}
 
 	return TodoFromTodoRow(todo), err
 }
 
-func (s *TodoService) CreateTodo(todo Todo) (Todo, error) {
+func (s *TodoService) CreateTodo(ctx context.Context, todo Todo) (Todo, error) {
 	todoRow := TodoRowFromTodo(todo)
 
 	newTodoRow, err := s.repo.Create(todoRow)
 
 	if err != nil {
-		log.Print(err)
+		s.logger.ErrorContext(ctx, err.Error())
 		return Todo{}, err
 	}
 
 	return TodoFromTodoRow(newTodoRow), err
 }
 
-func (s *TodoService) DeleteTodo(id int64) error {
+func (s *TodoService) DeleteTodo(ctx context.Context, id int64) error {
 	err := s.repo.Delete(id)
 
 	if err == repository.ErrNotFound {
 		return ErrNotFound
 	}
 
+	if (err != nil) {
+		s.logger.ErrorContext(ctx, err.Error())
+	}
+
 	return err
 }
 
-func (s *TodoService) UpdateTodo(todo Todo) error {
+func (s *TodoService) UpdateTodo(ctx context.Context, todo Todo) error {
 	todoRow := TodoRowFromTodo(todo)
 
 	err := s.repo.Update(todoRow)
@@ -94,5 +104,9 @@ func (s *TodoService) UpdateTodo(todo Todo) error {
 		return ErrNotFound
 	}
 
+	if (err != nil) {
+		s.logger.ErrorContext(ctx, err.Error())
+	}
+
 	return err
 }

makefile

@@ -7,5 +7,8 @@ build:
 test:
 	go test ./...
 
+format:
+	go fmt ./...
+
 clean:
 	rm tmp/main habits.db