Structured Logging with slog
Write log lines as key/value pairs with log/slog so a log aggregator can filter and count them instead of guessing at text.
logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo}))A log line written as a sentence, like order 1021 failed after 812ms, is readable by a person and almost useless to a machine. Structured logging writes the same facts as named fields instead: a message plus order_id=1021 and ms=812. A log aggregator is the service that collects log lines from every running copy of your program; given fields it can filter on order_id and count by status, which no amount of pattern matching on prose will do reliably.
Logger, handler, level
log/slog arrived in Go 1.21. A *slog.Logger takes your message and fields; a handler decides what the output looks like. slog.NewJSONHandler writes one JSON object per line, which is what you want in production. slog.NewTextHandler writes key=value pairs, which is easier to read in a terminal.
Every record has a level, meaning how important it is: LevelDebug (-4), LevelInfo (0), LevelWarn (4), LevelError (8). The handler drops anything below its own level, so raising the level quiets a noisy service without a code change.
Two ways to write fields
Fields can be loose alternating pairs, logger.Info("saved", "id", 7), or typed attributes, logger.Info("saved", slog.Int("id", 7)). The first is shorthand for the second and produces an identical record. The typed form costs less work at run time and cannot be miscounted.
What trips people up
Field names drifting. One place logs user_id, another userID. Pick names once and attach the common ones with Logger.With.
Example
package main
import (
"log/slog"
"os"
)
func main() {
opts := &slog.HandlerOptions{
Level: slog.LevelInfo, // Debug records are dropped
// ReplaceAttr rewrites each field before it is written. Here it drops
// the timestamp so this program prints the same thing every run.
ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
if len(groups) == 0 && a.Key == slog.TimeKey {
return slog.Attr{} // a zero Attr is left out
}
return a
},
}
logger := slog.New(slog.NewJSONHandler(os.Stdout, opts))
// Shorthand: alternating key, value pairs.
logger.Info("order placed", "order_id", 1021, "total_cents", 4250)
// Longhand: the same record with the types written out.
logger.Info("order placed", slog.Int("order_id", 1021), slog.Int("total_cents", 4250))
logger.Debug("never printed: below the handler's level")
// With returns a logger that repeats these fields on every later record.
svc := logger.With(slog.String("service", "checkout"))
svc.Warn("slow database call", slog.Int("ms", 812))
}
// Output:
// {"level":"INFO","msg":"order placed","order_id":1021,"total_cents":4250}
// {"level":"INFO","msg":"order placed","order_id":1021,"total_cents":4250}
// {"level":"WARN","msg":"slow database call","service":"checkout","ms":812}
When to use it
- Make every log line from a service machine-queryable so an alert can count status=500 by endpoint.
- Turn on debug logging for one running pod through an admin endpoint, then turn it off.
- Tag all lines from the orders subsystem so a search can isolate them during an incident.
More examples
Changing the level while the program is running
Debug logging is expensive and noisy, so it is off in production, which is exactly when you want it. A LevelVar passed as the handler's Level lets you turn it on for a few minutes without a redeploy. LevelVar is safe for several goroutines to use at once, so no lock is needed around Set.
// A LevelVar is a level you can change later. Its zero value is LevelInfo.
var level slog.LevelVar
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: &level}))
slog.SetDefault(logger) // now the package functions slog.Info, slog.Error use it
mux := http.NewServeMux()
// Method and path patterns in ServeMux arrived in Go 1.22.
mux.HandleFunc("PUT /admin/log-level", func(w http.ResponseWriter, r *http.Request) {
var l slog.Level
if err := l.UnmarshalText([]byte(r.URL.Query().Get("level"))); err != nil {
http.Error(w, "level must be debug, info, warn or error", http.StatusBadRequest)
return
}
level.Set(l) // safe to call while other goroutines are logging
w.WriteHeader(http.StatusNoContent)
})
}Grouping related fields
Groups keep names short without making them ambiguous: http.status and db.ms rather than a flat status and ms that could belong to anything. Most aggregators index nested keys with a dot path, so you can still filter on http.status=500. Reach for a group when one record carries fields from two different subsystems.
logger.Info("request finished",
slog.Group("http",
"method", "GET",
"path", "/orders",
"status", 200,
),
slog.Group("db",
"queries", 3,
"ms", 12,
),
)
// JSON output nests them:
// {"level":"INFO","msg":"request finished",
// "http":{"method":"GET","path":"/orders","status":200},
// "db":{"queries":3,"ms":12}}One logger per component, built once
Passing a *slog.Logger in rather than reaching for the global one means a test can hand over a logger writing to a buffer and assert on what was recorded. The With call happens once at construction, so the per-line cost is nothing. ErrorContext takes the context, which matters once a handler puts a request id in it.
type OrderStore struct {
db *sql.DB
log *slog.Logger
}
func NewOrderStore(db *sql.DB, log *slog.Logger) *OrderStore {
// Every line from this store carries component=orders without repeating it.
return &OrderStore{db: db, log: log.With(slog.String("component", "orders"))}
}
func (s *OrderStore) Delete(ctx context.Context, id int64) error {
_, err := s.db.ExecContext(ctx, "DELETE FROM orders WHERE id = $1", id)
if err != nil {
// The error text goes in a field, not glued into the message.
s.log.ErrorContext(ctx, "delete order", "order_id", id, "error", err)
return fmt.Errorf("delete order %d: %w", id, err)
}
return nil
}
Discussion