[FAB-2351] Add revert to peer startup log levels

This change adds the mechanism to store the module map at the end
at the end of peer startup and adds a method to revert all modules
to those levels. It can be called from CLI using
'peer logging revertlevels'.

This CR follows https://gerrit.hyperledger.org/r/#/c/7281/. A future
CR will update all peer code to use flogging.MustGetLogger
instead of logging.MustGetLogger to enable these new features.

Change-Id: I297c22b625041e34ebf3a9795ed3b673a63b3212
Signed-off-by: Will Lahti <wtlahti@us.ibm.com>

common/flogging/logging.go

@@ -37,8 +37,11 @@ var (
 
 	defaultOutput *os.File
 
-	modules map[string]string // Holds the map of all modules and their respective log level
-	lock    sync.Mutex
+	modules          map[string]string // Holds the map of all modules and their respective log level
+	peerStartModules map[string]string
+
+	lock sync.RWMutex
+	once sync.Once
 
 	// IsSetLevelByRegExpEnabled allows the setting of log levels using a regular
 	// expression, instead of one module at a time, when set to true.
@@ -56,7 +59,7 @@ func init() {
 func Reset() {
 	IsSetLevelByRegExpEnabled = false // redundant since the default for booleans is `false` but added for clarity
 	modules = make(map[string]string)
-	lock = sync.Mutex{}
+	lock = sync.RWMutex{}
 
 	defaultOutput = os.Stderr
 	InitBackend(SetFormat(defaultFormat), defaultOutput)
@@ -98,16 +101,20 @@ func GetModuleLevel(module string) string {
 // regular expression. Can be used to dynamically change the log level for the
 // module.
 func SetModuleLevel(moduleRegExp string, level string) (string, error) {
-	var re *regexp.Regexp
+	return setModuleLevel(moduleRegExp, level, false)
+}
 
+func setModuleLevel(moduleRegExp string, level string, revert bool) (string, error) {
+
+	var re *regexp.Regexp
 	logLevel, err := logging.LogLevel(level)
 	if err != nil {
 		logger.Warningf("Invalid logging level '%s' - ignored", level)
 	} else {
 		// TODO This check is here to preserve the old functionality until all
 		// other packages switch to `flogging.MustGetLogger` (from
 		// `logging.MustGetLogger`).
-		if !IsSetLevelByRegExpEnabled {
+		if !IsSetLevelByRegExpEnabled || revert {
 			logging.SetLevel(logging.Level(logLevel), moduleRegExp)
 			logger.Debugf("Module '%s' logger enabled for log level '%s'", moduleRegExp, logLevel)
 		} else {
@@ -123,7 +130,7 @@ func SetModuleLevel(moduleRegExp string, level string) (string, error) {
 				if re.MatchString(module) {
 					logging.SetLevel(logging.Level(logLevel), module)
 					modules[module] = logLevel.String()
-					logger.Infof("Module '%s' logger enabled for log level '%s'", module, logLevel)
+					logger.Debugf("Module '%s' logger enabled for log level '%s'", module, logLevel)
 				}
 			}
 		}
@@ -185,3 +192,44 @@ func InitFromSpec(spec string) string {
 	logging.SetLevel(levelAll, "") // set the logging level for all modules
 	return levelAll.String()
 }
+
+// SetPeerStartupModulesMap saves the modules and their log levels.
+// this function should only be called at the end of peer startup.
+func SetPeerStartupModulesMap() {
+	lock.Lock()
+	defer lock.Unlock()
+
+	once.Do(func() {
+		peerStartModules = make(map[string]string)
+		for k, v := range modules {
+			peerStartModules[k] = v
+		}
+	})
+}
+
+// GetPeerStartupLevel returns the peer startup level for the specified module.
+// It will return an empty string if the input parameter is empty or the module
+// is not found
+func GetPeerStartupLevel(module string) string {
+	if module != "" {
+		if level, ok := peerStartModules[module]; ok {
+			return level
+		}
+	}
+
+	return ""
+}
+
+// RevertToPeerStartupLevels reverts the log levels for all modules to the level
+// defined at the end of peer startup.
+func RevertToPeerStartupLevels() error {
+	lock.RLock()
+	defer lock.RUnlock()
+	for key := range peerStartModules {
+		_, err := setModuleLevel(key, peerStartModules[key], true)
+		if err != nil {
+			return err
+		}
+	}
+	return nil
+}

common/flogging/logging_test.go

@@ -33,6 +33,7 @@ type testCase struct {
 	expectedLevels []string
 	modules        []string
 	withRegEx      bool
+	revert         bool
 	shouldErr      bool
 }
 
@@ -46,22 +47,24 @@ func TestSetModuleLevel(t *testing.T) {
 	var tc []testCase
 
 	tc = append(tc,
-		testCase{"Valid", []string{"a", "warning"}, []string{"WARNING"}, []string{"a"}, false, false},
+		testCase{"Valid", []string{"a", "warning"}, []string{"WARNING"}, []string{"a"}, false, false, false},
 		// Same as before
-		testCase{"Invalid", []string{"a", "foo"}, []string{"WARNING"}, []string{"a"}, false, false},
+		testCase{"Invalid", []string{"a", "foo"}, []string{"WARNING"}, []string{"a"}, false, false, false},
 		// Tests with regular expressions
 		testCase{"RegexModuleWithSubmodule", []string{"foo", "warning"}, []string{"WARNING", "WARNING", flogging.DefaultLevel()},
-			[]string{"foo", "foo/bar", "baz"}, true, false},
+			[]string{"foo", "foo/bar", "baz"}, true, false, false},
 		// Set the level for modules that contain "foo" or "baz"
 		testCase{"RegexOr", []string{"foo|baz", "debug"}, []string{"DEBUG", "DEBUG", "DEBUG", flogging.DefaultLevel()},
-			[]string{"foo", "foo/bar", "baz", "random"}, true, false},
+			[]string{"foo", "foo/bar", "baz", "random"}, true, false, false},
 		// Set the level for modules that end with "bar"
 		testCase{"RegexSuffix", []string{"bar$", "error"}, []string{"ERROR", flogging.DefaultLevel()},
-			[]string{"foo/bar", "bar/baz"}, true, false},
+			[]string{"foo/bar", "bar/baz"}, true, false, false},
 		testCase{"RegexComplex", []string{"^[a-z]+\\/[a-z]+#.+$", "warning"}, []string{flogging.DefaultLevel(), flogging.DefaultLevel(), "WARNING", "WARNING", "WARNING"},
-			[]string{"gossip/util", "orderer/util", "gossip/gossip#0.0.0.0:7051", "gossip/conn#-1", "orderer/conn#0.0.0.0:7051"}, true, false},
+			[]string{"gossip/util", "orderer/util", "gossip/gossip#0.0.0.0:7051", "gossip/conn#-1", "orderer/conn#0.0.0.0:7051"}, true, false, false},
 		testCase{"RegexInvalid", []string{"(", "warning"}, []string{flogging.DefaultLevel()},
-			[]string{"foo"}, true, true},
+			[]string{"foo"}, true, false, true},
+		testCase{"RevertLevels", []string{"revertmodule1", "warning", "revertmodule2", "debug"}, []string{"WARNING", "DEBUG", "DEBUG"},
+			[]string{"revertmodule1", "revertmodule2", "revertmodule2/submodule"}, true, true, false},
 	)
 
 	assert := assert.New(t)
@@ -72,26 +75,33 @@ func TestSetModuleLevel(t *testing.T) {
 				for j := 0; j < len(tc[i].modules); j++ {
 					flogging.MustGetLogger(tc[i].modules[j])
 				}
+				if tc[i].revert {
+					flogging.SetPeerStartupModulesMap()
+				}
 				flogging.IsSetLevelByRegExpEnabled = true // enable for call below
 			}
-
-			_, err := flogging.SetModuleLevel(tc[i].args[0], tc[i].args[1])
-			if tc[i].shouldErr {
-				assert.NotNil(err, "Should have returned an error")
+			for k := 0; k < len(tc[i].args); k = k + 2 {
+				_, err := flogging.SetModuleLevel(tc[i].args[k], tc[i].args[k+1])
+				if tc[i].shouldErr {
+					assert.NotNil(err, "Should have returned an error")
+				}
 			}
-			for k := 0; k < len(tc[i].expectedLevels); k++ {
-				assert.Equal(tc[i].expectedLevels[k], flogging.GetModuleLevel(tc[i].modules[k]))
+			for l := 0; l < len(tc[i].expectedLevels); l++ {
+				assert.Equal(tc[i].expectedLevels[l], flogging.GetModuleLevel(tc[i].modules[l]))
+			}
+			if tc[i].revert {
+				flogging.RevertToPeerStartupLevels()
+				for m := 0; m < len(tc[i].modules); m++ {
+					assert.Equal(flogging.GetPeerStartupLevel(tc[i].modules[m]), flogging.GetModuleLevel(tc[i].modules[m]))
+				}
 			}
-
 			if tc[i].withRegEx {
 				// Force reset (a) in case the next test is non-regex, (b) so as
 				// to reset the modules map and reuse module names.
 				flogging.Reset()
-
 			}
 		})
 	}
-
 }
 
 func TestInitFromSpec(t *testing.T) {
@@ -120,25 +130,25 @@ func TestInitFromSpec(t *testing.T) {
 	// MODULES
 
 	tc = append(tc,
-		testCase{"SingleModuleLevel", []string{"a=info"}, []string{"INFO"}, []string{"a"}, false, false},
-		testCase{"MultipleModulesMultipleLevels", []string{"a=info:b=debug"}, []string{"INFO", "DEBUG"}, []string{"a", "b"}, false, false},
-		testCase{"MultipleModulesSameLevel", []string{"a,b=warning"}, []string{"WARNING", "WARNING"}, []string{"a", "b"}, false, false},
+		testCase{"SingleModuleLevel", []string{"a=info"}, []string{"INFO"}, []string{"a"}, false, false, false},
+		testCase{"MultipleModulesMultipleLevels", []string{"a=info:b=debug"}, []string{"INFO", "DEBUG"}, []string{"a", "b"}, false, false, false},
+		testCase{"MultipleModulesSameLevel", []string{"a,b=warning"}, []string{"WARNING", "WARNING"}, []string{"a", "b"}, false, false, false},
 	)
 
 	// MODULES + DEFAULT
 
 	tc = append(tc,
-		testCase{"GlobalDefaultAndSingleModuleLevel", []string{"info:a=warning"}, []string{"INFO", "WARNING"}, []string{"", "a"}, false, false},
-		testCase{"SingleModuleLevelAndGlobalDefaultAtEnd", []string{"a=warning:info"}, []string{"WARNING", "INFO"}, []string{"a", ""}, false, false},
+		testCase{"GlobalDefaultAndSingleModuleLevel", []string{"info:a=warning"}, []string{"INFO", "WARNING"}, []string{"", "a"}, false, false, false},
+		testCase{"SingleModuleLevelAndGlobalDefaultAtEnd", []string{"a=warning:info"}, []string{"WARNING", "INFO"}, []string{"a", ""}, false, false, false},
 	)
 
 	// INVALID INPUT
 
 	tc = append(tc,
-		testCase{"InvalidLevel", []string{"foo"}, []string{flogging.DefaultLevel()}, []string{""}, false, false},
-		testCase{"InvalidLevelForSingleModule", []string{"a=foo"}, []string{flogging.DefaultLevel()}, []string{""}, false, false},
-		testCase{"EmptyModuleEqualsLevel", []string{"=warning"}, []string{flogging.DefaultLevel()}, []string{""}, false, false},
-		testCase{"InvalidModuleSyntax", []string{"a=b=c"}, []string{flogging.DefaultLevel()}, []string{""}, false, false},
+		testCase{"InvalidLevel", []string{"foo"}, []string{flogging.DefaultLevel()}, []string{""}, false, false, false},
+		testCase{"InvalidLevelForSingleModule", []string{"a=foo"}, []string{flogging.DefaultLevel()}, []string{""}, false, false, false},
+		testCase{"EmptyModuleEqualsLevel", []string{"=warning"}, []string{flogging.DefaultLevel()}, []string{""}, false, false, false},
+		testCase{"InvalidModuleSyntax", []string{"a=b=c"}, []string{flogging.DefaultLevel()}, []string{""}, false, false, false},
 	)
 
 	assert := assert.New(t)

core/admin.go

@@ -94,3 +94,11 @@ func (*ServerAdmin) SetModuleLogLevel(ctx context.Context, request *pb.LogLevelR
 	logResponse := &pb.LogLevelResponse{LogModule: request.LogModule, LogLevel: logLevelString}
 	return logResponse, err
 }
+
+// RevertLogLevels reverts the log levels for all modules to the level
+// defined at the end of peer startup.
+func (*ServerAdmin) RevertLogLevels(context.Context, *empty.Empty) (*empty.Empty, error) {
+	err := flogging.RevertToPeerStartupLevels()
+
+	return &empty.Empty{}, err
+}

peer/clilogging/common.go

@@ -25,11 +25,17 @@ import (
 
 func checkLoggingCmdParams(cmd *cobra.Command, args []string) error {
 	var err error
-
-	// check that at least one parameter is passed in
-	if len(args) == 0 {
-		err = errors.ErrorWithCallstack("Logging", "NoParameters", "No parameters provided.")
-		return err
+	if cmd.Name() == "revertlevels" {
+		if len(args) > 0 {
+			err = errors.ErrorWithCallstack("Logging", "ExtraParameters", "More parameters than necessary were provided. Expected 0, received %d.", len(args))
+			return err
+		}
+	} else {
+		// check that at least one parameter is passed in
+		if len(args) == 0 {
+			err = errors.ErrorWithCallstack("Logging", "NoParameters", "No parameters provided.")
+			return err
+		}
 	}
 
 	if cmd.Name() == "setlevel" {

peer/clilogging/logging.go

@@ -32,6 +32,7 @@ var logger = logging.MustGetLogger("loggingCmd")
 func Cmd() *cobra.Command {
 	loggingCmd.AddCommand(getLevelCmd())
 	loggingCmd.AddCommand(setLevelCmd())
+	loggingCmd.AddCommand(revertLevelsCmd())
 
 	return loggingCmd
 }

peer/clilogging/logging_test.go

@@ -39,7 +39,7 @@ func TestGetLevel(t *testing.T) {
 	err := checkLoggingCmdParams(getLevelCmd(), args)
 
 	if err != nil {
-		t.FailNow()
+		t.Fatal(err)
 	}
 }
 
@@ -93,6 +93,31 @@ func TestSetLevel(t *testing.T) {
 	err := checkLoggingCmdParams(setLevelCmd(), args)
 
 	if err != nil {
+		t.Fatal(err)
+	}
+}
+
+// TestRevertLevels tests the parameter checking for revertlevels, which
+// should return a nil error when zero parameters are provided
+func TestRevertLevels(t *testing.T) {
+	var args []string
+
+	err := checkLoggingCmdParams(revertLevelsCmd(), args)
+
+	if err != nil {
+		t.Fatal(err)
+	}
+}
+
+// TestRevertLevels_extraParameter tests the parameter checking for setlevel, which
+// should return an error when any amount of parameters are provided
+func TestRevertLevels_extraParameter(t *testing.T) {
+	args := make([]string, 1)
+	args[0] = "extraparameter"
+
+	err := checkLoggingCmdParams(revertLevelsCmd(), args)
+
+	if err == nil {
 		t.FailNow()
 	}
 }

peer/clilogging/revertlevels.go

@@ -0,0 +1,62 @@
+/*
+Copyright IBM Corp. 2017 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 clilogging
+
+import (
+	"golang.org/x/net/context"
+
+	"github.com/golang/protobuf/ptypes/empty"
+	"github.com/hyperledger/fabric/peer/common"
+
+	"github.com/spf13/cobra"
+)
+
+func revertLevelsCmd() *cobra.Command {
+	return loggingRevertLevelsCmd
+}
+
+var loggingRevertLevelsCmd = &cobra.Command{
+	Use:   "revertlevels",
+	Short: "Reverts the logging levels to the levels at the end of peer startup.",
+	Long:  `Reverts the logging levels to the levels at the end of peer startup`,
+	Run: func(cmd *cobra.Command, args []string) {
+		revertLevels(cmd, args)
+	},
+}
+
+func revertLevels(cmd *cobra.Command, args []string) (err error) {
+	err = checkLoggingCmdParams(cmd, args)
+
+	if err != nil {
+		logger.Warningf("Error: %s", err)
+	} else {
+		adminClient, err := common.GetAdminClient()
+		if err != nil {
+			logger.Warningf("%s", err)
+			return err
+		}
+
+		_, err = adminClient.RevertLogLevels(context.Background(), &empty.Empty{})
+
+		if err != nil {
+			logger.Warningf("%s", err)
+			return err
+		}
+		logger.Info("Log levels reverted to the levels at the end of peer startup.")
+	}
+	return err
+}

peer/node/start.go

@@ -30,6 +30,7 @@ import (
 
 	genesisconfig "github.com/hyperledger/fabric/common/configtx/tool/localconfig"
 	"github.com/hyperledger/fabric/common/configtx/tool/provisional"
+	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/hyperledger/fabric/common/localmsp"
 	"github.com/hyperledger/fabric/common/util"
 	"github.com/hyperledger/fabric/core"
@@ -264,6 +265,13 @@ func serve(args []string) error {
 	common.SetLogLevelFromViper("error")
 	common.SetLogLevelFromViper("msp")
 
+	// TODO This check is here to preserve the old functionality until all
+	// other packages switch to `flogging.MustGetLogger` (from
+	// `logging.MustGetLogger`).
+	if flogging.IsSetLevelByRegExpEnabled {
+		flogging.SetPeerStartupModulesMap()
+	}
+
 	// Block until grpc server exits
 	return <-serve
 }