387 lines
12 KiB
Markdown
387 lines
12 KiB
Markdown
# 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.
|