diff --git a/common/flogging/logging.go b/common/flogging/logging.go index e90c13d290d..9717ef9496f 100644 --- a/common/flogging/logging.go +++ b/common/flogging/logging.go @@ -1,5 +1,5 @@ /* -Copyright IBM Corp. 2016 All Rights Reserved. +Copyright IBM Corp. 2017 All Rights Reserved. Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. @@ -24,154 +24,96 @@ import ( "sync" "github.com/op/go-logging" - "github.com/spf13/viper" ) -// A logger to log logging logs! -var logger = logging.MustGetLogger("logging") - -var defaultFormat = "%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message}" -var defaultOutput = os.Stderr +const ( + pkgLogID = "flogging" + defaultFormat = "%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message}" + defaultLevel = logging.INFO +) -// The default logging level, in force until LoggingInit() is called or in -// case of configuration errors. -var fallbackDefaultLevel = logging.INFO +var ( + logger *logging.Logger -var lock = sync.Mutex{} + defaultOutput *os.File -// modules holds the map of all modules and the current log level -var modules map[string]string + modules map[string]string // Holds the map of all modules and their respective log level + lock sync.Mutex -// IsSetLevelByRegExpEnabled disables the code that will allow setting log -// levels using a regular expression instead of one module/submodule at a time. -// TODO - remove once peer code has switched over to using -// flogging.MustGetLogger in place of logging.MustGetLogger -var IsSetLevelByRegExpEnabled = false + // IsSetLevelByRegExpEnabled allows the setting of log levels using a regular + // expression, instead of one module at a time, when set to true. + // TODO Remove once all other packages have switched to + // `flogging.MustGetLogger` from `logging.MustGetLogger`. + IsSetLevelByRegExpEnabled bool +) func init() { - modules = make(map[string]string) -} - -// InitFromViper is a 'hook' called at the beginning of command processing to -// parse logging-related options specified either on the command-line or in -// config files. Command-line options take precedence over config file -// options, and can also be passed as suitably-named environment variables. To -// change module logging levels at runtime call `logging.SetLevel(level, -// module)`. To debug this routine include logging=debug as the first -// term of the logging specification. -// TODO this initialization is specific to the peer config format. The viper -// references should be removed, and this path should be moved into the peer -func InitFromViper(command string) { - spec := viper.GetString("logging_level") - if spec == "" { - spec = viper.GetString("logging." + command) - } - defaultLevel := InitFromSpec(spec) - logger.Debugf("Setting default logging level to %s for command '%s'", defaultLevel, command) -} - -// InitFromSpec initializes the logging based on the supplied spec, it is exposed externally -// so that consumers of the flogging package who do not wish to use the default config structure -// may parse their own logging specification -func InitFromSpec(spec string) logging.Level { - // Parse the logging specification in the form - // [[,...]=][:[[,...]=]...] - defaultLevel := fallbackDefaultLevel - var err error - if spec != "" { - fields := strings.Split(spec, ":") - for _, field := range fields { - split := strings.Split(field, "=") - switch len(split) { - case 1: - // Default level - defaultLevel, err = logging.LogLevel(field) - if err != nil { - logger.Warningf("Logging level '%s' not recognized, defaulting to %s : %s", field, defaultLevel, err) - defaultLevel = fallbackDefaultLevel // NB - 'defaultLevel' was overwritten - } - case 2: - // [,...]= - if level, err := logging.LogLevel(split[1]); err != nil { - logger.Warningf("Invalid logging level in '%s' ignored", field) - } else if split[0] == "" { - logger.Warningf("Invalid logging override specification '%s' ignored - no module specified", field) - } else { - modules := strings.Split(split[0], ",") - for _, module := range modules { - logging.SetLevel(level, module) - logger.Debugf("Setting logging level for module '%s' to %s", module, level) - } - } - default: - logger.Warningf("Invalid logging override '%s' ignored; Missing ':' ?", field) - } - } - } - // Set the default logging level for all modules - logging.SetLevel(defaultLevel, "") - return defaultLevel + logger = logging.MustGetLogger(pkgLogID) + Reset() } -// DefaultLevel returns the fallback value for loggers to use if parsing fails -func DefaultLevel() logging.Level { - return fallbackDefaultLevel -} +// Reset sets to logging to the defaults defined in this package. +func Reset() { + IsSetLevelByRegExpEnabled = false // redundant since the default for booleans is `false` but added for clarity + modules = make(map[string]string) + lock = sync.Mutex{} -// Initiate 'leveled' logging using the default format and output location -func init() { - SetLoggingFormat(defaultFormat, defaultOutput) + defaultOutput = os.Stderr + InitBackend(SetFormat(defaultFormat), defaultOutput) + InitFromSpec("") } -// SetLoggingFormat sets the logging format and the location of the log output -func SetLoggingFormat(formatString string, output io.Writer) { - if formatString == "" { - formatString = defaultFormat +// SetFormat sets the logging format. +func SetFormat(formatSpec string) logging.Formatter { + if formatSpec == "" { + formatSpec = defaultFormat } - format := logging.MustStringFormatter(formatString) - - initLoggingBackend(format, output) + return logging.MustStringFormatter(formatSpec) } -// initialize the logging backend based on the provided logging formatter -// and I/O writer -func initLoggingBackend(logFormatter logging.Formatter, output io.Writer) { +// InitBackend sets up the logging backend based on +// the provided logging formatter and I/O writer. +func InitBackend(formatter logging.Formatter, output io.Writer) { backend := logging.NewLogBackend(output, "", 0) - backendFormatter := logging.NewBackendFormatter(backend, logFormatter) - logging.SetBackend(backendFormatter).SetLevel(fallbackDefaultLevel, "") + backendFormatter := logging.NewBackendFormatter(backend, formatter) + logging.SetBackend(backendFormatter).SetLevel(defaultLevel, "") } -// GetModuleLevel gets the current logging level for the specified module -func GetModuleLevel(module string) (string, error) { +// DefaultLevel returns the fallback value for loggers to use if parsing fails. +func DefaultLevel() string { + return defaultLevel.String() +} + +// GetModuleLevel gets the current logging level for the specified module. +func GetModuleLevel(module string) string { // logging.GetLevel() returns the logging level for the module, if defined. - // otherwise, it returns the default logging level, as set by - // flogging/logging.go + // Otherwise, it returns the default logging level, as set by + // `flogging/logging.go`. level := logging.GetLevel(module).String() - - logger.Debugf("Module '%s' logger enabled for log level: %s", module, level) - - return level, nil + logger.Debugf("Module '%s' logger set to '%s' log level", module, level) + return level } -// SetModuleLevel sets the logging level for the modules that match the -// supplied regular expression. This is can be called from anywhere in the -// code on a running peer to dynamically change log levels. -func SetModuleLevel(moduleRegExp string, logLevel string) (string, error) { - level, err := logging.LogLevel(logLevel) +// SetModuleLevel 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 SetModuleLevel(moduleRegExp string, level string) (string, error) { + var re *regexp.Regexp + logLevel, err := logging.LogLevel(level) if err != nil { - logger.Warningf("Invalid logging level: %s - ignored", logLevel) + logger.Warningf("Invalid logging level '%s' - ignored", level) } else { - // TODO - this check is in here temporarily until all modules have been - // converted to using flogging.MustGetLogger. until that point, this flag - // keeps the previous behavior in place. + // TODO This check is here to preserve the old functionality until all + // other packages switch to `flogging.MustGetLogger` (from + // `logging.MustGetLogger`). if !IsSetLevelByRegExpEnabled { - logging.SetLevel(logging.Level(level), moduleRegExp) - logger.Infof("Module '%s' logger enabled for log level: %s", moduleRegExp, level) + logging.SetLevel(logging.Level(logLevel), moduleRegExp) + logger.Debugf("Module '%s' logger enabled for log level '%s'", moduleRegExp, logLevel) } else { - re, err := regexp.Compile(moduleRegExp) + re, err = regexp.Compile(moduleRegExp) if err != nil { - logger.Warningf("Invalid regular expression for module: %s", moduleRegExp) + logger.Warningf("Invalid regular expression: %s", moduleRegExp) return "", err } @@ -179,31 +121,67 @@ func SetModuleLevel(moduleRegExp string, logLevel string) (string, error) { defer lock.Unlock() for module := range modules { if re.MatchString(module) { - logging.SetLevel(logging.Level(level), module) - modules[module] = logLevel - logger.Infof("Module '%s' logger enabled for log level: %s", module, level) + logging.SetLevel(logging.Level(logLevel), module) + modules[module] = logLevel.String() + logger.Infof("Module '%s' logger enabled for log level '%s'", module, logLevel) } } } } - - logLevelString := level.String() - - return logLevelString, err + return logLevel.String(), err } -// 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 system +// 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 system. func MustGetLogger(module string) *logging.Logger { - logger := logging.MustGetLogger(module) - - // retrieve the current log level for the logger - level := logging.GetLevel(module).String() - - // store the module's name as well as the current log level for the logger + l := logging.MustGetLogger(module) lock.Lock() defer lock.Unlock() - modules[module] = level + modules[module] = GetModuleLevel(module) + return l +} + +// InitFromSpec initializes the logging based on the supplied spec. It is +// exposed externally so that consumers of the flogging package may parse their +// own logging specification. The logging specification has the following form: +// [[,...]=][:[[,...]=]...] +func InitFromSpec(spec string) string { + levelAll := defaultLevel + var err error + + if spec != "" { + fields := strings.Split(spec, ":") + for _, field := range fields { + split := strings.Split(field, "=") + switch len(split) { + case 1: + if levelAll, err = logging.LogLevel(field); err != nil { + logger.Warningf("Logging level '%s' not recognized, defaulting to '%s': %s", field, defaultLevel, err) + levelAll = defaultLevel // need to reset cause original value was overwritten + } + case 2: + // [,...]= + levelSingle, err := logging.LogLevel(split[1]) + if err != nil { + logger.Warningf("Invalid logging level in '%s' ignored", field) + continue + } + + if split[0] == "" { + logger.Warningf("Invalid logging override specification '%s' ignored - no module specified", field) + } else { + modules := strings.Split(split[0], ",") + for _, module := range modules { + logger.Debugf("Setting logging level for module '%s' to '%s'", module, levelSingle) + logging.SetLevel(levelSingle, module) + } + } + default: + logger.Warningf("Invalid logging override '%s' ignored - missing ':'?", field) + } + } + } - return logger + logging.SetLevel(levelAll, "") // set the logging level for all modules + return levelAll.String() } diff --git a/common/flogging/logging_test.go b/common/flogging/logging_test.go index 5501942dad9..92e411c096b 100644 --- a/common/flogging/logging_test.go +++ b/common/flogging/logging_test.go @@ -22,345 +22,150 @@ import ( "github.com/hyperledger/fabric/common/flogging" "github.com/op/go-logging" - "github.com/spf13/viper" + "github.com/stretchr/testify/assert" ) -func TestLevelDefault(t *testing.T) { - viper.Reset() +const logLevelCount = 6 - flogging.InitFromViper("") - - assertDefaultLevel(t, flogging.DefaultLevel()) -} - -func TestLevelOtherThanDefault(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "warning") - - flogging.InitFromViper("") - - assertDefaultLevel(t, logging.WARNING) -} - -func TestLevelForSpecificModule(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "core=info") - - flogging.InitFromViper("") - - assertModuleLevel(t, "core", logging.INFO) -} - -func TestLeveltForMultipleModules(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "core=warning:test=debug") - - flogging.InitFromViper("") - - assertModuleLevel(t, "core", logging.WARNING) - assertModuleLevel(t, "test", logging.DEBUG) -} - -func TestLevelForMultipleModulesAtSameLevel(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "core,test=warning") - - flogging.InitFromViper("") - - assertModuleLevel(t, "core", logging.WARNING) - assertModuleLevel(t, "test", logging.WARNING) -} - -func TestLevelForModuleWithDefault(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "info:test=warning") - - flogging.InitFromViper("") - - assertDefaultLevel(t, logging.INFO) - assertModuleLevel(t, "test", logging.WARNING) -} - -func TestLevelForModuleWithDefaultAtEnd(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "test=warning:info") - - flogging.InitFromViper("") - - assertDefaultLevel(t, logging.INFO) - assertModuleLevel(t, "test", logging.WARNING) -} - -func TestLevelForSpecificCommand(t *testing.T) { - viper.Reset() - viper.Set("logging.node", "error") - - flogging.InitFromViper("node") - - assertDefaultLevel(t, logging.ERROR) -} - -func TestLevelForUnknownCommandGoesToDefault(t *testing.T) { - viper.Reset() - - flogging.InitFromViper("unknown command") - - assertDefaultLevel(t, flogging.DefaultLevel()) -} - -func TestLevelInvalid(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "invalidlevel") - - flogging.InitFromViper("") - - assertDefaultLevel(t, flogging.DefaultLevel()) -} - -func TestLevelInvalidModules(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "core=invalid") - - flogging.InitFromViper("") - - assertDefaultLevel(t, flogging.DefaultLevel()) -} - -func TestLevelInvalidEmptyModule(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "=warning") - - flogging.InitFromViper("") - - assertDefaultLevel(t, flogging.DefaultLevel()) -} - -func TestLevelInvalidModuleSyntax(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "type=warn=again") - - flogging.InitFromViper("") - - assertDefaultLevel(t, flogging.DefaultLevel()) +type testCase struct { + name string + args []string + expectedLevels []string + modules []string + withRegEx bool + shouldErr bool } func TestGetModuleLevelDefault(t *testing.T) { - level, _ := flogging.GetModuleLevel("peer") - - // peer should be using the default log level at this point - assertEquals(t, logging.INFO.String(), level) - -} - -func TestGetModuleLevelDebug(t *testing.T) { - flogging.SetModuleLevel("peer", "DEBUG") - level, _ := flogging.GetModuleLevel("peer") - - // ensure that the log level has changed to debug - assertEquals(t, logging.DEBUG.String(), level) -} - -func TestGetModuleLevelInvalid(t *testing.T) { - flogging.SetModuleLevel("peer", "invalid") - level, _ := flogging.GetModuleLevel("peer") - - // ensure that the log level didn't change after invalid log level specified - assertEquals(t, logging.DEBUG.String(), level) + assert.Equal(t, flogging.DefaultLevel(), flogging.GetModuleLevel("a")) } func TestSetModuleLevel(t *testing.T) { - flogging.SetModuleLevel("peer", "WARNING") - - // ensure that the log level has changed to warning - assertModuleLevel(t, "peer", logging.WARNING) -} - -func TestSetModuleLevelInvalid(t *testing.T) { - flogging.SetModuleLevel("peer", "invalid") + defer flogging.Reset() + + var tc []testCase + + tc = append(tc, + testCase{"Valid", []string{"a", "warning"}, []string{"WARNING"}, []string{"a"}, false, false}, + // Same as before + testCase{"Invalid", []string{"a", "foo"}, []string{"WARNING"}, []string{"a"}, false, false}, + // Tests with regular expressions + testCase{"RegexModuleWithSubmodule", []string{"foo", "warning"}, []string{"WARNING", "WARNING", flogging.DefaultLevel()}, + []string{"foo", "foo/bar", "baz"}, true, false}, + // Set the level for modules that contain "foo" or "baz" + testCase{"RegexOr", []string{"foo|baz", "debug"}, []string{"DEBUG", "DEBUG", "DEBUG", flogging.DefaultLevel()}, + []string{"foo", "foo/bar", "baz", "random"}, true, false}, + // Set the level for modules that end with "bar" + testCase{"RegexSuffix", []string{"bar$", "error"}, []string{"ERROR", flogging.DefaultLevel()}, + []string{"foo/bar", "bar/baz"}, true, false}, + testCase{"RegexComplex", []string{"^[a-z]+\\/[a-z]+#.+$", "warning"}, []string{flogging.DefaultLevel(), flogging.DefaultLevel(), "WARNING", "WARNING", "WARNING"}, + []string{"gossip/util", "orderer/util", "gossip/gossip#0.0.0.0:7051", "gossip/conn#-1", "orderer/conn#0.0.0.0:7051"}, true, false}, + testCase{"RegexInvalid", []string{"(", "warning"}, []string{flogging.DefaultLevel()}, + []string{"foo"}, true, true}, + ) + + assert := assert.New(t) + + for i := 0; i < len(tc); i++ { + t.Run(tc[i].name, func(t *testing.T) { + if tc[i].withRegEx { + for j := 0; j < len(tc[i].modules); j++ { + flogging.MustGetLogger(tc[i].modules[j]) + } + flogging.IsSetLevelByRegExpEnabled = true // enable for call below + } + + _, err := flogging.SetModuleLevel(tc[i].args[0], tc[i].args[1]) + if tc[i].shouldErr { + assert.NotNil(err, "Should have returned an error") + } + for k := 0; k < len(tc[i].expectedLevels); k++ { + assert.Equal(tc[i].expectedLevels[k], flogging.GetModuleLevel(tc[i].modules[k])) + } + + if tc[i].withRegEx { + // Force reset (a) in case the next test is non-regex, (b) so as + // to reset the modules map and reuse module names. + flogging.Reset() + + } + }) + } - // ensure that the log level didn't change after invalid log level specified - assertModuleLevel(t, "peer", logging.WARNING) } -func ExampleSetLoggingFormat() { - // initializes logging backend for testing and sets - // time to 1970-01-01 00:00:00.000 UTC - logging.InitForTesting(flogging.DefaultLevel()) +func TestInitFromSpec(t *testing.T) { + var tc []testCase - logFormat := "%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x} %{message}" - flogging.SetLoggingFormat(logFormat, os.Stdout) + // GLOBAL - logger := logging.MustGetLogger("floggingTest") - logger.Infof("test") + // all allowed log levels + for i := 0; i < logLevelCount; i++ { + level := logging.Level(i).String() + tc = append(tc, testCase{ + name: "Global" + level, + args: []string{level}, + expectedLevels: []string{level}, + modules: []string{""}, + }) + } + // NIL INPUT + tc = append(tc, testCase{ + name: "Global" + "NIL", + args: []string{""}, + expectedLevels: []string{flogging.DefaultLevel()}, + modules: []string{""}, + }) + + // MODULES + + tc = append(tc, + testCase{"SingleModuleLevel", []string{"a=info"}, []string{"INFO"}, []string{"a"}, false, false}, + testCase{"MultipleModulesMultipleLevels", []string{"a=info:b=debug"}, []string{"INFO", "DEBUG"}, []string{"a", "b"}, false, false}, + testCase{"MultipleModulesSameLevel", []string{"a,b=warning"}, []string{"WARNING", "WARNING"}, []string{"a", "b"}, false, false}, + ) + + // MODULES + DEFAULT + + tc = append(tc, + testCase{"GlobalDefaultAndSingleModuleLevel", []string{"info:a=warning"}, []string{"INFO", "WARNING"}, []string{"", "a"}, false, false}, + testCase{"SingleModuleLevelAndGlobalDefaultAtEnd", []string{"a=warning:info"}, []string{"WARNING", "INFO"}, []string{"a", ""}, false, false}, + ) + + // INVALID INPUT + + tc = append(tc, + testCase{"InvalidLevel", []string{"foo"}, []string{flogging.DefaultLevel()}, []string{""}, false, false}, + testCase{"InvalidLevelForSingleModule", []string{"a=foo"}, []string{flogging.DefaultLevel()}, []string{""}, false, false}, + testCase{"EmptyModuleEqualsLevel", []string{"=warning"}, []string{flogging.DefaultLevel()}, []string{""}, false, false}, + testCase{"InvalidModuleSyntax", []string{"a=b=c"}, []string{flogging.DefaultLevel()}, []string{""}, false, false}, + ) + + assert := assert.New(t) + + for i := 0; i < len(tc); i++ { + t.Run(tc[i].name, func(t *testing.T) { + defer flogging.Reset() + flogging.InitFromSpec(tc[i].args[0]) + for j := 0; j < len(tc[i].expectedLevels); j++ { + assert.Equal(tc[i].expectedLevels[j], flogging.GetModuleLevel(tc[i].modules[j])) + } + }) + } - // Output: - // 1970-01-01 00:00:00.000 UTC [floggingTest] ExampleSetLoggingFormat -> INFO 001 test } -func ExampleSetLoggingFormat_second() { - // initializes logging backend for testing and sets - // time to 1970-01-01 00:00:00.000 UTC - logging.InitForTesting(flogging.DefaultLevel()) +func ExampleInitBackend() { + level, _ := logging.LogLevel(flogging.DefaultLevel()) + // initializes logging backend for testing and sets time to 1970-01-01 00:00:00.000 UTC + logging.InitForTesting(level) - logFormat := "%{time:15:04:05.000} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x} %{message}" - flogging.SetLoggingFormat(logFormat, os.Stdout) + formatSpec := "%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x} %{message}" + flogging.InitBackend(flogging.SetFormat(formatSpec), os.Stdout) - logger := logging.MustGetLogger("floggingTest") - logger.Infof("test") + logger := logging.MustGetLogger("testModule") + logger.Info("test output") // Output: - // 00:00:00.000 [floggingTest] ExampleSetLoggingFormat_second -> INFO 001 test -} - -// TestSetModuleLevel_moduleWithSubmodule and the following tests use the new -// flogging.MustGetLogger to initialize their loggers. flogging.MustGetLogger -// adds a modules map to track which module names have been defined and their -// current log level -func TestSetModuleLevel_moduleWithSubmodule(t *testing.T) { - // enable setting the level by regular expressions - // TODO - remove this once all modules have been updated to use - // flogging.MustGetLogger - flogging.IsSetLevelByRegExpEnabled = true - - flogging.MustGetLogger("module") - flogging.MustGetLogger("module/subcomponent") - flogging.MustGetLogger("sub") - - // ensure that the log level is the default level, INFO - assertModuleLevel(t, "module", logging.INFO) - assertModuleLevel(t, "module/subcomponent", logging.INFO) - assertModuleLevel(t, "sub", logging.INFO) - - // set level for modules that contain 'module' - flogging.SetModuleLevel("module", "warning") - - // ensure that the log level has changed to WARNING for the modules - // that match the regular expression - assertModuleLevel(t, "module", logging.WARNING) - assertModuleLevel(t, "module/subcomponent", logging.WARNING) - assertModuleLevel(t, "sub", logging.INFO) - - flogging.IsSetLevelByRegExpEnabled = false -} - -func TestSetModuleLevel_regExpOr(t *testing.T) { - flogging.IsSetLevelByRegExpEnabled = true - - flogging.MustGetLogger("module2") - flogging.MustGetLogger("module2/subcomponent") - flogging.MustGetLogger("sub2") - flogging.MustGetLogger("randomLogger2") - - // ensure that the log level is the default level, INFO - assertModuleLevel(t, "module2", logging.INFO) - assertModuleLevel(t, "module2/subcomponent", logging.INFO) - assertModuleLevel(t, "sub2", logging.INFO) - assertModuleLevel(t, "randomLogger2", logging.INFO) - - // set level for modules that contain 'mod' OR 'sub' - flogging.SetModuleLevel("mod|sub", "DEBUG") - - // ensure that the log level has changed to DEBUG for the modules that match - // the regular expression - assertModuleLevel(t, "module2", logging.DEBUG) - assertModuleLevel(t, "module2/subcomponent", logging.DEBUG) - assertModuleLevel(t, "sub2", logging.DEBUG) - assertModuleLevel(t, "randomLogger2", logging.INFO) - - flogging.IsSetLevelByRegExpEnabled = false -} - -func TestSetModuleLevel_regExpSuffix(t *testing.T) { - flogging.IsSetLevelByRegExpEnabled = true - - flogging.MustGetLogger("module3") - flogging.MustGetLogger("module3/subcomponent") - flogging.MustGetLogger("sub3") - flogging.MustGetLogger("sub3/subcomponent") - flogging.MustGetLogger("randomLogger3") - - // ensure that the log level is the default level, INFO - assertModuleLevel(t, "module3", logging.INFO) - assertModuleLevel(t, "module3/subcomponent", logging.INFO) - assertModuleLevel(t, "sub3", logging.INFO) - assertModuleLevel(t, "sub3/subcomponent", logging.INFO) - assertModuleLevel(t, "randomLogger3", logging.INFO) - - // set level for modules that contain component - flogging.SetModuleLevel("component$", "ERROR") - - // ensure that the log level has changed to ERROR for the modules that match - // the regular expression - assertModuleLevel(t, "module3", logging.INFO) - assertModuleLevel(t, "module3/subcomponent", logging.ERROR) - assertModuleLevel(t, "sub3", logging.INFO) - assertModuleLevel(t, "sub3/subcomponent", logging.ERROR) - assertModuleLevel(t, "randomLogger3", logging.INFO) - - flogging.IsSetLevelByRegExpEnabled = false -} - -func TestSetModuleLevel_regExpComplex(t *testing.T) { - flogging.IsSetLevelByRegExpEnabled = true - - flogging.MustGetLogger("gossip/util") - flogging.MustGetLogger("orderer/util") - flogging.MustGetLogger("gossip/gossip#0.0.0.0:7051") - flogging.MustGetLogger("gossip/conn#-1") - flogging.MustGetLogger("orderer/conn#0.0.0.0:7051") - - // ensure that the log level is the default level, INFO - assertModuleLevel(t, "gossip/util", logging.INFO) - assertModuleLevel(t, "orderer/util", logging.INFO) - assertModuleLevel(t, "gossip/gossip#0.0.0.0:7051", logging.INFO) - assertModuleLevel(t, "gossip/conn#-1", logging.INFO) - assertModuleLevel(t, "orderer/conn#0.0.0.0:7051", logging.INFO) - - // set level for modules that match the regular rexpression - flogging.SetModuleLevel("^[a-z]+\\/[a-z]+#.+$", "WARNING") - - // ensure that the log level has changed to WARNING for the modules that match - // the regular expression - assertModuleLevel(t, "gossip/util", logging.INFO) - assertModuleLevel(t, "orderer/util", logging.INFO) - assertModuleLevel(t, "gossip/gossip#0.0.0.0:7051", logging.WARNING) - assertModuleLevel(t, "gossip/conn#-1", logging.WARNING) - assertModuleLevel(t, "orderer/conn#0.0.0.0:7051", logging.WARNING) - - flogging.IsSetLevelByRegExpEnabled = false -} - -func TestSetModuleLevel_invalidRegExp(t *testing.T) { - flogging.IsSetLevelByRegExpEnabled = true - - flogging.MustGetLogger("(module") - - // ensure that the log level is the default level, INFO - assertModuleLevel(t, "(module", logging.INFO) - - level, err := flogging.SetModuleLevel("(", "info") - - assertEquals(t, "", level) - if err == nil { - t.FailNow() - } - - // ensure that the log level hasn't changed - assertModuleLevel(t, "(module", logging.INFO) - - flogging.IsSetLevelByRegExpEnabled = false -} - -func assertDefaultLevel(t *testing.T, expectedLevel logging.Level) { - assertModuleLevel(t, "", expectedLevel) -} - -func assertModuleLevel(t *testing.T, module string, expectedLevel logging.Level) { - assertEquals(t, expectedLevel, logging.GetLevel(module)) -} - -func assertEquals(t *testing.T, expected interface{}, actual interface{}) { - if expected != actual { - t.Errorf("Expected: %v, Got: %v", expected, actual) - } + // 1970-01-01 00:00:00.000 UTC [testModule] ExampleInitBackend -> INFO 001 test output } diff --git a/core/admin.go b/core/admin.go index c29c5ac1504..f3b4661265e 100644 --- a/core/admin.go +++ b/core/admin.go @@ -81,17 +81,16 @@ func (*ServerAdmin) StopServer(context.Context, *empty.Empty) (*pb.ServerStatus, } // GetModuleLogLevel gets the current logging level for the specified module +// TODO Modify the signature so as to remove the error return - it's always been nil func (*ServerAdmin) GetModuleLogLevel(ctx context.Context, request *pb.LogLevelRequest) (*pb.LogLevelResponse, error) { - logLevelString, err := flogging.GetModuleLevel(request.LogModule) + logLevelString := flogging.GetModuleLevel(request.LogModule) logResponse := &pb.LogLevelResponse{LogModule: request.LogModule, LogLevel: logLevelString} - - return logResponse, err + return logResponse, nil } // SetModuleLogLevel sets the logging level for the specified module func (*ServerAdmin) SetModuleLogLevel(ctx context.Context, request *pb.LogLevelRequest) (*pb.LogLevelResponse, error) { logLevelString, err := flogging.SetModuleLevel(request.LogModule, request.LogLevel) logResponse := &pb.LogLevelResponse{LogModule: request.LogModule, LogLevel: logLevelString} - return logResponse, err } diff --git a/core/chaincode/chaincode_support.go b/core/chaincode/chaincode_support.go index d45669410b8..d7f13019fb7 100644 --- a/core/chaincode/chaincode_support.go +++ b/core/chaincode/chaincode_support.go @@ -190,8 +190,8 @@ func NewChaincodeSupport(getPeerEndpoint func() (*pb.PeerEndpoint, error), userr if err == nil { theChaincodeSupport.chaincodeLogLevel = chaincodeLogLevel.String() } else { - chaincodeLogger.Warningf("Chaincode logging level %s is invalid; defaulting to %s", chaincodeLogLevelString, flogging.DefaultLevel().String()) - theChaincodeSupport.chaincodeLogLevel = flogging.DefaultLevel().String() + chaincodeLogger.Warningf("Chaincode logging level %s is invalid; defaulting to %s", chaincodeLogLevelString, flogging.DefaultLevel()) + theChaincodeSupport.chaincodeLogLevel = flogging.DefaultLevel() } theChaincodeSupport.logFormat = viper.GetString("chaincode.logFormat") diff --git a/core/chaincode/shim/chaincode.go b/core/chaincode/shim/chaincode.go index e4c98487bc8..773cc822fc5 100644 --- a/core/chaincode/shim/chaincode.go +++ b/core/chaincode/shim/chaincode.go @@ -127,8 +127,9 @@ func SetupChaincodeLogging() { replacer := strings.NewReplacer(".", "_") viper.SetEnvKeyReplacer(replacer) - logFormat := viper.GetString("chaincode.logFormat") - flogging.SetLoggingFormat(logFormat, logOutput) + // setup system-wide logging backend + logFormat := flogging.SetFormat(viper.GetString("chaincode.logFormat")) + flogging.InitBackend(logFormat, logOutput) chaincodeLogLevelString := viper.GetString("chaincode.logLevel") if chaincodeLogLevelString == "" { diff --git a/core/errors/errors.go b/core/errors/errors.go index fcc6473b0f2..df7c5386f9e 100644 --- a/core/errors/errors.go +++ b/core/errors/errors.go @@ -116,7 +116,7 @@ func (h *hlError) Message() string { // initialize logging level for errors from core.yaml. it can also be set // for code running on the peer dynamically via CLI using // "peer logging setlevel error " - errorLogLevelString, _ := flogging.GetModuleLevel("error") + errorLogLevelString := flogging.GetModuleLevel("error") if errorLogLevelString == logging.DEBUG.String() { message = appendCallStack(message, h.GetStack()) diff --git a/peer/main.go b/peer/main.go index 9fb559a8ad6..f10c03cddc1 100644 --- a/peer/main.go +++ b/peer/main.go @@ -49,8 +49,7 @@ const cmdRoot = "core" var mainCmd = &cobra.Command{ Use: "peer", PersistentPreRunE: func(cmd *cobra.Command, args []string) error { - peerCommand := getPeerCommandFromCobraCommand(cmd) - flogging.InitFromViper(peerCommand) + flogging.InitFromSpec(viper.GetString("logging_level")) return core.CacheConfiguration() }, @@ -96,8 +95,8 @@ func main() { runtime.GOMAXPROCS(viper.GetInt("peer.gomaxprocs")) - // initialize logging format from core.yaml - flogging.SetLoggingFormat(viper.GetString("logging.format"), logOutput) + // setup system-wide logging backend based on settings from core.yaml + flogging.InitBackend(flogging.SetFormat(viper.GetString("logging.format")), logOutput) // Init the MSP var mspMgrConfigDir = viper.GetString("peer.mspConfigPath") @@ -113,35 +112,3 @@ func main() { } logger.Info("Exiting.....") } - -// getPeerCommandFromCobraCommand retreives the peer command from the cobra command struct. -// i.e. for a command of `peer node start`, this should return "node" -// For the main/root command this will return the root name (i.e. peer) -// For invalid commands (i.e. nil commands) this will return an empty string -func getPeerCommandFromCobraCommand(command *cobra.Command) string { - var commandName string - - if command == nil { - return commandName - } - - if peerCommand, ok := findChildOfRootCommand(command); ok { - commandName = peerCommand.Name() - } else { - commandName = command.Name() - } - - return commandName -} - -func findChildOfRootCommand(command *cobra.Command) (*cobra.Command, bool) { - for command.HasParent() { - if !command.Parent().HasParent() { - return command, true - } - - command = command.Parent() - } - - return nil, false -} diff --git a/peer/main_test.go b/peer/main_test.go deleted file mode 100644 index 17b48ee3094..00000000000 --- a/peer/main_test.go +++ /dev/null @@ -1,82 +0,0 @@ -/* -Copyright IBM Corp. 2016 All Rights Reserved. - -Licensed under the Apache License, Version 2.0 (the "License"); -you may not use this file except in compliance with the License. -You may obtain a copy of the License at - - http://www.apache.org/licenses/LICENSE-2.0 - -Unless required by applicable law or agreed to in writing, software -distributed under the License is distributed on an "AS IS" BASIS, -WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -See the License for the specific language governing permissions and -limitations under the License. -*/ - -package main - -import ( - "testing" - - "github.com/spf13/cobra" -) - -func TestBuildcommandNameOutputSingleCommand(t *testing.T) { - command := &cobra.Command{Use: "command"} - - commandNameOutput := getPeerCommandFromCobraCommand(command) - - assertEqual(t, "command", commandNameOutput) -} - -func TestBuildcommandNameOutputNilCommand(t *testing.T) { - var command *cobra.Command - - commandNameOutput := getPeerCommandFromCobraCommand(command) - - assertEqual(t, "", commandNameOutput) -} - -func TestBuildcommandNameOutputTwoCommands(t *testing.T) { - rootCommand := &cobra.Command{Use: "rootcommand"} - childCommand := &cobra.Command{Use: "childcommand"} - rootCommand.AddCommand(childCommand) - - commandNameOutput := getPeerCommandFromCobraCommand(childCommand) - - assertEqual(t, "childcommand", commandNameOutput) -} - -func TestBuildcommandNameOutputThreeCommands(t *testing.T) { - rootCommand := &cobra.Command{Use: "rootcommand"} - childCommand := &cobra.Command{Use: "childcommand"} - leafCommand := &cobra.Command{Use: "leafCommand"} - rootCommand.AddCommand(childCommand) - childCommand.AddCommand(leafCommand) - - commandNameOutput := getPeerCommandFromCobraCommand(leafCommand) - - assertEqual(t, "childcommand", commandNameOutput) -} - -func TestBuildcommandNameOutputFourCommands(t *testing.T) { - rootCommand := &cobra.Command{Use: "rootcommand"} - childCommand := &cobra.Command{Use: "childcommand"} - secondChildCommand := &cobra.Command{Use: "secondChildCommand"} - leafCommand := &cobra.Command{Use: "leafCommand"} - - rootCommand.AddCommand(childCommand) - childCommand.AddCommand(secondChildCommand) - secondChildCommand.AddCommand(leafCommand) - - commandNameOutput := getPeerCommandFromCobraCommand(leafCommand) - - assertEqual(t, "childcommand", commandNameOutput) -} - -func assertEqual(t *testing.T, expected interface{}, actual interface{}) { - if expected != actual { - t.Errorf("Expected %v, got %v", expected, actual) - } -}