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

* go-template/_template/internal/log: swapped zap logger with log/slog; added trace context handler; added gRPC interceptor logger

* go-template/_template/cmd/app: swapped zap logger with log/slog

* go-template/README: updated documentation references for logging

* fixup! go-template/go.mod: ran go mod tidy

* fixup! go-template/_template/cmd/app: swapped zap logger with log/slog

* go-template/pkg/gotemplate: excluded '_test.go' files from going into the text template parser

* fixup! go-template/_template/cmd/app: swapped zap logger with log/slog

* fixup! go-template/_template/internal/log: swapped zap logger with log/slog; added trace context handler; added gRPC interceptor logger

* Update _template/internal/log/context_test.go

Co-authored-by: Johannes Riecken <[email protected]>

* Update _template/internal/log/context_test.go

Co-authored-by: Johannes Riecken <[email protected]>

* fixup! go-template/_template/internal/log: swapped zap logger with log/slog; added trace context handler; added gRPC interceptor logger

* fixup! go-template/_template/internal/log: swapped zap logger with log/slog; added trace context handler; added gRPC interceptor logger

* fixup! go-template/_template/cmd/app: swapped zap logger with log/slog

* fixup! go-template/_template/cmd/app: swapped zap logger with log/slog

* fixup! go-template/_template/internal/log: swapped zap logger with log/slog; added trace context handler; added gRPC interceptor logger

* fixup! go-template/_template/cmd/app: swapped zap logger with log/slog

* fixup! go-template/_template/cmd/app: swapped zap logger with log/slog

* fixup! go-template/_template/cmd/app: swapped zap logger with log/slog

* fixup! go-template/_template/internal/log: swapped zap logger with log/slog; added trace context handler; added gRPC interceptor logger

* fixup! go-template/_template/internal/log: swapped zap logger with log/slog; added trace context handler; added gRPC interceptor logger

* fixup! go-template/_template/cmd/app: swapped zap logger with log/slog

* fixup! go-template/_template/internal/log: swapped zap logger with log/slog; added trace context handler; added gRPC interceptor logger

* 311: github/workflows: bump Go version to 1.21

* fixup! go-template/go.mod: ran go mod tidy

* fixup! 311: github/workflows: bump Go version to 1.21

* fixup! go-template/_template/cmd/app: swapped zap logger with log/slog

* fixup! go-template/_template/cmd/app: swapped zap logger with log/slog

* fixup! go-template/_template/internal/log: swapped zap logger with log/slog; added trace context handler; added gRPC interceptor logger

* fixup! go-template/_template/internal/log: swapped zap logger with log/slog; added trace context handler; added gRPC interceptor logger

* fixup! go-template/_template/internal/log: swapped zap logger with log/slog; added trace context handler; added gRPC interceptor logger

---------

Co-authored-by: Johannes Riecken <[email protected]>

.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),
+	}
+}