Skip to content

Commit

Permalink
Merge "[FAB-1333] Make orderer logging configurable"
Browse files Browse the repository at this point in the history
  • Loading branch information
yacovm authored and Gerrit Code Review committed Jan 6, 2017
2 parents 2f6433f + cb8fe31 commit af3a722
Show file tree
Hide file tree
Showing 31 changed files with 363 additions and 333 deletions.
1 change: 1 addition & 0 deletions bddtests/docker-compose-orderer-base.yml
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand Down
70 changes: 40 additions & 30 deletions core/flogging/logging.go → common/flogging/logging.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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)

Expand All @@ -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()
Expand Down
232 changes: 232 additions & 0 deletions common/flogging/logging_test.go
Original file line number Diff line number Diff line change
@@ -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)
}
}
Loading

0 comments on commit af3a722

Please sign in to comment.