Logging

Logging is crucial for developers to monitor system behavior and is often the first step in debugging. Logs can be voluminous, so quickly searching and filtering them is essential.

Logging with log/slog

Structured logs, which use key-value pairs, allow for efficient parsing, filtering, searching, and analysis.

The log/slog package introduced in Go 1.21 brings structured logging to the standard library.

Structured Logging

package main

import "log/slog"

func main() {
    slog.Info("hello, world", "key", "value")
}

Output:

2024/10/26 14:46:41 INFO hello, world key=value

TextHandler

To log in a text format:

logger := slog.New(slog.NewTextHandler(os.Stdout, nil))
logger.Info("hello, world", "key", "value")

Output:

time=2024-10-26T14:49:19.081+08:00 level=INFO msg="hello, world" key=value

JSONHandler

To log in JSON format:

logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
logger.Info("hello, world", "key", "value")

Output:

{"time":"2024-10-26T14:49:52.613743+08:00","level":"INFO","msg":"hello, world","key":"value"}

Logging Context Information

In Go, Context is a mechanism to carry deadlines, cancellation signals, and other request-scoped values across API boundaries and through layers of the application.

package main

import (
    "context"
    "fmt"
    "log/slog"
    "net/http"
)

func processRequest(w http.ResponseWriter, r *http.Request) {
    slog.Info("processRequest",
        "requestId", r.Context().Value("request-id"),
        "name", r.PathValue("name"))
    
    fmt.Fprintf(w, "Hello %s!", r.PathValue("name"))
}

func main() {
    http.HandleFunc("/hello/{name}", func(w http.ResponseWriter, r *http.Request) {
        processRequest(w, r.WithContext(context.WithValue(r.Context(), "request-id", r.Header.Get("x-request-id"))))
    })

    if err := http.ListenAndServe(":3000", nil); err != nil {
        panic(err)
    }
}

Example request:

curl localhost:3000/hello/x -H 'X-Request-ID: 8b036946-b46b-4a24-bad0-254e109093a9'

Log:

2024/10/27 11:11:58 INFO processRequest requestId=8b036946-b46b-4a24-bad0-254e109093a9 name=x

Manually printing context information can be inconvenient. The slog package provides a method to automatically include context information.

package main

import (
    "context"
    "fmt"
    "log/slog"
    "net/http"
    "os"
)

func processRequest(w http.ResponseWriter, r *http.Request) {
    r.Context().Value("logger").(*slog.Logger).Info("processRequest", "name", r.PathValue("name"))
    fmt.Fprintf(w, "Hello %s!", r.PathValue("name"))
}

func main() {
    http.HandleFunc("/hello/{name}", func(w http.ResponseWriter, r *http.Request) {
        logger := slog.New(slog.NewTextHandler(os.Stdout, nil))
        logger = logger.With("request-id", r.Header.Get("x-request-id"))
        processRequest(w, r.WithContext(context.WithValue(r.Context(), "logger", logger)))
    })

    if err := http.ListenAndServe(":3000", nil); err != nil {
        panic(err)
    }
}

Custom Logger Handler

Alternatively, you can log contextual information using the .InfoContext() method, but this requires a custom log handler.

package main

import (
    "context"
    "log/slog"
    "net/http"
    "os"
)

type ContextHandler struct {
    slog.Handler
}

func (h *ContextHandler) Handle(ctx context.Context, r slog.Record) error {
    if requestID, ok := ctx.Value("request-id").(string); ok {
        r.AddAttrs(slog.String("request-id", requestID))
    }
    return h.Handler.Handle(ctx, r)
}

func main() {
    logger := slog.New(&ContextHandler{Handler: slog.NewTextHandler(os.Stdout, nil)})

    http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
        ctx := context.WithValue(r.Context(), "request-id", r.Header.Get("x-request-id"))
        logger.InfoContext(ctx, "hello")
    })

    if err := http.ListenAndServe(":3000", nil); err != nil {
        panic(err)
    }
}