# Lesson 2 — Structured JSON Logging with `slog` > **New Go concepts in this lesson:** closures (the three-layer middleware > pattern), variadic-style function calls, type aliases for interfaces. > Review the "closures" section of `00-go-basics-2-functions-structs-pointers.md` > before this one if middleware still feels confusing after Lesson 1. ## Why this matters Right now (end of Lesson 1), `middleware.Logger` from chi prints human-readable text to your terminal. That's fine to read by eye, but if you ever want to ship logs to something like Grafana Loki (via Grafana Alloy), you want **structured JSON** — one JSON object per log line — so you can filter and query by field (`status=500`, `path="/login"`, etc.) instead of parsing free-form text with regexes. Go's standard library has had a structured logging package, `log/slog`, since Go 1.21 — no third-party dependency needed. ## Part A — standalone playground Build understanding in isolation first, in a throwaway project: ```bash mkdir ~/go-playground/slog-demo && cd ~/go-playground/slog-demo go mod init slog-demo ``` **`main.go`** ```go package main import ( "log/slog" "os" "time" ) func main() { // 1. A plain text logger (human-readable, default style) textLogger := slog.New(slog.NewTextHandler(os.Stdout, nil)) textLogger.Info("this is text format", "user", "hamid", "attempt", 1) // 2. A JSON logger (what we want for Loki) jsonLogger := slog.New(slog.NewJSONHandler(os.Stdout, nil)) jsonLogger.Info("this is json format", "user", "hamid", "attempt", 1) // 3. Log levels jsonLogger.Debug("debug message - hidden by default") jsonLogger.Info("info message - shown") jsonLogger.Warn("warn message - shown") jsonLogger.Error("error message - shown", "err", "something broke") // 4. Structured fields with types jsonLogger.Info("user logged in", slog.String("username", "hamid"), slog.Int("user_id", 42), slog.Duration("took", 150*time.Millisecond), slog.Bool("success", true), ) // 5. A logger with permanent fields attached requestLogger := jsonLogger.With( slog.String("request_id", "abc-123"), slog.String("service", "go-simple-api"), ) requestLogger.Info("handling request") requestLogger.Info("finished request", slog.Int("status", 200)) // 6. Controlling minimum level explicitly debugLogger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{ Level: slog.LevelDebug, })) debugLogger.Debug("now debug shows up because we set the level") } ``` Run it: ```bash go run . ``` What to notice: - `slog.New(handler)` — every logger is a `*slog.Logger` wrapping a **Handler**, which decides output format and destination. Swap `NewTextHandler` ↔ `NewJSONHandler` and everything else in your code stays identical — this is the interface/implementation split from Go Basics Part 3 in action: your code depends on `*slog.Logger`'s methods (`Info`, `Error`, ...), not on which Handler is behind it. - By default, `Debug(...)` calls are **silently dropped** unless you explicitly set `Level: slog.LevelDebug` in `HandlerOptions` — that's why section 3's debug line doesn't print, but section 6's does. - `slog.String`, `slog.Int`, `slog.Duration`, `slog.Bool` are typed field constructors. You *can* skip them and just pass raw `"key", value` pairs (as in sections 1–2) and `slog` infers the type, but explicit typing is slightly faster and safer in hot paths. - `.With(...)` (section 5) returns a **new logger** with those fields baked in permanently — every call on `requestLogger` afterward automatically includes `request_id` and `service`. This is exactly the pattern we'll use per-request: attach a request ID once, log normally after that. ### How to change a logger's level *after* it's created You can't mutate the level on an existing logger directly — it lives inside the Handler and is normally fixed at creation. The fix is `slog.LevelVar`, a small mutable "box" for a level: ```go var level slog.LevelVar // defaults to LevelInfo logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{ Level: &level, // pointer to the LevelVar, not a fixed value })) logger.Debug("hidden") // nothing prints, level is Info level.Set(slog.LevelDebug) // change it later, anytime logger.Debug("now visible") // this prints ``` `HandlerOptions.Level` accepts anything implementing a `Leveler` interface (one method: `Level() slog.Level`). A plain `slog.Level` implements it by returning itself (fixed forever); `*slog.LevelVar` also implements it, but its `Level()` reads a value you can change at runtime via `.Set()`. The handler re-checks the level on every log call. ## Part B — apply it to the project **No new dependencies** — `log/slog` is part of the standard library. **`internal/logging/logger.go`** ```go package logging import ( "log/slog" "os" ) func New() *slog.Logger { level := slog.LevelInfo if os.Getenv("LOG_LEVEL") == "debug" { level = slog.LevelDebug } handler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{ Level: level, }) return slog.New(handler) } ``` Matches Part A section 6 — JSON handler, level controlled by env var instead of hardcoded. ### The middleware "three-layer function" pattern, explained from scratch Before the request-logging middleware code, let's build up to it slowly, since this shape (a function that takes some setup and returns a `func(http.Handler) http.Handler`) will reappear for authentication in Lesson 8. **Step 1 — the simplest possible middleware, no arguments:** ```go func SimpleLogger(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { log.Println("before request") next.ServeHTTP(w, r) log.Println("after request") }) } ``` - Takes `next` (whatever handler comes after this one in the chain). - Returns a NEW `http.Handler`. `http.HandlerFunc(...)` is a type conversion — it turns a plain `func(w, r)` into something satisfying the `http.Handler` interface (see Go Basics Part 3: interfaces are just "has the right method," and `HandlerFunc` is a built-in adapter that gives any matching function a `ServeHTTP` method for free). - Code before `next.ServeHTTP(w, r)` runs **before** the real request handling; code after runs **after**. - Usage: `r.Use(SimpleLogger)` — no parentheses needed after `SimpleLogger`, since we're passing the function itself, and it already has the exact shape `r.Use` expects. **Step 2 — now we want to pass in a logger.** `r.Use()` only accepts `func(http.Handler) http.Handler` — no room for extra arguments. So we wrap that shape inside ANOTHER function that takes the logger first: ```go func RequestLogger(logger *slog.Logger) func(http.Handler) http.Handler { // ^ takes the logger ^ returns the middleware shape return func(next http.Handler) http.Handler { // ^ THIS is the actual func(http.Handler) http.Handler chi wants return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { // ^ THIS is the real per-request logic ... }) } } ``` Three layers, each running at a different time: | Layer | Runs when | Purpose | |---|---|---| | `RequestLogger(logger)` | Once, when building the router | Captures `logger` in a closure | | `func(next http.Handler) http.Handler` | Once, when chi wires up the chain | Captures `next` in a closure | | `func(w, r) {...}` | On every single HTTP request | Does the actual logging | This is exactly the **closure** concept from Go Basics Part 2's `makeCounter` example — each inner function "remembers" variables from the outer function that created it, even after that outer function has returned. Usage: `r.Use(RequestLogger(logger))` — note `RequestLogger(logger)` is a **function call**, not a bare reference. It runs the outer layer immediately and returns the middle layer, which is what actually gets handed to `r.Use()`. ### `internal/middleware/request_logger.go` ```go package middleware import ( "log/slog" "net/http" "time" chimw "github.com/go-chi/chi/v5/middleware" ) func RequestLogger(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) { start := time.Now() // record the time BEFORE the request is handled, so we can // measure how long it took afterward ww := chimw.NewWrapResponseWriter(w, r.ProtoMajor) // a plain http.ResponseWriter only lets you WRITE a // status/body, not read it back afterward. This wraps it so // ww.Status() and ww.BytesWritten() become available once the // response has been sent. next.ServeHTTP(ww, r) // run the rest of the chain / the final handler. We pass ww // (the wrapped writer), not w, so the wrapping actually // captures what gets written downstream. Everything BELOW // this line runs AFTER the response is done. logger.Info("http_request", slog.String("request_id", chimw.GetReqID(r.Context())), // the RequestID middleware (earlier in the chain) stored // an ID inside the request's context; we read it back // here slog.String("method", r.Method), slog.String("path", r.URL.Path), slog.Int("status", ww.Status()), slog.Int("bytes", ww.BytesWritten()), slog.Duration("duration_ms", time.Since(start)), slog.String("remote_addr", r.RemoteAddr), ) }) } } ``` We alias `chimw "github.com/go-chi/chi/v5/middleware"` in the import so it doesn't collide with our own package's name (`middleware`). ### `internal/router/router.go` (updated) ```go package router import ( "log/slog" "time" "github.com/go-chi/chi/v5" chimw "github.com/go-chi/chi/v5/middleware" "git.hamidsoltani.com/hamid/go-simple-api/internal/handlers" "git.hamidsoltani.com/hamid/go-simple-api/internal/middleware" ) func New(logger *slog.Logger) *chi.Mux { r := chi.NewRouter() r.Use(chimw.RequestID) r.Use(middleware.RequestLogger(logger)) r.Use(chimw.Recoverer) r.Use(chimw.Timeout(60 * time.Second)) r.Get("/health", handlers.Health) return r } ``` `New` now takes a `*slog.Logger` **parameter** — this is dependency injection (see the main README/ARCHITECTURE docs): instead of the router building its own logger internally, it receives one from `main.go`, so the whole app shares exactly one logger instance. ### `cmd/api/main.go` (updated) ```go package main import ( "context" "net/http" "os" "os/signal" "syscall" "time" "git.hamidsoltani.com/hamid/go-simple-api/internal/config" "git.hamidsoltani.com/hamid/go-simple-api/internal/logging" "git.hamidsoltani.com/hamid/go-simple-api/internal/router" ) func main() { cfg := config.Load() logger := logging.New() r := router.New(logger) srv := &http.Server{ Addr: ":" + cfg.Port, Handler: r, } go func() { logger.Info("server starting", "port", cfg.Port) if err := srv.ListenAndServe(); err != nil && err != http.ErrServerClosed { logger.Error("server error", "error", err) os.Exit(1) } }() quit := make(chan os.Signal, 1) signal.Notify(quit, syscall.SIGINT, syscall.SIGTERM) <-quit logger.Info("shutting down gracefully") ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() if err := srv.Shutdown(ctx); err != nil { logger.Error("forced shutdown", "error", err) os.Exit(1) } logger.Info("server stopped") } ``` We swapped `log.Printf`/`log.Fatalf` for our structured `logger`. Note `logger.Info("server starting", "port", cfg.Port)` — `slog`'s convenience methods also accept plain alternating key/value pairs (no `slog.String` wrapper needed) when calling `.Info`/`.Error` directly; both styles produce the same structured JSON. We replaced `log.Fatalf` with `logger.Error(...)` + `os.Exit(1)`, since `log.Fatal` writes plain text and would break our "everything is JSON" goal. ## Try it ```bash go run ./cmd/api curl http://localhost:8080/health ``` You should see JSON lines like: ```json {"time":"2026-07-15T10:00:00Z","level":"INFO","msg":"server starting","port":"8080"} {"time":"2026-07-15T10:00:05Z","level":"INFO","msg":"http_request","request_id":"...","method":"GET","path":"/health","status":200,"bytes":16,"duration_ms":123000,"remote_addr":"127.0.0.1:54321"} ``` This is exactly the shape Grafana Alloy likes to scrape from container stdout and ship to Loki — one JSON object per line, consistent keys, no custom parsing needed. Once both parts run cleanly, move to Lesson 3 — config & MySQL connection.