diff --git a/README.md b/README.md index c996715..66a40c2 100644 --- a/README.md +++ b/README.md @@ -1,13 +1,24 @@ # go-log -[![](https://img.shields.io/badge/made%20by-Protocol%20Labs-blue.svg?style=flat-square)](https://protocol.ai) [![](https://img.shields.io/badge/project-IPFS-blue.svg?style=flat-square)](https://ipfs.io/) [![GoDoc](https://pkg.go.dev/badge/github.com/ipfs/go-log/v2.svg)](https://pkg.go.dev/github.com/ipfs/go-log/v2) -> The logging library used by go-ipfs +> The logging library used by IPFS Kubo -go-log wraps [zap](https://github.com/uber-go/zap) to provide a logging facade. go-log manages logging -instances and allows for their levels to be controlled individually. +go-log wraps [zap](https://github.com/uber-go/zap) to provide per-subsystem level control and optional log/slog integration for unified logging across IPFS/libp2p components. + +## Table of Contents + +- [Install](#install) +- [Usage](#usage) +- [Environment Variables](#environment-variables) +- [Slog Integration](#slog-integration) + - [Application Setup (Required)](#application-setup-required) + - [For library authors](#for-library-authors) + - [Approach 1: Duck-typing detection (automatic)](#approach-1-duck-typing-detection-automatic) + - [Approach 2: Explicit handler passing (manual)](#approach-2-explicit-handler-passing-manual) +- [Contribute](#contribute) +- [License](#license) ## Install @@ -53,7 +64,7 @@ if err != nil { } ``` -### Environment Variables +## Environment Variables This package can be configured through various environment variables. @@ -122,6 +133,229 @@ pairs. For example, the following add `{"app": "example_app", "dc": "sjc-1"}` to export GOLOG_LOG_LABELS="app=example_app,dc=sjc-1" ``` +#### `GOLOG_CAPTURE_DEFAULT_SLOG` + +By default, go-log does NOT automatically install its slog handler as `slog.Default()`. Applications should explicitly call `slog.SetDefault(slog.New(golog.SlogHandler()))` for slog integration (see Slog Integration section below). + +Alternatively, you can enable automatic installation by setting: + +```bash +export GOLOG_CAPTURE_DEFAULT_SLOG="true" +``` + +When enabled, go-log automatically installs its handler as `slog.Default()` during `SetupLogging()`, which allows libraries using `slog` to automatically use go-log's formatting and dynamic level control. + +## Slog Integration + +go-log provides integration with Go's `log/slog` package for unified log management. This provides: + +1. **Unified formatting**: slog logs use the same format as go-log (color/nocolor/json) +2. **Dynamic level control**: slog loggers respect `SetLogLevel()` and environment variables +3. **Subsystem-aware filtering**: slog loggers with subsystem attributes get per-subsystem level control + +**Note**: This slog bridge exists as an intermediate solution while go-log uses zap internally. In the future, go-log may migrate from zap to native slog, which would simplify this integration. + +### Application Setup (Required) + +For slog-based logging to use go-log's formatting and level control, applications must explicitly set go-log's handler as the slog default: + +```go +import ( + "log/slog" + golog "github.com/ipfs/go-log/v2" + "github.com/libp2p/go-libp2p/gologshim" +) + +func init() { + // Set go-log's handler as the application-wide slog default. + // This ensures all slog-based logging uses go-log's formatting. + slog.SetDefault(slog.New(golog.SlogHandler())) + + // Wire libraries that use explicit handler passing (like go-libp2p). + // This ensures proper subsystem attribution for per-logger level control. + gologshim.SetDefaultHandler(golog.SlogHandler()) +} +``` + +This two-layer approach ensures: +- **Application-level**: All slog usage (application code + libraries) flows through go-log +- **Library-level**: Libraries with explicit wiring (like go-libp2p) include proper subsystem attributes + +### How it works + +When configured as shown above, slog-based libraries gain unified formatting and dynamic level control. + +**Attributes added by libraries:** +- `logger`: Subsystem name (e.g., "foo", "bar", "baz") +- Any additional labels from `GOLOG_LOG_LABELS` + +Example: +```go +var log = logging.Logger("foo") // gologshim +log.Debug("operation failed", "err", err) +``` + +When integrated with go-log, output is formatted by go-log (JSON format shown here, also supports color/nocolor): +```json +{ + "level": "debug", + "ts": "2025-10-27T12:34:56.789+0100", + "logger": "foo", + "caller": "foo/foo.go:72", + "msg": "operation failed", + "err": "connection refused" +} +``` + +### Controlling slog logger levels + +These loggers respect go-log's level configuration: + +```bash +# Via environment variable (before daemon starts) +export GOLOG_LOG_LEVEL="error,foo=debug" + +# Via API (while daemon is running) +logging.SetLogLevel("foo", "debug") +``` + +This works even if the logger is created lazily or hasn't been created yet. Level settings are preserved and applied when the logger is first used. + +### Direct slog usage without subsystem + +When using slog.Default() directly without adding a "logger" attribute, logs still work but have limitations: + +**What works:** +- Logs appear in output with go-log's formatting (JSON/color/nocolor) +- Uses global log level from `GOLOG_LOG_LEVEL` fallback or `SetAllLoggers()` + +**Limitations:** +- No subsystem-specific level control via `SetLogLevel("subsystem", "level")` +- Empty logger name in output +- Less efficient (no early atomic level filtering) + +**Example:** +```go +// Direct slog usage - uses global level only +slog.Info("message") // LoggerName = "", uses global level + +// Library with subsystem - subsystem-aware +log := mylib.Logger("foo") +log.Info("message") // LoggerName = "foo", uses subsystem level +``` + +For libraries, use the "logger" attribute pattern to enable per-subsystem control. + +### Why "logger" attribute? + +go-log uses `"logger"` as the attribute key for subsystem names to maintain backward compatibility with its existing Zap-based output format: + +- Maintains compatibility with existing go-log output format +- Existing tooling, dashboards, and log processors already parse the "logger" field +- Simplifies migration path from Zap to slog bridge + +Libraries integrating with go-log should use this same attribute key to ensure proper subsystem-aware level control. + +### For library authors + +Libraries using slog can integrate with go-log without adding go-log as a dependency. There are two approaches: + +#### Approach 1: Duck-typing detection (automatic) + +Detect go-log's slog bridge via an interface marker to avoid requiring go-log in library's go.mod: + +```go +// In your library's logging package +func Logger(subsystem string) *slog.Logger { + // Check if slog.Default() is go-log's bridge. + // This works when applications call slog.SetDefault(slog.New(golog.SlogHandler())). + handler := slog.Default().Handler() + + type goLogBridge interface { + GoLogBridge() + } + if _, ok := handler.(goLogBridge); ok { + // go-log's bridge is active - use it with subsystem attribute + h := handler.WithAttrs([]slog.Attr{ + slog.String("logger", subsystem), + }) + return slog.New(h) + } + + // Standalone handler when go-log is not present + return slog.New(createStandaloneHandler(subsystem)) +} +``` + +Usage in your library: +```go +var log = mylib.Logger("foo") +log.Debug("operation completed", "key", value) +``` + +This pattern allows libraries to automatically integrate when the application has set up go-log's handler, without requiring go-log as a dependency. + +#### Approach 2: Explicit handler passing (manual) + +Alternatively, expose a way for applications to provide a handler explicitly: + +```go +// In your library's logging package +var defaultHandler atomic.Pointer[slog.Handler] + +func SetDefaultHandler(handler slog.Handler) { + defaultHandler.Store(&handler) +} + +func Logger(subsystem string) *slog.Logger { + if h := defaultHandler.Load(); h != nil { + // Use provided handler with subsystem attribute + return slog.New((*h).WithAttrs([]slog.Attr{ + slog.String("logger", subsystem), + })) + } + // Standalone handler when go-log is not present + return slog.New(createStandaloneHandler(subsystem)) +} +``` + +Usage in your library: +```go +var log = mylib.Logger("bar") +log.Info("started service", "addr", addr) +``` + +**Application side** must explicitly wire it, for example, go-libp2p requires: + +```go +import ( + golog "github.com/ipfs/go-log/v2" + "github.com/libp2p/go-libp2p/gologshim" +) + +func init() { + // Use go-log's SlogHandler() to get the bridge directly. + // This works regardless of GOLOG_CAPTURE_DEFAULT_SLOG setting. + gologshim.SetDefaultHandler(golog.SlogHandler()) +} +``` + +**Tradeoff**: Approach 2 requires manual coordination in every application, while Approach 1 works automatically when applications set up `slog.Default()`. + +For a complete example, see [go-libp2p's gologshim](https://github.com/libp2p/go-libp2p/blob/master/gologshim/gologshim.go). + +### Enabling automatic slog capture (opt-in) + +**Note**: This is mostly used during development, when a library author decides between Approach 1 or 2 for proper (subsystem-aware) integration with go-log. + +You can enable automatic installation of go-log's handler during `SetupLogging()`: + +```bash +export GOLOG_CAPTURE_DEFAULT_SLOG="true" +``` + +When enabled, go-log automatically installs its handler as `slog.Default()`, which allows slog-based libraries to automatically use go-log's formatting without explicit application setup. + ## Contribute Feel free to join in. All welcome. Open an [issue](https://github.com/ipfs/go-log/issues)! diff --git a/core.go b/core.go index 78c510d..d0ac401 100644 --- a/core.go +++ b/core.go @@ -51,6 +51,7 @@ func (l *lockedMultiCore) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *za func (l *lockedMultiCore) Write(ent zapcore.Entry, fields []zapcore.Field) error { l.mu.RLock() defer l.mu.RUnlock() + var errs []error for i := range l.cores { err := l.cores[i].Write(ent, fields) diff --git a/setup.go b/setup.go index f13ee9a..b08f46e 100644 --- a/setup.go +++ b/setup.go @@ -3,10 +3,12 @@ package log import ( "errors" "fmt" + "log/slog" "os" "regexp" "strings" "sync" + "sync/atomic" "github.com/mattn/go-isatty" "go.uber.org/zap" @@ -35,8 +37,9 @@ const ( envLoggingFile = "GOLOG_FILE" // /path/to/file envLoggingURL = "GOLOG_URL" // url that will be processed by sink in the zap - envLoggingOutput = "GOLOG_OUTPUT" // possible values: stdout|stderr|file combine multiple values with '+' - envLoggingLabels = "GOLOG_LOG_LABELS" // comma-separated key-value pairs, i.e. "app=example_app,dc=sjc-1" + envLoggingOutput = "GOLOG_OUTPUT" // possible values: stdout|stderr|file combine multiple values with '+' + envLoggingLabels = "GOLOG_LOG_LABELS" // comma-separated key-value pairs, i.e. "app=example_app,dc=sjc-1" + envCaptureSlog = "GOLOG_CAPTURE_DEFAULT_SLOG" // set to "true" to enable routing slog logs through go-log's zap core ) type LogFormat int @@ -95,6 +98,12 @@ var primaryCore zapcore.Core // loggerCore is the base for all loggers created by this package var loggerCore = &lockedMultiCore{} +// slogBridge is go-log's slog.Handler that routes slog logs through zap. +// It's always created during SetupLogging, even when GOLOG_CAPTURE_DEFAULT_SLOG=false. +// This allows applications to explicitly wire slog-based libraries (like go-libp2p) +// to go-log using SlogHandler(), regardless of whether it's installed as slog.Default(). +var slogBridge atomic.Pointer[slog.Handler] + // GetConfig returns a copy of the saved config. It can be inspected, modified, // and re-applied using a subsequent call to SetupLogging(). func GetConfig() Config { @@ -156,6 +165,70 @@ func SetupLogging(cfg Config) { levels[name] = zap.NewAtomicLevelAt(zapcore.Level(level)) } } + + // Create the slog bridge (always available via SlogHandler()). + // This allows applications to explicitly wire slog-based libraries to go-log + // regardless of GOLOG_CAPTURE_DEFAULT_SLOG setting. + bridge := newZapToSlogBridge(loggerCore) + slogBridge.Store(&bridge) + + // Install the bridge as slog.Default() if explicitly enabled. + // When enabled, libraries using slog automatically use go-log's formatting. + // Libraries can also opt-in to dynamic per-logger level control if they include "logger" attribute. + if os.Getenv(envCaptureSlog) == "true" { + captureSlogDefault(bridge) + } +} + +// SlogHandler returns go-log's slog.Handler for explicit wiring. +// This allows applications to integrate slog-based logging with go-log's +// formatting and level control. +// +// Example usage in an application's init(): +// +// import ( +// "log/slog" +// golog "github.com/ipfs/go-log/v2" +// "github.com/libp2p/go-libp2p/gologshim" +// ) +// +// func init() { +// // Set go-log's slog handler as the application-wide default. +// // This ensures all slog-based logging uses go-log's formatting. +// slog.SetDefault(slog.New(golog.SlogHandler())) +// +// // Wire go-log's slog bridge to go-libp2p's gologshim. +// // This provides go-libp2p loggers with the "logger" attribute +// // for per-subsystem level control. +// gologshim.SetDefaultHandler(golog.SlogHandler()) +// } +func SlogHandler() slog.Handler { + if h := slogBridge.Load(); h != nil { + return *h + } + // Should never happen since SetupLogging() is called in init() + panic("go-log: SlogHandler called before SetupLogging") +} + +// captureSlogDefault installs go-log's slog bridge as slog.Default() +func captureSlogDefault(bridge slog.Handler) { + // Check if slog.Default() is already customized (not stdlib default) + // and warn the user that we're replacing it + defaultHandler := slog.Default().Handler() + if _, isGoLogBridge := defaultHandler.(interface{ GoLogBridge() }); !isGoLogBridge { + // Not a go-log bridge, check if it's a custom handler + // We detect custom handlers by checking if it's not a standard text/json handler + // This is imperfect but reasonably safe - custom handlers are likely wrapped or different types + handlerType := fmt.Sprintf("%T", defaultHandler) + if !strings.Contains(handlerType, "slog.defaultHandler") && + !strings.Contains(handlerType, "slog.commonHandler") { + + fmt.Fprintf(os.Stderr, "WARN: go-log is overriding custom slog.Default() handler (%s) to ensure logs from slog-based libraries are captured and formatted consistently. This prevents missing logs or stderr pollution. Set GOLOG_CAPTURE_DEFAULT_SLOG=false to disable this behavior.\n", handlerType) + + } + } + + slog.SetDefault(slog.New(bridge)) } // SetPrimaryCore changes the primary logging core. If the SetupLogging was @@ -195,8 +268,12 @@ func setAllLoggers(lvl LogLevel) { } } -// SetLogLevel changes the log level of a specific subsystem -// name=="*" changes all subsystems +// SetLogLevel changes the log level of a specific subsystem. +// name=="*" changes all subsystems. +// +// This function works for both native go-log loggers and slog-based loggers +// (e.g., from go-libp2p via gologshim). If the subsystem doesn't exist yet, +// a level entry is created and will be applied when the logger is created. func SetLogLevel(name, level string) error { lvl, err := Parse(level) if err != nil { @@ -210,16 +287,18 @@ func SetLogLevel(name, level string) error { return nil } - loggerMutex.RLock() - defer loggerMutex.RUnlock() + loggerMutex.Lock() + defer loggerMutex.Unlock() - // Check if we have a logger by that name - if _, ok := levels[name]; !ok { - return ErrNoSuchLogger + // Get or create atomic level for this subsystem + atomicLevel, ok := levels[name] + if !ok { + atomicLevel = zap.NewAtomicLevelAt(zapcore.Level(lvl)) + levels[name] = atomicLevel + } else { + atomicLevel.SetLevel(zapcore.Level(lvl)) } - levels[name].SetLevel(zapcore.Level(lvl)) - return nil } diff --git a/setup_test.go b/setup_test.go index ecfa6ee..73293f6 100644 --- a/setup_test.go +++ b/setup_test.go @@ -3,7 +3,9 @@ package log import ( "bytes" "io" + "log/slog" "os" + "sync" "testing" "github.com/stretchr/testify/require" @@ -297,3 +299,165 @@ func TestLogToStdoutOnly(t *testing.T) { } require.Contains(t, buf.String(), want) } + +func TestSetLogLevelAutoCreate(t *testing.T) { + // Save and restore original state to avoid test pollution + loggerMutex.Lock() + originalLevels := levels + levels = make(map[string]zap.AtomicLevel) + loggerMutex.Unlock() + defer func() { + loggerMutex.Lock() + levels = originalLevels + loggerMutex.Unlock() + }() + + // Set level for non-existent subsystem (should succeed) + err := SetLogLevel("nonexistent", "debug") + require.NoError(t, err) + + // Verify level entry was created + loggerMutex.RLock() + atomicLevel, exists := levels["nonexistent"] + loggerMutex.RUnlock() + + require.True(t, exists, "level entry should be auto-created") + require.Equal(t, zapcore.DebugLevel, atomicLevel.Level()) + + // Change level (should update existing entry) + err = SetLogLevel("nonexistent", "error") + require.NoError(t, err) + require.Equal(t, zapcore.ErrorLevel, atomicLevel.Level()) + + // Invalid level should still fail + err = SetLogLevel("nonexistent", "invalid") + require.Error(t, err) +} + +func TestSlogHandler_ReturnsNonNil(t *testing.T) { + // SetupLogging is called in init(), so SlogHandler should return non-nil + handler := SlogHandler() + require.NotNil(t, handler, "SlogHandler should return non-nil handler") +} + +func TestSlogHandler_MatchesSlogDefault(t *testing.T) { + // Save original slog.Default for cleanup + originalDefault := slog.Default() + defer slog.SetDefault(originalDefault) + + // Enable automatic capture + os.Setenv(envCaptureSlog, "true") + defer os.Unsetenv(envCaptureSlog) + + // Setup with capture enabled + SetupLogging(Config{ + Format: PlaintextOutput, + Stderr: true, + Level: LevelError, + }) + + // SlogHandler and slog.Default().Handler() should be the same when capture is enabled + handler := SlogHandler() + defaultHandler := slog.Default().Handler() + + require.NotNil(t, handler) + require.NotNil(t, defaultHandler) + + // Verify duck-typing marker works + type goLogBridge interface { + GoLogBridge() + } + _, ok := handler.(goLogBridge) + require.True(t, ok, "SlogHandler should implement GoLogBridge marker") + + _, ok = defaultHandler.(goLogBridge) + require.True(t, ok, "slog.Default().Handler() should implement GoLogBridge marker when capture is enabled") +} + +func TestSlogHandler_WorksWithoutAutomaticCapture(t *testing.T) { + // Save original slog.Default for cleanup + originalDefault := slog.Default() + defer slog.SetDefault(originalDefault) + + // Reset slog.Default() to stdlib default before testing + slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr, nil))) + + // Setup with default behavior (automatic capture disabled by default) + SetupLogging(Config{ + Format: PlaintextOutput, + Stderr: true, + Level: LevelError, + }) + + // SlogHandler should still return a valid handler + handler := SlogHandler() + require.NotNil(t, handler, "SlogHandler should work without automatic capture") + + // Verify it's go-log's bridge + type goLogBridge interface { + GoLogBridge() + } + _, ok := handler.(goLogBridge) + require.True(t, ok, "SlogHandler should return go-log's bridge") + + // But slog.Default() should NOT be go-log's bridge by default (should remain stdlib default) + defaultHandler := slog.Default().Handler() + _, ok = defaultHandler.(goLogBridge) + require.False(t, ok, "slog.Default() should not be go-log's bridge by default") +} + +func TestSlogHandler_MultipleSetupLogging(t *testing.T) { + // First setup + SetupLogging(Config{ + Format: PlaintextOutput, + Stderr: true, + Level: LevelError, + }) + handler1 := SlogHandler() + require.NotNil(t, handler1) + + // Second setup with different config + SetupLogging(Config{ + Format: JSONOutput, + Stderr: true, + Level: LevelDebug, + }) + handler2 := SlogHandler() + require.NotNil(t, handler2) + + // Handler should be updated (different instance) + // We can't directly compare handlers, but we can verify both are valid + type goLogBridge interface { + GoLogBridge() + } + _, ok := handler2.(goLogBridge) + require.True(t, ok, "Handler should still be valid after multiple SetupLogging calls") +} + +func TestSlogHandler_Concurrent(t *testing.T) { + // Test thread-safety: multiple goroutines calling SlogHandler() concurrently + const goroutines = 100 + const iterations = 100 + + var wg sync.WaitGroup + wg.Add(goroutines) + + for i := 0; i < goroutines; i++ { + go func() { + defer wg.Done() + for j := 0; j < iterations; j++ { + handler := SlogHandler() + require.NotNil(t, handler, "SlogHandler should always return non-nil") + + // Verify it's a valid handler + type goLogBridge interface { + GoLogBridge() + } + _, ok := handler.(goLogBridge) + require.True(t, ok, "Handler should be valid go-log bridge") + } + }() + } + + wg.Wait() +} diff --git a/slog_bridge.go b/slog_bridge.go new file mode 100644 index 0000000..a30dc7e --- /dev/null +++ b/slog_bridge.go @@ -0,0 +1,251 @@ +package log + +import ( + "context" + "log/slog" + "math" + "runtime" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// subsystemAttrKey is the attribute key used by gologshim to pass subsystem names +const subsystemAttrKey = "logger" + +// zapToSlogBridge adapts a zapcore.Core to implement slog.Handler. +// This allows slog logs to be processed through zap's formatting. +// IMPORTANT: core field maintains a reference to the LIVE loggerCore, not a snapshot. +// This ensures logs reach cores added dynamically (e.g., pipe readers from ipfs log tail). +type zapToSlogBridge struct { + core zapcore.Core + subsystemName string // Used for LoggerName in zap entries + fields []zapcore.Field // Fields accumulated from WithAttrs calls +} + +// newZapToSlogBridge creates a new slog.Handler that writes to the given zap core. +func newZapToSlogBridge(core zapcore.Core) slog.Handler { + return &zapToSlogBridge{core: core} +} + +// subsystemAwareHandler wraps zapToSlogBridge and provides early level filtering +// using go-log's per-subsystem atomic levels. This avoids expensive conversions +// for filtered log messages. +type subsystemAwareHandler struct { + bridge *zapToSlogBridge + subsystem string + atomicLevel zap.AtomicLevel +} + +// GoLogBridge is a marker method that allows libraries to detect go-log's slog bridge +// at runtime via duck typing, without adding go-log to their dependency tree. +// This enables automatic integration when go-log is present in the application. +func (h *subsystemAwareHandler) GoLogBridge() {} + +func (h *subsystemAwareHandler) Enabled(_ context.Context, level slog.Level) bool { + // Fast path - check subsystem level FIRST before expensive conversions + zapLevel := slogLevelToZap(level) + if !h.atomicLevel.Enabled(zapLevel) { + return false + } + return h.bridge.core.Enabled(zapLevel) +} + +func (h *subsystemAwareHandler) Handle(ctx context.Context, record slog.Record) error { + return h.bridge.Handle(ctx, record) +} + +func (h *subsystemAwareHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + // Convert attrs to zap fields, filtering out subsystem key if present + fields := make([]zapcore.Field, 0, len(h.bridge.fields)+len(attrs)) + fields = append(fields, h.bridge.fields...) // Preserve existing fields + for _, attr := range attrs { + if attr.Key != subsystemAttrKey { + fields = append(fields, slogAttrToZapField(attr)) + } + } + + return &subsystemAwareHandler{ + bridge: &zapToSlogBridge{ + core: h.bridge.core, // Keep reference to LIVE loggerCore + subsystemName: h.subsystem, + fields: fields, // Accumulate fields + }, + subsystem: h.subsystem, + atomicLevel: h.atomicLevel, + } +} + +func (h *subsystemAwareHandler) WithGroup(name string) slog.Handler { + return &subsystemAwareHandler{ + bridge: &zapToSlogBridge{ + core: h.bridge.core, + subsystemName: h.subsystem, + fields: h.bridge.fields, // Preserve fields + }, + subsystem: h.subsystem, + atomicLevel: h.atomicLevel, + } +} + +// getOrCreateAtomicLevel returns the atomic level for a subsystem, +// creating it with the default level if it doesn't exist. +func getOrCreateAtomicLevel(subsystem string) zap.AtomicLevel { + loggerMutex.RLock() + atomicLevel, exists := levels[subsystem] + loggerMutex.RUnlock() + + if !exists { + loggerMutex.Lock() + // Check again in case another goroutine created it + if atomicLevel, exists = levels[subsystem]; !exists { + atomicLevel = zap.NewAtomicLevelAt(zapcore.Level(defaultLevel)) + levels[subsystem] = atomicLevel + } + loggerMutex.Unlock() + } + + return atomicLevel +} + +// GoLogBridge is a marker method that allows libraries to detect go-log's slog bridge +// at runtime via duck typing, without adding go-log to their dependency tree. +// This enables automatic integration when go-log is present in the application. +func (h *zapToSlogBridge) GoLogBridge() {} + +// Enabled implements slog.Handler. +func (h *zapToSlogBridge) Enabled(_ context.Context, level slog.Level) bool { + return h.core.Enabled(slogLevelToZap(level)) +} + +// Handle implements slog.Handler. +func (h *zapToSlogBridge) Handle(_ context.Context, record slog.Record) error { + // Convert slog.Record to zap fields, prepending stored fields from WithAttrs + fields := make([]zapcore.Field, 0, len(h.fields)+record.NumAttrs()) + fields = append(fields, h.fields...) // Add stored fields first + record.Attrs(func(attr slog.Attr) bool { + fields = append(fields, slogAttrToZapField(attr)) + return true + }) + + // Resolve PC to file:line for accurate source location + var caller zapcore.EntryCaller + if record.PC != 0 { + frames := runtime.CallersFrames([]uintptr{record.PC}) + frame, _ := frames.Next() + caller = zapcore.NewEntryCaller(record.PC, frame.File, frame.Line, frame.PC != 0) + } else { + caller = zapcore.NewEntryCaller(0, "", 0, false) + } + + // Create zap entry + entry := zapcore.Entry{ + Level: slogLevelToZap(record.Level), + Time: record.Time, + Message: record.Message, + LoggerName: h.subsystemName, + Caller: caller, + } + + // Use Check() to respect each core's level filtering (important for pipe readers) + ce := h.core.Check(entry, nil) + if ce != nil { + ce.Write(fields...) + } + return nil +} + +// WithAttrs implements slog.Handler. +func (h *zapToSlogBridge) WithAttrs(attrs []slog.Attr) slog.Handler { + // Check if subsystem attribute present (gologshim adds this) + var subsystem string + fields := make([]zapcore.Field, 0, len(h.fields)+len(attrs)) + fields = append(fields, h.fields...) // Preserve existing fields + + for _, attr := range attrs { + if attr.Key == subsystemAttrKey { + subsystem = attr.Value.String() + // Don't include as a field - will use as LoggerName + } else { + fields = append(fields, slogAttrToZapField(attr)) + } + } + + newBridge := &zapToSlogBridge{ + core: h.core, // Keep reference to LIVE loggerCore, don't snapshot + subsystemName: subsystem, + fields: fields, // Accumulate fields to apply during Handle() + } + + // If subsystem specified, wrap with level-aware handler for early filtering + if subsystem != "" { + atomicLevel := getOrCreateAtomicLevel(subsystem) + return &subsystemAwareHandler{ + bridge: newBridge, + subsystem: subsystem, + atomicLevel: atomicLevel, + } + } + + return newBridge +} + +// WithGroup implements slog.Handler. +func (h *zapToSlogBridge) WithGroup(name string) slog.Handler { + // Groups are currently not implemented - just return a handler preserving the subsystem. + // A more sophisticated implementation would nest fields under the group name. + return &zapToSlogBridge{ + core: h.core, + subsystemName: h.subsystemName, // Preserve subsystem + fields: h.fields, // Preserve fields + } +} + +// slogLevelToZap converts slog.Level to zapcore.Level. +func slogLevelToZap(level slog.Level) zapcore.Level { + switch { + case level >= slog.LevelError: + return zapcore.ErrorLevel + case level >= slog.LevelWarn: + return zapcore.WarnLevel + case level >= slog.LevelInfo: + return zapcore.InfoLevel + default: + return zapcore.DebugLevel + } +} + +// slogAttrToZapField converts slog.Attr to zapcore.Field. +func slogAttrToZapField(attr slog.Attr) zapcore.Field { + key := attr.Key + value := attr.Value + + switch value.Kind() { + case slog.KindString: + return zapcore.Field{Key: key, Type: zapcore.StringType, String: value.String()} + case slog.KindInt64: + return zapcore.Field{Key: key, Type: zapcore.Int64Type, Integer: value.Int64()} + case slog.KindUint64: + return zapcore.Field{Key: key, Type: zapcore.Uint64Type, Integer: int64(value.Uint64())} + case slog.KindFloat64: + return zapcore.Field{Key: key, Type: zapcore.Float64Type, Integer: int64(math.Float64bits(value.Float64()))} + case slog.KindBool: + return zapcore.Field{Key: key, Type: zapcore.BoolType, Integer: boolToInt64(value.Bool())} + case slog.KindDuration: + return zapcore.Field{Key: key, Type: zapcore.DurationType, Integer: value.Duration().Nanoseconds()} + case slog.KindTime: + return zapcore.Field{Key: key, Type: zapcore.TimeType, Integer: value.Time().UnixNano(), Interface: value.Time().Location()} + case slog.KindAny: + return zapcore.Field{Key: key, Type: zapcore.ReflectType, Interface: value.Any()} + default: + // Fallback for complex types + return zapcore.Field{Key: key, Type: zapcore.ReflectType, Interface: value.Any()} + } +} + +func boolToInt64(b bool) int64 { + if b { + return 1 + } + return 0 +} diff --git a/slog_bridge_test.go b/slog_bridge_test.go new file mode 100644 index 0000000..f2922da --- /dev/null +++ b/slog_bridge_test.go @@ -0,0 +1,446 @@ +package log + +import ( + "bufio" + "bytes" + "log/slog" + "os" + "strings" + "testing" + "time" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// goLogBridge is used to detect go-log's slog bridge +type goLogBridge interface { + GoLogBridge() +} + +func TestSlogInterop(t *testing.T) { + // Save initial state + originalDefault := slog.Default() + defer slog.SetDefault(originalDefault) + + t.Run("disabled by default", func(t *testing.T) { + beforeSetup := slog.Default() + + cfg := Config{ + Format: PlaintextOutput, + Level: LevelInfo, + Stderr: true, + } + + SetupLogging(cfg) + + // slog.Default should NOT have changed automatically + if slog.Default() != beforeSetup { + t.Error("slog.Default() should NOT be automatically set by SetupLogging") + } + + // Test that slog logs still work via SlogHandler() + slog.Info("test message", "key", "value") + }) + + t.Run("enabled via GOLOG_CAPTURE_DEFAULT_SLOG=true", func(t *testing.T) { + beforeSetup := slog.Default() + + // Set env var to enable + os.Setenv("GOLOG_CAPTURE_DEFAULT_SLOG", "true") + defer os.Unsetenv("GOLOG_CAPTURE_DEFAULT_SLOG") + + cfg := Config{ + Format: PlaintextOutput, + Level: LevelInfo, + Stderr: true, + } + + SetupLogging(cfg) + + // slog.Default should have changed + if slog.Default() == beforeSetup { + t.Error("slog.Default() should be modified when GOLOG_CAPTURE_DEFAULT_SLOG=true") + } + }) +} + +func TestSlogBridgeLevels(t *testing.T) { + tests := []struct { + slogLevel slog.Level + wantZap string + }{ + {slog.LevelDebug, "debug"}, + {slog.LevelInfo, "info"}, + {slog.LevelWarn, "warn"}, + {slog.LevelError, "error"}, + } + + for _, tt := range tests { + t.Run(strings.ToUpper(tt.wantZap), func(t *testing.T) { + zapLevel := slogLevelToZap(tt.slogLevel) + if !strings.Contains(zapLevel.String(), tt.wantZap) { + t.Errorf("slogLevelToZap(%v) = %v, want to contain %v", tt.slogLevel, zapLevel, tt.wantZap) + } + }) + } +} + +func TestSlogAttrFieldConversions(t *testing.T) { + // Save and restore global state + originalDefault := slog.Default() + defer slog.SetDefault(originalDefault) + + // Test that slog.Attr types are correctly converted to zap fields + var buf bytes.Buffer + ws := zapcore.AddSync(&buf) + testCore := newCore(PlaintextOutput, ws, LevelDebug) + setPrimaryCore(testCore) + + bridge := newZapToSlogBridge(testCore) + slog.SetDefault(slog.New(bridge)) + + // Test all slog attribute types + logger := slog.Default() + + // String + logger.Info("test", "string_key", "string_value") + output := buf.String() + if !strings.Contains(output, "string_key") || !strings.Contains(output, "string_value") { + t.Error("String attribute not correctly converted") + } + + // Int64 + buf.Reset() + logger.Info("test", "int64_key", int64(42)) + output = buf.String() + if !strings.Contains(output, "int64_key") || !strings.Contains(output, "42") { + t.Error("Int64 attribute not correctly converted") + } + + // Uint64 + buf.Reset() + logger.Info("test", "uint64_key", uint64(100)) + output = buf.String() + if !strings.Contains(output, "uint64_key") || !strings.Contains(output, "100") { + t.Error("Uint64 attribute not correctly converted") + } + + // Float64 - this tests the bug fix + buf.Reset() + logger.Info("test", "float64_key", float64(3.14159)) + output = buf.String() + if !strings.Contains(output, "float64_key") || !strings.Contains(output, "3.14159") { + t.Errorf("Float64 attribute not correctly converted: %s", output) + } + + // Bool + buf.Reset() + logger.Info("test", "bool_key", true) + output = buf.String() + if !strings.Contains(output, "bool_key") || !strings.Contains(output, "true") { + t.Error("Bool attribute not correctly converted") + } + + // Duration + buf.Reset() + logger.Info("test", "duration_key", slog.DurationValue(5*time.Second)) + output = buf.String() + if !strings.Contains(output, "duration_key") || !strings.Contains(output, "5") { + t.Error("Duration attribute not correctly converted") + } + + // Time + buf.Reset() + testTime := time.Date(2025, 10, 26, 12, 0, 0, 0, time.UTC) + logger.Info("test", "time_key", slog.TimeValue(testTime)) + output = buf.String() + if !strings.Contains(output, "time_key") || !strings.Contains(output, "2025") { + t.Error("Time attribute not correctly converted") + } + + // Any (complex type) + buf.Reset() + logger.Info("test", "any_key", slog.AnyValue(map[string]int{"count": 5})) + output = buf.String() + if !strings.Contains(output, "any_key") { + t.Error("Any attribute not correctly converted") + } +} + +func TestSubsystemAwareLevelControl(t *testing.T) { + // Save and restore global state + originalDefault := slog.Default() + defer slog.SetDefault(originalDefault) + + loggerMutex.Lock() + originalLevels := levels + originalDefaultLevel := defaultLevel + levels = make(map[string]zap.AtomicLevel) + defaultLevel = LevelError + loggerMutex.Unlock() + defer func() { + loggerMutex.Lock() + levels = originalLevels + defaultLevel = originalDefaultLevel + loggerMutex.Unlock() + }() + + // Capture log output + var buf bytes.Buffer + + // Create a custom core that writes to our buffer + ws := zapcore.AddSync(&buf) + testCore := newCore(PlaintextOutput, ws, LevelDebug) + setPrimaryCore(testCore) + setAllLoggers(LevelError) + + // Set up slog bridge + bridge := newZapToSlogBridge(testCore) + slog.SetDefault(slog.New(bridge)) + + // Create a subsystem-aware logger (mimics gologshim behavior) + logger := slog.Default().With("logger", "test-subsystem") + + // Try to log debug message - should be filtered at ERROR level + logger.Debug("this should not appear") + output := buf.String() + if strings.Contains(output, "this should not appear") { + t.Error("Debug log should be filtered when subsystem is at ERROR level") + } + + // Change level dynamically using SetLogLevel (mimics `ipfs log level` RPC) + err := SetLogLevel("test-subsystem", "debug") + if err != nil { + t.Fatalf("SetLogLevel failed: %v", err) + } + + // Now log debug message - should appear + buf.Reset() + logger.Debug("this should appear", "key", "value") + output = buf.String() + + if !strings.Contains(output, "this should appear") { + t.Error("Debug log should appear after SetLogLevel to debug") + } + if !strings.Contains(output, "test-subsystem") { + t.Error("Log should contain subsystem name") + } + if !strings.Contains(output, "key") || !strings.Contains(output, "value") { + t.Error("Log should contain key-value attributes") + } + + // Change back to info - debug should be filtered again + err = SetLogLevel("test-subsystem", "info") + if err != nil { + t.Fatalf("SetLogLevel failed: %v", err) + } + + buf.Reset() + logger.Debug("this should not appear again") + output = buf.String() + if strings.Contains(output, "this should not appear again") { + t.Error("Debug log should be filtered when level changed back to INFO") + } + + // Info should still work + logger.Info("info message") + output = buf.String() + if !strings.Contains(output, "info message") { + t.Error("Info log should appear at INFO level") + } +} + +func TestSetLogLevelWithSlog(t *testing.T) { + // Save and restore global state + originalDefault := slog.Default() + defer slog.SetDefault(originalDefault) + + loggerMutex.Lock() + originalLevels := levels + originalDefaultLevel := defaultLevel + levels = make(map[string]zap.AtomicLevel) + defaultLevel = LevelError + loggerMutex.Unlock() + defer func() { + loggerMutex.Lock() + levels = originalLevels + defaultLevel = originalDefaultLevel + loggerMutex.Unlock() + }() + + // Setup go-log + var buf bytes.Buffer + ws := zapcore.AddSync(&buf) + testCore := newCore(PlaintextOutput, ws, LevelDebug) + setPrimaryCore(testCore) + setAllLoggers(LevelError) + + bridge := newZapToSlogBridge(testCore) + slog.SetDefault(slog.New(bridge)) + + // Create slog logger for subsystem that doesn't exist yet + logger := slog.Default().With("logger", "test-slog-subsystem") + + // Debug should be filtered (default is error) + logger.Debug("should not appear") + if strings.Contains(buf.String(), "should not appear") { + t.Error("Debug log should be filtered at ERROR level") + } + + // Set level dynamically via SetLogLevel + err := SetLogLevel("test-slog-subsystem", "debug") + if err != nil { + t.Fatalf("SetLogLevel failed: %v", err) + } + + // Debug should now appear + buf.Reset() + logger.Debug("should appear") + if !strings.Contains(buf.String(), "should appear") { + t.Error("Debug log should appear after SetLogLevel to debug") + } +} + +func TestPipeReaderCapturesSlogLogs(t *testing.T) { + // Setup go-log + SetupLogging(Config{ + Format: JSONOutput, + Level: LevelError, + Stderr: false, + Stdout: false, + }) + + // Explicitly set go-log's handler as slog.Default + slog.SetDefault(slog.New(SlogHandler())) + + // Set levels for both subsystems + SetLogLevel("test-native", "debug") + SetLogLevel("test-slog", "debug") + + // Create pipe reader + pipeReader := NewPipeReader() + defer pipeReader.Close() + + // Start reading from pipe + var buf bytes.Buffer + done := make(chan struct{}) + go func() { + scanner := bufio.NewScanner(pipeReader) + for scanner.Scan() { + buf.WriteString(scanner.Text()) + buf.WriteString("\n") + } + close(done) + }() + + // Log from native go-log logger + nativeLogger := Logger("test-native") + nativeLogger.Debug("native debug message") + + // Log from slog (simulating gologshim behavior) + slogLogger := slog.Default().With("logger", "test-slog") + slogLogger.Debug("slog debug message") + + // Give logs time to flush + time.Sleep(200 * time.Millisecond) + pipeReader.Close() + <-done + + output := buf.String() + t.Logf("Pipe reader captured:\n%s", output) + + // Check both logs were captured + if !strings.Contains(output, "test-native") { + t.Error("Native log not captured") + } + if !strings.Contains(output, "native debug message") { + t.Error("Native log message not found") + } + if !strings.Contains(output, "test-slog") { + t.Error("Slog logger name not captured") + } + if !strings.Contains(output, "slog debug message") { + t.Error("Slog log message not found") + } +} + +// createGologshimStyleLogger simulates gologshim.Logger() behavior. +// After SetupLogging is called, slog.Default() contains go-log's bridge. +// This function checks for the bridge and uses it with WithAttrs to add the subsystem. +func createGologshimStyleLogger(system string) *slog.Logger { + if _, ok := slog.Default().Handler().(goLogBridge); ok { + attrs := []slog.Attr{slog.String("logger", system)} + h := slog.Default().Handler().WithAttrs(attrs) + return slog.New(h) + } + panic("go-log bridge not detected") +} + +func TestPipeReaderCapturesGologshimStyleLogs(t *testing.T) { + // Setup go-log + SetupLogging(Config{ + Format: JSONOutput, + Level: LevelError, + Stderr: false, + Stdout: false, + }) + + // Explicitly set go-log's handler as slog.Default + slog.SetDefault(slog.New(SlogHandler())) + + // Verify slog.Default() has the bridge + if _, ok := slog.Default().Handler().(goLogBridge); !ok { + t.Fatal("slog.Default() does not have go-log bridge") + } + + // Set levels + SetLogLevel("test-native", "debug") + SetLogLevel("test-gologshim", "debug") + + // Create pipe reader + pipeReader := NewPipeReader() + defer pipeReader.Close() + + // Start reading from pipe + var buf bytes.Buffer + done := make(chan struct{}) + go func() { + scanner := bufio.NewScanner(pipeReader) + for scanner.Scan() { + buf.WriteString(scanner.Text()) + buf.WriteString("\n") + } + close(done) + }() + + // Log from native go-log logger + nativeLogger := Logger("test-native") + nativeLogger.Debug("native debug message") + + // Log from gologshim-style logger + gologshimLogger := createGologshimStyleLogger("test-gologshim") + gologshimLogger.Debug("gologshim debug message") + + // Give logs time to flush + time.Sleep(200 * time.Millisecond) + pipeReader.Close() + <-done + + output := buf.String() + t.Logf("Pipe reader captured:\n%s", output) + + // Check both logs were captured + if !strings.Contains(output, "test-native") { + t.Error("Native log not captured") + } + if !strings.Contains(output, "native debug message") { + t.Error("Native log message not found") + } + if !strings.Contains(output, "test-gologshim") { + t.Error("Gologshim logger name not captured") + } + if !strings.Contains(output, "gologshim debug message") { + t.Error("Gologshim log message not found") + } +}