diff --git a/.env.example b/.env.example index 5018362..c6519d2 100644 --- a/.env.example +++ b/.env.example @@ -3,3 +3,5 @@ POSTGRES_PASSWORD=mysecretpassword POSTGRES_DB=mydatabase API_PORT=8080 +# Readable one-line request logs instead of ECS JSON. +# LOG_CONCISE=true diff --git a/CLAUDE.md b/CLAUDE.md index b4c1bf9..1014a82 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -5,7 +5,8 @@ This file provides guidance to Claude Code (claude.ai/code) when working with co ## Overview Go REST API for tasks. `net/http` + chi for routing, pgx for Postgres, sqlc for type-safe -queries generated from plain SQL, goose for migrations. No ORM, no framework. See +queries generated from plain SQL, goose for migrations, httplog v3 for request logging. No +ORM, no framework. See [README.md](README.md) for the full API reference, data model, and configuration table. ## Commands @@ -59,7 +60,7 @@ Boundaries that matter: seam for testing the HTTP layer with a fake instead of a live database — see `fakeQuerier` in [fake_querier_test.go](internal/handler/fake_querier_test.go) and the handler tests in [task_test.go](internal/handler/task_test.go). Those tests live in - `package handler` (not `handler_test`) so they can build a `Handler{q: fake, ...}` literal + `package handler` (not `handler_test`) so they can build a `Handler{q: fake}` literal directly — `q` is unexported and there's no constructor that takes a `Querier`. ## Conventions and gotchas @@ -70,10 +71,21 @@ Boundaries that matter: - **`PUT /v1/tasks/{id}` is a full replacement, not a patch.** Omitted fields reset to their defaults — the handler substitutes `"todo"` for an empty `status` in both `CreateTask` and `UpdateTask`. Any new field with a default needs the same treatment in both places. -- **Error responses never leak internals.** Log the real error with `h.logger.Error`, then - return a generic message via `writeError` / `writeValidationError` - ([errors.go](internal/handler/errors.go)). Validation failures are 422 with a `fields` map; - a bad `{id}` or malformed JSON is 400; `pgx.ErrNoRows` maps to 404. +- **The httplog schema is shared state between `main.go` and `server.New`.** `main.go` builds + one `*httplog.Schema` (`httplog.SchemaECS.Concise(cfg.LogConcise)`) and passes it both to the + `slog` handler's `ReplaceAttr` and to `server.New`. Passing a different schema to either side + renames attributes under one mapping and filters them under another. `httplog.RequestLogger` + replaces chi's `middleware.Logger` *and* `middleware.Recoverer` — its `RecoverPanics: true` + does the recovery, so don't re-add `Recoverer`. `middleware.RequestID` still runs first and + the ID is attached to the request log via `LogExtraAttrs`. +- **Error responses never leak internals.** 500s go through `serverError` + ([errors.go](internal/handler/errors.go)), which attaches the real error and an `op` name to + the request log via `httplog.SetError` / `SetAttrs` and returns a generic message. + `Handler` has no logger of its own — the error rides the single request log line, correlated + with method, path, status and `request_id`. The catch: `httplog.SetAttrs` is a silent no-op + outside `httplog.RequestLogger`, so a handler mounted without that middleware logs nothing. + Everything else uses `writeError` / `writeValidationError` directly: validation failures are + 422 with a `fields` map; a bad `{id}` or malformed JSON is 400; `pgx.ErrNoRows` maps to 404. - **Query params degrade rather than error.** Unparseable `page` / `page_size` fall back to defaults, and `page_size` is clamped to 100 so a client can never request unbounded rows. - **Nullable SQL params use `sqlc.narg`**, which surfaces as `pgtype.Text` in Go (see the diff --git a/README.md b/README.md index b8f1abf..96f822b 100644 --- a/README.md +++ b/README.md @@ -4,8 +4,8 @@ A small, production-shaped REST API for managing tasks, written in Go with Postg It is deliberately dependency-light: `net/http` with [chi](https://github.com/go-chi/chi) for routing, [pgx](https://github.com/jackc/pgx) for the database, [sqlc](https://sqlc.dev) for type-safe -queries generated from plain SQL, and [goose](https://github.com/pressly/goose) for migrations. -No ORM, no framework. +queries generated from plain SQL, [goose](https://github.com/pressly/goose) for migrations, and +[httplog](https://github.com/go-chi/httplog) for `log/slog` request logging. No ORM, no framework. An OpenAPI spec is generated from handler comments by [swag](https://github.com/swaggo/swag) and served as Swagger UI at `/swagger/index.html`. @@ -34,7 +34,8 @@ served as Swagger UI at `/swagger/index.html`. - Request validation with per-field error messages (HTTP 422) - Type-safe database access — Go code generated from `.sql` files by sqlc - Versioned SQL migrations via goose -- Structured JSON logging (`log/slog`) +- Structured request logging in ECS format (`log/slog` + [httplog](https://github.com/go-chi/httplog)), + with a concise human-readable mode for local development - Graceful shutdown on `SIGINT`/`SIGTERM` with a 10s drain window - Request IDs, panic recovery, and a 15s request timeout middleware - `/healthz` liveness endpoint @@ -115,12 +116,17 @@ make run | `POSTGRES_DB` | yes | — | Database name | | `API_PORT` | no | `8080` | Host port mapped to the API container's `8080` | -The API binary itself reads only these two variables from its own environment: +The API binary itself reads only these variables from its own environment: -| Variable | Required | Default | Description | -| -------------- | -------- | ------- | ---------------------------------------------------- | -| `DATABASE_URL` | yes | — | Postgres connection string; startup fails without it | -| `HTTP_ADDR` | no | `:8080` | Listen address | +| Variable | Required | Default | Description | +| -------------- | -------- | ------- | ------------------------------------------------------- | +| `DATABASE_URL` | yes | — | Postgres connection string; startup fails without it | +| `HTTP_ADDR` | no | `:8080` | Listen address | +| `LOG_CONCISE` | no | `false` | `true` swaps ECS JSON logs for short human-readable lines | + +An unparseable `LOG_CONCISE` falls back to `false` rather than failing startup. The Makefile +exports everything in `.env`, so setting it there applies to `make run` and `make dev`; the +`api` container only receives `DATABASE_URL` from Compose. Compose builds `DATABASE_URL` for the `api` service from the `POSTGRES_*` values, pointing at the `db` service on the internal network. `make run` builds the same URL against `localhost`. @@ -253,8 +259,10 @@ Errors are JSON with an `error` message. Validation failures add a `fields` map. } ``` -Server-side failures log the underlying error and return a generic message — internal -details are never leaked to clients. +Server-side failures return a generic message — internal details are never leaked to clients. +The underlying error is recorded on that request's log line instead, as `error.message` +alongside an `op` naming the failed operation, so the cause stays correlated with the method, +path, status and `request_id` of the request that hit it. See [Logging](#logging). ## Data model @@ -339,6 +347,45 @@ All commands come from the [Makefile](Makefile): | `make tidy` | `go mod tidy` | | `make test` | `go test ./...` | +### Logging + +Request logging is [httplog](https://github.com/go-chi/httplog) v3 wired into `log/slog`. +There is no separate logger type: `httplog.RequestLogger` is chi middleware that writes to the +same `*slog.Logger` the handlers use, and the schema (`httplog.SchemaECS`) renames the +attributes to [Elastic Common Schema](https://www.elastic.co/guide/en/ecs/current/index.html) +field names — `http.response.status_code`, `event.duration`, and so on. + +One log line is emitted per response, at a level derived from the status: `INFO` for 2xx/3xx, +`WARN` for 4xx, `ERROR` for 5xx. Panics are recovered by the middleware (`RecoverPanics`), +logged with a stack trace, and turned into a 500. `/healthz` is skipped so probe traffic does +not drown out real requests. The chi request ID is attached as `request_id`. + +Handlers do not log separately. A failed query calls `serverError` +([errors.go](internal/handler/errors.go)), which attaches the real error and an `op` label to +the request log through `httplog.SetError` and returns a generic message to the client: + +```json +{"log.level":"ERROR","message":"GET /v1/tasks?status=todo => HTTP 500 (491µs)","url.path":"/v1/tasks","http.response.status_code":500,"op":"count tasks","error.message":"boom: connection refused","request_id":"host/xxxx-000001"} +``` + +`httplog.SetAttrs` is a no-op outside the middleware, so a handler mounted without +`httplog.RequestLogger` still answers correctly but records nothing — `server.New` is the only +wiring and always installs it. + +`LOG_CONCISE=true` switches to a text handler and the concise schema, which drops everything +but the summary line: + +``` +time=2026-07-28T12:00:00.000+03:00 level=WARN msg="GET /v1/tasks/999 => HTTP 404 (1.2ms)" request_id=host/xxxx-000001 +``` + +The default (`LOG_CONCISE` unset) is full ECS JSON on stdout, which is what the container +should run. + +The schema built in `main.go` is passed to both the `slog` handler's `ReplaceAttr` and +`server.New` — they have to be the same value, or attributes get renamed by one schema and +filtered by another. + ### Changing the database 1. `make new-migration name=add_something` and fill in the `Up`/`Down` blocks. diff --git a/cmd/api/main.go b/cmd/api/main.go index 66b48a0..bde51f9 100644 --- a/cmd/api/main.go +++ b/cmd/api/main.go @@ -10,6 +10,7 @@ import ( "syscall" "time" + "github.com/go-chi/httplog/v3" "github.com/jackc/pgx/v5/pgxpool" "github.com/denysdovzhenko/task-api/internal/config" @@ -22,19 +23,35 @@ import ( // @description A small REST API for managing tasks, backed by Postgres. // @BasePath /v1 func main() { - logger := slog.New(slog.NewJSONHandler(os.Stdout, nil)) - if err := run(logger); err != nil { + // Config is loaded before the logger because LOG_CONCISE picks the format; + // a load failure is reported through the logger built from the zero Config. + cfg, cfgErr := config.Load() + schema, logger := newLogger(cfg.LogConcise) + + if cfgErr != nil { + logger.Error("startup failed", "err", cfgErr) + os.Exit(1) + } + if err := run(cfg, logger, schema); err != nil { logger.Error("startup failed", "err", err) os.Exit(1) } } -func run(logger *slog.Logger) error { - cfg, err := config.Load() - if err != nil { - return err +// newLogger returns the httplog schema and a logger whose attributes are +// renamed to match it. The schema has to be handed to the request-logger +// middleware as well — see server.New. +func newLogger(concise bool) (*httplog.Schema, *slog.Logger) { + schema := httplog.SchemaECS.Concise(concise) + opts := &slog.HandlerOptions{ReplaceAttr: schema.ReplaceAttr} + + if concise { + return schema, slog.New(slog.NewTextHandler(os.Stdout, opts)) } + return schema, slog.New(slog.NewJSONHandler(os.Stdout, opts)) +} +func run(cfg config.Config, logger *slog.Logger, schema *httplog.Schema) error { ctx := context.Background() pool, err := pgxpool.New(ctx, cfg.DatabaseURL) @@ -48,10 +65,10 @@ func run(logger *slog.Logger) error { } logger.Info("connected to postgres") - h := handler.New(pool, logger) + h := handler.New(pool) srv := &http.Server{ Addr: cfg.HTTPAddr, - Handler: server.New(h), + Handler: server.New(h, logger, schema), ReadTimeout: 5 * time.Second, WriteTimeout: 10 * time.Second, IdleTimeout: 60 * time.Second, diff --git a/go.mod b/go.mod index 1d6c23d..e86bafe 100644 --- a/go.mod +++ b/go.mod @@ -4,6 +4,7 @@ go 1.26.5 require ( github.com/go-chi/chi/v5 v5.3.1 + github.com/go-chi/httplog/v3 v3.4.0 github.com/jackc/pgx/v5 v5.10.0 github.com/swaggo/http-swagger v1.3.4 github.com/swaggo/swag v1.16.6 diff --git a/go.sum b/go.sum index 2012ec7..1340982 100644 --- a/go.sum +++ b/go.sum @@ -135,6 +135,8 @@ github.com/getkin/kin-openapi v0.140.0/go.mod h1:lISrB64F0CPcuDJ3LdtPTMJBY8VENjR github.com/ghodss/yaml v1.0.0/go.mod h1:4dBDuWmgqj2HViK6kFavaiC9ZROes6MMH2rRYeMEF04= github.com/go-chi/chi/v5 v5.3.1 h1:3j4HZLGZQ3JpMCrPJF/Jl3mYJfWLKBfNJ6quurUGCf8= github.com/go-chi/chi/v5 v5.3.1/go.mod h1:R+tYY2hNuVUUjxoPtqUdgBqevM9s9njzkTLutVsOCto= +github.com/go-chi/httplog/v3 v3.4.0 h1:gO4fvt8HEtFwHq926HoKe1aV2DymfPJuZy4+U4zwT3I= +github.com/go-chi/httplog/v3 v3.4.0/go.mod h1:tDhJo9G+F4mioDgX4pKbyA0uVZwCtHejoSsDkvJkFkU= github.com/go-faster/city v1.0.1 h1:4WAxSZ3V2Ws4QRDrscLEDcibJY8uf41H6AhXDrNDcGw= github.com/go-faster/city v1.0.1/go.mod h1:jKcUJId49qdW3L1qKHH/3wPeUstCVpVSXTM6vO3VcTw= github.com/go-faster/errors v0.7.1 h1:MkJTnDoEdi9pDabt1dpWf7AA8/BaSYZqibYyhZ20AYg= diff --git a/internal/config/config.go b/internal/config/config.go index ffee5c1..a51e31c 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -3,17 +3,22 @@ package config import ( "fmt" "os" + "strconv" ) type Config struct { HTTPAddr string DatabaseURL string + // LogConcise trades the structured JSON request log for a short, + // human-readable line — useful for `make run` / `make dev`. + LogConcise bool } func Load() (Config, error) { cfg := Config{ HTTPAddr: getEnv("HTTP_ADDR", ":8080"), DatabaseURL: os.Getenv("DATABASE_URL"), + LogConcise: getBoolEnv("LOG_CONCISE", false), } if cfg.DatabaseURL == "" { return Config{}, fmt.Errorf("DATABASE_URL is required") @@ -27,3 +32,12 @@ func getEnv(key, fallback string) string { } return fallback } + +// getBoolEnv falls back rather than failing on an unparseable value. +func getBoolEnv(key string, fallback bool) bool { + v, err := strconv.ParseBool(os.Getenv(key)) + if err != nil { + return fallback + } + return v +} diff --git a/internal/handler/errors.go b/internal/handler/errors.go index aca8280..f93860c 100644 --- a/internal/handler/errors.go +++ b/internal/handler/errors.go @@ -1,6 +1,11 @@ package handler -import "net/http" +import ( + "log/slog" + "net/http" + + "github.com/go-chi/httplog/v3" +) type errorResponse struct { Error string `json:"error"` @@ -11,6 +16,22 @@ func writeError(w http.ResponseWriter, status int, msg string) { writeJSON(w, status, errorResponse{Error: msg}) } +// serverError attaches the real error to the request log line that httplog +// writes when the response is finished, then returns a generic message to the +// client — internals are never leaked. op names the failing operation, because +// the request log has no message of its own to carry that (two calls can fail +// behind one route, e.g. list and count in ListTasks). +// +// httplog.SetAttrs is a no-op if the request did not pass through +// httplog.RequestLogger, so a handler mounted without that middleware records +// nothing. internal/server is the only wiring and it always installs it. +func serverError(w http.ResponseWriter, r *http.Request, op string, err error, msg string) { + ctx := r.Context() + httplog.SetAttrs(ctx, slog.String("op", op)) + httplog.SetError(ctx, err) + writeError(w, http.StatusInternalServerError, msg) +} + func writeValidationError(w http.ResponseWriter, fields map[string]string) { writeJSON(w, http.StatusUnprocessableEntity, errorResponse{ Error: "validation failed", Fields: fields, diff --git a/internal/handler/handler.go b/internal/handler/handler.go index bf3e121..4ddb5c7 100644 --- a/internal/handler/handler.go +++ b/internal/handler/handler.go @@ -2,7 +2,6 @@ package handler import ( "encoding/json" - "log/slog" "net/http" "github.com/jackc/pgx/v5/pgxpool" @@ -11,12 +10,14 @@ import ( ) type Handler struct { - q sqlc.Querier - logger *slog.Logger + q sqlc.Querier } -func New(pool *pgxpool.Pool, logger *slog.Logger) *Handler { - return &Handler{q: sqlc.New(pool), logger: logger} +// New builds the handler. There is no logger argument: server-side failures are +// recorded on the request log line written by httplog.RequestLogger, so the +// handler must be mounted behind that middleware — see serverError. +func New(pool *pgxpool.Pool) *Handler { + return &Handler{q: sqlc.New(pool)} } func writeJSON(w http.ResponseWriter, status int, v any) { diff --git a/internal/handler/task.go b/internal/handler/task.go index 337bc3a..f9e9dab 100644 --- a/internal/handler/task.go +++ b/internal/handler/task.go @@ -97,8 +97,7 @@ func (h *Handler) CreateTask(w http.ResponseWriter, r *http.Request) { Status: status, Priority: in.Priority, DueDate: in.DueDate, }) if err != nil { - h.logger.Error("create task", "err", err) - writeError(w, http.StatusInternalServerError, "could not create task") + serverError(w, r, "create task", err, "could not create task") return } writeJSON(w, http.StatusCreated, toTaskResponse(task)) @@ -126,8 +125,7 @@ func (h *Handler) GetTask(w http.ResponseWriter, r *http.Request) { writeError(w, http.StatusNotFound, "task not found") return } - h.logger.Error("get task", "err", err) - writeError(w, http.StatusInternalServerError, "could not fetch task") + serverError(w, r, "get task", err, "could not fetch task") return } writeJSON(w, http.StatusOK, toTaskResponse(task)) @@ -175,14 +173,12 @@ func (h *Handler) ListTasks(w http.ResponseWriter, r *http.Request) { Status: status, Limit: pageSize, Offset: (page - 1) * pageSize, }) if err != nil { - h.logger.Error("list tasks", "err", err) - writeError(w, http.StatusInternalServerError, "could not list tasks") + serverError(w, r, "list tasks", err, "could not list tasks") return } total, err := h.q.CountTasks(r.Context(), status) if err != nil { - h.logger.Error("count tasks", "err", err) - writeError(w, http.StatusInternalServerError, "could not list tasks") + serverError(w, r, "count tasks", err, "could not list tasks") return } @@ -232,8 +228,7 @@ func (h *Handler) UpdateTask(w http.ResponseWriter, r *http.Request) { writeError(w, http.StatusNotFound, "task not found") return } - h.logger.Error("update task", "err", err) - writeError(w, http.StatusInternalServerError, "could not update task") + serverError(w, r, "update task", err, "could not update task") return } writeJSON(w, http.StatusOK, toTaskResponse(task)) @@ -256,8 +251,7 @@ func (h *Handler) DeleteTask(w http.ResponseWriter, r *http.Request) { } rows, err := h.q.DeleteTask(r.Context(), id) if err != nil { - h.logger.Error("delete task", "err", err) - writeError(w, http.StatusInternalServerError, "could not delete task") + serverError(w, r, "delete task", err, "could not delete task") return } if rows == 0 { diff --git a/internal/handler/task_test.go b/internal/handler/task_test.go index db7bbca..cb77a19 100644 --- a/internal/handler/task_test.go +++ b/internal/handler/task_test.go @@ -3,8 +3,6 @@ package handler import ( "context" "encoding/json" - "io" - "log/slog" "net/http" "net/http/httptest" "strings" @@ -19,7 +17,7 @@ import ( ) func testHandler(q *fakeQuerier) *Handler { - return &Handler{q: q, logger: slog.New(slog.NewTextHandler(io.Discard, nil))} + return &Handler{q: q} } // testRouter mirrors the /v1/tasks routes wired up in internal/server, so diff --git a/internal/server/server.go b/internal/server/server.go index 9098cd4..5962d76 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -1,23 +1,41 @@ package server import ( + "log/slog" "net/http" "time" "github.com/go-chi/chi/v5" "github.com/go-chi/chi/v5/middleware" + "github.com/go-chi/httplog/v3" httpSwagger "github.com/swaggo/http-swagger" _ "github.com/denysdovzhenko/task-api/docs" "github.com/denysdovzhenko/task-api/internal/handler" ) -func New(h *handler.Handler) http.Handler { +// New builds the router. schema must be the same *httplog.Schema the logger's +// ReplaceAttr was built from, otherwise the request attributes are renamed by +// one schema and filtered by another. +func New(h *handler.Handler, logger *slog.Logger, schema *httplog.Schema) http.Handler { r := chi.NewRouter() - r.Use(middleware.Logger) r.Use(middleware.RequestID) - r.Use(middleware.Recoverer) + r.Use(httplog.RequestLogger(logger, &httplog.Options{ + Level: slog.LevelInfo, + Schema: schema, + RecoverPanics: true, + // Health probes are polled constantly and say nothing when they pass. + Skip: func(req *http.Request, _ int) bool { + return req.URL.Path == "/healthz" + }, + LogExtraAttrs: func(req *http.Request, _ string, _ int) []slog.Attr { + if id := middleware.GetReqID(req.Context()); id != "" { + return []slog.Attr{slog.String("request_id", id)} + } + return nil + }, + })) r.Use(middleware.Timeout(15 * time.Second)) r.Get("/healthz", func(w http.ResponseWriter, _ *http.Request) {