diff --git a/bddtests/docker-compose-orderer-base.yml b/bddtests/docker-compose-orderer-base.yml index 3502a30366c..ff9d6f87378 100644 --- a/bddtests/docker-compose-orderer-base.yml +++ b/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: diff --git a/core/flogging/logging.go b/common/flogging/logging.go similarity index 59% rename from core/flogging/logging.go rename to common/flogging/logging.go index e9f5edaed00..0b9e816caf3 100644 --- a/core/flogging/logging.go +++ b/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 - // [[,...]=][:[[,...]=]...] - 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 + // [[,...]=][:[[,...]=]...] + 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: // [,...]= 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() diff --git a/common/flogging/logging_test.go b/common/flogging/logging_test.go new file mode 100644 index 00000000000..c434830d69d --- /dev/null +++ b/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) + } +} diff --git a/core/admin.go b/core/admin.go index 9b517d8b8eb..c29c5ac1504 100644 --- a/core/admin.go +++ b/core/admin.go @@ -25,7 +25,7 @@ import ( "golang.org/x/net/context" "github.com/golang/protobuf/ptypes/empty" - "github.com/hyperledger/fabric/core/flogging" + "github.com/hyperledger/fabric/common/flogging" pb "github.com/hyperledger/fabric/protos/peer" ) @@ -82,7 +82,7 @@ func (*ServerAdmin) StopServer(context.Context, *empty.Empty) (*pb.ServerStatus, // GetModuleLogLevel gets the current logging level for the specified module func (*ServerAdmin) GetModuleLogLevel(ctx context.Context, request *pb.LogLevelRequest) (*pb.LogLevelResponse, error) { - logLevelString, err := flogging.GetModuleLogLevel(request.LogModule) + logLevelString, err := flogging.GetModuleLevel(request.LogModule) logResponse := &pb.LogLevelResponse{LogModule: request.LogModule, LogLevel: logLevelString} return logResponse, err @@ -90,7 +90,7 @@ func (*ServerAdmin) GetModuleLogLevel(ctx context.Context, request *pb.LogLevelR // SetModuleLogLevel sets the logging level for the specified module func (*ServerAdmin) SetModuleLogLevel(ctx context.Context, request *pb.LogLevelRequest) (*pb.LogLevelResponse, error) { - logLevelString, err := flogging.SetModuleLogLevel(request.LogModule, request.LogLevel) + 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 21ebfd7ade2..419ec1e1eed 100644 --- a/core/chaincode/chaincode_support.go +++ b/core/chaincode/chaincode_support.go @@ -31,9 +31,9 @@ import ( "strings" + "github.com/hyperledger/fabric/common/flogging" "github.com/hyperledger/fabric/core/container" "github.com/hyperledger/fabric/core/container/ccintf" - "github.com/hyperledger/fabric/core/flogging" "github.com/hyperledger/fabric/core/ledger" pb "github.com/hyperledger/fabric/protos/peer" ) @@ -218,8 +218,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.DefaultLoggingLevel().String()) - theChaincodeSupport.chaincodeLogLevel = flogging.DefaultLoggingLevel().String() + chaincodeLogger.Warningf("Chaincode logging level %s is invalid; defaulting to %s", chaincodeLogLevelString, flogging.DefaultLevel().String()) + theChaincodeSupport.chaincodeLogLevel = flogging.DefaultLevel().String() } return theChaincodeSupport diff --git a/core/errors/errors.go b/core/errors/errors.go index c67dce14d81..1a8f19125a7 100644 --- a/core/errors/errors.go +++ b/core/errors/errors.go @@ -22,7 +22,7 @@ import ( "fmt" "runtime" - "github.com/hyperledger/fabric/core/flogging" + "github.com/hyperledger/fabric/common/flogging" logging "github.com/op/go-logging" ) @@ -136,7 +136,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.GetModuleLogLevel("error") + errorLogLevelString, _ := flogging.GetModuleLevel("error") if errorLogLevelString == logging.DEBUG.String() { messageWithCallStack := fmt.Sprintf(emap[fmt.Sprintf("%s", h.componentcode)][fmt.Sprintf("%s", h.reasoncode)][language], h.args...) + "\n" + h.GetStack() return messageWithCallStack diff --git a/core/errors/errors_test.go b/core/errors/errors_test.go index 358c6905b36..f637c2894e2 100644 --- a/core/errors/errors_test.go +++ b/core/errors/errors_test.go @@ -21,7 +21,7 @@ import ( "strings" "testing" - "github.com/hyperledger/fabric/core/flogging" + "github.com/hyperledger/fabric/common/flogging" ) func TestError(t *testing.T) { @@ -65,7 +65,7 @@ func TestErrorWithCallstackAndArg(t *testing.T) { func TestErrorWithCallstackMessage(t *testing.T) { // when the 'error' module is set to debug, the callstack will be appended // to the error message - flogging.SetModuleLogLevel("error", "debug") + flogging.SetModuleLevel("error", "debug") e := ErrorWithCallstack(Utility, UtilityUnknownError) s := e.GetStack() @@ -83,7 +83,7 @@ func TestErrorWithCallstackMessage(t *testing.T) { func ExampleError() { // when the 'error' module is set to anything but debug, the callstack will // not be appended to the error message - flogging.SetModuleLogLevel("error", "warning") + flogging.SetModuleLevel("error", "warning") err := ErrorWithCallstack(Utility, UtilityUnknownError) @@ -109,7 +109,7 @@ func ExampleError() { func ExampleUtilityErrorWithArg() { // when the 'error' module is set to anything but debug, the callstack will // not be appended to the error message - flogging.SetModuleLogLevel("error", "warning") + flogging.SetModuleLevel("error", "warning") err := ErrorWithCallstack(Utility, UtilityErrorWithArg, "arg1") @@ -135,7 +135,7 @@ func ExampleUtilityErrorWithArg() { func ExampleLoggingInvalidLogLevel() { // when the 'error' module is set to anything but debug, the callstack will // not be appended to the error message - flogging.SetModuleLogLevel("error", "warning") + flogging.SetModuleLevel("error", "warning") err := ErrorWithCallstack(Logging, LoggingInvalidLogLevel, "invalid") diff --git a/core/flogging/logging_test.go b/core/flogging/logging_test.go deleted file mode 100644 index f0221abb642..00000000000 --- a/core/flogging/logging_test.go +++ /dev/null @@ -1,232 +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 flogging_test - -import ( - "os" - "testing" - - "github.com/hyperledger/fabric/core/flogging" - "github.com/op/go-logging" - "github.com/spf13/viper" -) - -func TestLoggingLevelDefault(t *testing.T) { - viper.Reset() - - flogging.LoggingInit("") - - assertDefaultLoggingLevel(t, flogging.DefaultLoggingLevel()) -} - -func TestLoggingLevelOtherThanDefault(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "warning") - - flogging.LoggingInit("") - - assertDefaultLoggingLevel(t, logging.WARNING) -} - -func TestLoggingLevelForSpecificModule(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "core=info") - - flogging.LoggingInit("") - - assertModuleLoggingLevel(t, "core", logging.INFO) -} - -func TestLoggingLeveltForMultipleModules(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "core=warning:test=debug") - - flogging.LoggingInit("") - - assertModuleLoggingLevel(t, "core", logging.WARNING) - assertModuleLoggingLevel(t, "test", logging.DEBUG) -} - -func TestLoggingLevelForMultipleModulesAtSameLevel(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "core,test=warning") - - flogging.LoggingInit("") - - assertModuleLoggingLevel(t, "core", logging.WARNING) - assertModuleLoggingLevel(t, "test", logging.WARNING) -} - -func TestLoggingLevelForModuleWithDefault(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "info:test=warning") - - flogging.LoggingInit("") - - assertDefaultLoggingLevel(t, logging.INFO) - assertModuleLoggingLevel(t, "test", logging.WARNING) -} - -func TestLoggingLevelForModuleWithDefaultAtEnd(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "test=warning:info") - - flogging.LoggingInit("") - - assertDefaultLoggingLevel(t, logging.INFO) - assertModuleLoggingLevel(t, "test", logging.WARNING) -} - -func TestLoggingLevelForSpecificCommand(t *testing.T) { - viper.Reset() - viper.Set("logging.node", "error") - - flogging.LoggingInit("node") - - assertDefaultLoggingLevel(t, logging.ERROR) -} - -func TestLoggingLevelForUnknownCommandGoesToDefault(t *testing.T) { - viper.Reset() - - flogging.LoggingInit("unknown command") - - assertDefaultLoggingLevel(t, flogging.DefaultLoggingLevel()) -} - -func TestLoggingLevelInvalid(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "invalidlevel") - - flogging.LoggingInit("") - - assertDefaultLoggingLevel(t, flogging.DefaultLoggingLevel()) -} - -func TestLoggingLevelInvalidModules(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "core=invalid") - - flogging.LoggingInit("") - - assertDefaultLoggingLevel(t, flogging.DefaultLoggingLevel()) -} - -func TestLoggingLevelInvalidEmptyModule(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "=warning") - - flogging.LoggingInit("") - - assertDefaultLoggingLevel(t, flogging.DefaultLoggingLevel()) -} - -func TestLoggingLevelInvalidModuleSyntax(t *testing.T) { - viper.Reset() - viper.Set("logging_level", "type=warn=again") - - flogging.LoggingInit("") - - assertDefaultLoggingLevel(t, flogging.DefaultLoggingLevel()) -} - -func TestGetModuleLoggingLevelDefault(t *testing.T) { - level, _ := flogging.GetModuleLogLevel("peer") - - // peer should be using the default log level at this point - if level != "INFO" { - t.FailNow() - } -} - -func TestGetModuleLoggingLevelDebug(t *testing.T) { - flogging.SetModuleLogLevel("peer", "DEBUG") - level, _ := flogging.GetModuleLogLevel("peer") - - // ensure that the log level has changed to debug - if level != "DEBUG" { - t.FailNow() - } -} - -func TestGetModuleLoggingLevelInvalid(t *testing.T) { - flogging.SetModuleLogLevel("peer", "invalid") - level, _ := flogging.GetModuleLogLevel("peer") - - // ensure that the log level didn't change after invalid log level specified - if level != "DEBUG" { - t.FailNow() - } -} - -func TestSetModuleLoggingLevel(t *testing.T) { - flogging.SetModuleLogLevel("peer", "WARNING") - - // ensure that the log level has changed to warning - assertModuleLoggingLevel(t, "peer", logging.WARNING) -} - -func TestSetModuleLoggingLevelInvalid(t *testing.T) { - flogging.SetModuleLogLevel("peer", "invalid") - - // ensure that the log level didn't change after invalid log level specified - assertModuleLoggingLevel(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.DefaultLoggingLevel()) - - 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.DefaultLoggingLevel()) - - 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 assertDefaultLoggingLevel(t *testing.T, expectedLevel logging.Level) { - assertModuleLoggingLevel(t, "", expectedLevel) -} - -func assertModuleLoggingLevel(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) - } -} diff --git a/orderer/common/blockcutter/blockcutter.go b/orderer/common/blockcutter/blockcutter.go index afb0717a2eb..1751c13d306 100644 --- a/orderer/common/blockcutter/blockcutter.go +++ b/orderer/common/blockcutter/blockcutter.go @@ -26,10 +26,6 @@ import ( var logger = logging.MustGetLogger("orderer/common/blockcutter") -func init() { - logging.SetLevel(logging.DEBUG, "") -} - // Receiver defines a sink for the ordered broadcast messages type Receiver interface { // Ordered should be invoked sequentially as messages are ordered diff --git a/orderer/common/blockcutter/blockcutter_test.go b/orderer/common/blockcutter/blockcutter_test.go index 9291bce28bc..8e816bc4867 100644 --- a/orderer/common/blockcutter/blockcutter_test.go +++ b/orderer/common/blockcutter/blockcutter_test.go @@ -24,8 +24,13 @@ import ( mocksharedconfig "github.com/hyperledger/fabric/orderer/mocks/sharedconfig" cb "github.com/hyperledger/fabric/protos/common" ab "github.com/hyperledger/fabric/protos/orderer" + logging "github.com/op/go-logging" ) +func init() { + logging.SetLevel(logging.DEBUG, "") +} + type isolatedCommitter struct{} func (ic isolatedCommitter) Isolated() bool { return true } diff --git a/orderer/common/broadcast/broadcast.go b/orderer/common/broadcast/broadcast.go index 97438491c27..4d966f8fe21 100644 --- a/orderer/common/broadcast/broadcast.go +++ b/orderer/common/broadcast/broadcast.go @@ -29,10 +29,6 @@ import ( var logger = logging.MustGetLogger("orderer/common/broadcast") -func init() { - logging.SetLevel(logging.DEBUG, "") -} - // Handler defines an interface which handles broadcasts type Handler interface { // Handle starts a service thread for a given gRPC connection and services the broadcast connection diff --git a/orderer/common/broadcast/broadcast_test.go b/orderer/common/broadcast/broadcast_test.go index 898f12751af..df185e24be7 100644 --- a/orderer/common/broadcast/broadcast_test.go +++ b/orderer/common/broadcast/broadcast_test.go @@ -26,9 +26,14 @@ import ( ab "github.com/hyperledger/fabric/protos/orderer" "github.com/hyperledger/fabric/protos/utils" + logging "github.com/op/go-logging" "google.golang.org/grpc" ) +func init() { + logging.SetLevel(logging.DEBUG, "") +} + var systemChain = "systemChain" type mockB struct { diff --git a/orderer/common/deliver/deliver.go b/orderer/common/deliver/deliver.go index 611a52823f2..bed3c1102b3 100644 --- a/orderer/common/deliver/deliver.go +++ b/orderer/common/deliver/deliver.go @@ -26,10 +26,6 @@ import ( var logger = logging.MustGetLogger("orderer/common/deliver") -func init() { - logging.SetLevel(logging.DEBUG, "") -} - // Handler defines an interface which handles Deliver requests type Handler interface { Handle(srv ab.AtomicBroadcast_DeliverServer) error diff --git a/orderer/common/deliver/deliver_test.go b/orderer/common/deliver/deliver_test.go index b1206a96670..25e86385df4 100644 --- a/orderer/common/deliver/deliver_test.go +++ b/orderer/common/deliver/deliver_test.go @@ -29,6 +29,7 @@ import ( cb "github.com/hyperledger/fabric/protos/common" ab "github.com/hyperledger/fabric/protos/orderer" + logging "github.com/op/go-logging" "google.golang.org/grpc" ) @@ -39,6 +40,7 @@ var systemChainID = "systemChain" const ledgerSize = 10 func init() { + logging.SetLevel(logging.DEBUG, "") genesisBlock = provisional.New(config.Load()).GenesisBlock() } diff --git a/orderer/common/sharedconfig/sharedconfig.go b/orderer/common/sharedconfig/sharedconfig.go index 476e5f587e5..876eebf3236 100644 --- a/orderer/common/sharedconfig/sharedconfig.go +++ b/orderer/common/sharedconfig/sharedconfig.go @@ -49,10 +49,6 @@ const ( var logger = logging.MustGetLogger("orderer/common/sharedconfig") -func init() { - logging.SetLevel(logging.DEBUG, "") -} - // Manager stores the common shared orderer configuration // It is intended to be the primary accessor of ManagerImpl // It is intended to discourage use of the other exported ManagerImpl methods diff --git a/orderer/common/sharedconfig/sharedconfig_test.go b/orderer/common/sharedconfig/sharedconfig_test.go index e2332230f1d..5a9792f469b 100644 --- a/orderer/common/sharedconfig/sharedconfig_test.go +++ b/orderer/common/sharedconfig/sharedconfig_test.go @@ -25,8 +25,14 @@ import ( cb "github.com/hyperledger/fabric/protos/common" ab "github.com/hyperledger/fabric/protos/orderer" "github.com/hyperledger/fabric/protos/utils" + + logging "github.com/op/go-logging" ) +func init() { + logging.SetLevel(logging.DEBUG, "") +} + func doesFuncCrash(crasher func(), test string) bool { // Adapted from https://talks.golang.org/2014/testing.slide#23 to test os.Exit() functionality if os.Getenv("BE_CRASHER") == "1" { diff --git a/orderer/kafka/log.go b/orderer/kafka/log.go index c092a61dfc8..d88ee2586ca 100644 --- a/orderer/kafka/log.go +++ b/orderer/kafka/log.go @@ -17,25 +17,7 @@ limitations under the License. package kafka import ( - "os" - "strings" - logging "github.com/op/go-logging" ) -var logger *logging.Logger - -func init() { - backend := logging.NewLogBackend(os.Stderr, "", 0) - logging.SetBackend(backend) - formatter := logging.MustStringFormatter("[%{time:15:04:05.000}] %{shortfile:18s}: %{color}[%{level:-5s}]%{color:reset} %{message}") - logging.SetFormatter(formatter) - logger = logging.MustGetLogger("orderer/kafka") - logging.SetLevel(logging.INFO, "") // Silence debug-level outputs when testing -} - -// SetLogLevel sets the package logging level -func SetLogLevel(level string) { - logLevel, _ := logging.LogLevel(strings.ToUpper(level)) // TODO Validate input - logging.SetLevel(logLevel, logger.Module) -} +var logger = logging.MustGetLogger("orderer/kafka") diff --git a/orderer/kafka/log_test.go b/orderer/kafka/log_test.go new file mode 100644 index 00000000000..25faa2a7e80 --- /dev/null +++ b/orderer/kafka/log_test.go @@ -0,0 +1,25 @@ +/* +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 kafka + +import ( + logging "github.com/op/go-logging" +) + +func init() { + logging.SetLevel(logging.INFO, "") // Silence debug-level outputs when testing +} diff --git a/orderer/localconfig/config.go b/orderer/localconfig/config.go index e3ee70ff977..8b4f47d6435 100644 --- a/orderer/localconfig/config.go +++ b/orderer/localconfig/config.go @@ -31,7 +31,7 @@ import ( var logger = logging.MustGetLogger("orderer/config") func init() { - logging.SetLevel(logging.DEBUG, "") + logging.SetLevel(logging.ERROR, "") } // Prefix is the default config prefix for the orderer @@ -50,6 +50,7 @@ type General struct { BatchSize BatchSize GenesisFile string Profile Profile + LogLevel string } // BatchSize contains configuration affecting the size of batches @@ -118,6 +119,7 @@ var defaults = TopLevel{ Enabled: false, Address: "0.0.0.0:6060", }, + LogLevel: "INFO", }, RAMLedger: RAMLedger{ HistorySize: 10000, @@ -166,6 +168,9 @@ func (c *TopLevel) completeInitialization() { case c.General.ListenPort == 0: logger.Infof("General.ListenPort unset, setting to %s", defaults.General.ListenPort) c.General.ListenPort = defaults.General.ListenPort + case c.General.LogLevel == "": + logger.Infof("General.LogLevel unset, setting to %s", defaults.General.LogLevel) + c.General.LogLevel = defaults.General.LogLevel case c.General.GenesisMethod == "": c.General.GenesisMethod = defaults.General.GenesisMethod case c.General.GenesisFile == "": diff --git a/orderer/main.go b/orderer/main.go index c9546903b3f..8f405e208c7 100644 --- a/orderer/main.go +++ b/orderer/main.go @@ -25,7 +25,7 @@ import ( _ "net/http/pprof" "os" - "github.com/Shopify/sarama" + "github.com/hyperledger/fabric/common/flogging" "github.com/hyperledger/fabric/orderer/common/bootstrap/file" "github.com/hyperledger/fabric/orderer/common/bootstrap/provisional" "github.com/hyperledger/fabric/orderer/kafka" @@ -37,6 +37,8 @@ import ( "github.com/hyperledger/fabric/orderer/solo" cb "github.com/hyperledger/fabric/protos/common" ab "github.com/hyperledger/fabric/protos/orderer" + + "github.com/Shopify/sarama" "github.com/op/go-logging" "google.golang.org/grpc" @@ -44,12 +46,9 @@ import ( var logger = logging.MustGetLogger("orderer/main") -func init() { - logging.SetLevel(logging.DEBUG, "") -} - func main() { conf := config.Load() + flogging.InitFromSpec(conf.General.LogLevel) // Start the profiling service if enabled. // The ListenAndServe() call does not return unless an error occurs. diff --git a/orderer/multichain/manager.go b/orderer/multichain/manager.go index a40ac070ebc..e90520bfd6b 100644 --- a/orderer/multichain/manager.go +++ b/orderer/multichain/manager.go @@ -40,10 +40,6 @@ func (xxx xxxCryptoHelper) VerifySignature(msg []byte, ids []byte, sigs []byte) return true } -func init() { - logging.SetLevel(logging.DEBUG, "") -} - // Manager coordinates the creation and access of chains type Manager interface { // GetChain retrieves the chain support for a chain (and whether it exists) diff --git a/orderer/multichain/manager_test.go b/orderer/multichain/manager_test.go index 1dd9826995c..db5295d06d4 100644 --- a/orderer/multichain/manager_test.go +++ b/orderer/multichain/manager_test.go @@ -28,6 +28,8 @@ import ( cb "github.com/hyperledger/fabric/protos/common" ab "github.com/hyperledger/fabric/protos/orderer" "github.com/hyperledger/fabric/protos/utils" + + logging "github.com/op/go-logging" ) var conf *config.TopLevel @@ -35,6 +37,7 @@ var genesisBlock *cb.Block func init() { conf = config.Load() + logging.SetLevel(logging.DEBUG, "") genesisBlock = provisional.New(conf).GenesisBlock() } diff --git a/orderer/orderer.yaml b/orderer/orderer.yaml index a3a5e2bbc16..65ba093513a 100644 --- a/orderer/orderer.yaml +++ b/orderer/orderer.yaml @@ -40,6 +40,10 @@ General: # Listen port: The port on which to bind to listen ListenPort: 7050 + # Log Level: The level at which to log. This accepts logging specifications + # per fabric/docs/Setup/logging-control.md + LogLevel: info + # Genesis method: The method by which to retrieve/generate the genesis block. Available values are "provisional", "file" GenesisMethod: provisional diff --git a/orderer/rawledger/fileledger/fileledger.go b/orderer/rawledger/fileledger/fileledger.go index e831e206d5a..b85ccac512f 100644 --- a/orderer/rawledger/fileledger/fileledger.go +++ b/orderer/rawledger/fileledger/fileledger.go @@ -36,7 +36,6 @@ var logger = logging.MustGetLogger("rawledger/fileledger") var closedChan chan struct{} func init() { - logging.SetLevel(logging.DEBUG, "") closedChan = make(chan struct{}) close(closedChan) } diff --git a/orderer/rawledger/fileledger/fileledger_test.go b/orderer/rawledger/fileledger/fileledger_test.go index 22367c0f5b0..0326156bba1 100644 --- a/orderer/rawledger/fileledger/fileledger_test.go +++ b/orderer/rawledger/fileledger/fileledger_test.go @@ -26,11 +26,14 @@ import ( "github.com/hyperledger/fabric/orderer/localconfig" cb "github.com/hyperledger/fabric/protos/common" ab "github.com/hyperledger/fabric/protos/orderer" + + logging "github.com/op/go-logging" ) var genesisBlock *cb.Block func init() { + logging.SetLevel(logging.DEBUG, "") genesisBlock = provisional.New(config.Load()).GenesisBlock() } diff --git a/orderer/rawledger/ramledger/ramledger.go b/orderer/rawledger/ramledger/ramledger.go index 42bd29888f6..5a00fdf03fd 100644 --- a/orderer/rawledger/ramledger/ramledger.go +++ b/orderer/rawledger/ramledger/ramledger.go @@ -29,10 +29,6 @@ import ( var logger = logging.MustGetLogger("rawledger/ramledger") -func init() { - logging.SetLevel(logging.DEBUG, "") -} - type cursor struct { list *simpleList } diff --git a/orderer/rawledger/ramledger/ramledger_test.go b/orderer/rawledger/ramledger/ramledger_test.go index 34ae460ca3d..ca6ba52ba32 100644 --- a/orderer/rawledger/ramledger/ramledger_test.go +++ b/orderer/rawledger/ramledger/ramledger_test.go @@ -22,11 +22,14 @@ import ( "github.com/hyperledger/fabric/orderer/common/bootstrap/provisional" "github.com/hyperledger/fabric/orderer/localconfig" cb "github.com/hyperledger/fabric/protos/common" + + logging "github.com/op/go-logging" ) var genesisBlock *cb.Block func init() { + logging.SetLevel(logging.DEBUG, "") genesisBlock = provisional.New(config.Load()).GenesisBlock() } diff --git a/orderer/solo/consensus.go b/orderer/solo/consensus.go index 5045b5a08f6..8085339c72c 100644 --- a/orderer/solo/consensus.go +++ b/orderer/solo/consensus.go @@ -26,10 +26,6 @@ import ( var logger = logging.MustGetLogger("orderer/solo") -func init() { - logging.SetLevel(logging.DEBUG, "") -} - type consenter struct{} type chain struct { diff --git a/orderer/solo/consensus_test.go b/orderer/solo/consensus_test.go index 151915ecb4e..bd49cc79234 100644 --- a/orderer/solo/consensus_test.go +++ b/orderer/solo/consensus_test.go @@ -24,8 +24,14 @@ import ( mockmultichain "github.com/hyperledger/fabric/orderer/mocks/multichain" mocksharedconfig "github.com/hyperledger/fabric/orderer/mocks/sharedconfig" cb "github.com/hyperledger/fabric/protos/common" + + logging "github.com/op/go-logging" ) +func init() { + logging.SetLevel(logging.DEBUG, "") +} + var testMessage = &cb.Envelope{Payload: []byte("TEST_MESSAGE")} func syncQueueMessage(msg *cb.Envelope, chain *chain, bc *mockblockcutter.Receiver) { diff --git a/peer/common/common.go b/peer/common/common.go old mode 100755 new mode 100644 index b18f6747dc8..5f3d6031754 --- a/peer/common/common.go +++ b/peer/common/common.go @@ -21,9 +21,9 @@ import ( "os" "path/filepath" + "github.com/hyperledger/fabric/common/flogging" "github.com/hyperledger/fabric/core/crypto/primitives" "github.com/hyperledger/fabric/core/errors" - "github.com/hyperledger/fabric/core/flogging" "github.com/hyperledger/fabric/core/peer" "github.com/hyperledger/fabric/core/peer/msp" "github.com/hyperledger/fabric/msp" @@ -106,7 +106,7 @@ func GetAdminClient() (pb.AdminClient, error) { // core.yaml func SetErrorLoggingLevel() error { viperErrorLoggingLevel := viper.GetString("logging.error") - _, err := flogging.SetModuleLogLevel("error", viperErrorLoggingLevel) + _, err := flogging.SetModuleLevel("error", viperErrorLoggingLevel) return err } diff --git a/peer/main.go b/peer/main.go index d8b249e2192..796c13d839c 100644 --- a/peer/main.go +++ b/peer/main.go @@ -28,9 +28,9 @@ import ( _ "net/http/pprof" + "github.com/hyperledger/fabric/common/flogging" "github.com/hyperledger/fabric/core" "github.com/hyperledger/fabric/core/crypto/primitives" - "github.com/hyperledger/fabric/core/flogging" "github.com/hyperledger/fabric/peer/chaincode" "github.com/hyperledger/fabric/peer/clilogging" "github.com/hyperledger/fabric/peer/common" @@ -50,7 +50,7 @@ var mainCmd = &cobra.Command{ Use: "peer", PersistentPreRunE: func(cmd *cobra.Command, args []string) error { peerCommand := getPeerCommandFromCobraCommand(cmd) - flogging.LoggingInit(peerCommand) + flogging.InitFromViper(peerCommand) return core.CacheConfiguration() },