Merge pull request #134 from hashicorp/f-better-levels

Implement the ability to more logically share level hierarchies

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 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 *uint64
+
+	// 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(uint64),
 		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.AddUint64(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.LoadUint64(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

logger.go

@@ -304,6 +304,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

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) {