From 0ea6a093dcf2146140746f56d7e99d8137c11238 Mon Sep 17 00:00:00 2001 From: Malte Poll <1780588+malt3@users.noreply.github.com> Date: Mon, 8 Jan 2024 18:12:48 +0100 Subject: [PATCH] logger: add default logger and subsystem log handler Adds ability to control logging via env vars. --- internal/logger/handler.go | 75 +++++++++++++ internal/logger/handler_test.go | 109 +++++++++++++++++++ internal/logger/logger.go | 66 ++++++++++++ internal/logger/logger_test.go | 186 ++++++++++++++++++++++++++++++++ 4 files changed, 436 insertions(+) create mode 100644 internal/logger/handler.go create mode 100644 internal/logger/handler_test.go create mode 100644 internal/logger/logger.go create mode 100644 internal/logger/logger_test.go diff --git a/internal/logger/handler.go b/internal/logger/handler.go new file mode 100644 index 0000000000..5262825e40 --- /dev/null +++ b/internal/logger/handler.go @@ -0,0 +1,75 @@ +package logger + +import ( + "context" + "log/slog" + "os" + "strings" +) + +// Handler is a slog.Handler that can be used to enable logging on a per-subsystem basis. +type Handler struct { + inner slog.Handler + subsystem string + enabled bool +} + +// NewHandler returns a new Handler. +func NewHandler(inner slog.Handler, subsystem string) *Handler { + if subsystem != "" { + inner = inner.WithGroup(subsystem) + } + + return &Handler{ + inner: inner, + subsystem: subsystem, + enabled: subsystemEnvEnabled(os.Getenv, subsystem), + } +} + +// Enabled returns true if the given level is enabled. +func (h *Handler) Enabled(ctx context.Context, level slog.Level) bool { + return h.enabled && h.inner.Enabled(ctx, level) +} + +// Handle handles the given record. +func (h *Handler) Handle(ctx context.Context, record slog.Record) error { + return h.inner.Handle(ctx, record) +} + +// WithAttrs returns a new Handler with the given attributes. +func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &Handler{ + inner: h.inner.WithAttrs(attrs), + subsystem: h.subsystem, + enabled: h.enabled, + } +} + +// WithGroup returns a new Handler with the given group. +func (h *Handler) WithGroup(name string) slog.Handler { + return &Handler{ + inner: h.inner.WithGroup(name), + subsystem: h.subsystem, + enabled: h.enabled, + } +} + +func subsystemEnvEnabled(getEnv func(string) string, subsystem string) bool { + allowList := getEnv(LogSubsystems) + + return subsystemAllowListMatch(subsystem, allowList) +} + +func subsystemAllowListMatch(subsystem string, allowList string) bool { + if allowList == "*" { + return true + } + for _, allow := range strings.Split(allowList, ",") { + allow = strings.ToLower(strings.TrimSpace(allow)) + if allow == subsystem { + return true + } + } + return false +} diff --git a/internal/logger/handler_test.go b/internal/logger/handler_test.go new file mode 100644 index 0000000000..60fd5ecf24 --- /dev/null +++ b/internal/logger/handler_test.go @@ -0,0 +1,109 @@ +package logger + +import ( + "bytes" + "log/slog" + "strings" + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestHandlerOutput(t *testing.T) { + testCases := map[string]struct { + subsystem string + subsystemEnvList string + wantMessages int + }{ + "star": { + subsystem: "foo", + subsystemEnvList: "*", + wantMessages: 2, // message and empty line + }, + "match": { + subsystem: "foo", + subsystemEnvList: "foo,bar,baz", + wantMessages: 2, // message and empty line + }, + "no match": { + subsystem: "foo", + wantMessages: 1, // empty line + }, + } + + for name, tc := range testCases { + t.Run(name, func(t *testing.T) { + assert := assert.New(t) + + getEnv := newTestGetEnv(map[string]string{ + LogSubsystems: tc.subsystemEnvList, + }) + + buf := new(bytes.Buffer) + + handler := &Handler{ + inner: slog.NewJSONHandler(buf, nil).WithGroup(tc.subsystem), + subsystem: tc.subsystem, + enabled: subsystemEnvEnabled(getEnv, tc.subsystem), + } + logger := slog.New(handler) + + logger.Info("info", "key", "value") + + got := buf.String() + lines := strings.Split(got, "\n") + assert.Len(lines, tc.wantMessages) + for _, line := range lines { + if line == "" { + continue + } + assert.Contains(line, tc.subsystem) + } + }) + } +} + +func TestSubsystemEnvEnabled(t *testing.T) { + testCases := map[string]struct { + subsystem string + subsystemEnvList string + wantEnabled bool + }{ + "empty with star": { + subsystem: "", + subsystemEnvList: "*", + wantEnabled: true, + }, + "value with star": { + subsystem: "foo", + subsystemEnvList: "*", + wantEnabled: true, + }, + "empty list": { + subsystem: "bar", + subsystemEnvList: "", + }, + "match": { + subsystem: "bar", + subsystemEnvList: "foo,bar,baz", + wantEnabled: true, + }, + "no match": { + subsystem: "bar", + subsystemEnvList: "foo,baz", + }, + } + + for name, tc := range testCases { + t.Run(name, func(t *testing.T) { + assert := assert.New(t) + + getEnv := newTestGetEnv(map[string]string{ + LogSubsystems: tc.subsystemEnvList, + }) + + got := subsystemEnvEnabled(getEnv, tc.subsystem) + assert.Equal(tc.wantEnabled, got) + }) + } +} diff --git a/internal/logger/logger.go b/internal/logger/logger.go new file mode 100644 index 0000000000..1eba5aafa9 --- /dev/null +++ b/internal/logger/logger.go @@ -0,0 +1,66 @@ +// Package logger provides a slog.Logger that can be configured via environment variables. +// NUNKI_LOG_LEVEL can be used to set the log level. +// NUNKI_LOG_FORMAT can be used to set the log format. +// It also offer a slog.Handler that can be used to enable logging on a per-subsystem basis. +// NUNKI_LOG_SUBSYSTEMS can be used to enable logging for specific subsystems. +// If NUNKI_LOG_SUBSYSTEMS has the special value "*", all subsystems are enabled. +// Otherwise, a comma-separated list of subsystem names can be specified. +package logger + +import ( + "fmt" + "io" + "log/slog" + "os" + "strconv" + "strings" +) + +const ( + LogLevel = "NUNKI_LOG_LEVEL" + LogFormat = "NUNKI_LOG_FORMAT" + LogSubsystems = "NUNKI_LOG_SUBSYSTEMS" +) + +// Default returns a logger configured via environment variables. +func Default() (*slog.Logger, error) { + logLevel, err := getLogLevel(os.Getenv) + if err != nil { + return nil, err + } + return slog.New(logHandler(os.Getenv)(os.Stderr, &slog.HandlerOptions{ + Level: logLevel, + })), nil +} + +func getLogLevel(getEnv func(string) string) (slog.Level, error) { + logLevel := getEnv(LogLevel) + switch strings.ToLower(logLevel) { + case "debug": + return slog.LevelDebug, nil + case "", "info": + return slog.LevelInfo, nil + case "warn": + return slog.LevelWarn, nil + case "error": + return slog.LevelError, nil + } + + numericLevel, err := strconv.Atoi(logLevel) + if err != nil { + return slog.Level(0), fmt.Errorf("invalid log level: %q", logLevel) + } + return slog.Level(numericLevel), nil +} + +func logHandler(getEnv func(string) string) func(w io.Writer, opts *slog.HandlerOptions) slog.Handler { + switch strings.ToLower(getEnv(LogFormat)) { + case "json": + return func(w io.Writer, opts *slog.HandlerOptions) slog.Handler { + return slog.NewJSONHandler(w, opts) + } + } + return func(w io.Writer, opts *slog.HandlerOptions) slog.Handler { + return slog.NewTextHandler(w, opts) + } +} diff --git a/internal/logger/logger_test.go b/internal/logger/logger_test.go new file mode 100644 index 0000000000..7120c88cff --- /dev/null +++ b/internal/logger/logger_test.go @@ -0,0 +1,186 @@ +package logger + +import ( + "bytes" + "encoding/json" + "log/slog" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestLogOutput(t *testing.T) { + testCases := map[string]struct { + logLevel string + logFormat string + wantMessages int + }{ + "default": { + wantMessages: 4, + }, + "text warning": { + logLevel: "warn", + logFormat: "text", + wantMessages: 3, + }, + "json debug": { + logLevel: "debug", + logFormat: "json", + wantMessages: 5, + }, + } + + for name, tc := range testCases { + t.Run(name, func(t *testing.T) { + assert := assert.New(t) + + getEnv := newTestGetEnv(map[string]string{ + LogLevel: tc.logLevel, + LogFormat: tc.logFormat, + }) + + buf := new(bytes.Buffer) + + level, err := getLogLevel(getEnv) + require.NoError(t, err) + handler := logHandler(getEnv)(buf, &slog.HandlerOptions{ + Level: level, + }) + logger := slog.New(handler) + + logger.Debug("debug") + logger.Info("info") + logger.Warn("warn") + logger.Error("error") + + got := buf.String() + lines := strings.Split(got, "\n") + assert.Len(lines, tc.wantMessages) + for _, line := range lines { + if line == "" { + continue + } + if tc.logFormat == "json" { + assert.NoError(json.Unmarshal([]byte(line), &map[string]interface{}{})) + } else { + assert.Error(json.Unmarshal([]byte(line), &map[string]interface{}{})) + } + } + }) + } +} + +func TestGetLogLevel(t *testing.T) { + testCases := map[string]struct { + logLevel string + want slog.Level + wantErr bool + }{ + "empty": { + logLevel: "", + want: slog.LevelInfo, + }, + "debug": { + logLevel: "debug", + want: slog.LevelDebug, + }, + "info with casing": { + logLevel: "InFo", + want: slog.LevelInfo, + }, + "warn": { + logLevel: "warn", + want: slog.LevelWarn, + }, + "error": { + logLevel: "error", + want: slog.LevelError, + }, + "numeric": { + logLevel: "3", + want: slog.Level(3), + }, + "custom numeric": { + logLevel: "-42", + want: slog.Level(-42), + }, + "invalid": { + logLevel: "invalid", + wantErr: true, + }, + } + + for name, tc := range testCases { + t.Run(name, func(t *testing.T) { + assert := assert.New(t) + require := require.New(t) + + getEnv := newTestGetEnv(map[string]string{ + LogLevel: tc.logLevel, + }) + + got, err := getLogLevel(getEnv) + if tc.wantErr { + assert.Error(err) + return + } + require.NoError(err) + assert.Equal(tc.want, got) + }) + } +} + +func TestLogHandler(t *testing.T) { + testCases := map[string]struct { + logFormat string + correctHandler func(slog.Handler) bool + }{ + "empty": { + logFormat: "", + correctHandler: isTextHandler, + }, + "fallback": { + logFormat: "foo", + correctHandler: isTextHandler, + }, + "text": { + logFormat: "text", + correctHandler: isTextHandler, + }, + "json": { + logFormat: "jSoN", + correctHandler: isJSONHandler, + }, + } + + for name, tc := range testCases { + t.Run(name, func(t *testing.T) { + assert := assert.New(t) + + getEnv := newTestGetEnv(map[string]string{ + LogLevel: tc.logFormat, + }) + + got := logHandler(getEnv)(nil, nil) + assert.True(tc.correctHandler(got)) + }) + } +} + +func newTestGetEnv(environ map[string]string) func(string) string { + return func(key string) string { + return environ[key] + } +} + +func isTextHandler(h slog.Handler) bool { + _, ok := h.(*slog.TextHandler) + return ok +} + +func isJSONHandler(h slog.Handler) bool { + _, ok := h.(*slog.JSONHandler) + return ok +}