[FAB-1333] Make orderer logging configurable

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

The orderer code has taken an ad-hoc approach to logging during
construction.  This changeset unifies the logging across the common
components, solo, and kafka.  It deliberately does not touch the sbft
portion of the package so as not to disrupt its development until it is
ready to move onto the common config and common code.

Note that this moves flogging into the common package, and splits the
LoggingInit into two pieces.  The peer assumes a single global viper and
peer specific config structures.  This dependency leaked into flogging,
but in reality, the spec should probably be passed from the peer to
flogging, rather than having flogging interrogate the configuration
itself.  This would however have balooned the changeset, so it is left
as is for now.

Revision 3: Per feedback from Kostas, fixed the stuttering which was
prevalent in the flogging package.
Revision 4: Fix linting errors
Revision 6: Fix rebasing bugs which balooned the diff

Change-Id: I3ed21a3a001fb1e9c6b28be700203b84c69ee9f0
Signed-off-by: Jason Yellick <[email protected]>

Author: Jason Yellick

bddtests/docker-compose-orderer-base.yml

@@ -10,6 +10,7 @@ services:
             - ORDERER_GENERAL_BATCHSIZE_MAXMESSAGECOUNT=10
             - ORDERER_GENERAL_MAXWINDOWSIZE=1000
             - ORDERER_GENERAL_LISTENADDRESS=0.0.0.0
+            - ORDERER_GENERAL_LOGLEVEL=debug
             - ORDERER_GENERAL_GENESISIFILE=${ORDERER_GENERAL_GENESISIFILE}
             - ORDERER_RAMLEDGER_HISTORY_SIZE=100
         volumes:

core/flogging/logging.go common/flogging/logging.go

@@ -26,31 +26,41 @@ import (
 )
 
 // A logger to log logging logs!
-var loggingLogger = logging.MustGetLogger("logging")
+var logger = logging.MustGetLogger("logging")
 
-var loggingDefaultFormat = "%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message}"
-var loggingDefaultOutput = os.Stderr
+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
 
 // The default logging level, in force until LoggingInit() is called or in
 // case of configuration errors.
-var loggingDefaultLevel = logging.INFO
+var fallbackDefaultLevel = logging.INFO
 
-// LoggingInit is a 'hook' called at the beginning of command processing to
+// LoggingInitFromViper 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.
-func LoggingInit(command string) {
-	// Parse the logging specification in the form
-	//     [<module>[,<module>...]=]<level>[:[<module>[,<module>...]=]<level>...]
-	defaultLevel := loggingDefaultLevel
-	var err error
+// 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)
+}
+
+// LoggingInit 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
+	//     [<module>[,<module>...]=]<level>[:[<module>[,<module>...]=]<level>...]
+	defaultLevel := fallbackDefaultLevel
+	var err error
 	if spec != "" {
 		fields := strings.Split(spec, ":")
 		for _, field := range fields {
@@ -60,46 +70,46 @@ func LoggingInit(command string) {
 				// Default level
 				defaultLevel, err = logging.LogLevel(field)
 				if err != nil {
-					loggingLogger.Warningf("Logging level '%s' not recognized, defaulting to %s : %s", field, loggingDefaultLevel, err)
-					defaultLevel = loggingDefaultLevel // NB - 'defaultLevel' was overwritten
+					logger.Warningf("Logging level '%s' not recognized, defaulting to %s : %s", field, defaultLevel, err)
+					defaultLevel = fallbackDefaultLevel // NB - 'defaultLevel' was overwritten
 				}
 			case 2:
 				// <module>[,<module>...]=<level>
 				if level, err := logging.LogLevel(split[1]); err != nil {
-					loggingLogger.Warningf("Invalid logging level in '%s' ignored", field)
+					logger.Warningf("Invalid logging level in '%s' ignored", field)
 				} else if split[0] == "" {
-					loggingLogger.Warningf("Invalid logging override specification '%s' ignored - no module specified", field)
+					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)
-						loggingLogger.Debugf("Setting logging level for module '%s' to %s", module, level)
+						logger.Debugf("Setting logging level for module '%s' to %s", module, level)
 					}
 				}
 			default:
-				loggingLogger.Warningf("Invalid logging override '%s' ignored; Missing ':' ?", field)
+				logger.Warningf("Invalid logging override '%s' ignored; Missing ':' ?", field)
 			}
 		}
 	}
 	// Set the default logging level for all modules
 	logging.SetLevel(defaultLevel, "")
-	loggingLogger.Debugf("Setting default logging level to %s for command '%s'", defaultLevel, command)
+	return defaultLevel
 }
 
-// DefaultLoggingLevel returns the fallback value for loggers to use if parsing fails
-func DefaultLoggingLevel() logging.Level {
-	return loggingDefaultLevel
+// DefaultLevel returns the fallback value for loggers to use if parsing fails
+func DefaultLevel() logging.Level {
+	return fallbackDefaultLevel
 }
 
 // Initiate 'leveled' logging using the default format and output location
 func init() {
-	SetLoggingFormat(loggingDefaultFormat, loggingDefaultOutput)
+	SetLoggingFormat(defaultFormat, defaultOutput)
 }
 
 // SetLoggingFormat sets the logging format and the location of the log output
 func SetLoggingFormat(formatString string, output io.Writer) {
 	if formatString == "" {
-		formatString = loggingDefaultFormat
+		formatString = defaultFormat
 	}
 	format := logging.MustStringFormatter(formatString)
 
@@ -111,32 +121,32 @@ func SetLoggingFormat(formatString string, output io.Writer) {
 func initLoggingBackend(logFormatter logging.Formatter, output io.Writer) {
 	backend := logging.NewLogBackend(output, "", 0)
 	backendFormatter := logging.NewBackendFormatter(backend, logFormatter)
-	logging.SetBackend(backendFormatter).SetLevel(loggingDefaultLevel, "")
+	logging.SetBackend(backendFormatter).SetLevel(fallbackDefaultLevel, "")
 }
 
-// GetModuleLogLevel gets the current logging level for the specified module
-func GetModuleLogLevel(module string) (string, error) {
+// GetModuleLevel gets the current logging level for the specified module
+func GetModuleLevel(module string) (string, error) {
 	// logging.GetLevel() returns the logging level for the module, if defined.
 	// otherwise, it returns the default logging level, as set by
 	// flogging/logging.go
 	level := logging.GetLevel(module).String()
 
-	loggingLogger.Debugf("Module '%s' logger enabled for log level: %s", module, level)
+	logger.Debugf("Module '%s' logger enabled for log level: %s", module, level)
 
 	return level, nil
 }
 
-// SetModuleLogLevel sets the logging level for the specified module. This is
+// 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 SetModuleLogLevel(module string, logLevel string) (string, error) {
+func SetModuleLevel(module string, logLevel string) (string, error) {
 	level, err := logging.LogLevel(logLevel)
 
 	if err != nil {
-		loggingLogger.Warningf("Invalid logging level: %s - ignored", logLevel)
+		logger.Warningf("Invalid logging level: %s - ignored", logLevel)
 	} else {
 		logging.SetLevel(logging.Level(level), module)
-		loggingLogger.Debugf("Module '%s' logger enabled for log level: %s", module, level)
+		logger.Debugf("Module '%s' logger enabled for log level: %s", module, level)
 	}
 
 	logLevelString := level.String()

common/flogging/logging_test.go

@@ -0,0 +1,232 @@
+/*
+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 flogging_test
+
+import (
+	"os"
+	"testing"
+
+	"github.com/hyperledger/fabric/common/flogging"
+	"github.com/op/go-logging"
+	"github.com/spf13/viper"
+)
+
+func TestLevelDefault(t *testing.T) {
+	viper.Reset()
+
+	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())
+}
+
+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()
+	}
+}
+
+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()
+	}
+}
+
+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()
+	}
+}
+
+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")
+
+	// 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())
+
+	logFormat := "%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x} %{message}"
+	flogging.SetLoggingFormat(logFormat, os.Stdout)
+
+	logger := logging.MustGetLogger("floggingTest")
+	logger.Infof("test")
+
+	// 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())
+
+	logFormat := "%{time:15:04:05.000} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x} %{message}"
+	flogging.SetLoggingFormat(logFormat, os.Stdout)
+
+	logger := logging.MustGetLogger("floggingTest")
+	logger.Infof("test")
+
+	// Output:
+	// 00:00:00.000 [floggingTest] ExampleSetLoggingFormat_second -> INFO 001 test
+}
+
+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)
+	}
+}