[FAB-15432] improve level enabled checks

Change-Id: Ia5fb43fa69aa2085cb74008a55ce92c7f561054b
Signed-off-by: Dereck Luo <Chongxin.Luo@ibm.com>
Signed-off-by: Matthew Sykes <sykesmat@us.ibm.com>

Author: DereckLuo

common/flogging/loggerlevels.go

@@ -19,11 +19,11 @@ import (
 
 // LoggerLevels tracks the logging level of named loggers.
 type LoggerLevels struct {
+	mutex        sync.RWMutex
+	levelCache   map[string]zapcore.Level
+	specs        map[string]zapcore.Level
 	defaultLevel zapcore.Level
-
-	mutex      sync.RWMutex
-	levelCache map[string]zapcore.Level
-	specs      map[string]zapcore.Level
+	minLevel     zapcore.Level
 }
 
 // DefaultLevel returns the default logging level for loggers that do not have
@@ -80,6 +80,14 @@ func (l *LoggerLevels) ActivateSpec(spec string) error {
 		}
 	}
 
+	minLevel := defaultLevel
+	for _, lvl := range specs {
+		if lvl < minLevel {
+			minLevel = lvl
+		}
+	}
+
+	l.minLevel = minLevel
 	l.defaultLevel = defaultLevel
 	l.specs = specs
 	l.levelCache = map[string]zapcore.Level{}
@@ -155,3 +163,12 @@ func (l *LoggerLevels) Spec() string {
 
 	return strings.Join(fields, ":")
 }
+
+// Enabled function is an enabled check that evaluates the minimum active logging level.
+// It serves as a fast check before the (relatively) expensive Check call in the core.
+func (l *LoggerLevels) Enabled(lvl zapcore.Level) bool {
+	l.mutex.RLock()
+	enabled := l.minLevel.Enabled(lvl)
+	l.mutex.RUnlock()
+	return enabled
+}

common/flogging/loggerlevels_test.go

@@ -8,6 +8,7 @@ package flogging_test
 
 import (
 	"errors"
+	"strconv"
 	"testing"
 
 	"github.com/hyperledger/fabric/common/flogging"
@@ -155,3 +156,37 @@ func TestSpec(t *testing.T) {
 		assert.Equal(t, tc.output, ll.Spec())
 	}
 }
+
+func TestEnabled(t *testing.T) {
+	var tests = []struct {
+		spec      string
+		enabledAt zapcore.Level
+	}{
+		{spec: "payload", enabledAt: flogging.PayloadLevel},
+		{spec: "debug", enabledAt: zapcore.DebugLevel},
+		{spec: "info", enabledAt: zapcore.InfoLevel},
+		{spec: "warn", enabledAt: zapcore.WarnLevel},
+		{spec: "panic", enabledAt: zapcore.PanicLevel},
+		{spec: "fatal", enabledAt: zapcore.FatalLevel},
+		{spec: "fatal:a=debug", enabledAt: zapcore.DebugLevel},
+		{spec: "a=fatal:b=warn", enabledAt: zapcore.InfoLevel},
+		{spec: "a=warn", enabledAt: zapcore.InfoLevel},
+		{spec: "a=debug", enabledAt: zapcore.DebugLevel},
+	}
+
+	for i, tc := range tests {
+		t.Run(strconv.Itoa(i), func(t *testing.T) {
+			ll := &flogging.LoggerLevels{}
+			err := ll.ActivateSpec(tc.spec)
+			assert.NoError(t, err)
+
+			for i := flogging.PayloadLevel; i <= zapcore.FatalLevel; i++ {
+				if tc.enabledAt <= i {
+					assert.Truef(t, ll.Enabled(i), "expected level %s and spec %s to be enabled", zapcore.Level(i), tc.spec)
+				} else {
+					assert.False(t, ll.Enabled(i), "expected level %s and spec %s to be disabled", zapcore.Level(i), tc.spec)
+				}
+			}
+		})
+	}
+}

common/flogging/logging.go

@@ -209,14 +209,9 @@ func (s *Logging) ZapLogger(name string) *zap.Logger {
 		panic(fmt.Sprintf("invalid logger name: %s", name))
 	}
 
-	// always return true here because the core's Check()
-	// method computes the level for the logger name based
-	// on the active logging spec
-	levelEnabler := zap.LevelEnablerFunc(func(l zapcore.Level) bool { return true })
-
 	s.mutex.RLock()
 	core := &Core{
-		LevelEnabler: levelEnabler,
+		LevelEnabler: s.LoggerLevels,
 		Levels:       s.LoggerLevels,
 		Encoders: map[Encoding]zapcore.Encoder{
 			JSON:    zapcore.NewJSONEncoder(s.encoderConfig),

common/flogging/logging_test.go

@@ -133,3 +133,18 @@ func TestCheck(t *testing.T) {
 	l.Check(zapcore.Entry{}, nil)
 	assert.Equal(t, 1, observer.CheckCallCount())
 }
+
+func TestLoggerCoreCheck(t *testing.T) {
+	logging, err := flogging.New(flogging.Config{})
+	assert.NoError(t, err)
+
+	logger := logging.ZapLogger("foo")
+
+	err = logging.ActivateSpec("info")
+	assert.NoError(t, err)
+	assert.False(t, logger.Core().Enabled(zapcore.DebugLevel), "debug should not be enabled at info level")
+
+	err = logging.ActivateSpec("debug")
+	assert.NoError(t, err)
+	assert.True(t, logger.Core().Enabled(zapcore.DebugLevel), "debug should now be enabled at debug level")
+}

common/flogging/zap_test.go

@@ -14,6 +14,7 @@ import (
 
 	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/hyperledger/fabric/common/flogging/fabenc"
+	"github.com/hyperledger/fabric/common/flogging/mock"
 	"github.com/stretchr/testify/assert"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
@@ -308,3 +309,30 @@ func TestGRPCLogger(t *testing.T) {
 	callWrapper(gl, "message")
 	assert.Equal(t, "grpc DEBUG TestGRPCLogger message\n", buf.String())
 }
+
+// FAB-15432
+//
+// When the FabricLogger is used, the zap Core check function should not be
+// driven if the minimum log level is above the level we are logging at.
+// In other words, with a log spec of "info", logging at Debug should prevent
+// a call to Check while logging at Info will not.
+func TestEnabledLevelCheck(t *testing.T) {
+	buf := &bytes.Buffer{}
+	logging, err := flogging.New(flogging.Config{
+		LogSpec: "info",
+		Writer:  buf,
+	})
+	assert.NoError(t, err)
+
+	fakeObserver := &mock.Observer{}
+	logging.SetObserver(fakeObserver)
+
+	logger := logging.ZapLogger("foo")
+	fabricLogger := flogging.NewFabricLogger(logger)
+
+	fabricLogger.Debug("debug message")
+	assert.Equal(t, 0, fakeObserver.CheckCallCount(), "Check should not have been called")
+
+	fabricLogger.Info("info message")
+	assert.Equal(t, 1, fakeObserver.CheckCallCount(), "Check should have been called")
+}