From f9a8e9666ed31dc3b8ef82709bea8273b553a371 Mon Sep 17 00:00:00 2001 From: Michael Thomson Date: Thu, 15 May 2025 12:34:32 -0400 Subject: [PATCH] logging and middleware chaining --- cmd/main.go | 19 +++-- flake.nix | 1 + internal/logging/logging.go | 6 +- internal/middleware/context.go | 5 +- internal/middleware/util.go | 19 +++++ internal/migrate/migrate.go | 10 +-- internal/test/test_database.go | 62 ++++++++++++++++ internal/todo/repository/postgres/postgres.go | 15 ++-- .../todo/repository/postgres/postgres_test.go | 70 +++---------------- internal/todo/service/service.go | 16 ++--- internal/todo/service/service_test.go | 45 ++++++++---- 11 files changed, 168 insertions(+), 100 deletions(-) create mode 100644 internal/middleware/util.go create mode 100644 internal/test/test_database.go diff --git a/cmd/main.go b/cmd/main.go index 33c3856..6ed39cc 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -4,6 +4,7 @@ import ( "database/sql" "log" "net/http" + "os" "gitea.michaelthomson.dev/mthomson/habits/internal/logging" "gitea.michaelthomson.dev/mthomson/habits/internal/middleware" @@ -22,16 +23,22 @@ func main() { contextMiddleware := middleware.ContextMiddleware(logger) loggingMiddleware := middleware.LoggingMiddleware(logger) + stack := []middleware.Middleware{ + contextMiddleware, + loggingMiddleware, + } + // create db pool postgresUrl := "postgres://todo:password@localhost:5432/todo" db, err := sql.Open("pgx", postgresUrl) if err != nil { - log.Fatalf("Failed to open db pool: %v", err) + logger.Error(err.Error()) + os.Exit(1); } defer db.Close() // run migrations - migrate.Migrate(db) + migrate.Migrate(logger, db) // create repos todoRepository := todorepository.NewPostgresTodoRepository(logger, db) @@ -43,10 +50,10 @@ func main() { mux := http.NewServeMux() // register handlers - mux.Handle("GET /todo/{id}", contextMiddleware(loggingMiddleware(todohandler.HandleTodoGet(logger, todoService)))) - mux.Handle("POST /todo", contextMiddleware(loggingMiddleware(todohandler.HandleTodoCreate(logger, todoService)))) - mux.Handle("DELETE /todo/{id}", contextMiddleware(loggingMiddleware(todohandler.HandleTodoDelete(logger, todoService)))) - mux.Handle("PUT /todo/{id}", contextMiddleware(loggingMiddleware(todohandler.HandleTodoUpdate(logger, todoService)))) + mux.Handle("GET /todo/{id}", middleware.CompileMiddleware(todohandler.HandleTodoGet(logger, todoService), stack)) + mux.Handle("POST /todo", middleware.CompileMiddleware(todohandler.HandleTodoCreate(logger, todoService), stack)) + mux.Handle("DELETE /todo/{id}", middleware.CompileMiddleware(todohandler.HandleTodoDelete(logger, todoService), stack)) + mux.Handle("PUT /todo/{id}", middleware.CompileMiddleware(todohandler.HandleTodoUpdate(logger, todoService), stack)) // create server server := &http.Server{ diff --git a/flake.nix b/flake.nix index 672be8f..d08d1ce 100644 --- a/flake.nix +++ b/flake.nix @@ -36,6 +36,7 @@ docker docker-compose + gopls ]; }; }); diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 1a0ff39..df6f811 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -4,6 +4,8 @@ import ( "context" "log/slog" "os" + + "gitea.michaelthomson.dev/mthomson/habits/internal/middleware" ) type ContextHandler struct { @@ -11,8 +13,8 @@ type ContextHandler struct { } 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)) + if requestID, ok := ctx.Value(middleware.TraceIdKey).(string); ok { + r.AddAttrs(slog.String(string(middleware.TraceIdKey), requestID)) } return h.Handler.Handle(ctx, r) } diff --git a/internal/middleware/context.go b/internal/middleware/context.go index e8cd9dd..35211b3 100644 --- a/internal/middleware/context.go +++ b/internal/middleware/context.go @@ -8,11 +8,14 @@ import ( "github.com/google/uuid" ) +type contextKey string +const TraceIdKey contextKey = "trace_id" + 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) + ctx := context.WithValue(r.Context(), TraceIdKey, traceid) newReq := r.WithContext(ctx) next.ServeHTTP(w, newReq) diff --git a/internal/middleware/util.go b/internal/middleware/util.go new file mode 100644 index 0000000..50ed4fb --- /dev/null +++ b/internal/middleware/util.go @@ -0,0 +1,19 @@ +package middleware + +import "net/http" + +type Middleware func(http.Handler) http.Handler + +func CompileMiddleware(h http.Handler, m []Middleware) http.Handler { + if len(m) < 1 { + return h + } + + wrapped := h + + for i := len(m) - 1; i >= 0; i-- { + wrapped = m[i](wrapped) + } + + return wrapped +} diff --git a/internal/migrate/migrate.go b/internal/migrate/migrate.go index 586d04a..a4a4f26 100644 --- a/internal/migrate/migrate.go +++ b/internal/migrate/migrate.go @@ -7,7 +7,7 @@ import ( "log" "log/slog" - _ "github.com/mattn/go-sqlite3" + _ "github.com/jackc/pgx/v5/stdlib" ) //go:embed migrations/*.sql @@ -18,8 +18,8 @@ type Migration struct { Name string } -func Migrate(db *sql.DB) { - slog.Info("Running migrations...") +func Migrate(logger *slog.Logger, db *sql.DB) { + logger.Info("Running migrations...") migrationTableSql := ` CREATE TABLE IF NOT EXISTS migrations( version SERIAL PRIMARY KEY, @@ -41,7 +41,7 @@ func Migrate(db *sql.DB) { row := db.QueryRow("SELECT * FROM migrations WHERE name = $1;", file.Name()) err = row.Scan(&migration.Version, &migration.Name) if err == sql.ErrNoRows { - slog.Info(fmt.Sprintf("Running migration: %s", file.Name())) + logger.Info(fmt.Sprintf("Running migration: %s", file.Name())) migrationSql, err := migrations.ReadFile(fmt.Sprintf("migrations/%s", file.Name())) if err != nil { log.Fatal(err) @@ -58,5 +58,5 @@ func Migrate(db *sql.DB) { } } } - slog.Info("Migrations completed") + logger.Info("Migrations completed") } diff --git a/internal/test/test_database.go b/internal/test/test_database.go new file mode 100644 index 0000000..8fea403 --- /dev/null +++ b/internal/test/test_database.go @@ -0,0 +1,62 @@ +package test + +import ( + "context" + "database/sql" + "log/slog" + "testing" + "time" + + "gitea.michaelthomson.dev/mthomson/habits/internal/migrate" + "github.com/testcontainers/testcontainers-go" + "github.com/testcontainers/testcontainers-go/modules/postgres" + "github.com/testcontainers/testcontainers-go/wait" +) + +type TestDatabase struct { + Db *sql.DB + container testcontainers.Container +} + +func NewTestDatabase(tb testing.TB) *TestDatabase { + tb.Helper() + ctx := context.Background() + // create container + postgresContainer, err := postgres.Run(ctx, + "postgres:16-alpine", + postgres.WithDatabase("todo"), + postgres.WithUsername("todo"), + postgres.WithPassword("password"), + testcontainers.WithWaitStrategy( + wait.ForLog("database system is ready to accept connections"). + WithOccurrence(2). + WithStartupTimeout(5*time.Second)), + ) + + if err != nil { + tb.Fatalf("Failed to create postgres container, %v", err) + } + + connectionString, err := postgresContainer.ConnectionString(ctx) + if err != nil { + tb.Fatalf("Failed to get connection string: %v", err) + } + + // create db pool + db, err := sql.Open("pgx", connectionString) + if err != nil { + tb.Fatalf("Failed to open db pool: %v", err) + } + + migrate.Migrate(slog.Default(), db) + + return &TestDatabase{ + Db: db, + container: postgresContainer, + } +} + +func (tdb *TestDatabase) TearDown() { + tdb.Db.Close() + _ = tdb.container.Terminate(context.Background()) +} diff --git a/internal/todo/repository/postgres/postgres.go b/internal/todo/repository/postgres/postgres.go index b80ff27..c1c834f 100644 --- a/internal/todo/repository/postgres/postgres.go +++ b/internal/todo/repository/postgres/postgres.go @@ -1,6 +1,7 @@ package postgres import ( + "context" "database/sql" "log/slog" @@ -19,7 +20,7 @@ func NewPostgresTodoRepository(logger *slog.Logger, db *sql.DB) *PostgresTodoRep } } -func (r *PostgresTodoRepository) GetById(id int64) (repository.TodoRow, error) { +func (r *PostgresTodoRepository) GetById(ctx context.Context, id int64) (repository.TodoRow, error) { todo := repository.TodoRow{} err := r.db.QueryRow("SELECT * FROM todo WHERE id = $1;", id).Scan(&todo.Id, &todo.Name, &todo.Done) @@ -29,33 +30,37 @@ func (r *PostgresTodoRepository) GetById(id int64) (repository.TodoRow, error) { return todo, repository.ErrNotFound } + r.logger.ErrorContext(ctx, err.Error()) return todo, err } return todo, nil } -func (r *PostgresTodoRepository) Create(todo repository.TodoRow) (repository.TodoRow, error) { +func (r *PostgresTodoRepository) Create(ctx context.Context, todo repository.TodoRow) (repository.TodoRow, error) { result := r.db.QueryRow("INSERT INTO todo (name, done) VALUES ($1, $2) RETURNING id;", todo.Name, todo.Done) err := result.Scan(&todo.Id) if err != nil { + r.logger.ErrorContext(ctx, err.Error()) return repository.TodoRow{}, err } return todo, nil } -func (r *PostgresTodoRepository) Update(todo repository.TodoRow) error { +func (r *PostgresTodoRepository) Update(ctx context.Context, todo repository.TodoRow) error { result, err := r.db.Exec("UPDATE todo SET name = $1, done = $2 WHERE id = $3;", todo.Name, todo.Done, todo.Id) if err != nil { + r.logger.ErrorContext(ctx, err.Error()) return err } rowsAffected, err := result.RowsAffected() if err != nil { + r.logger.ErrorContext(ctx, err.Error()) return err } @@ -66,16 +71,18 @@ func (r *PostgresTodoRepository) Update(todo repository.TodoRow) error { return nil } -func (r *PostgresTodoRepository) Delete(id int64) error { +func (r *PostgresTodoRepository) Delete(ctx context.Context, id int64) error { result, err := r.db.Exec("DELETE FROM todo WHERE id = $1;", id) if err != nil { + r.logger.ErrorContext(ctx, err.Error()) return err } rowsAffected, err := result.RowsAffected() if err != nil { + r.logger.ErrorContext(ctx, err.Error()) return err } diff --git a/internal/todo/repository/postgres/postgres_test.go b/internal/todo/repository/postgres/postgres_test.go index 5d2a096..a858954 100644 --- a/internal/todo/repository/postgres/postgres_test.go +++ b/internal/todo/repository/postgres/postgres_test.go @@ -2,105 +2,53 @@ package postgres import ( "context" - "database/sql" "errors" "log/slog" "testing" - "time" - "gitea.michaelthomson.dev/mthomson/habits/internal/migrate" + "gitea.michaelthomson.dev/mthomson/habits/internal/test" "gitea.michaelthomson.dev/mthomson/habits/internal/todo/repository" _ "github.com/jackc/pgx/v5/stdlib" - "github.com/testcontainers/testcontainers-go" - "github.com/testcontainers/testcontainers-go/modules/postgres" - "github.com/testcontainers/testcontainers-go/wait" ) -type TestDatabase struct { - Db *sql.DB - container testcontainers.Container -} - -func NewTestDatabase(tb testing.TB) *TestDatabase { - tb.Helper() - ctx := context.Background() - // create container - postgresContainer, err := postgres.Run(ctx, - "postgres:16-alpine", - postgres.WithDatabase("todo"), - postgres.WithUsername("todo"), - postgres.WithPassword("password"), - testcontainers.WithWaitStrategy( - wait.ForLog("database system is ready to accept connections"). - WithOccurrence(2). - WithStartupTimeout(5*time.Second)), - ) - - if err != nil { - tb.Fatalf("Failed to create postgres container, %v", err) - } - - connectionString, err := postgresContainer.ConnectionString(ctx) - if err != nil { - tb.Fatalf("Failed to get connection string: %v", err) - } - - // create db pool - db, err := sql.Open("pgx", connectionString) - if err != nil { - tb.Fatalf("Failed to open db pool: %v", err) - } - - migrate.Migrate(db) - - return &TestDatabase{ - Db: db, - container: postgresContainer, - } -} - -func (tdb *TestDatabase) TearDown() { - tdb.Db.Close() - _ = tdb.container.Terminate(context.Background()) -} - func TestCRUD(t *testing.T) { + ctx := context.Background() logger := slog.Default() - tdb := NewTestDatabase(t) + tdb := test.NewTestDatabase(t) defer tdb.TearDown() r := NewPostgresTodoRepository(logger, tdb.Db) t.Run("creates new todo", func(t *testing.T) { want := repository.TodoRow{Id: 1, Name: "clean dishes", Done: false} newTodo := repository.TodoRow{Name: "clean dishes", Done: false} - got, err := r.Create(newTodo) + got, err := r.Create(ctx, newTodo) AssertNoError(t, err) AssertTodoRows(t, got, want) }) t.Run("gets todo", func(t *testing.T) { want := repository.TodoRow{Id: 1, Name: "clean dishes", Done: false} - got, err := r.GetById(1) + got, err := r.GetById(ctx, 1) AssertNoError(t, err) AssertTodoRows(t, got, want) }) t.Run("updates todo", func(t *testing.T) { want := repository.TodoRow{Id: 1, Name: "clean dishes", Done: true} - err := r.Update(want) + err := r.Update(ctx, want) AssertNoError(t, err) - got, err := r.GetById(1) + got, err := r.GetById(ctx, 1) AssertNoError(t, err) AssertTodoRows(t, got, want) }) t.Run("deletes todo", func(t *testing.T) { - err := r.Delete(1) + err := r.Delete(ctx, 1) AssertNoError(t, err) want := repository.ErrNotFound - _, got := r.GetById(1) + _, got := r.GetById(ctx, 1) AssertErrors(t, got, want) }) diff --git a/internal/todo/service/service.go b/internal/todo/service/service.go index 4e5714e..43d28a8 100644 --- a/internal/todo/service/service.go +++ b/internal/todo/service/service.go @@ -35,10 +35,10 @@ func (t Todo) Equal(todo Todo) bool { } type TodoRepository interface { - Create(todo repository.TodoRow) (repository.TodoRow, error) - GetById(id int64) (repository.TodoRow, error) - Update(todo repository.TodoRow) error - Delete(id int64) error + Create(ctx context.Context, todo repository.TodoRow) (repository.TodoRow, error) + GetById(ctx context.Context, id int64) (repository.TodoRow, error) + Update(ctx context.Context, todo repository.TodoRow) error + Delete(ctx context.Context, id int64) error } type TodoService struct { @@ -54,7 +54,7 @@ func NewTodoService(logger *slog.Logger, todoRepo TodoRepository) *TodoService { } func (s *TodoService) GetTodo(ctx context.Context, id int64) (Todo, error) { - todo, err := s.repo.GetById(id) + todo, err := s.repo.GetById(ctx, id) if err != nil { if err == repository.ErrNotFound { @@ -71,7 +71,7 @@ func (s *TodoService) GetTodo(ctx context.Context, id int64) (Todo, error) { func (s *TodoService) CreateTodo(ctx context.Context, todo Todo) (Todo, error) { todoRow := TodoRowFromTodo(todo) - newTodoRow, err := s.repo.Create(todoRow) + newTodoRow, err := s.repo.Create(ctx, todoRow) if err != nil { s.logger.ErrorContext(ctx, err.Error()) @@ -82,7 +82,7 @@ func (s *TodoService) CreateTodo(ctx context.Context, todo Todo) (Todo, error) { } func (s *TodoService) DeleteTodo(ctx context.Context, id int64) error { - err := s.repo.Delete(id) + err := s.repo.Delete(ctx, id) if err == repository.ErrNotFound { return ErrNotFound @@ -98,7 +98,7 @@ func (s *TodoService) DeleteTodo(ctx context.Context, id int64) error { func (s *TodoService) UpdateTodo(ctx context.Context, todo Todo) error { todoRow := TodoRowFromTodo(todo) - err := s.repo.Update(todoRow) + err := s.repo.Update(ctx, todoRow) if err == repository.ErrNotFound { return ErrNotFound diff --git a/internal/todo/service/service_test.go b/internal/todo/service/service_test.go index c4c154c..bf1c84c 100644 --- a/internal/todo/service/service_test.go +++ b/internal/todo/service/service_test.go @@ -5,18 +5,22 @@ import ( "log/slog" "testing" + "gitea.michaelthomson.dev/mthomson/habits/internal/test" "gitea.michaelthomson.dev/mthomson/habits/internal/todo/repository" - "gitea.michaelthomson.dev/mthomson/habits/internal/todo/repository/inmemory" + "gitea.michaelthomson.dev/mthomson/habits/internal/todo/repository/postgres" "gitea.michaelthomson.dev/mthomson/habits/internal/todo/service" + _ "github.com/jackc/pgx/v5/stdlib" ) func TestCreateTodo(t *testing.T) { + t.Parallel() ctx := context.Background() logger := slog.Default() + tdb := test.NewTestDatabase(t) + defer tdb.TearDown() + r := postgres.NewPostgresTodoRepository(logger, tdb.Db) - todoRepository := inmemory.NewInMemoryTodoRepository() - - todoService := service.NewTodoService(logger, &todoRepository) + todoService := service.NewTodoService(logger, r) t.Run("Create todo", func(t *testing.T) { todo := service.NewTodo("clean dishes", false) @@ -28,13 +32,18 @@ func TestCreateTodo(t *testing.T) { } func TestGetTodo(t *testing.T) { + t.Parallel() ctx := context.Background() logger := slog.Default() - todoRepository := inmemory.NewInMemoryTodoRepository() + tdb := test.NewTestDatabase(t) + defer tdb.TearDown() + r := postgres.NewPostgresTodoRepository(logger, tdb.Db) - todoRepository.Db[1] = repository.TodoRow{Id: 1, Name: "clean dishes", Done: false} + row := repository.TodoRow{Id: 1, Name: "clean dishes", Done: false} + _, err := r.Create(ctx, row) + AssertNoError(t, err); - todoService := service.NewTodoService(logger, &todoRepository) + todoService := service.NewTodoService(logger, r) t.Run("Get exisiting todo", func(t *testing.T) { _, err := todoService.GetTodo(ctx, 1) @@ -50,13 +59,18 @@ func TestGetTodo(t *testing.T) { } func TestDeleteTodo(t *testing.T) { + t.Parallel() ctx := context.Background() logger := slog.Default() - todoRepository := inmemory.NewInMemoryTodoRepository() + tdb := test.NewTestDatabase(t) + defer tdb.TearDown() + r := postgres.NewPostgresTodoRepository(logger, tdb.Db) - todoRepository.Db[1] = repository.TodoRow{Id: 1, Name: "clean dishes", Done: false} + row := repository.TodoRow{Id: 1, Name: "clean dishes", Done: false} + _, err := r.Create(ctx, row) + AssertNoError(t, err); - todoService := service.NewTodoService(logger, &todoRepository) + todoService := service.NewTodoService(logger, r) t.Run("Delete exisiting todo", func(t *testing.T) { err := todoService.DeleteTodo(ctx, 1) @@ -72,13 +86,18 @@ func TestDeleteTodo(t *testing.T) { } func TestUpdateTodo(t *testing.T) { + t.Parallel() ctx := context.Background() logger := slog.Default() - todoRepository := inmemory.NewInMemoryTodoRepository() + tdb := test.NewTestDatabase(t) + defer tdb.TearDown() + r := postgres.NewPostgresTodoRepository(logger, tdb.Db) - todoRepository.Db[1] = repository.TodoRow{Id: 1, Name: "clean dishes", Done: false} + row := repository.TodoRow{Id: 1, Name: "clean dishes", Done: false} + _, err := r.Create(ctx, row) + AssertNoError(t, err); - todoService := service.NewTodoService(logger, &todoRepository) + todoService := service.NewTodoService(logger, r) t.Run("Update exisiting todo", func(t *testing.T) { todo := service.Todo{1, "clean dishes", true}