feat(logging): Swap loggers from zap to log/slog

.github/workflows/generate.yml

@@ -21,7 +21,7 @@ jobs:
  - name: Install Go
  uses: actions/setup-go@v5
  with:
- go-version: "^1.20.6"
+ go-version: "^1.21.6"
 
  - name: Checkout code
  uses: actions/checkout@v4

.github/workflows/main.yml

@@ -17,7 +17,7 @@ jobs:
  - name: Install Go
  uses: actions/setup-go@v5
  with:
- go-version: "^1.20.6"
+ go-version: "^1.21.6"
 
  - name: Checkout code
  uses: actions/checkout@v4

.github/workflows/release.yaml

@@ -22,7 +22,7 @@ jobs:
  - name: Set up Go
  uses: actions/setup-go@v5
  with:
- go-version: 1.20
+ go-version: 1.21
  - uses: actions/cache@v4
  with:
  path: |

README.md

@@ -20,7 +20,7 @@
 - gRPC support
 - folder structure based on [github.com/golang-standards/project-layout](https://github.com/golang-standards/project-layout)
 - enforced default packages
- - `go.uber.org/zap` for logging
+ - `log/slog` for logging
  - `go.uber.org/automaxprocs` to be safe in container environments (see [this article](https://martin.baillie.id/wrote/gotchas-in-the-go-network-packages-defaults/#bonus-gomaxprocs-containers-and-the-cfs) for more information)
 
 ## Usage

_template/cmd/{{.Base.appName}}/main.go

@@ -1,35 +1,42 @@
 package main
 
 import (
+ "context"
  "fmt"
+ "log/slog"
  "os"
 
- "{{.Base.moduleName}}/internal/log"
- "go.uber.org/zap"
-
  // This controls the maxprocs environment variable in container runtimes.
  // see https://martin.baillie.id/wrote/gotchas-in-the-go-network-packages-defaults/#bonus-gomaxprocs-containers-and-the-cfs
- _ "go.uber.org/automaxprocs"
+ "go.uber.org/automaxprocs/maxprocs"
+
+ "{{.Base.moduleName}}/internal/log"
 )
 
 func main() {
- if err := run(); err != nil {
- fmt.Fprintf(os.Stderr, "an error occurred: %s\n", err)
+ // Logger configuration
+ logger := log.New(
+ log.WithLevel(os.Getenv("LOG_LEVEL")),
+ log.WithSource(),
+ )
+
+ if err := run(logger); err != nil {
+ logger.ErrorContext(context.Background(), "an error occurred", slog.String("error", err.Error()))
  os.Exit(1)
  }
 }
 
-func run() error {
- logger, err := log.NewAtLevel(os.Getenv("LOG_LEVEL"))
+func run(logger *slog.Logger) error {
+ ctx := context.Background()
+
+ _, err := maxprocs.Set(maxprocs.Logger(func(s string, i ...interface{}) {
+ logger.DebugContext(ctx, fmt.Sprintf(s, i...))
+ }))
  if err != nil {
- return err
+ return fmt.Errorf("setting max procs: %w", err)
  }
 
- defer func() {
- err = logger.Sync()
- }()
-
- logger.Info("Hello world!", zap.String("location", "world"))
+ logger.InfoContext(ctx, "Hello world!", slog.String("location", "world"))
 
- return err
+ return nil
 }

_template/internal/log/access_log.go

@@ -0,0 +1,17 @@
+package log
+
+import (
+ "context"
+ "log/slog"
+
+ "github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging"
+)
+
+// InterceptorLogger is a gRPC interceptor that logs calls to gRPC endpoints, from:
+// https://github.com/grpc-ecosystem/go-grpc-middleware/blob/main/interceptors/logging/examples/slog/example_test.go
+// licensed as Apache 2.0.
+func InterceptorLogger(l *slog.Logger) logging.Logger {
+ return logging.LoggerFunc(func(ctx context.Context, lvl logging.Level, msg string, fields ...any) {
+ l.Log(ctx, slog.Level(lvl), msg, fields...)
+ })
+}

_template/internal/log/access_log_test.go

@@ -0,0 +1,97 @@
+package log
+
+import (
+ "bytes"
+ "context"
+ "log/slog"
+ "testing"
+
+ "github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging"
+ "github.com/stretchr/testify/require"
+)
+
+func TestInterceptorLogger(t *testing.T) {
+ testcases := []struct {
+ Name string
+
+ LoggerLevel slog.Leveler
+
+ Level logging.Level
+ Message string
+ Fields []any
+
+ Expected string
+ }{{
+ Name: "Info log with fields",
+ LoggerLevel: slog.LevelInfo,
+ Level: logging.LevelInfo,
+ Message: "Test info message",
+ Fields: []any{
+ "string", "hello world",
+ "int", 42,
+ "int16", int16(1),
+ "int32", int32(2),
+ "int64", int64(3),
+ "bool", true,
+ "float32", float32(3.141),
+ "float64", 3.1415926,
+ "any",
+ struct{}{},
+ },
+ Expected: `","level":"INFO","msg":"Test info message","string":"hello world",` +
+ `"int":42,"int16":1,"int32":2,"int64":3,"bool":true,"float32":3.1410000324249268,"float64":3.1415926,"any":{}}`,
+ }, {
+ Name: "Debug log but deactivated",
+ LoggerLevel: slog.LevelInfo,
+ Level: logging.LevelDebug,
+ Message: "debug log deactivated",
+ Fields: nil,
+ Expected: "",
+ }, {
+ Name: "Warn log",
+ LoggerLevel: slog.LevelInfo,
+ Level: logging.LevelWarn,
+ Message: "This is a warning log",
+ Fields: nil,
+ Expected: `,"level":"WARN","msg":"This is a warning log"}`,
+ }, {
+ Name: "Error log",
+ LoggerLevel: slog.LevelInfo,
+ Level: logging.LevelError,
+ Message: "This is an error log",
+ Fields: nil,
+ Expected: `,"level":"ERROR","msg":"This is an error log"}`,
+ }, {
+ Name: "Invalid log level",
+ LoggerLevel: slog.LevelInfo,
+ Level: 42,
+ Message: "level 42!",
+ Fields: nil,
+ Expected: `,"level":"ERROR+34","msg":"level 42!"}`,
+ }, {
+ Name: "Invalid field key",
+ LoggerLevel: slog.LevelInfo,
+ Level: logging.LevelInfo,
+ Message: "test",
+ Fields: logging.Fields{
+ 42, "test",
+ },
+ Expected: `,"level":"INFO","msg":"test","!BADKEY":42,"!BADKEY":"test"}`,
+ }}
+
+ for _, testcase := range testcases {
+ t.Run(testcase.Name, func(t *testing.T) {
+ buffer := bytes.Buffer{}
+ logger := slog.New(slog.NewJSONHandler(&buffer, &slog.HandlerOptions{
+ AddSource: false, // so it can be tested without a filesystem path
+ Level: testcase.LoggerLevel,
+ }))
+
+ loggerFunc := InterceptorLogger(logger)
+
+ loggerFunc.Log(context.Background(), testcase.Level, testcase.Message, testcase.Fields...)
+
+ require.Contains(t, buffer.String(), testcase.Expected)
+ })
+ }
+}

_template/internal/log/context.go

@@ -0,0 +1,129 @@
+package log
+
+import (
+ "context"
+ "log/slog"
+ "os"
+
+ "go.opentelemetry.io/otel/trace"
+)
+
+// traceIDKey and spanIDKey define the key values for log attributes, for tracing metadata
+//
+// https://opentelemetry.io/docs/specs/otel/compatibility/logging_trace_context/
+const (
+ traceIDKey = "trace_id"
+ spanIDKey = "span_id"
+)
+
+const maxSpanContextAttrs = 2
+
+// SpanContextHandler is a slog.Handler wrapper that adds trace data as log attributes on each
+// Handle call, given that the input context to the method contains a valid trace.SpanContext.
+type SpanContextHandler struct {
+ withSpanID bool
+ handler slog.Handler
+}
+
+//nolint:gochecknoglobals // instantiated once on a package level to be used in comparisons in NewSpanContextHandler
+var nilHandler = slog.Handler(nil)
+
+// NewSpanContextHandler creates a SpanContextHandler from the input slog.Handler and optional
+// configuration.
+func NewSpanContextHandler(handler slog.Handler, withSpanID bool) slog.Handler {
+ if handler == nil || handler == nilHandler {
+ handler = defaultHandler()
+ }
+
+ return &SpanContextHandler{
+ withSpanID: withSpanID,
+ handler: handler,
+ }
+}
+
+func defaultHandler() slog.Handler {
+ return slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
+ AddSource: true,
+ })
+}
+
+// Enabled reports whether the handler handles records at the given level.
+// The handler ignores records whose level is lower.
+// It is called early, before any arguments are processed,
+// to save effort if the log event should be discarded.
+// If called from a Logger method, the first argument is the context
+// passed to that method, or context.Background() if nil was passed
+// or the method does not take a context.
+// The context is passed so Enabled can use its values
+// to make a decision.
+func (h *SpanContextHandler) Enabled(ctx context.Context, level slog.Level) bool {
+ return h.handler.Enabled(ctx, level)
+}
+
+// Handle handles the Record.
+// It will only be called when Enabled returns true.
+// The Context argument is as for Enabled.
+// It is present solely to provide Handlers access to the context's values.
+// Canceling the context should not affect record processing.
+// (Among other things, log messages may be necessary to debug a
+// cancellation-related problem.)
+//
+// Handle methods that produce output should observe the following rules:
+// - If r.Time is the zero time, ignore the time.
+// - If r.PC is zero, ignore it.
+// - Attr's values should be resolved.
+// - If an Attr's key and value are both the zero value, ignore the Attr.
+// This can be tested with attr.Equal(Attr{}).
+// - If a group's key is empty, inline the group's Attrs.
+// - If a group has no Attrs (even if it has a non-empty key),
+// ignore it.
+func (h *SpanContextHandler) Handle(ctx context.Context, record slog.Record) error {
+ if sc := trace.SpanContextFromContext(ctx); sc.IsValid() {
+ attrs := make([]slog.Attr, 1, maxSpanContextAttrs)
+ attrs[0] = slog.String(traceIDKey, sc.TraceID().String())
+
+ if h.withSpanID {
+ attrs = append(attrs, slog.String(spanIDKey, sc.SpanID().String()))
+ }
+
+ record.AddAttrs(attrs...)
+ }
+
+ return h.handler.Handle(ctx, record)
+}
+
+// WithAttrs returns a new Handler whose attributes consist of
+// both the receiver's attributes and the arguments.
+// The Handler owns the slice: it may retain, modify or discard it.
+func (h *SpanContextHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
+ return &SpanContextHandler{
+ withSpanID: h.withSpanID,
+ handler: h.handler.WithAttrs(attrs),
+ }
+}
+
+// WithGroup returns a new Handler with the given group appended to
+// the receiver's existing groups.
+// The keys of all subsequent attributes, whether added by With or in a
+// Record, should be qualified by the sequence of group names.
+//
+// How this qualification happens is up to the Handler, so long as
+// this Handler's attribute keys differ from those of another Handler
+// with a different sequence of group names.
+//
+// A Handler should treat WithGroup as starting a Group of Attrs that ends
+// at the end of the log event. That is,
+//
+// logger.WithGroup("s").LogAttrs(level, msg, slog.Int("a", 1), slog.Int("b", 2))
+//
+// should behave like
+//
+// logger.LogAttrs(level, msg, slog.Group("s", slog.Int("a", 1), slog.Int("b", 2)))
+//
+// If the name is empty, WithGroup returns the receiver.
+func (h *SpanContextHandler) WithGroup(name string) slog.Handler {
+ return &SpanContextHandler{
+ withSpanID: h.withSpanID,
+ handler: h.handler.WithGroup(name),
+ }
+}