From a39befba5ac5550a92ac259418c923186beb3577 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Wed, 23 Jul 2025 11:03:35 +0200 Subject: [PATCH 1/3] v2: add unit tests to assert SubSystem level inheritance This commit adds a unit test to assert the current, correct, behaviour of SubSystem in that it will create a new logger that does not inherit any log level changes from its parent after creation. --- v2/handler.go | 7 +++- v2/handler_test.go | 102 +++++++++++++++++++++++++++++++++++++++++++++ v2/interface.go | 5 +++ v2/log.go | 5 +++ 4 files changed, 118 insertions(+), 1 deletion(-) diff --git a/v2/handler.go b/v2/handler.go index 97723f8..a9fec19 100644 --- a/v2/handler.go +++ b/v2/handler.go @@ -276,7 +276,12 @@ func (d *DefaultHandler) WithGroup(name string) slog.Handler { // attributes added with WithAttrs will be kept but all groups added with // WithGroup are lost. // -// note: this is part of the handler interface. +// NOTE: this creates a new logger with an independent log level. This +// means that SetLevel needs to be called on the new logger to change +// the level as any changes to the parent logger's level after creation +// will not be inherited by the new logger. +// +// NOTE: this is part of the Handler interface. func (d *DefaultHandler) SubSystem(tag string) Handler { return d.with(tag, d.prefix, false) } diff --git a/v2/handler_test.go b/v2/handler_test.go index 3c6f7ff..455c49c 100644 --- a/v2/handler_test.go +++ b/v2/handler_test.go @@ -298,3 +298,105 @@ value `, }, } + +// TestSubSystemLevelIndependence tests that child loggers created with +// SubSystem have independent level control and don't affect their parent's +// level. +func TestSubSystemLevelIndependence(t *testing.T) { + t.Parallel() + + var ( + buf bytes.Buffer + handler = NewDefaultHandler(&buf) + logger = NewSLogger(handler) + ) + + // Set initial level to Info. + logger.SetLevel(LevelInfo) + + // Create a child logger with subsystem. + childLogger := logger.SubSystem("CHILD") + + // Both loggers should initially have the same level. + if logger.Level() != childLogger.Level() { + t.Fatalf("Child logger level mismatch. Expected %s, got %s", + logger.Level(), childLogger.Level()) + } + + // Debug messages should not appear (level is Info). + logger.Debug("parent debug") + childLogger.Debug("child debug") + + // Assert that neither logger wrote to the buffer. + if buf.String() != "" { + t.Fatalf("Debug messages should not appear. Got: %s", + buf.String()) + } + + // Now, change ONLY child level to Debug. + childLogger.SetLevel(LevelDebug) + + // Loggers should now have different levels. + if logger.Level() == childLogger.Level() { + t.Fatalf("Child logger should have independent level. "+ + "Parent: %s, Child: %s", logger.Level(), + childLogger.Level()) + } + + // Verify parent is still Info and child is Debug. + if logger.Level() != LevelInfo { + t.Fatalf("Parent level should still be Info. Got: %s", + logger.Level()) + } + + if childLogger.Level() != LevelDebug { + t.Fatalf("Child level should be Debug. Got: %s", + childLogger.Level()) + } + + // Reset buffer. + buf.Reset() + + // Debug messages should only appear from child. + logger.Debug("parent debug") + childLogger.Debug("child debug") + + // Parent debug should NOT appear. + if bytes.Contains(buf.Bytes(), []byte("parent debug")) { + t.Fatalf("Parent debug message should not appear. Got: %s", + buf.String()) + } + + // Child debug SHOULD appear. + if !bytes.Contains(buf.Bytes(), []byte("child debug")) { + t.Fatalf("Child debug message should appear. Got: %s", + buf.String()) + } + + // Reset buffer. + buf.Reset() + + // Change parent level to Debug. + logger.SetLevel(LevelDebug) + + // Child level should remain unchanged. + if childLogger.Level() != LevelDebug { + t.Fatalf("Child level should remain Debug. Got: %s", + childLogger.Level()) + } + + // Now both should log debug messages. + logger.Debug("parent debug 2") + childLogger.Debug("child debug 2") + + // Both messages should appear. + if !bytes.Contains(buf.Bytes(), []byte("parent debug 2")) { + t.Fatalf("Parent debug message should appear. Got: %s", + buf.String()) + } + + if !bytes.Contains(buf.Bytes(), []byte("child debug 2")) { + t.Fatalf("Child debug message should appear. Got: %s", + buf.String()) + } +} diff --git a/v2/interface.go b/v2/interface.go index 34d4903..ea824ba 100644 --- a/v2/interface.go +++ b/v2/interface.go @@ -96,6 +96,11 @@ type Logger interface { // SubSystem returns a copy of the logger but with the new subsystem // tag. + // + // NOTE: this creates a new logger with an independent log level. This + // means that SetLevel needs to be called on the new logger to change + // the level as any changes to the parent logger's level after creation + // will not be inherited by the new logger. SubSystem(tag string) Logger // WithPrefix returns a copy of the logger but with the given string diff --git a/v2/log.go b/v2/log.go index 9145ab5..b4fa5ce 100644 --- a/v2/log.go +++ b/v2/log.go @@ -26,6 +26,11 @@ type Handler interface { SetLevel(level btclog.Level) // SubSystem returns a copy of the given handler but with the new tag. + // + // NOTE: this creates a new logger with an independent log level. This + // means that SetLevel needs to be called on the new logger to change + // the level as any changes to the parent logger's level after creation + // will not be inherited by the new logger. SubSystem(tag string) Handler // WithPrefix returns a copy of the Handler but with the given string From 28e42d275d464bf7c0017e26112a0acfae43d623 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Wed, 23 Jul 2025 11:05:09 +0200 Subject: [PATCH 2/3] v2: add log level inheritance test This commit adds a new `TestWithPrefixLevelInheritance` unit test which demonstrates that log level inheritance between parent loggers and child loggers created via "WithPrefix" does not work as expected. --- v2/handler_test.go | 60 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 60 insertions(+) diff --git a/v2/handler_test.go b/v2/handler_test.go index 455c49c..71e9626 100644 --- a/v2/handler_test.go +++ b/v2/handler_test.go @@ -400,3 +400,63 @@ func TestSubSystemLevelIndependence(t *testing.T) { buf.String()) } } + +// TestWithPrefixLevelInheritance tests that child loggers created with +// WithPrefix properly inherit level changes from their parent logger. +// +// NOTE: This currently demonstrate that inheritance is not working as expected. +// This will be fixed in the next commit. +func TestWithPrefixLevelInheritance(t *testing.T) { + t.Parallel() + + var ( + buf bytes.Buffer + handler = NewDefaultHandler(&buf) + logger = NewSLogger(handler) + ) + + // Set initial level to Info. + logger.SetLevel(LevelInfo) + + // Create a child logger with prefix. + childLogger := logger.WithPrefix("child") + + // Both loggers should have the same level. + if logger.Level() != childLogger.Level() { + t.Fatalf("Child logger level mismatch. Expected %s, got %s", + logger.Level(), childLogger.Level()) + } + + // Debug messages should not appear (level is Info). + logger.Debug("parent debug") + childLogger.Debug("child debug") + + // Assert that neither logger wrote to the buffer. + if buf.String() != "" { + t.Fatalf("Debug messages should not appear. Got: %s", + buf.String()) + } + + // Now, change parent level to Debug. + logger.SetLevel(LevelDebug) + + // Reset buffer. + buf.Reset() + + // Now debug messages should appear from both loggers. + logger.Debug("parent debug") + childLogger.Debug("child debug") + + // Show that the buffer contains the parent log. + if !bytes.Contains(buf.Bytes(), []byte("parent debug")) { + t.Fatalf("Parent debug message not found in output: %s", + buf.String()) + } + + // Show that the buffer currently _does not_ contain the child log. + // NOTE: This is a bug and will be fixed in the next commit. + if bytes.Contains(buf.Bytes(), []byte("child debug")) { + t.Fatalf("Child debug message found in output: %s", + buf.String()) + } +} From f0b9cb61021dbcabaeb91d9174fd94302cbdf4b2 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Wed, 23 Jul 2025 11:11:35 +0200 Subject: [PATCH 3/3] v2: fix child logger level inheritance In this commit, the bug demonstrated in the previous commit is fixed. Any child logger derived via WithPrefix will inherit a pointer to the same `level` variable of the parent meaning that any change inl log level will be reflected in the child logger. --- v2/handler.go | 37 +++++++++++++++++++++++++----------- v2/handler_test.go | 16 +++++++++------- v2/interface.go | 4 ++++ v2/log.go | 47 +++++++++++++++++++++++----------------------- 4 files changed, 62 insertions(+), 42 deletions(-) diff --git a/v2/handler.go b/v2/handler.go index a9fec19..8a0328f 100644 --- a/v2/handler.go +++ b/v2/handler.go @@ -119,7 +119,7 @@ func WithNoTimestamp() HandlerOption { // DefaultHandler is a Handler that can be used along with NewSLogger to // instantiate a structured logger. type DefaultHandler struct { - level atomic.Int64 + level *atomic.Int64 opts *handlerOpts buf *buffer @@ -162,10 +162,11 @@ func NewDefaultHandler(w io.Writer, options ...HandlerOption) *DefaultHandler { } handler := &DefaultHandler{ - w: w, - opts: opts, - buf: newBuffer(), - mu: &sync.Mutex{}, + w: w, + opts: opts, + buf: newBuffer(), + mu: &sync.Mutex{}, + level: &atomic.Int64{}, } handler.level.Store(int64(levelInfo)) @@ -257,7 +258,7 @@ func (d *DefaultHandler) Handle(_ context.Context, r slog.Record) error { // // NOTE: this is part of the slog.Handler interface. func (d *DefaultHandler) WithAttrs(attrs []slog.Attr) slog.Handler { - return d.with(d.tag, d.prefix, true, attrs...) + return d.with(d.tag, d.prefix, true, false, attrs...) } // WithGroup returns a new Handler with the given group appended to @@ -269,7 +270,7 @@ func (d *DefaultHandler) WithGroup(name string) slog.Handler { if d.tag != "" { name = d.tag + "." + name } - return d.with(name, d.prefix, true) + return d.with(name, d.prefix, true, false) } // SubSystem returns a copy of the given handler but with the new tag. All @@ -283,23 +284,29 @@ func (d *DefaultHandler) WithGroup(name string) slog.Handler { // // NOTE: this is part of the Handler interface. func (d *DefaultHandler) SubSystem(tag string) Handler { - return d.with(tag, d.prefix, false) + return d.with(tag, d.prefix, false, false) } // WithPrefix returns a copy of the Handler but with the given string prefixed // to each log message. Note that the subsystem of the original logger is kept // but any existing prefix is overridden. // -// note: this is part of the handler interface. +// NOTE: this creates a new logger with an inherited log level. This +// means that if SetLevel is called on the parent logger, then this new +// level will be inherited by the new logger +// +// NOTE: this is part of the Handler interface. func (d *DefaultHandler) WithPrefix(prefix string) Handler { - return d.with(d.tag, prefix, false) + return d.with(d.tag, prefix, false, true) } // with returns a new logger with the given attributes added. // withCallstackOffset should be false if the caller returns a concrete // DefaultHandler and true if the caller returns the Handler interface. +// The shareLevel param determines whether the new handler shares the same +// level reference or gets its own independent level. func (d *DefaultHandler) with(tag, prefix string, withCallstackOffset bool, - attrs ...slog.Attr) *DefaultHandler { + shareLevel bool, attrs ...slog.Attr) *DefaultHandler { d.mu.Lock() sl := *d @@ -315,6 +322,14 @@ func (d *DefaultHandler) with(tag, prefix string, withCallstackOffset bool, sl.tag = tag sl.prefix = prefix + // If shareLevel is false, create a new independent level. Otherwise, + // sl.level already points to d.level. + if !shareLevel { + newLevel := &atomic.Int64{} + newLevel.Store(d.level.Load()) + sl.level = newLevel + } + return &sl } diff --git a/v2/handler_test.go b/v2/handler_test.go index 71e9626..4813a35 100644 --- a/v2/handler_test.go +++ b/v2/handler_test.go @@ -403,9 +403,6 @@ func TestSubSystemLevelIndependence(t *testing.T) { // TestWithPrefixLevelInheritance tests that child loggers created with // WithPrefix properly inherit level changes from their parent logger. -// -// NOTE: This currently demonstrate that inheritance is not working as expected. -// This will be fixed in the next commit. func TestWithPrefixLevelInheritance(t *testing.T) { t.Parallel() @@ -440,6 +437,12 @@ func TestWithPrefixLevelInheritance(t *testing.T) { // Now, change parent level to Debug. logger.SetLevel(LevelDebug) + // Both loggers should have the same level. + if logger.Level() != childLogger.Level() { + t.Fatalf("Child logger level mismatch. Expected %s, got %s", + logger.Level(), childLogger.Level()) + } + // Reset buffer. buf.Reset() @@ -453,10 +456,9 @@ func TestWithPrefixLevelInheritance(t *testing.T) { buf.String()) } - // Show that the buffer currently _does not_ contain the child log. - // NOTE: This is a bug and will be fixed in the next commit. - if bytes.Contains(buf.Bytes(), []byte("child debug")) { - t.Fatalf("Child debug message found in output: %s", + // Show that the buffer contains the child log. + if !bytes.Contains(buf.Bytes(), []byte("child debug")) { + t.Fatalf("Child debug message not found in output: %s", buf.String()) } } diff --git a/v2/interface.go b/v2/interface.go index ea824ba..02855bc 100644 --- a/v2/interface.go +++ b/v2/interface.go @@ -106,6 +106,10 @@ type Logger interface { // WithPrefix returns a copy of the logger but with the given string // prefixed to each log message. Note that the subsystem of the original // logger is kept but any existing prefix is overridden. + // + // NOTE: this creates a new logger with an inherited log level. This + // means that if SetLevel is called on the parent logger, then this new + // level will be inherited by the new logger WithPrefix(prefix string) Logger } diff --git a/v2/log.go b/v2/log.go index b4fa5ce..f6531d7 100644 --- a/v2/log.go +++ b/v2/log.go @@ -5,7 +5,6 @@ import ( "fmt" "io" "log/slog" - "sync/atomic" "github.com/btcsuite/btclog" ) @@ -36,13 +35,15 @@ type Handler interface { // WithPrefix returns a copy of the Handler but with the given string // prefixed to each log message. Note that the subsystem of the original // logger is kept but any existing prefix is overridden. + // + // NOTE: this creates a new logger with an inherited log level. This + // means that if SetLevel is called on the parent logger, then this new + // level will be inherited by the new logger WithPrefix(prefix string) Handler } // sLogger is an implementation of Logger backed by a structured sLogger. type sLogger struct { - level atomic.Int64 - handler Handler logger *slog.Logger @@ -64,7 +65,6 @@ func NewSLogger(handler Handler) Logger { logger: slog.New(handler), unusedCtx: context.Background(), } - l.level.Store(int64(toSlogLevel(handler.Level()))) return l } @@ -74,7 +74,7 @@ func NewSLogger(handler Handler) Logger { // // This is part of the Logger interface implementation. func (l *sLogger) Tracef(format string, params ...any) { - if l.level.Load() > int64(levelTrace) { + if !l.handler.Enabled(l.unusedCtx, levelTrace) { return } @@ -86,7 +86,7 @@ func (l *sLogger) Tracef(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Debugf(format string, params ...any) { - if l.level.Load() > int64(levelDebug) { + if !l.handler.Enabled(l.unusedCtx, levelDebug) { return } @@ -98,7 +98,7 @@ func (l *sLogger) Debugf(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Infof(format string, params ...any) { - if l.level.Load() > int64(levelInfo) { + if !l.handler.Enabled(l.unusedCtx, levelInfo) { return } @@ -110,7 +110,7 @@ func (l *sLogger) Infof(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Warnf(format string, params ...any) { - if l.level.Load() > int64(levelWarn) { + if !l.handler.Enabled(l.unusedCtx, levelWarn) { return } @@ -122,7 +122,7 @@ func (l *sLogger) Warnf(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Errorf(format string, params ...any) { - if l.level.Load() > int64(levelError) { + if !l.handler.Enabled(l.unusedCtx, levelError) { return } @@ -134,7 +134,7 @@ func (l *sLogger) Errorf(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Criticalf(format string, params ...any) { - if l.level.Load() > int64(levelCritical) { + if !l.handler.Enabled(l.unusedCtx, levelCritical) { return } @@ -146,7 +146,7 @@ func (l *sLogger) Criticalf(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Trace(v ...any) { - if l.level.Load() > int64(levelTrace) { + if !l.handler.Enabled(l.unusedCtx, levelTrace) { return } @@ -158,7 +158,7 @@ func (l *sLogger) Trace(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Debug(v ...any) { - if l.level.Load() > int64(levelDebug) { + if !l.handler.Enabled(l.unusedCtx, levelDebug) { return } @@ -170,7 +170,7 @@ func (l *sLogger) Debug(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Info(v ...any) { - if l.level.Load() > int64(levelInfo) { + if !l.handler.Enabled(l.unusedCtx, levelInfo) { return } @@ -182,7 +182,7 @@ func (l *sLogger) Info(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Warn(v ...any) { - if l.level.Load() > int64(levelWarn) { + if !l.handler.Enabled(l.unusedCtx, levelWarn) { return } @@ -194,7 +194,7 @@ func (l *sLogger) Warn(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Error(v ...any) { - if l.level.Load() > int64(levelError) { + if !l.handler.Enabled(l.unusedCtx, levelError) { return } @@ -206,7 +206,7 @@ func (l *sLogger) Error(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Critical(v ...any) { - if l.level.Load() > int64(levelCritical) { + if !l.handler.Enabled(l.unusedCtx, levelCritical) { return } @@ -218,7 +218,7 @@ func (l *sLogger) Critical(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) TraceS(ctx context.Context, msg string, attrs ...any) { - if l.level.Load() > int64(levelTrace) { + if !l.handler.Enabled(ctx, levelTrace) { return } @@ -230,7 +230,7 @@ func (l *sLogger) TraceS(ctx context.Context, msg string, attrs ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) DebugS(ctx context.Context, msg string, attrs ...any) { - if l.level.Load() > int64(levelDebug) { + if !l.handler.Enabled(ctx, levelDebug) { return } @@ -242,7 +242,7 @@ func (l *sLogger) DebugS(ctx context.Context, msg string, attrs ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) InfoS(ctx context.Context, msg string, attrs ...any) { - if l.level.Load() > int64(levelInfo) { + if !l.handler.Enabled(ctx, levelInfo) { return } @@ -256,7 +256,7 @@ func (l *sLogger) InfoS(ctx context.Context, msg string, attrs ...any) { func (l *sLogger) WarnS(ctx context.Context, msg string, err error, attrs ...any) { - if l.level.Load() > int64(levelWarn) { + if !l.handler.Enabled(ctx, levelWarn) { return } @@ -274,7 +274,7 @@ func (l *sLogger) WarnS(ctx context.Context, msg string, err error, func (l *sLogger) ErrorS(ctx context.Context, msg string, err error, attrs ...any) { - if l.level.Load() > int64(levelError) { + if !l.handler.Enabled(ctx, levelError) { return } @@ -292,7 +292,7 @@ func (l *sLogger) ErrorS(ctx context.Context, msg string, err error, func (l *sLogger) CriticalS(ctx context.Context, msg string, err error, attrs ...any) { - if l.level.Load() > int64(levelCritical) { + if !l.handler.Enabled(ctx, levelCritical) { return } @@ -307,14 +307,13 @@ func (l *sLogger) CriticalS(ctx context.Context, msg string, err error, // // This is part of the Logger interface implementation. func (l *sLogger) Level() btclog.Level { - return fromSlogLevel(slog.Level(l.level.Load())) + return l.handler.Level() } // SetLevel changes the logging level of the Handler to the passed level. // // This is part of the Logger interface implementation. func (l *sLogger) SetLevel(level btclog.Level) { - l.level.Store(int64(toSlogLevel(level))) l.handler.SetLevel(level) }