Commit f23ebd55 authored by Saad Karim's avatar Saad Karim Committed by Gari Singh
Browse files

Update level evaluation to use log spec



Loggers shouldn't need to "register" in order to determine
their level. Updated the Level() logic to evaluate a logger's
module name against the current log spec.

FAB-12528 #done

Change-Id: I54bf378cd021ad1e4310b16cf1e313c9e4a39bb0
Signed-off-by: default avatarSaad Karim <skarim@us.ibm.com>
Signed-off-by: default avatarWill Lahti <wtlahti@us.ibm.com>
Signed-off-by: default avatarMatthew Sykes <sykesmat@us.ibm.com>
parent a5ff8e98
......@@ -7,7 +7,6 @@ SPDX-License-Identifier: Apache-2.0
package flogging
import (
"regexp"
"strings"
"go.uber.org/zap/zapcore"
......@@ -46,7 +45,6 @@ func Init(config Config) {
//
// Used in tests and in the package init
func Reset() {
Global.ResetLevels()
Global.Apply(Config{})
}
......@@ -55,40 +53,16 @@ func GetModuleLevel(module string) string {
return strings.ToUpper(Global.Level(module).String())
}
// SetModuleLevels sets the logging level for the modules that match the
// supplied regular expression. Can be used to dynamically change the log level
// for the module.
func SetModuleLevels(moduleRegexp, level string) error {
re, err := regexp.Compile(moduleRegexp)
if err != nil {
return err
}
Global.SetLevels(re, NameToLevel(level))
return nil
}
// SetModuleLevel sets the logging level for a single module.
func SetModuleLevel(module string, level string) error {
Global.SetLevel(module, NameToLevel(level))
return nil
}
// MustGetLogger is used in place of `logging.MustGetLogger` to allow us to
// store a map of all modules and submodules that have loggers in the logging.
func MustGetLogger(module string) *FabricLogger {
return Global.Logger(module)
}
// GetModuleLevels takes a snapshot of the global module level information and
// returns it as a map. The map can then be used to restore logging levels to
// values in the snapshot.
func GetModuleLevels() map[string]zapcore.Level {
return Global.Levels()
}
// RestoreLevels sets the global module level information to the contents of the
// provided map.
func RestoreLevels(levels map[string]zapcore.Level) {
Global.RestoreLevels(levels)
// ActivateSpec is used to acivate a logging specification.
func ActivateSpec(spec string) {
err := Global.ActivateSpec(spec)
if err != nil {
panic(err)
}
}
......@@ -16,8 +16,9 @@ import (
func TestGlobalReset(t *testing.T) {
flogging.Reset()
flogging.SetModuleLevel("module", "DEBUG")
flogging.Global.SetFormat("json")
err := flogging.Global.ActivateSpec("module=debug")
assert.NoError(t, err)
system, err := flogging.New(flogging.Config{})
assert.NoError(t, err)
......@@ -74,58 +75,15 @@ func TestGlobalInitPanic(t *testing.T) {
})
}
func TestGlobalGetAndRestoreLevels(t *testing.T) {
flogging.Reset()
flogging.SetModuleLevel("test-1", "DEBUG")
flogging.SetModuleLevel("test-2", "ERROR")
flogging.SetModuleLevel("test-3", "WARN")
levels := flogging.GetModuleLevels()
assert.Equal(t, "DEBUG", flogging.GetModuleLevel("test-1"))
assert.Equal(t, "ERROR", flogging.GetModuleLevel("test-2"))
assert.Equal(t, "WARN", flogging.GetModuleLevel("test-3"))
flogging.Reset()
assert.Equal(t, "INFO", flogging.GetModuleLevel("test-1"))
assert.Equal(t, "INFO", flogging.GetModuleLevel("test-2"))
assert.Equal(t, "INFO", flogging.GetModuleLevel("test-3"))
flogging.RestoreLevels(levels)
assert.Equal(t, "DEBUG", flogging.GetModuleLevel("test-1"))
assert.Equal(t, "ERROR", flogging.GetModuleLevel("test-2"))
assert.Equal(t, "WARN", flogging.GetModuleLevel("test-3"))
}
func TestGlobalDefaultLevel(t *testing.T) {
flogging.Reset()
assert.Equal(t, "INFO", flogging.DefaultLevel())
}
func TestGlobalSetModuleLevels(t *testing.T) {
flogging.Reset()
flogging.SetModuleLevel("a-module", "DEBUG")
flogging.SetModuleLevel("another-module", "DEBUG")
assert.Equal(t, "DEBUG", flogging.GetModuleLevel("a-module"))
assert.Equal(t, "DEBUG", flogging.GetModuleLevel("another-module"))
flogging.SetModuleLevels("^a-", "INFO")
assert.Equal(t, "INFO", flogging.GetModuleLevel("a-module"))
assert.Equal(t, "DEBUG", flogging.GetModuleLevel("another-module"))
flogging.SetModuleLevels("module", "WARN")
assert.Equal(t, "WARN", flogging.GetModuleLevel("a-module"))
assert.Equal(t, "WARN", flogging.GetModuleLevel("another-module"))
}
func TestGlobalSetModuleLevelsBadRegex(t *testing.T) {
func TestGlobalGetModuleLevel(t *testing.T) {
flogging.Reset()
err := flogging.SetModuleLevels("((", "DEBUG")
assert.Error(t, err)
assert.Contains(t, err.Error(), "error parsing regexp: ")
assert.Equal(t, "INFO", flogging.GetModuleLevel("some.logger"))
}
func TestGlobalMustGetLogger(t *testing.T) {
......@@ -145,69 +103,17 @@ func TestFlogginInitPanic(t *testing.T) {
})
}
func TestGlobalInitFromSpec(t *testing.T) {
func TestActivateSpec(t *testing.T) {
defer flogging.Reset()
tests := []struct {
name string
spec string
expectedResult string
expectedLevels map[string]string
}{
{
name: "SingleModuleLevel",
spec: "a=info",
expectedResult: "INFO",
expectedLevels: map[string]string{"a": "INFO"},
},
{
name: "MultipleModulesMultipleLevels",
spec: "a=info:b=debug",
expectedResult: "INFO",
expectedLevels: map[string]string{"a": "INFO", "b": "DEBUG"},
},
{
name: "MultipleModulesSameLevel",
spec: "a,b=warning",
expectedResult: "INFO",
expectedLevels: map[string]string{"a": "WARN", "b": "WARN"},
},
{
name: "DefaultAndModules",
spec: "ERROR:a=warning",
expectedResult: "ERROR",
expectedLevels: map[string]string{"a": "WARN"},
},
{
name: "ModuleAndDefault",
spec: "a=debug:info",
expectedResult: "INFO",
expectedLevels: map[string]string{"a": "DEBUG"},
},
{
name: "EmptyModuleEqualsLevel",
spec: "=info",
expectedResult: "INFO",
expectedLevels: map[string]string{},
},
{
name: "InvalidSyntax",
spec: "a=b=c",
expectedResult: "INFO",
expectedLevels: map[string]string{},
},
}
for _, tc := range tests {
t.Run(tc.name, func(t *testing.T) {
flogging.Reset()
l := flogging.InitFromSpec(tc.spec)
assert.Equal(t, tc.expectedResult, l)
for k, v := range tc.expectedLevels {
assert.Equal(t, v, flogging.GetModuleLevel(k))
}
})
}
flogging.ActivateSpec("fatal")
assert.Equal(t, "fatal", flogging.Global.Spec())
}
func TestActivateSpecPanic(t *testing.T) {
defer flogging.Reset()
assert.Panics(t, func() {
flogging.ActivateSpec("busted")
})
}
/*
Copyright IBM Corp. All Rights Reserved.
SPDX-License-Identifier: Apache-2.0
*/
package flogging_test
import (
"testing"
"github.com/hyperledger/fabric/common/flogging"
"github.com/stretchr/testify/assert"
)
func TestLegacyInitFromSpec(t *testing.T) {
defer flogging.Reset()
tests := []struct {
name string
spec string
expectedResult string
expectedLevels map[string]string
}{
{
name: "SingleModuleLevel",
spec: "a=info",
expectedResult: "INFO",
expectedLevels: map[string]string{"a": "INFO"},
},
{
name: "MultipleModulesMultipleLevels",
spec: "a=info:b=debug",
expectedResult: "INFO",
expectedLevels: map[string]string{"a": "INFO", "b": "DEBUG"},
},
{
name: "MultipleModulesSameLevel",
spec: "a,b=warning",
expectedResult: "INFO",
expectedLevels: map[string]string{"a": "WARN", "b": "WARN"},
},
{
name: "DefaultAndModules",
spec: "ERROR:a=warning",
expectedResult: "ERROR",
expectedLevels: map[string]string{"a": "WARN"},
},
{
name: "ModuleAndDefault",
spec: "a=debug:info",
expectedResult: "INFO",
expectedLevels: map[string]string{"a": "DEBUG"},
},
{
name: "EmptyModuleEqualsLevel",
spec: "=info",
expectedResult: "INFO",
expectedLevels: map[string]string{},
},
{
name: "InvalidSyntax",
spec: "a=b=c",
expectedResult: "INFO",
expectedLevels: map[string]string{},
},
}
for _, tc := range tests {
t.Run(tc.name, func(t *testing.T) {
flogging.Reset()
l := flogging.InitFromSpec(tc.spec)
assert.Equal(t, tc.expectedResult, l)
for k, v := range tc.expectedLevels {
assert.Equal(t, v, flogging.GetModuleLevel(k))
}
})
}
}
......@@ -189,8 +189,6 @@ func (s *Logging) Encoding() Encoding {
func (s *Logging) ZapLogger(module string) *zap.Logger {
s.mutex.RLock()
module = strings.Replace(module, "/", ".", -1)
level := s.ModuleLevels.Level(module)
s.ModuleLevels.SetLevel(module, level)
core := &Core{
LevelEnabler: s.ModuleLevels.LevelEnabler(module),
Encoders: map[Encoding]zapcore.Encoder{
......
......@@ -7,9 +7,7 @@ SPDX-License-Identifier: Apache-2.0
package flogging_test
import (
"bytes"
"errors"
"regexp"
"testing"
"github.com/hyperledger/fabric/common/flogging"
......@@ -22,7 +20,6 @@ func TestNew(t *testing.T) {
logging, err := flogging.New(flogging.Config{})
assert.NoError(t, err)
assert.Equal(t, zapcore.InfoLevel, logging.DefaultLevel())
assert.Empty(t, logging.Levels())
_, err = flogging.New(flogging.Config{
LogSpec: "::=borken=::",
......@@ -30,70 +27,6 @@ func TestNew(t *testing.T) {
assert.EqualError(t, err, "invalid logging specification '::=borken=::': bad segment '=borken='")
}
func TestLoggingReset(t *testing.T) {
logging, err := flogging.New(flogging.Config{})
assert.NoError(t, err)
var tests = []struct {
desc string
flogging.Config
err error
expectedRegexp string
}{
{
desc: "implicit log spec",
Config: flogging.Config{Format: "%{message}"},
expectedRegexp: regexp.QuoteMeta("this is a warning message\n"),
},
{
desc: "simple debug config",
Config: flogging.Config{LogSpec: "debug", Format: "%{message}"},
expectedRegexp: regexp.QuoteMeta("this is a debug message\nthis is a warning message\n"),
},
{
desc: "module error config",
Config: flogging.Config{LogSpec: "test-module=error:info", Format: "%{message}"},
expectedRegexp: "^$",
},
{
desc: "json",
Config: flogging.Config{LogSpec: "info", Format: "json"},
expectedRegexp: `{"level":"warn","ts":\d+\.\d+,"name":"test-module","caller":"flogging/logging_test.go:\d+","msg":"this is a warning message"}`,
},
{
desc: "bad log spec",
Config: flogging.Config{LogSpec: "::=borken=::", Format: "%{message}"},
err: errors.New("invalid logging specification '::=borken=::': bad segment '=borken='"),
},
{
desc: "bad format",
Config: flogging.Config{LogSpec: "info", Format: "%{color:bad}"},
err: errors.New("invalid color option: bad"),
},
}
for _, tc := range tests {
t.Run(tc.desc, func(t *testing.T) {
buf := &bytes.Buffer{}
tc.Config.Writer = buf
logging.ResetLevels()
err := logging.Apply(tc.Config)
if tc.err != nil {
assert.EqualError(t, err, tc.err.Error())
return
}
assert.NoError(t, err)
logger := logging.Logger("test-module")
logger.Debug("this is a debug message")
logger.Warn("this is a warning message")
assert.Regexp(t, tc.expectedRegexp, buf.String())
})
}
}
//go:generate counterfeiter -o mock/write_syncer.go -fake-name WriteSyncer . writeSyncer
type writeSyncer interface {
zapcore.WriteSyncer
......@@ -119,14 +52,14 @@ func TestLoggingSetWriter(t *testing.T) {
}
func TestZapLoggerNameConversion(t *testing.T) {
logging, err := flogging.New(flogging.Config{})
logging, err := flogging.New(flogging.Config{
LogSpec: "fatal:test=debug",
})
assert.NoError(t, err)
logging.Logger("test/module/name")
assert.Equal(t, zapcore.FatalLevel, logging.Level("test/module/name"))
assert.Equal(t, zapcore.DebugLevel, logging.Level("test.module.name"))
levels := logging.Levels()
_, ok := levels["test.module.name"]
assert.True(t, ok)
_, ok = levels["test/module/name"]
assert.False(t, ok)
logger := logging.Logger("test/module/name")
assert.True(t, logger.IsEnabledFor(zapcore.DebugLevel))
}
......@@ -7,7 +7,8 @@ SPDX-License-Identifier: Apache-2.0
package flogging
import (
"regexp"
"fmt"
"sort"
"strings"
"sync"
......@@ -20,16 +21,9 @@ import (
type ModuleLevels struct {
defaultLevel zapcore.Level
mutex sync.RWMutex
levels map[string]zapcore.Level
}
// SetDefaultLevel sets the default logging level for modules that do not have
// an explicit level set.
func (m *ModuleLevels) SetDefaultLevel(l zapcore.Level) {
m.mutex.Lock()
m.defaultLevel = l
m.mutex.Unlock()
mutex sync.RWMutex
levelCache map[string]zapcore.Level
specs map[string]zapcore.Level
}
// DefaultLevel returns the default logging level for modules that do not have
......@@ -41,39 +35,37 @@ func (m *ModuleLevels) DefaultLevel() zapcore.Level {
return l
}
// ResetLevels discards level information about all modules and restores the default
// logging level to zapcore.InfoLevel.
func (m *ModuleLevels) ResetLevels() {
m.mutex.Lock()
m.levels = nil
m.defaultLevel = zapcore.InfoLevel
m.mutex.Unlock()
}
// ActivateSpec is used to modify module logging levels.
// ActivateSpec is used to modify logging levels.
//
// The logging specification has the following form:
// [<module>[,<module>...]=]<level>[:[<module>[,<module>...]=]<level>...]
// [<logger>[,<logger>...]=]<level>[:[<logger>[,<logger>...]=]<level>...]
func (m *ModuleLevels) ActivateSpec(spec string) error {
var levelAll *zapcore.Level
updates := map[string]zapcore.Level{}
m.mutex.Lock()
defer m.mutex.Unlock()
fields := strings.Split(spec, ":")
for _, field := range fields {
defaultLevel := zapcore.InfoLevel
specs := map[string]zapcore.Level{}
for _, field := range strings.Split(spec, ":") {
split := strings.Split(field, "=")
switch len(split) {
case 1: // level
l := NameToLevel(field)
levelAll = &l
case 2: // <module>[,<module>...]=<level>
level := NameToLevel(split[1])
if field != "" && !IsValidLevel(field) {
return errors.Errorf("invalid logging specification '%s': bad segment '%s'", spec, field)
}
defaultLevel = NameToLevel(field)
case 2: // <logger>[,<logger>...]=<level>
if split[0] == "" {
return errors.Errorf("invalid logging specification '%s': no module specified in segment '%s'", spec, field)
return errors.Errorf("invalid logging specification '%s': no logger specified in segment '%s'", spec, field)
}
if field != "" && !IsValidLevel(split[1]) {
return errors.Errorf("invalid logging specification '%s': bad segment '%s'", spec, field)
}
modules := strings.Split(split[0], ",")
for _, module := range modules {
updates[module] = level
level := NameToLevel(split[1])
loggers := strings.Split(split[0], ",")
for _, loggers := range loggers {
specs[loggers] = level
}
default:
......@@ -81,86 +73,74 @@ func (m *ModuleLevels) ActivateSpec(spec string) error {
}
}
// Update existing modules iff an unqualified level is set.
if levelAll != nil {
l := *levelAll
m.SetDefaultLevel(l)
for module := range m.Levels() {
m.SetLevel(module, l)
}
}
for module, level := range updates {
m.SetLevel(module, level)
}
m.defaultLevel = defaultLevel
m.specs = specs
m.levelCache = map[string]zapcore.Level{}
return nil
}
// SetLevel sets the logging level for a single logging module.
func (m *ModuleLevels) SetLevel(module string, l zapcore.Level) {
m.mutex.Lock()
if m.levels == nil {
m.levels = map[string]zapcore.Level{}
// Level returns the effective logging level for a logger. If a level has not
// been explicitly set for the logger, the default logging level will be
// returned.
func (m *ModuleLevels) Level(loggerName string) zapcore.Level {
if level, ok := m.cachedLevel(loggerName); ok {
return level
}
m.levels[module] = l
m.mutex.Lock()
level := m.calculateLevel(loggerName)
m.levelCache[loggerName] = level
m.mutex.Unlock()
return level
}
// SetLevels sets the logging level for all logging modules that match the
// provided regular expression.
func (m *ModuleLevels) SetLevels(re *regexp.Regexp, l zapcore.Level) {
m.mutex.Lock()
defer m.mutex.Unlock()
// calculateLevel walks the logger name back to find the appropriate
// log level from the current spec.
func (m *ModuleLevels) calculateLevel(loggerName string) zapcore.Level {
candidate := loggerName + "."
for {
if lvl, ok := m.specs[candidate]; ok {
return lvl
}
for module := range m.levels {
if re.MatchString(module) {
m.levels[module] = l
idx := strings.LastIndex(candidate, ".")
if idx <= 0 {
return m.defaultLevel
}
candidate = candidate[:idx]
}
}
// Level returns the effective logging level for a module. If a level has not
// been explicitly set for the module, the default logging level will be
// returned.
func (m *ModuleLevels) Level(module string) zapcore.Level {
// cachedLevel attempts to retrieve the effective log level for a logger from the
// cache. If the logger is not found, ok will be false.
func (m *ModuleLevels) cachedLevel(loggerName string) (lvl zapcore.Level, ok bool) {
m.mutex.RLock()
l, ok := m.levels[module]
if !ok {
l = m.defaultLevel
}
level, ok := m.levelCache[loggerName]
m.mutex.RUnlock()
return l
return level, ok
}
// Levels returns a copy of current log levels.
func (m *ModuleLevels) Levels() map[string]zapcore.Level {
m.mutex.RLock()
defer m.mutex.RUnlock()
levels := make(map[string]zapcore.Level, len(m.levels))
for k, v := range m.levels {
levels[k] = v
}
return levels