core Check() evaluate level for entry's logger name

The existing code uses a level enabler for each logger
that assumes logger names never change, which isn't true
when creating a named logger with a parent logger. This
CR ensures the core's Check() method evaluates the level
based on the zapcore.Entry's logger name.

FAB-12611 #done

Change-Id: I096c90c1f9b4bea897ebfa33be201cd18098c281
Signed-off-by: Will Lahti <wtlahti@us.ibm.com>

Author: wlahti

common/flogging/core.go

@@ -38,24 +38,14 @@ type EncodingSelector interface {
 // from the zapcore.ObjectEncoder would need to be implemented to delegate to
 // the correct backend.
 //
-// Finally, fabric logging can go through initialization multiple times. The
-// first is via package initialization where hard-coded defaults are used for
-// configuration. The second init is typically after any process configuration
-// has been processed. This configuration can come from environment variables,
-// command line flags, or config documents.
-//
-// Since logging can be initialized multiple times, we need to be able to
-// handle modification of the type of encoders we are using. While, for legacy
-// reasons, a console based encoder is the default, a JSON logger is more likely
-// to be desired in production.
-//
 // This implementation works by associating multiple encoders with a core. When
 // fields are added to the core, the fields are added to all of the encoder
 // implementations. The core also references the logging configuration to
 // determine the proper encoding to use, the writer to delegate to, and the
 // enabled levels.
 type Core struct {
 	zapcore.LevelEnabler
+	Levels   *ModuleLevels
 	Encoders map[Encoding]zapcore.Encoder
 	Selector EncodingSelector
 	Output   zapcore.WriteSyncer
@@ -71,14 +61,15 @@ func (c *Core) With(fields []zapcore.Field) zapcore.Core {
 
 	return &Core{
 		LevelEnabler: c.LevelEnabler,
+		Levels:       c.Levels,
 		Encoders:     clones,
 		Selector:     c.Selector,
 		Output:       c.Output,
 	}
 }
 
 func (c *Core) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
-	if c.Enabled(e.Level) {
+	if c.Enabled(e.Level) && c.Levels.Level(e.LoggerName).Enabled(e.Level) {
 		return ce.AddCore(e, c)
 	}
 	return ce

common/flogging/core_test.go

@@ -46,22 +46,26 @@ func TestCoreWith(t *testing.T) {
 
 func TestCoreCheck(t *testing.T) {
 	var enabledArgs []zapcore.Level
+	levels := &flogging.ModuleLevels{}
+	err := levels.ActivateSpec("warning")
+	assert.NoError(t, err)
 	core := &flogging.Core{
 		LevelEnabler: zap.LevelEnablerFunc(func(l zapcore.Level) bool {
 			enabledArgs = append(enabledArgs, l)
-			return l != zapcore.WarnLevel
+			return l >= zapcore.WarnLevel
 		}),
+		Levels: levels,
 	}
 
-	// enabled
+	// not enabled
 	ce := core.Check(zapcore.Entry{Level: zapcore.DebugLevel}, nil)
-	assert.NotNil(t, ce)
+	assert.Nil(t, ce)
 	ce = core.Check(zapcore.Entry{Level: zapcore.InfoLevel}, nil)
-	assert.NotNil(t, ce)
+	assert.Nil(t, ce)
 
-	// not enabled
+	// enabled
 	ce = core.Check(zapcore.Entry{Level: zapcore.WarnLevel}, nil)
-	assert.Nil(t, ce)
+	assert.NotNil(t, ce)
 
 	assert.Equal(t, enabledArgs, []zapcore.Level{zapcore.DebugLevel, zapcore.InfoLevel, zapcore.WarnLevel})
 }

common/flogging/logging.go

@@ -189,8 +189,15 @@ func (s *Logging) Encoding() Encoding {
 func (s *Logging) ZapLogger(module string) *zap.Logger {
 	s.mutex.RLock()
 	module = strings.Replace(module, "/", ".", -1)
+	levelEnabler := zap.LevelEnablerFunc(func(l zapcore.Level) bool {
+		// always return true here because the core's Check()
+		// method computes the level for the logger name based
+		// on the active logging spec
+		return true
+	})
 	core := &Core{
-		LevelEnabler: s.ModuleLevels.LevelEnabler(module),
+		LevelEnabler: levelEnabler,
+		Levels:       s.ModuleLevels,
 		Encoders: map[Encoding]zapcore.Encoder{
 			JSON:    zapcore.NewJSONEncoder(s.encoderConfig),
 			CONSOLE: fabenc.NewFormatEncoder(s.multiFormatter),

common/flogging/logging_test.go

@@ -7,6 +7,7 @@ SPDX-License-Identifier: Apache-2.0
 package flogging_test
 
 import (
+	"bytes"
 	"errors"
 	"testing"
 
@@ -63,3 +64,31 @@ func TestZapLoggerNameConversion(t *testing.T) {
 	logger := logging.Logger("test/module/name")
 	assert.True(t, logger.IsEnabledFor(zapcore.DebugLevel))
 }
+
+func TestNamedLogger(t *testing.T) {
+	defer flogging.Reset()
+	buf := &bytes.Buffer{}
+	flogging.Global.SetWriter(buf)
+
+	t.Run("logger and named (child) logger with different levels", func(t *testing.T) {
+		defer buf.Reset()
+		logger := flogging.MustGetLogger("eugene")
+		logger2 := logger.Named("george")
+		flogging.ActivateSpec("eugene=info:eugene.george=error")
+
+		logger.Info("from eugene")
+		logger2.Info("from george")
+		assert.Contains(t, buf.String(), "from eugene")
+		assert.NotContains(t, buf.String(), "from george")
+	})
+
+	t.Run("named logger where parent logger isn't enabled", func(t *testing.T) {
+		logger := flogging.MustGetLogger("foo")
+		logger2 := logger.Named("bar")
+		flogging.ActivateSpec("foo=fatal:foo.bar=error")
+		logger.Error("from foo")
+		logger2.Error("from bar")
+		assert.NotContains(t, buf.String(), "from foo")
+		assert.Contains(t, buf.String(), "from bar")
+	})
+}

common/flogging/modulelevels.go

@@ -13,7 +13,6 @@ import (
 	"sync"
 
 	"github.com/pkg/errors"
-	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 )
 
@@ -122,13 +121,6 @@ func (m *ModuleLevels) cachedLevel(loggerName string) (lvl zapcore.Level, ok boo
 	return level, ok
 }
 
-// LevelEnabler adapts ModuleLevels for use with zap as a zapcore.LevelEnabler.
-func (m *ModuleLevels) LevelEnabler(module string) zapcore.LevelEnabler {
-	return zap.LevelEnablerFunc(func(l zapcore.Level) bool {
-		return m.Level(module).Enabled(l)
-	})
-}
-
 // Spec returns a normalized version of the active logging spec.
 func (m *ModuleLevels) Spec() string {
 	m.mutex.RLock()

common/flogging/modulelevels_test.go

@@ -130,23 +130,6 @@ func TestModuleLevelsActivateSpecErrors(t *testing.T) {
 	}
 }
 
-func TestModuleLevelsEnabler(t *testing.T) {
-	ml := &flogging.ModuleLevels{}
-	err := ml.ActivateSpec("logger=error")
-	assert.NoError(t, err)
-
-	for _, name := range []string{"logger.one.two", "logger.one", "logger"} {
-		enabler := ml.LevelEnabler(name)
-		assert.False(t, enabler.Enabled(zapcore.DebugLevel))
-		assert.False(t, enabler.Enabled(zapcore.InfoLevel))
-		assert.False(t, enabler.Enabled(zapcore.WarnLevel))
-		assert.True(t, enabler.Enabled(zapcore.ErrorLevel))
-		assert.True(t, enabler.Enabled(zapcore.DPanicLevel))
-		assert.True(t, enabler.Enabled(zapcore.PanicLevel))
-		assert.True(t, enabler.Enabled(zapcore.FatalLevel))
-	}
-}
-
 func TestModuleLevelSpec(t *testing.T) {
 	var tests = []struct {
 		input  string