diff --git a/go.mod b/go.mod index 91dc181..f956479 100644 --- a/go.mod +++ b/go.mod @@ -3,9 +3,12 @@ module github.com/stacklok/toolhive-core go 1.25.6 require ( + github.com/go-logr/logr v1.4.3 + github.com/go-logr/zapr v1.3.0 github.com/google/cel-go v0.27.0 github.com/stretchr/testify v1.11.1 go.uber.org/mock v0.6.0 + go.uber.org/zap v1.27.1 golang.org/x/net v0.49.0 ) diff --git a/logger/logger.go b/logger/logger.go new file mode 100644 index 0000000..fa4a230 --- /dev/null +++ b/logger/logger.go @@ -0,0 +1,197 @@ +// SPDX-FileCopyrightText: Copyright 2025 Stacklok, Inc. +// SPDX-License-Identifier: Apache-2.0 + +// Package logger provides a logging capability for toolhive projects for running locally as a CLI and in Kubernetes +package logger + +import ( + "strconv" + "time" + + "github.com/go-logr/logr" + "github.com/go-logr/zapr" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + + "github.com/stacklok/toolhive-core/env" +) + +// Debug logs a message at debug level using the singleton logger. +func Debug(msg string) { + zap.S().Debug(msg) +} + +// Debugf logs a message at debug level using the singleton logger. +func Debugf(msg string, args ...any) { + zap.S().Debugf(msg, args...) +} + +// Debugw logs a message at debug level using the singleton logger with additional key-value pairs. +func Debugw(msg string, keysAndValues ...any) { + zap.S().Debugw(msg, keysAndValues...) +} + +// Info logs a message at info level using the singleton logger. +func Info(msg string) { + zap.S().Info(msg) +} + +// Infof logs a message at info level using the singleton logger. +func Infof(msg string, args ...any) { + zap.S().Infof(msg, args...) +} + +// Infow logs a message at info level using the singleton logger with additional key-value pairs. +func Infow(msg string, keysAndValues ...any) { + zap.S().Infow(msg, keysAndValues...) +} + +// Warn logs a message at warning level using the singleton logger. +func Warn(msg string) { + zap.S().Warn(msg) +} + +// Warnf logs a message at warning level using the singleton logger. +func Warnf(msg string, args ...any) { + zap.S().Warnf(msg, args...) +} + +// Warnw logs a message at warning level using the singleton logger with additional key-value pairs. +func Warnw(msg string, keysAndValues ...any) { + zap.S().Warnw(msg, keysAndValues...) +} + +// Error logs a message at error level using the singleton logger. +func Error(msg string) { + zap.S().Error(msg) +} + +// Errorf logs a message at error level using the singleton logger. +func Errorf(msg string, args ...any) { + zap.S().Errorf(msg, args...) +} + +// Errorw logs a message at error level using the singleton logger with additional key-value pairs. +func Errorw(msg string, keysAndValues ...any) { + zap.S().Errorw(msg, keysAndValues...) +} + +// Panic logs a message at error level using the singleton logger and panics the program. +func Panic(msg string) { + zap.S().Panic(msg) +} + +// Panicf logs a message at error level using the singleton logger and panics the program. +func Panicf(msg string, args ...any) { + zap.S().Panicf(msg, args...) +} + +// Panicw logs a message at error level using the singleton logger with additional key-value pairs and panics the program. +func Panicw(msg string, keysAndValues ...any) { + zap.S().Panicw(msg, keysAndValues...) +} + +// DPanic logs a message at error level using the singleton logger and panics the program. +func DPanic(msg string) { + zap.S().DPanic(msg) +} + +// DPanicf logs a message at error level using the singleton logger and panics the program. +func DPanicf(msg string, args ...any) { + zap.S().DPanicf(msg, args...) +} + +// DPanicw logs a message at error level using the singleton logger with additional key-value pairs and panics the program. +func DPanicw(msg string, keysAndValues ...any) { + zap.S().DPanicw(msg, keysAndValues...) +} + +// Fatal logs a message at error level using the singleton logger and exits the program. +func Fatal(msg string) { + zap.S().Fatal(msg) +} + +// Fatalf logs a message at error level using the singleton logger and exits the program. +func Fatalf(msg string, args ...any) { + zap.S().Fatalf(msg, args...) +} + +// Fatalw logs a message at error level using the singleton logger with additional key-value pairs and exits the program. +func Fatalw(msg string, keysAndValues ...any) { + zap.S().Fatalw(msg, keysAndValues...) +} + +// NewLogr returns a logr.Logger which uses zap logger +func NewLogr() logr.Logger { + return zapr.NewLogger(zap.L()) +} + +// DebugProvider is an interface for checking if debug mode is enabled. +// This allows different projects to plug in their own debug flag implementation. +type DebugProvider interface { + IsDebug() bool +} + +// defaultDebugProvider provides a default implementation that returns false. +type defaultDebugProvider struct{} + +func (*defaultDebugProvider) IsDebug() bool { + return false +} + +// Initialize creates and configures the appropriate logger using the default debug provider. +// If the UNSTRUCTURED_LOGS is set to true, it will output plain log message +// with only time and LogLevelType (INFO, DEBUG, ERROR, WARN). +// Otherwise it will create a standard structured slog logger. +func Initialize() { + InitializeWithOptions(&env.OSReader{}, &defaultDebugProvider{}) +} + +// InitializeWithDebug creates and configures the logger with a custom debug provider. +// This allows callers to plug in their own debug flag implementation (e.g., viper). +func InitializeWithDebug(debugProvider DebugProvider) { + InitializeWithOptions(&env.OSReader{}, debugProvider) +} + +// InitializeWithEnv creates and configures the appropriate logger with a custom environment reader. +// This allows for dependency injection of environment variable access for testing. +// Deprecated: Use InitializeWithOptions instead. +func InitializeWithEnv(envReader env.Reader) { + InitializeWithOptions(envReader, &defaultDebugProvider{}) +} + +// InitializeWithOptions creates and configures the logger with custom environment reader and debug provider. +// This provides full control over logger configuration for both testing and production use. +func InitializeWithOptions(envReader env.Reader, debugProvider DebugProvider) { + var config zap.Config + if unstructuredLogsWithEnv(envReader) { + config = zap.NewDevelopmentConfig() + config.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder + config.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout(time.Kitchen) + config.OutputPaths = []string{"stderr"} + config.DisableStacktrace = true + config.DisableCaller = true + } else { + config = zap.NewProductionConfig() + config.OutputPaths = []string{"stdout"} + } + + // Set log level based on current debug flag + if debugProvider.IsDebug() { + config.Level = zap.NewAtomicLevelAt(zap.DebugLevel) + } else { + config.Level = zap.NewAtomicLevelAt(zap.InfoLevel) + } + + zap.ReplaceGlobals(zap.Must(config.Build())) +} + +func unstructuredLogsWithEnv(envReader env.Reader) bool { + unstructuredLogs, err := strconv.ParseBool(envReader.Getenv("UNSTRUCTURED_LOGS")) + if err != nil { + // at this point if the error is not nil, the env var wasn't set, or is "" + // which means we just default to outputting unstructured logs. + return true + } + return unstructuredLogs +} diff --git a/logger/logger_test.go b/logger/logger_test.go new file mode 100644 index 0000000..c7a1708 --- /dev/null +++ b/logger/logger_test.go @@ -0,0 +1,259 @@ +// SPDX-FileCopyrightText: Copyright 2025 Stacklok, Inc. +// SPDX-License-Identifier: Apache-2.0 + +package logger + +import ( + "bytes" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/mock/gomock" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" + + "github.com/stacklok/toolhive-core/env/mocks" +) + +// mockDebugProvider implements DebugProvider for testing +type mockDebugProvider struct { + debug bool +} + +func (m *mockDebugProvider) IsDebug() bool { + return m.debug +} + +// TestUnstructuredLogsCheck tests the unstructuredLogs function +func TestUnstructuredLogsCheck(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + envValue string + expected bool + }{ + {"Default Case", "", true}, + {"Explicitly True", "true", true}, + {"Explicitly False", "false", false}, + {"Invalid Value", "not-a-bool", true}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + ctrl := gomock.NewController(t) + defer ctrl.Finish() + + mockEnv := mocks.NewMockReader(ctrl) + mockEnv.EXPECT().Getenv("UNSTRUCTURED_LOGS").Return(tt.envValue) + + if got := unstructuredLogsWithEnv(mockEnv); got != tt.expected { + t.Errorf("unstructuredLogsWithEnv() = %v, want %v", got, tt.expected) + } + }) + } +} + +// TestUnstructuredLogger tests the unstructured logger functionality +func TestUnstructuredLogger(t *testing.T) { //nolint:paralleltest // Uses global logger state + // we only test for the formatted logs here because the unstructured logs + // do not contain the key/value pair format that the structured logs do + const ( + levelDebug = "DEBUG" + levelInfo = "INFO" + levelWarn = "WARN" + levelError = "ERROR" + levelDPanic = "DPANIC" + levelPanic = "PANIC" + ) + + formattedLogTestCases := []struct { + level string + message string + key string + value string + expected string + }{ + {levelDebug, "debug message %s and %s", "key", "value", "debug message key and value"}, + {levelInfo, "info message %s and %s", "key", "value", "info message key and value"}, + {levelWarn, "warn message %s and %s", "key", "value", "warn message key and value"}, + {levelError, "error message %s and %s", "key", "value", "error message key and value"}, + {levelDPanic, "dpanic message %s and %s", "key", "value", "dpanic message key and value"}, + {levelPanic, "panic message %s and %s", "key", "value", "panic message key and value"}, + } + + for _, tc := range formattedLogTestCases { //nolint:paralleltest // Uses global logger state + t.Run("FormattedLogs_"+tc.level, func(t *testing.T) { + // For unstructured logs, we still need to capture stderr output + // but we can use a buffer-based approach that's more coverage-friendly + var buf bytes.Buffer + + // Create a development config that writes to our buffer instead of stderr + config := zap.NewDevelopmentConfig() + config.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder + config.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout("15:04:05") + config.DisableStacktrace = true + config.DisableCaller = true + + // Create a core that writes to our buffer + core := zapcore.NewCore( + zapcore.NewConsoleEncoder(config.EncoderConfig), + zapcore.AddSync(&buf), + zapcore.DebugLevel, + ) + + logger := zap.New(core) + zap.ReplaceGlobals(logger) + + // Handle panic recovery for DPANIC and PANIC levels + var panicOccurred bool + defer func() { + if r := recover(); r != nil { + panicOccurred = true + if tc.level != "PANIC" { + t.Errorf("Unexpected panic for level %s: %v", tc.level, r) + } + } + }() + + // Log the message based on the level + switch tc.level { + case levelDebug: + Debugf(tc.message, tc.key, tc.value) + case levelInfo: + Infof(tc.message, tc.key, tc.value) + case levelWarn: + Warnf(tc.message, tc.key, tc.value) + case levelError: + Errorf(tc.message, tc.key, tc.value) + case levelDPanic: + DPanicf(tc.message, tc.key, tc.value) + case levelPanic: + Panicf(tc.message, tc.key, tc.value) + } + + // For panic levels, verify panic occurred, otherwise check output + if tc.level == "PANIC" { + require.True(t, panicOccurred, "Expected panic for level %s", tc.level) + // For panic levels, we might not get log entries before the panic + return + } + + // Note: DPanic only panics in development mode, not in tests by default + // So we treat it like a regular error level for verification purposes + + // Get the captured output from buffer + output := buf.String() + assert.Contains(t, output, tc.level, "Expected log entry '%s' to contain log level '%s'", output, tc.level) + assert.Contains(t, output, tc.expected, "Expected log entry '%s' to contain message '%s'", output, tc.expected) + }) + } +} + +// TestInitialize tests the Initialize function +func TestInitialize(t *testing.T) { //nolint:paralleltest // Uses global logger state + // Test structured logs (JSON) + t.Run("Structured Logs", func(t *testing.T) { //nolint:paralleltest // Uses global logger state + + // Create observer to capture logs in memory + core, observedLogs := observer.New(zapcore.InfoLevel) + logger := zap.New(core) + zap.ReplaceGlobals(logger) + + // Log a test message + Info("test message") + + // Get captured log entries from observer + allEntries := observedLogs.All() + require.Len(t, allEntries, 1, "Expected exactly one log entry") + + entry := allEntries[0] + assert.Equal(t, "info", entry.Level.String(), "Log level mismatch") + assert.Equal(t, "test message", entry.Message, "Log message mismatch") + }) + + // Test unstructured logs + t.Run("Unstructured Logs", func(t *testing.T) { //nolint:paralleltest // Uses global logger state + + // For unstructured logs, we use a buffer-based approach + var buf bytes.Buffer + + // Create a development config that writes to our buffer + config := zap.NewDevelopmentConfig() + config.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder + config.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout("15:04:05") + config.DisableStacktrace = true + config.DisableCaller = true + + // Create a core that writes to our buffer + core := zapcore.NewCore( + zapcore.NewConsoleEncoder(config.EncoderConfig), + zapcore.AddSync(&buf), + zapcore.InfoLevel, + ) + + logger := zap.New(core) + zap.ReplaceGlobals(logger) + + // Log a test message + Info("test message") + + // Get the captured output from buffer + output := buf.String() + + // Verify unstructured format (should contain message but not be JSON) + assert.Contains(t, output, "test message", "Expected output to contain 'test message'") + assert.Contains(t, output, "INFO", "Expected output to contain 'INFO'") + }) +} + +// TestInitializeWithDebug tests the debug provider functionality +func TestInitializeWithDebug(t *testing.T) { //nolint:paralleltest // Uses global logger state + t.Run("Debug Mode Enabled", func(t *testing.T) { //nolint:paralleltest // Uses global logger state + ctrl := gomock.NewController(t) + defer ctrl.Finish() + + mockEnv := mocks.NewMockReader(ctrl) + mockEnv.EXPECT().Getenv("UNSTRUCTURED_LOGS").Return("false") + + debugProvider := &mockDebugProvider{debug: true} + InitializeWithOptions(mockEnv, debugProvider) + + // Verify debug level is set by checking if debug messages are logged + core, observedLogs := observer.New(zapcore.DebugLevel) + logger := zap.New(core) + zap.ReplaceGlobals(logger) + + Debug("debug test message") + + allEntries := observedLogs.All() + require.Len(t, allEntries, 1, "Expected one log entry") + assert.Equal(t, "debug", allEntries[0].Level.String()) + }) + + t.Run("Debug Mode Disabled", func(t *testing.T) { //nolint:paralleltest // Uses global logger state + ctrl := gomock.NewController(t) + defer ctrl.Finish() + + mockEnv := mocks.NewMockReader(ctrl) + mockEnv.EXPECT().Getenv("UNSTRUCTURED_LOGS").Return("false") + + debugProvider := &mockDebugProvider{debug: false} + InitializeWithOptions(mockEnv, debugProvider) + + // With info level, debug messages should not be logged + core, observedLogs := observer.New(zapcore.InfoLevel) + logger := zap.New(core) + zap.ReplaceGlobals(logger) + + Debug("debug test message - should not appear") + Info("info test message") + + allEntries := observedLogs.All() + require.Len(t, allEntries, 1, "Expected only one log entry (info)") + assert.Equal(t, "info", allEntries[0].Level.String()) + }) +}