Add methods for setting log levels via regexp

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 <[email protected]>

Author: wlahti

common/flogging/logging.go

@@ -19,7 +19,9 @@ package flogging
 import (
 	"io"
 	"os"
+	"regexp"
 	"strings"
+	"sync"
 
 	"github.com/op/go-logging"
 	"github.com/spf13/viper"
@@ -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
@@ -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 {
@@ -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
+}

common/flogging/logging_test.go

@@ -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) {
@@ -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)
 }