[FAB-2351] Update loggers to flogging.MustGetLogger

This CR updates all loggers throughout the code base to use
`flogging.MustGetLogger`. This function wraps `logging.MustGetLogger`
and tracks the logger modules defined in the system. This enables the
ability to set log levels for modules using regular expressions.
and make it easy to change the levels for any module and all its
submodules with a single command (e.g. gossip, ledger, msp).

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

bccsp/factory/factory.go

@@ -20,7 +20,7 @@ import (
 	"sync"
 
 	"github.com/hyperledger/fabric/bccsp"
-	"github.com/op/go-logging"
+	"github.com/hyperledger/fabric/common/flogging"
 )
 
 var (
@@ -41,7 +41,7 @@ var (
 	// Factories' Initialization Error
 	factoriesInitError error
 
-	logger = logging.MustGetLogger("bccsp")
+	logger = flogging.MustGetLogger("bccsp")
 )
 
 // BCCSPFactory is used to get instances of the BCCSP interface.

bccsp/pkcs11/impl.go

@@ -32,13 +32,14 @@ import (
 
 	"github.com/hyperledger/fabric/bccsp"
 	"github.com/hyperledger/fabric/bccsp/utils"
+	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/miekg/pkcs11"
-	"github.com/op/go-logging"
+
 	"golang.org/x/crypto/sha3"
 )
 
 var (
-	logger           = logging.MustGetLogger("bccsp_p11")
+	logger           = flogging.MustGetLogger("bccsp_p11")
 	sessionCacheSize = 10
 )
 

bccsp/sw/impl.go

@@ -36,12 +36,12 @@ import (
 
 	"github.com/hyperledger/fabric/bccsp"
 	"github.com/hyperledger/fabric/bccsp/utils"
-	"github.com/op/go-logging"
+	"github.com/hyperledger/fabric/common/flogging"
 	"golang.org/x/crypto/sha3"
 )
 
 var (
-	logger = logging.MustGetLogger("bccsp_sw")
+	logger = flogging.MustGetLogger("bccsp_sw")
 )
 
 // NewDefaultSecurityLevel returns a new instance of the software-based BCCSP

common/cauthdsl/cauthdsl.go

@@ -19,13 +19,13 @@ package cauthdsl
 import (
 	"fmt"
 
+	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/hyperledger/fabric/msp"
 	cb "github.com/hyperledger/fabric/protos/common"
 	mb "github.com/hyperledger/fabric/protos/msp"
-	"github.com/op/go-logging"
 )
 
-var cauthdslLogger = logging.MustGetLogger("cauthdsl")
+var cauthdslLogger = flogging.MustGetLogger("cauthdsl")
 
 // compile recursively builds a go evaluatable function corresponding to the policy specified
 func compile(policy *cb.SignaturePolicy, identities []*mb.MSPPrincipal, deserializer msp.IdentityDeserializer) (func([]*cb.SignedData, []bool) bool, error) {

common/config/msp/config_util.go

@@ -23,10 +23,10 @@ import (
 	mspprotos "github.com/hyperledger/fabric/protos/msp"
 	"github.com/hyperledger/fabric/protos/utils"
 
-	logging "github.com/op/go-logging"
+	"github.com/hyperledger/fabric/common/flogging"
 )
 
-var logger = logging.MustGetLogger("configvalues/msp")
+var logger = flogging.MustGetLogger("configvalues/msp")
 
 const (
 	// ReadersPolicyKey is the key used for the read policy

common/config/proposer.go

@@ -21,10 +21,10 @@ import (
 	"sync"
 
 	"github.com/golang/protobuf/proto"
-	logging "github.com/op/go-logging"
+	"github.com/hyperledger/fabric/common/flogging"
 )
 
-var logger = logging.MustGetLogger("common/config")
+var logger = flogging.MustGetLogger("common/config")
 
 // ValueDeserializer provides a mechanism to retrieve proto messages to deserialize config values into
 type ValueDeserializer interface {

common/configtx/manager.go

@@ -22,13 +22,12 @@ import (
 	"regexp"
 
 	"github.com/hyperledger/fabric/common/configtx/api"
+	"github.com/hyperledger/fabric/common/flogging"
 	cb "github.com/hyperledger/fabric/protos/common"
 	"github.com/hyperledger/fabric/protos/utils"
-
-	logging "github.com/op/go-logging"
 )
 
-var logger = logging.MustGetLogger("common/configtx")
+var logger = flogging.MustGetLogger("common/configtx")
 
 // Constraints for valid chain IDs
 var (

common/configtx/test/helper.go

@@ -25,15 +25,14 @@ import (
 	"github.com/hyperledger/fabric/common/configtx"
 	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/genesis"
 	"github.com/hyperledger/fabric/msp"
 	cb "github.com/hyperledger/fabric/protos/common"
 	mspproto "github.com/hyperledger/fabric/protos/msp"
-
-	logging "github.com/op/go-logging"
 )
 
-var logger = logging.MustGetLogger("common/configtx/test")
+var logger = flogging.MustGetLogger("common/configtx/test")
 
 const (
 	// AcceptAllPolicyKey is the key of the AcceptAllPolicy.

common/configtx/tool/configtxgen/main.go

@@ -27,6 +27,7 @@ import (
 	"github.com/hyperledger/fabric/common/configtx"
 	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/msp"
 	cb "github.com/hyperledger/fabric/protos/common"
 	"github.com/hyperledger/fabric/protos/utils"
@@ -35,7 +36,7 @@ import (
 	logging "github.com/op/go-logging"
 )
 
-var logger = logging.MustGetLogger("common/configtx/tool")
+var logger = flogging.MustGetLogger("common/configtx/tool")
 
 func doOutputBlock(pgen provisional.Generator, channelID string, outputBlock string) error {
 	logger.Info("Generating genesis block")

common/configtx/tool/localconfig/config.go

@@ -23,15 +23,15 @@ import (
 	"strings"
 	"time"
 
+	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/hyperledger/fabric/common/viperutil"
 
-	"github.com/op/go-logging"
 	"github.com/spf13/viper"
 
 	bccsp "github.com/hyperledger/fabric/bccsp/factory"
 )
 
-var logger = logging.MustGetLogger("configtx/tool/localconfig")
+var logger = flogging.MustGetLogger("configtx/tool/localconfig")
 
 const (
 	// SampleInsecureProfile references the sample profile which does not include any MSPs and uses solo for ordering.

common/configtx/tool/provisional/provisional.go

@@ -26,18 +26,17 @@ import (
 	configvaluesmsp "github.com/hyperledger/fabric/common/config/msp"
 	"github.com/hyperledger/fabric/common/configtx"
 	genesisconfig "github.com/hyperledger/fabric/common/configtx/tool/localconfig"
+	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/hyperledger/fabric/common/genesis"
 	"github.com/hyperledger/fabric/common/policies"
 	"github.com/hyperledger/fabric/msp"
 	"github.com/hyperledger/fabric/orderer/common/bootstrap"
 	cb "github.com/hyperledger/fabric/protos/common"
 	ab "github.com/hyperledger/fabric/protos/orderer"
 	pb "github.com/hyperledger/fabric/protos/peer"
-
-	logging "github.com/op/go-logging"
 )
 
-var logger = logging.MustGetLogger("common/configtx/tool/provisional")
+var logger = flogging.MustGetLogger("common/configtx/tool/provisional")
 
 // Generator can either create an orderer genesis block or config template
 type Generator interface {

common/flogging/logging.go

@@ -42,12 +42,6 @@ var (
 
 	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.
-	// TODO Remove once all other packages have switched to
-	// `flogging.MustGetLogger` from `logging.MustGetLogger`.
-	IsSetLevelByRegExpEnabled bool
 )
 
 func init() {
@@ -57,7 +51,6 @@ func init() {
 
 // Reset sets to logging to the defaults defined in this package.
 func Reset() {
-	IsSetLevelByRegExpEnabled = false // redundant since the default for booleans is `false` but added for clarity
 	modules = make(map[string]string)
 	lock = sync.RWMutex{}
 
@@ -101,29 +94,29 @@ 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) {
-	return setModuleLevel(moduleRegExp, level, false)
+	// special case - `error` module, which is used to enable/disable callstacks
+	// in error messages, shouldn't use regular expressions
+	if moduleRegExp == "error" {
+		return setModuleLevel(moduleRegExp, level, false, false)
+	}
+	return setModuleLevel(moduleRegExp, level, true, false)
 }
 
-func setModuleLevel(moduleRegExp string, level string, revert bool) (string, error) {
-
+func setModuleLevel(moduleRegExp string, level string, isRegExp bool, 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 || revert {
-			logging.SetLevel(logging.Level(logLevel), moduleRegExp)
-			logger.Debugf("Module '%s' logger enabled for log level '%s'", moduleRegExp, logLevel)
+		if !isRegExp || revert {
+			logging.SetLevel(logLevel, moduleRegExp)
+			logger.Debugf("Module '%s' logger enabled for log level '%s'", moduleRegExp, level)
 		} else {
 			re, err = regexp.Compile(moduleRegExp)
 			if err != nil {
 				logger.Warningf("Invalid regular expression: %s", moduleRegExp)
 				return "", err
 			}
-
 			lock.Lock()
 			defer lock.Unlock()
 			for module := range modules {
@@ -190,6 +183,15 @@ func InitFromSpec(spec string) string {
 	}
 
 	logging.SetLevel(levelAll, "") // set the logging level for all modules
+
+	// iterate through modules to reload their level in the modules map based on
+	// the new default level
+	for k := range modules {
+		MustGetLogger(k)
+	}
+	// register flogging logger in the modules map
+	MustGetLogger(pkgLogID)
+
 	return levelAll.String()
 }
 
@@ -226,10 +228,11 @@ func RevertToPeerStartupLevels() error {
 	lock.RLock()
 	defer lock.RUnlock()
 	for key := range peerStartModules {
-		_, err := setModuleLevel(key, peerStartModules[key], true)
+		_, err := setModuleLevel(key, peerStartModules[key], false, true)
 		if err != nil {
 			return err
 		}
 	}
+	logger.Info("Log levels reverted to the levels defined at the end of peer startup")
 	return nil
 }

common/flogging/logging_test.go

@@ -32,7 +32,6 @@ type testCase struct {
 	args           []string
 	expectedLevels []string
 	modules        []string
-	withRegEx      bool
 	revert         bool
 	shouldErr      bool
 }
@@ -47,38 +46,37 @@ func TestSetModuleLevel(t *testing.T) {
 	var tc []testCase
 
 	tc = append(tc,
-		testCase{"Valid", []string{"a", "warning"}, []string{"WARNING"}, []string{"a"}, false, false, false},
+		testCase{"Valid", []string{"a", "warning"}, []string{"WARNING"}, []string{"a"}, false, false},
 		// Same as before
-		testCase{"Invalid", []string{"a", "foo"}, []string{"WARNING"}, []string{"a"}, false, false, false},
+		testCase{"Invalid", []string{"a", "foo"}, []string{flogging.DefaultLevel()}, []string{"a"}, false, false},
+		// Test setting the "error" module
+		testCase{"Error", []string{"error", "warning"}, []string{"WARNING"}, []string{"error"}, false, false},
 		// Tests with regular expressions
 		testCase{"RegexModuleWithSubmodule", []string{"foo", "warning"}, []string{"WARNING", "WARNING", flogging.DefaultLevel()},
-			[]string{"foo", "foo/bar", "baz"}, true, false, false},
+			[]string{"foo", "foo/bar", "baz"}, 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, false},
+			[]string{"foo", "foo/bar", "baz", "random"}, 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, false},
+			[]string{"foo/bar", "bar/baz"}, 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, false},
+			[]string{"gossip/util", "orderer/util", "gossip/gossip#0.0.0.0:7051", "gossip/conn#-1", "orderer/conn#0.0.0.0:7051"}, false, false},
 		testCase{"RegexInvalid", []string{"(", "warning"}, []string{flogging.DefaultLevel()},
-			[]string{"foo"}, true, false, true},
+			[]string{"foo"}, false, true},
 		testCase{"RevertLevels", []string{"revertmodule1", "warning", "revertmodule2", "debug"}, []string{"WARNING", "DEBUG", "DEBUG"},
-			[]string{"revertmodule1", "revertmodule2", "revertmodule2/submodule"}, true, true, false},
+			[]string{"revertmodule1", "revertmodule2", "revertmodule2/submodule"}, true, false},
 	)
 
 	assert := assert.New(t)
 
 	for i := 0; i < len(tc); i++ {
 		t.Run(tc[i].name, func(t *testing.T) {
-			if tc[i].withRegEx {
-				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
+			for j := 0; j < len(tc[i].modules); j++ {
+				flogging.MustGetLogger(tc[i].modules[j])
+			}
+			if tc[i].revert {
+				flogging.SetPeerStartupModulesMap()
 			}
 			for k := 0; k < len(tc[i].args); k = k + 2 {
 				_, err := flogging.SetModuleLevel(tc[i].args[k], tc[i].args[k+1])
@@ -95,11 +93,7 @@ func TestSetModuleLevel(t *testing.T) {
 					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()
-			}
+			flogging.Reset()
 		})
 	}
 }
@@ -130,25 +124,25 @@ func TestInitFromSpec(t *testing.T) {
 	// MODULES
 
 	tc = append(tc,
-		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},
+		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},
 	)
 
 	// MODULES + DEFAULT
 
 	tc = append(tc,
-		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},
+		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},
 	)
 
 	// INVALID INPUT
 
 	tc = append(tc,
-		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},
+		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},
 	)
 
 	assert := assert.New(t)
@@ -173,7 +167,7 @@ func ExampleInitBackend() {
 	formatSpec := "%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x} %{message}"
 	flogging.InitBackend(flogging.SetFormat(formatSpec), os.Stdout)
 
-	logger := logging.MustGetLogger("testModule")
+	logger := flogging.MustGetLogger("testModule")
 	logger.Info("test output")
 
 	// Output: