diff --git a/README.md b/README.md index 2e9120f..1af1a5b 100644 --- a/README.md +++ b/README.md @@ -14,7 +14,7 @@ one of them does not pull anything else in. | [deferred](./deferred) | Helpers for the `defer` calls. | | [dispatcher](./dispatcher) | Routing of keyed events to handlers, with priorities, propagation control and wildcards. | | [protomap](./protomap) | Deserialization of protobuf messages by their descriptor name. | -| [slogger](./slogger) | A `log/slog` logger with a configurable format, a hot-reloadable level and a writer. | +| [slogger](./slogger) | A `log/slog` logger with a configurable format, a hot-reloadable level and context helpers. | | [strcase](./strcase) | Detection of the case of a string and conversion between the case styles. | | [sync](./sync) | A `sync.Once` that keeps retrying until the guarded function succeeds. | | [time](./time) | A duration type that is serialized as a human-readable string. | diff --git a/slogger/README.md b/slogger/README.md index eaecb54..197b4fa 100644 --- a/slogger/README.md +++ b/slogger/README.md @@ -3,8 +3,17 @@ A `log/slog` logger with a configurable format, a hot-reloadable log level and a custom writer. +The module is split into two packages: + +- [`github.com/nbgrp/pkg/slogger`](./slogger.go) — the logger constructor. +- [`github.com/nbgrp/pkg/slogger/ctxlog`](./ctxlog/ctxlog.go) — the helpers that + pass the logger and its attributes through the + [context](https://pkg.go.dev/context). + ## Public API +The `slogger` package provides: + ```go type Options struct { // Leveler returns the current log level. @@ -20,6 +29,7 @@ type Options struct { } func New(ctx context.Context, opts Options) (*slog.Logger, error) +func NewToContext(ctx context.Context, opts Options) (context.Context, error) ``` - `Leveler` — the current log level: `"DEBUG"`, `"INFO"`, `"WARN"` or `"ERROR"` @@ -29,6 +39,10 @@ func New(ctx context.Context, opts Options) (*slog.Logger, error) change. Without it the level is set once, at startup. - `Writer` — the destination of the records; `os.Stdout` by default. +`NewToContext` is the same as `New`, but it puts the logger into the returned +context, so it can be used with the [`ctxlog`](#context-logger) helpers. The +returned context is nil if the logger cannot be initialized. + ## Usage ```go @@ -135,3 +149,81 @@ time=... level=ERROR msg="Failed to parse log level while hot-reload update" err The logger is safe for concurrent use, as any `slog.Logger` is. The `Leveler` is called from the watcher goroutine, so it must be safe for concurrent use as well. + +## Context logger + +The `ctxlog` package passes the logger through the +[context](https://pkg.go.dev/context): the logger is put into the context once, +and the package-level functions take it from there. The code that writes the log +stays independent of the way the logger is built and of the attributes of the +current request. + +### Public API + +```go +func ToContext(ctx context.Context, logger *slog.Logger) context.Context +func FromContext(ctx context.Context) *slog.Logger +func Debug(ctx context.Context, msg string, args ...any) +func Info(ctx context.Context, msg string, args ...any) +func Warn(ctx context.Context, msg string, args ...any) +func Error(ctx context.Context, msg string, args ...any) +func With(ctx context.Context, args ...any) context.Context +func Log(ctx context.Context, level slog.Level, msg string, args ...any) +func LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) +``` + +- `ToContext` puts the logger into the context, `FromContext` takes it from + there. If the context has no logger, `slog.Default()` is used. +- `With` returns a derived context with the given attributes bound to it: they + are added to every record written with that context. Without the arguments it + returns the context unchanged. +- `Log` and `LogAttrs` write a record with an arbitrary level; `Debug`, `Info`, + `Warn` and `Error` are the shortcuts for `slog.LevelDebug`, `slog.LevelInfo`, + `slog.LevelWarn` and `slog.LevelError`. + +### Usage + +```go +ctx, err := slogger.NewToContext(ctx, slogger.Options{ + Leveler: func() string { return "INFO" }, + Format: "json", +}) +if err != nil { + return err +} + +ctxlog.Info(ctx, "Server started", slog.String("addr", ":8080")) +``` + +The logger can also be put into the context explicitly: + +```go +logger, err := slogger.New(ctx, slogger.Options{ + Leveler: func() string { return "INFO" }, + Format: "json", +}) +if err != nil { + return err +} + +ctx = ctxlog.ToContext(ctx, logger) +``` + +The arguments are passed to `slog` as is, so all the forms the standard library +understands are supported: + +```go +ctxlog.Info(ctx, "Server started", "addr", ":8080") // a key-value pair +ctxlog.Info(ctx, "Server started", slog.String("addr", ":8080")) // a slog.Attr +``` + +The attributes common to all the records of the scope are bound to the context: + +```go +ctx = ctxlog.With(ctx, "request_id", requestID) + +ctxlog.Info(ctx, "Started") +``` + +The context passed to the logging call is passed to the handler as well, so a +custom handler can take the values from it. diff --git a/slogger/ctxlog/ctxlog.go b/slogger/ctxlog/ctxlog.go new file mode 100644 index 0000000..01e81e2 --- /dev/null +++ b/slogger/ctxlog/ctxlog.go @@ -0,0 +1,53 @@ +// SPDX-License-Identifier: BSD-3-Clause + +package ctxlog + +import ( + "context" + "log/slog" +) + +type loggerKey struct{} + +func ToContext(ctx context.Context, logger *slog.Logger) context.Context { + return context.WithValue(ctx, loggerKey{}, logger) +} + +func FromContext(ctx context.Context) *slog.Logger { + if l, ok := ctx.Value(loggerKey{}).(*slog.Logger); ok { + return l + } + return slog.Default() +} + +func Debug(ctx context.Context, msg string, args ...any) { + FromContext(ctx).DebugContext(ctx, msg, args...) +} + +func Info(ctx context.Context, msg string, args ...any) { + FromContext(ctx).InfoContext(ctx, msg, args...) +} + +func Warn(ctx context.Context, msg string, args ...any) { + FromContext(ctx).WarnContext(ctx, msg, args...) +} + +func Error(ctx context.Context, msg string, args ...any) { + FromContext(ctx).ErrorContext(ctx, msg, args...) +} + +func With(ctx context.Context, args ...any) context.Context { + if len(args) == 0 { + return ctx + } + + return ToContext(ctx, FromContext(ctx).With(args...)) +} + +func Log(ctx context.Context, level slog.Level, msg string, args ...any) { + FromContext(ctx).Log(ctx, level, msg, args...) +} + +func LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) { + FromContext(ctx).LogAttrs(ctx, level, msg, attrs...) +} diff --git a/slogger/ctxlog/ctxlog_test.go b/slogger/ctxlog/ctxlog_test.go new file mode 100644 index 0000000..e753350 --- /dev/null +++ b/slogger/ctxlog/ctxlog_test.go @@ -0,0 +1,281 @@ +// SPDX-License-Identifier: BSD-3-Clause + +package ctxlog_test + +import ( + "bytes" + "context" + "log/slog" + "slices" + "strings" + "sync" + "testing" + + . "github.com/nbgrp/pkg/slogger/ctxlog" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// setupLogger returns a buffer, a logger writing to it and a context with the +// logger attached. +func setupLogger(t *testing.T) (*bytes.Buffer, *slog.Logger, context.Context) { + t.Helper() + + buf := &bytes.Buffer{} + handler := slog.NewTextHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug}) + logger := slog.New(handler) + + return buf, logger, ToContext(t.Context(), logger) +} + +func TestToContext(t *testing.T) { + t.Parallel() + + _, logger, ctx := setupLogger(t) + + assert.Same(t, logger, FromContext(ctx)) +} + +func TestFromContext_Default(t *testing.T) { + t.Parallel() + + assert.Same(t, slog.Default(), FromContext(t.Context())) +} + +func TestLogs(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + log func(ctx context.Context) + want string + }{ + { + name: "debug", + log: func(ctx context.Context) { Debug(ctx, "Message") }, + want: "level=DEBUG msg=Message", + }, + { + name: "info", + log: func(ctx context.Context) { Info(ctx, "Message") }, + want: "level=INFO msg=Message", + }, + { + name: "warn", + log: func(ctx context.Context) { Warn(ctx, "Message") }, + want: "level=WARN msg=Message", + }, + { + name: "error", + log: func(ctx context.Context) { Error(ctx, "Message") }, + want: "level=ERROR msg=Message", + }, + { + name: "log", + log: func(ctx context.Context) { Log(ctx, slog.LevelWarn, "Message", "key", "value") }, + want: "level=WARN msg=Message key=value", + }, + { + name: "log_attrs", + log: func(ctx context.Context) { LogAttrs(ctx, slog.LevelError, "Message", slog.String("key", "value")) }, + want: "level=ERROR msg=Message key=value", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + buf, _, ctx := setupLogger(t) + + tt.log(ctx) + + assert.Contains(t, buf.String(), tt.want) + }) + } +} + +func TestAttrs(t *testing.T) { + t.Parallel() + + buf, _, ctx := setupLogger(t) + + Info(ctx, "Message", "key", "value", "num", 42) + + out := buf.String() + assert.Contains(t, out, "key=value") + assert.Contains(t, out, "num=42") +} + +func TestSlogAttr(t *testing.T) { + t.Parallel() + + buf, _, ctx := setupLogger(t) + + Info(ctx, "Message", slog.String("key", "value")) + + assert.Contains(t, buf.String(), "key=value") +} + +func TestAttrsMixed(t *testing.T) { + t.Parallel() + + buf, _, ctx := setupLogger(t) + + Info(ctx, "Message", "key", "value", slog.String("tenant", "acme")) + + out := buf.String() + assert.Contains(t, out, "key=value") + assert.Contains(t, out, "tenant=acme") +} + +func TestWith(t *testing.T) { + t.Parallel() + + buf, _, ctx := setupLogger(t) + + ctx = With(ctx, "request_id", "abc") + Info(ctx, "Message") + + assert.Contains(t, buf.String(), "request_id=abc") +} + +func TestWithSlogAttr(t *testing.T) { + t.Parallel() + + buf, _, ctx := setupLogger(t) + + ctx = With(ctx, slog.String("request_id", "abc")) + Info(ctx, "Message") + + assert.Contains(t, buf.String(), "request_id=abc") +} + +func TestWithMixedAttrs(t *testing.T) { + t.Parallel() + + buf, _, ctx := setupLogger(t) + + ctx = With(ctx, "request_id", "abc", slog.String("tenant", "acme")) + Info(ctx, "Message") + + out := buf.String() + assert.Contains(t, out, "request_id=abc") + assert.Contains(t, out, "tenant=acme") +} + +func TestWith_NoArgs(t *testing.T) { + t.Parallel() + + _, logger, ctx := setupLogger(t) + + ctx = With(ctx) + + assert.Same(t, logger, FromContext(ctx)) +} + +func TestWith_Scope(t *testing.T) { + t.Parallel() + + buf, _, ctx := setupLogger(t) + + scoped := With(ctx, "request_id", "abc") + + Info(scoped, "Message") + Info(ctx, "Message") + + // The attributes are bound to the derived context only. + assert.Equal(t, 1, strings.Count(buf.String(), "request_id=abc")) +} + +func TestWith_DefaultLogger(t *testing.T) { + t.Parallel() + + ctx := With(t.Context(), "request_id", "abc") + + assert.NotSame(t, slog.Default(), FromContext(ctx)) +} + +func TestErrorAttr(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + log func(ctx context.Context) + want string + }{ + { + name: "value", + log: func(ctx context.Context) { Error(ctx, "Message", "error", context.Canceled) }, + want: `error="context canceled"`, + }, + { + name: "attr", + log: func(ctx context.Context) { Error(ctx, "Message", slog.Any("error", context.Canceled)) }, + want: `error="context canceled"`, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + buf, _, ctx := setupLogger(t) + + tt.log(ctx) + + assert.Contains(t, buf.String(), tt.want) + }) + } +} + +// TestContextPropagation checks that the context passed to the logging call +// reaches the handler. The package uses the *Context methods of [slog.Logger], +// so a context-aware handler can take the values from it, e.g. a request ID or +// a trace span. +func TestContextPropagation(t *testing.T) { + t.Parallel() + + handler := &captureHandler{} + ctx := ToContext(t.Context(), slog.New(handler)) + + type ctxKey struct{} + ctx = context.WithValue(ctx, ctxKey{}, "value") + + Info(ctx, "Message") + + contexts := handler.contexts() + require.Len(t, contexts, 1) + assert.Equal(t, "value", contexts[0].Value(ctxKey{})) +} + +// captureHandler is a logger handler that captures the contexts it is called +// with. +type captureHandler struct { + ctxs []context.Context + mu sync.Mutex +} + +func (h *captureHandler) Enabled(context.Context, slog.Level) bool { return true } + +// Handle implements [slog.Handler]. +func (h *captureHandler) Handle(ctx context.Context, _ slog.Record) error { //nolint:gocritic // The signature is fixed by slog.Handler. + h.mu.Lock() + defer h.mu.Unlock() + + h.ctxs = append(h.ctxs, ctx) + + return nil +} + +func (h *captureHandler) WithAttrs([]slog.Attr) slog.Handler { return h } + +func (h *captureHandler) WithGroup(string) slog.Handler { return h } + +// contexts returns the captured contexts. +func (h *captureHandler) contexts() []context.Context { + h.mu.Lock() + defer h.mu.Unlock() + + return slices.Clone(h.ctxs) +} diff --git a/slogger/slogger.go b/slogger/slogger.go index eab4608..09f40d8 100644 --- a/slogger/slogger.go +++ b/slogger/slogger.go @@ -10,6 +10,8 @@ import ( "os" "sync" "time" + + "github.com/nbgrp/pkg/slogger/ctxlog" ) // Options configures the logger. @@ -62,6 +64,19 @@ func New(ctx context.Context, opts Options) (*slog.Logger, error) { return l, nil } +// NewToContext initializes a logger and puts it into the returned context, so +// it can be used with the [ctxlog] helpers. +// +// The returned context is nil if the logger cannot be initialized. +func NewToContext(ctx context.Context, opts Options) (context.Context, error) { + logger, err := New(ctx, opts) + if err != nil { + return nil, err + } + + return ctxlog.ToContext(ctx, logger), nil +} + // watchLogLevel reloads the log level on every notification of the condition // variable until the context is canceled. func watchLogLevel(ctx context.Context, logger *slog.Logger, cond *sync.Cond, currentLevel *slog.LevelVar, opts Options) { diff --git a/slogger/slogger_test.go b/slogger/slogger_test.go index 23e6ce7..f971bd0 100644 --- a/slogger/slogger_test.go +++ b/slogger/slogger_test.go @@ -14,6 +14,7 @@ import ( "time" . "github.com/nbgrp/pkg/slogger" + "github.com/nbgrp/pkg/slogger/ctxlog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/goleak" @@ -183,6 +184,60 @@ func TestNew_LevelReload(t *testing.T) { }) } +func TestNewToContext(t *testing.T) { + t.Parallel() + + t.Run("puts the logger into the context", func(t *testing.T) { + t.Parallel() + + buf := &safeBuffer{} + ctx, err := NewToContext(t.Context(), Options{ + Leveler: func() string { return "INFO" }, + Format: "text", + Writer: buf, + }) + require.NoError(t, err) + + logger := ctxlog.FromContext(ctx) + require.NotNil(t, logger) + assert.NotSame(t, slog.Default(), logger) + + logger.Info("Hello") + + assert.Contains(t, buf.String(), "Hello") + }) + + t.Run("applies the log level", func(t *testing.T) { + t.Parallel() + + buf := &safeBuffer{} + ctx, err := NewToContext(t.Context(), Options{ + Leveler: func() string { return "WARN" }, + Format: "text", + Writer: buf, + }) + require.NoError(t, err) + + ctxlog.Info(ctx, "Dropped message") + ctxlog.Warn(ctx, "Accepted message") + + out := buf.String() + assert.NotContains(t, out, "Dropped message") + assert.Contains(t, out, "Accepted message") + }) + + t.Run("returns no context on error", func(t *testing.T) { + t.Parallel() + + got, err := NewToContext(t.Context(), Options{ + Leveler: func() string { return "INFO" }, + Format: "xml", + }) + require.EqualError(t, err, `unknown log format "xml"`) + assert.Nil(t, got) + }) +} + // reloader is a logger with a hot-reloadable log level. type reloader struct { logger *slog.Logger