From 04ed887114657a3d62f1a81068d856f0b6c83f6a Mon Sep 17 00:00:00 2001 From: Evan Phoenix Date: Thu, 9 Nov 2023 14:29:55 -0800 Subject: [PATCH 1/3] Implement the ability to more logically share level hierarchies --- intlogger.go | 89 +++++++++++++++++++++++++++++++++++++++++++------- logger.go | 18 ++++++++++ logger_test.go | 82 ++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 177 insertions(+), 12 deletions(-) diff --git a/intlogger.go b/intlogger.go index b45064a..344d793 100644 --- a/intlogger.go +++ b/intlogger.go @@ -79,6 +79,16 @@ type intLogger struct { writer *writer level *int32 + // The value of curEpoch the last time we performed the level sync process + ownEpoch int32 + + // Shared amongst all the loggers created in this hierachy, used to determine + // if the level sync process should be run by comparing it with ownEpoch + curEpoch *int32 + + //The logger this one was created from. Only set when syncParentLevel is set + parent *intLogger + headerColor ColorOption fieldColor ColorOption @@ -88,6 +98,7 @@ type intLogger struct { // create subloggers with their own level setting independentLevels bool + syncParentLevel bool subloggerHook func(sub Logger) Logger } @@ -129,9 +140,9 @@ func newLogger(opts *LoggerOptions) *intLogger { } var ( - primaryColor ColorOption = ColorOff - headerColor ColorOption = ColorOff - fieldColor ColorOption = ColorOff + primaryColor = ColorOff + headerColor = ColorOff + fieldColor = ColorOff ) switch { case opts.ColorHeaderOnly: @@ -152,8 +163,10 @@ func newLogger(opts *LoggerOptions) *intLogger { mutex: mutex, writer: newWriter(output, primaryColor), level: new(int32), + curEpoch: new(int32), exclude: opts.Exclude, independentLevels: opts.IndependentLevels, + syncParentLevel: opts.SyncParentLevel, headerColor: headerColor, fieldColor: fieldColor, subloggerHook: opts.SubloggerHook, @@ -194,7 +207,7 @@ const offsetIntLogger = 3 // Log a message and a set of key/value pairs if the given level is at // or more severe that the threshold configured in the Logger. func (l *intLogger) log(name string, level Level, msg string, args ...interface{}) { - if level < Level(atomic.LoadInt32(l.level)) { + if level < l.GetLevel() { return } @@ -597,7 +610,7 @@ func (l *intLogger) logJSON(t time.Time, name string, level Level, msg string, a vals := l.jsonMapEntry(t, name, level, msg) args = append(l.implied, args...) - if args != nil && len(args) > 0 { + if len(args) > 0 { if len(args)%2 != 0 { cs, ok := args[len(args)-1].(CapturedStacktrace) if ok { @@ -718,27 +731,27 @@ func (l *intLogger) Error(msg string, args ...interface{}) { // Indicate that the logger would emit TRACE level logs func (l *intLogger) IsTrace() bool { - return Level(atomic.LoadInt32(l.level)) == Trace + return l.GetLevel() == Trace } // Indicate that the logger would emit DEBUG level logs func (l *intLogger) IsDebug() bool { - return Level(atomic.LoadInt32(l.level)) <= Debug + return l.GetLevel() <= Debug } // Indicate that the logger would emit INFO level logs func (l *intLogger) IsInfo() bool { - return Level(atomic.LoadInt32(l.level)) <= Info + return l.GetLevel() <= Info } // Indicate that the logger would emit WARN level logs func (l *intLogger) IsWarn() bool { - return Level(atomic.LoadInt32(l.level)) <= Warn + return l.GetLevel() <= Warn } // Indicate that the logger would emit ERROR level logs func (l *intLogger) IsError() bool { - return Level(atomic.LoadInt32(l.level)) <= Error + return l.GetLevel() <= Error } const MissingKey = "EXTRA_VALUE_AT_END" @@ -854,12 +867,62 @@ func (l *intLogger) resetOutput(opts *LoggerOptions) error { // Update the logging level on-the-fly. This will affect all subloggers as // well. func (l *intLogger) SetLevel(level Level) { - atomic.StoreInt32(l.level, int32(level)) + if !l.syncParentLevel { + atomic.StoreInt32(l.level, int32(level)) + return + } + + nsl := new(int32) + *nsl = int32(level) + + l.level = nsl + + l.ownEpoch = atomic.AddInt32(l.curEpoch, 1) +} + +func (l *intLogger) searchLevelPtr() *int32 { + p := l.parent + + ptr := l.level + + max := l.ownEpoch + + for p != nil { + if p.ownEpoch > max { + max = p.ownEpoch + ptr = p.level + } + + p = p.parent + } + + return ptr } // Returns the current level func (l *intLogger) GetLevel() Level { - return Level(atomic.LoadInt32(l.level)) + // We perform the loads immediately to keep the CPU pipeline busy, which + // effectively makes the second load cost nothing. Once loaded into registers + // the comparison returns the already loaded value. The comparison is almost + // always true, so the branch predictor should hit consistently with it. + var ( + curEpoch = atomic.LoadInt32(l.curEpoch) + level = Level(atomic.LoadInt32(l.level)) + own = l.ownEpoch + ) + + if curEpoch == own { + return level + } + + // Perform the level sync process. We'll avoid doing this next time by seeing the + // epoch as current. + + ptr := l.searchLevelPtr() + l.level = ptr + l.ownEpoch = curEpoch + + return Level(atomic.LoadInt32(ptr)) } // Create a *log.Logger that will send it's data through this Logger. This @@ -912,6 +975,8 @@ func (l *intLogger) copy() *intLogger { if l.independentLevels { sl.level = new(int32) *sl.level = *l.level + } else if l.syncParentLevel { + sl.parent = l } return &sl diff --git a/logger.go b/logger.go index 947ac0c..861f571 100644 --- a/logger.go +++ b/logger.go @@ -303,6 +303,24 @@ type LoggerOptions struct { // will not affect the parent or sibling loggers. IndependentLevels bool + // When set, changing the level of a logger effects only it's direct sub-loggers + // rather than all sub-loggers. For example: + // a := logger.Named("a") + // a.SetLevel(Error) + // b := a.Named("b") + // c := a.Named("c") + // b.GetLevel() => Error + // c.GetLevel() => Error + // b.SetLevel(Info) + // a.GetLevel() => Error + // b.GetLevel() => Info + // c.GetLevel() => Error + // a.SetLevel(Warn) + // a.GetLevel() => Warn + // b.GetLevel() => Warn + // c.GetLevel() => Warn + SyncParentLevel bool + // SubloggerHook registers a function that is called when a sublogger via // Named, With, or ResetNamed is created. If defined, the function is passed // the newly created Logger and the returned Logger is returned from the diff --git a/logger_test.go b/logger_test.go index 2440c2b..1d10e3e 100644 --- a/logger_test.go +++ b/logger_test.go @@ -586,6 +586,88 @@ func TestLogger(t *testing.T) { t.Fatal("output from disabled logger:", str) } }) + + t.Run("sub-loggers levels don't bubble upward", func(t *testing.T) { + var buf bytes.Buffer + + logger := New(&LoggerOptions{ + Name: "root", + Output: &buf, + SyncParentLevel: true, + }) + + another := logger.Named("sublogger") + another.SetLevel(Error) + + logger.Info("this is test") + str := buf.String() + dataIdx := strings.IndexByte(str, ' ') + rest := str[dataIdx+1:] + assert.Equal(t, "[INFO] root: this is test\n", rest) + + buf.Reset() + + a := logger.Named("a") + b := a.Named("b") + c := a.Named("c") + + a.SetLevel(Error) + + b.Info("this is a test") + + require.Empty(t, buf.String()) + + b.SetLevel(Info) + + assert.Equal(t, Error, a.GetLevel()) + + a.SetLevel(Error) + + assert.Equal(t, Error, b.GetLevel()) + + assert.Equal(t, Error, c.GetLevel()) + + // Make sure that setting a sibling logger doesn't confuse + // when b had previously had it's own level. + c.SetLevel(Info) + + assert.Equal(t, Error, b.GetLevel()) + }) + + t.Run("level sync example", func(t *testing.T) { + var buf bytes.Buffer + + logger := New(&LoggerOptions{ + Name: "root", + Output: &buf, + SyncParentLevel: true, + }) + + s := assert.New(t) + + a := logger.Named("a") + a.SetLevel(Error) + b := a.Named("b") + c := a.Named("c") + s.Equal(Error, b.GetLevel()) + s.Equal(Error, c.GetLevel()) + + b.SetLevel(Info) + s.Equal(Error, a.GetLevel()) + s.Equal(Info, b.GetLevel()) + s.Equal(Error, c.GetLevel()) + + a.SetLevel(Warn) + s.Equal(Warn, a.GetLevel()) + s.Equal(Warn, b.GetLevel()) + s.Equal(Warn, c.GetLevel()) + + logger.SetLevel(Trace) + s.Equal(Trace, logger.GetLevel()) + s.Equal(Trace, a.GetLevel()) + s.Equal(Trace, b.GetLevel()) + s.Equal(Trace, c.GetLevel()) + }) } func TestLogger_leveledWriter(t *testing.T) { From 3d493540e3bafde53c32fe39499ddc3170653f09 Mon Sep 17 00:00:00 2001 From: Evan Phoenix Date: Thu, 9 Nov 2023 20:20:16 -0800 Subject: [PATCH 2/3] Use uint64 for epoch to avoid dealing with overflows --- intlogger.go | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/intlogger.go b/intlogger.go index 344d793..05d4385 100644 --- a/intlogger.go +++ b/intlogger.go @@ -80,11 +80,11 @@ type intLogger struct { level *int32 // The value of curEpoch the last time we performed the level sync process - ownEpoch int32 + ownEpoch uint64 // Shared amongst all the loggers created in this hierachy, used to determine // if the level sync process should be run by comparing it with ownEpoch - curEpoch *int32 + curEpoch *uint64 //The logger this one was created from. Only set when syncParentLevel is set parent *intLogger @@ -163,7 +163,7 @@ func newLogger(opts *LoggerOptions) *intLogger { mutex: mutex, writer: newWriter(output, primaryColor), level: new(int32), - curEpoch: new(int32), + curEpoch: new(uint64), exclude: opts.Exclude, independentLevels: opts.IndependentLevels, syncParentLevel: opts.SyncParentLevel, @@ -877,7 +877,7 @@ func (l *intLogger) SetLevel(level Level) { l.level = nsl - l.ownEpoch = atomic.AddInt32(l.curEpoch, 1) + l.ownEpoch = atomic.AddUint64(l.curEpoch, 1) } func (l *intLogger) searchLevelPtr() *int32 { @@ -906,7 +906,7 @@ func (l *intLogger) GetLevel() Level { // the comparison returns the already loaded value. The comparison is almost // always true, so the branch predictor should hit consistently with it. var ( - curEpoch = atomic.LoadInt32(l.curEpoch) + curEpoch = atomic.LoadUint64(l.curEpoch) level = Level(atomic.LoadInt32(l.level)) own = l.ownEpoch ) From 4911d46834fce8161690850783ec51d83cc36683 Mon Sep 17 00:00:00 2001 From: Evan Phoenix Date: Tue, 14 Nov 2023 10:09:00 -0600 Subject: [PATCH 3/3] Update intlogger.go Co-authored-by: Paul Banks --- intlogger.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/intlogger.go b/intlogger.go index 05d4385..0f63466 100644 --- a/intlogger.go +++ b/intlogger.go @@ -86,7 +86,7 @@ type intLogger struct { // if the level sync process should be run by comparing it with ownEpoch curEpoch *uint64 - //The logger this one was created from. Only set when syncParentLevel is set + // The logger this one was created from. Only set when syncParentLevel is set parent *intLogger headerColor ColorOption