Skip to content

Commit

Permalink
Add methods for setting log levels via regexp
Browse files Browse the repository at this point in the history 
This change adds the methods to allow log levels to be set
dynamically using regular expressions instead of supplying
one module name at a time.

Future CRs will 1) store the module map at the end at the end
of peer startup and add a method to revert all modules to those
levels, and 2) update all peer code to use flogging.MustGetLogger
instead of logging.MustGetLogger to enable these new features.

https://jira.hyperledger.org/browse/FAB-2351

Change-Id: I173ee502c4f3666447212fb3c36e06f7ee88a8f1
Signed-off-by: Will Lahti <wtlahti@us.ibm.com>
  • Loading branch information
@wlahti @yacovm
wlahti authored and yacovm committed Mar 29, 2017
1 parent 51b7e85 commit 1e30d9d
Show file tree
Hide file tree
Showing 2 changed files with 205 additions and 17 deletions.
70 changes: 62 additions & 8 deletions common/flogging/logging.go
View file
Expand Up @@ -19,7 +19,9 @@ package flogging
import (
"io"
"os"
"regexp"
"strings"
"sync"

"github.com/op/go-logging"
"github.com/spf13/viper"
Expand All @@ -35,7 +37,22 @@ var defaultOutput = os.Stderr
// case of configuration errors.
var fallbackDefaultLevel = logging.INFO

// LoggingInitFromViper is a 'hook' called at the beginning of command processing to
var lock = sync.Mutex{}

// modules holds the map of all modules and the current log level
var modules map[string]string

// 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

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
Expand All @@ -53,7 +70,7 @@ func InitFromViper(command string) {
logger.Debugf("Setting default logging level to %s for command '%s'", defaultLevel, command)
}

// LoggingInit initializes the logging based on the supplied spec, it is exposed externally
// 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 {
Expand Down Expand Up @@ -136,20 +153,57 @@ func GetModuleLevel(module string) (string, error) {
return level, nil
}

// SetModuleLevel sets the logging level for the specified module. This is
// currently only called from admin.go but can be called from anywhere in the
// code on a running peer to dynamically change the log level for the module.
func SetModuleLevel(module string, logLevel string) (string, error) {
// 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)

if err != nil {
logger.Warningf("Invalid logging level: %s - ignored", logLevel)
} else {
logging.SetLevel(logging.Level(level), module)
logger.Debugf("Module '%s' logger enabled for log level: %s", module, level)
// 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.
if !IsSetLevelByRegExpEnabled {
logging.SetLevel(logging.Level(level), moduleRegExp)
logger.Infof("Module '%s' logger enabled for log level: %s", moduleRegExp, level)
} else {
re, err := regexp.Compile(moduleRegExp)
if err != nil {
logger.Warningf("Invalid regular expression for module: %s", moduleRegExp)
return "", err
}

lock.Lock()
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)
}
}
}
}

logLevelString := level.String()

return logLevelString, 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
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
lock.Lock()
defer lock.Unlock()
modules[module] = level

return logger
}
152 changes: 143 additions & 9 deletions common/flogging/logging_test.go
View file
Expand Up @@ -148,29 +148,24 @@ func TestGetModuleLevelDefault(t *testing.T) {
level, _ := flogging.GetModuleLevel("peer")

// peer should be using the default log level at this point
if level != "INFO" {
t.FailNow()
}
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
if level != "DEBUG" {
t.FailNow()
}
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
if level != "DEBUG" {
t.FailNow()
}
assertEquals(t, logging.DEBUG.String(), level)
}

func TestSetModuleLevel(t *testing.T) {
Expand Down Expand Up @@ -217,6 +212,145 @@ func ExampleSetLoggingFormat_second() {
// 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)
}
Expand Down

0 comments on commit 1e30d9d

Please sign in to comment.