first commit

2026-07-16 10:13:46 +03:30
commit 423c528b2f
42 changed files with 7298 additions and 0 deletions
@@ -0,0 +1,386 @@
+# 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.