Merge "[FAB-3232] Fix chaincode container logging"

core/chaincode/chaincode_support.go

@@ -185,18 +185,25 @@ func NewChaincodeSupport(getPeerEndpoint func() (*pb.PeerEndpoint, error), userr
 	replacer := strings.NewReplacer(".", "_")
 	viper.SetEnvKeyReplacer(replacer)
 
-	chaincodeLogLevelString := viper.GetString("chaincode.logLevel")
-	chaincodeLogLevel, err := logging.LogLevel(chaincodeLogLevelString)
+	theChaincodeSupport.chaincodeLogLevel = getLogLevelFromViper("level")
+	theChaincodeSupport.shimLogLevel = getLogLevelFromViper("shim")
+	theChaincodeSupport.logFormat = viper.GetString("chaincode.logging.format")
+
+	return theChaincodeSupport
+}
+
+// getLogLevelFromViper gets the chaincode container log levels from viper
+func getLogLevelFromViper(module string) string {
+	levelString := viper.GetString("chaincode.logging." + module)
+	_, err := logging.LogLevel(levelString)
 
 	if err == nil {
-		theChaincodeSupport.chaincodeLogLevel = chaincodeLogLevel.String()
+		chaincodeLogger.Debugf("CORE_CHAINCODE_%s set to level %s", strings.ToUpper(module), levelString)
 	} else {
-		chaincodeLogger.Warningf("Chaincode logging level %s is invalid; defaulting to %s", chaincodeLogLevelString, flogging.DefaultLevel())
-		theChaincodeSupport.chaincodeLogLevel = flogging.DefaultLevel()
+		chaincodeLogger.Warningf("CORE_CHAINCODE_%s has invalid log level %s. defaulting to %s", strings.ToUpper(module), levelString, flogging.DefaultLevel())
+		levelString = flogging.DefaultLevel()
 	}
-	theChaincodeSupport.logFormat = viper.GetString("chaincode.logFormat")
-
-	return theChaincodeSupport
+	return levelString
 }
 
 // // ChaincodeStream standard stream for ChaincodeMessage type.
@@ -219,6 +226,7 @@ type ChaincodeSupport struct {
 	peerTLSSvrHostOrd string
 	keepalive         time.Duration
 	chaincodeLogLevel string
+	shimLogLevel      string
 	logFormat         string
 	executetimeout    time.Duration
 }
@@ -360,11 +368,15 @@ func (chaincodeSupport *ChaincodeSupport) getArgsAndEnv(cccid *ccprovider.CCCont
 	}
 
 	if chaincodeSupport.chaincodeLogLevel != "" {
-		envs = append(envs, "CORE_CHAINCODE_LOGLEVEL="+chaincodeSupport.chaincodeLogLevel)
+		envs = append(envs, "CORE_CHAINCODE_LOGGING_LEVEL="+chaincodeSupport.chaincodeLogLevel)
+	}
+
+	if chaincodeSupport.shimLogLevel != "" {
+		envs = append(envs, "CORE_CHAINCODE_LOGGING_SHIM="+chaincodeSupport.shimLogLevel)
 	}
 
 	if chaincodeSupport.logFormat != "" {
-		envs = append(envs, "CORE_CHAINCODE_LOGFORMAT="+chaincodeSupport.logFormat)
+		envs = append(envs, "CORE_CHAINCODE_LOGGING_FORMAT="+chaincodeSupport.logFormat)
 	}
 	switch cLang {
 	case pb.ChaincodeSpec_GOLANG, pb.ChaincodeSpec_CAR:

core/chaincode/chaincodetest.yaml

@@ -407,7 +407,14 @@ chaincode:
         escc: enable
         vscc: enable
 
-    logLevel: debug
+    # Logging section for the chaincode container
+    logging:
+      # Default level for all loggers within the chaincode container
+      level:  info
+      # Override default level for the 'shim' module
+      shim:   warning
+      # Format for the chaincode container logs
+      format: '%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message}'
 
 ###############################################################################
 #

core/chaincode/shim/chaincode.go

@@ -133,22 +133,38 @@ func SetupChaincodeLogging() {
 	viper.SetEnvKeyReplacer(replacer)
 
 	// setup system-wide logging backend
-	logFormat := flogging.SetFormat(viper.GetString("chaincode.logFormat"))
+	logFormat := flogging.SetFormat(viper.GetString("chaincode.logging.format"))
 	flogging.InitBackend(logFormat, logOutput)
 
-	chaincodeLogLevelString := viper.GetString("chaincode.logLevel")
+	// set default log level for all modules
+	chaincodeLogLevelString := viper.GetString("chaincode.logging.level")
 	if chaincodeLogLevelString == "" {
-		shimLogLevelDefault := logging.Level(shimLoggingLevel)
-		chaincodeLogger.Infof("Chaincode log level not provided; defaulting to: %s", shimLogLevelDefault)
-		SetLoggingLevel(shimLoggingLevel)
+		chaincodeLogger.Infof("Chaincode log level not provided; defaulting to: %s", flogging.DefaultLevel())
+		flogging.InitFromSpec(flogging.DefaultLevel())
 	} else {
-		chaincodeLogLevel, err := LogLevel(chaincodeLogLevelString)
+		_, err := LogLevel(chaincodeLogLevelString)
 		if err == nil {
-			SetLoggingLevel(chaincodeLogLevel)
+			flogging.InitFromSpec(chaincodeLogLevelString)
 		} else {
-			chaincodeLogger.Warningf("Error: %s for chaincode log level: %s", err, chaincodeLogLevelString)
+			chaincodeLogger.Warningf("Error: '%s' for chaincode log level: %s; defaulting to %s", err, chaincodeLogLevelString, flogging.DefaultLevel())
+			flogging.InitFromSpec(flogging.DefaultLevel())
 		}
 	}
+
+	// override the log level for the shim logging module - note: if this value is
+	// blank or an invalid log level, then the above call to
+	// `flogging.InitFromSpec` already set the default log level so no action
+	// is required here.
+	shimLogLevelString := viper.GetString("chaincode.logging.shim")
+	if shimLogLevelString != "" {
+		shimLogLevel, err := LogLevel(shimLogLevelString)
+		if err == nil {
+			SetLoggingLevel(shimLogLevel)
+		} else {
+			chaincodeLogger.Warningf("Error: %s for shim log level: %s", err, shimLogLevelString)
+		}
+	}
+
 	//now that logging is setup, print build level. This will help making sure
 	//chaincode is matched with peer.
 	buildLevel := viper.GetString("chaincode.buildlevel")

core/chaincode/shim/mockstub_test.go

@@ -22,6 +22,7 @@ import (
 	"reflect"
 	"testing"
 
+	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/spf13/viper"
 )
 
@@ -88,12 +89,12 @@ func TestSetupChaincodeLogging_blankLevel(t *testing.T) {
 	testLogLevelString := ""
 	testLogFormat := "%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message}"
 
-	viper.Set("chaincode.logLevel", testLogLevelString)
-	viper.Set("chaincode.logFormat", testLogFormat)
+	viper.Set("chaincode.logging.level", testLogLevelString)
+	viper.Set("chaincode.logging.format", testLogFormat)
 
 	SetupChaincodeLogging()
 
-	if !IsEnabledForLogLevel("info") {
+	if !IsEnabledForLogLevel(flogging.DefaultLevel()) {
 		t.FailNow()
 	}
 }
@@ -102,15 +103,17 @@ func TestSetupChaincodeLogging_blankLevel(t *testing.T) {
 // set the chaincodeLogger's logging format and level
 func TestSetupChaincodeLogging(t *testing.T) {
 	// set log level to a non-default level
-	testLogLevelString := "debug"
+	testLogLevel := "debug"
+	testShimLogLevel := "warning"
 	testLogFormat := "%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message}"
 
-	viper.Set("chaincode.logLevel", testLogLevelString)
-	viper.Set("chaincode.logFormat", testLogFormat)
+	viper.Set("chaincode.logging.level", testLogLevel)
+	viper.Set("chaincode.logging.format", testLogFormat)
+	viper.Set("chaincode.logging.shim", testShimLogLevel)
 
 	SetupChaincodeLogging()
 
-	if !IsEnabledForLogLevel(testLogLevelString) {
+	if !IsEnabledForLogLevel(testShimLogLevel) {
 		t.FailNow()
 	}
 }

core/chaincode/shim/shim_test.go

@@ -18,9 +18,13 @@ package shim
 
 import (
 	"os"
+	"strings"
 	"testing"
 
+	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/op/go-logging"
+	"github.com/spf13/viper"
+	"github.com/stretchr/testify/assert"
 )
 
 // Test Go shim functionality that can be tested outside of a real chaincode
@@ -142,3 +146,51 @@ func TestNilEventName(t *testing.T) {
 	}
 
 }
+
+type testCase struct {
+	name         string
+	ccLogLevel   string
+	shimLogLevel string
+}
+
+func TestSetupChaincodeLogging_shim(t *testing.T) {
+	var tc []testCase
+
+	tc = append(tc,
+		testCase{"ValidLevels", "debug", "warning"},
+		testCase{"EmptyLevels", "", ""},
+		testCase{"BadShimLevel", "debug", "war"},
+		testCase{"BadCCLevel", "deb", "notice"},
+		testCase{"EmptyShimLevel", "error", ""},
+		testCase{"EmptyCCLevel", "", "critical"},
+	)
+
+	assert := assert.New(t)
+
+	for i := 0; i < len(tc); i++ {
+		t.Run(tc[i].name, func(t *testing.T) {
+			viper.Set("chaincode.logging.level", tc[i].ccLogLevel)
+			viper.Set("chaincode.logging.shim", tc[i].shimLogLevel)
+
+			SetupChaincodeLogging()
+
+			_, ccErr := logging.LogLevel(tc[i].ccLogLevel)
+			_, shimErr := logging.LogLevel(tc[i].shimLogLevel)
+			if ccErr == nil {
+				assert.Equal(strings.ToUpper(tc[i].ccLogLevel), flogging.GetModuleLevel("ccLogger"), "Test case '%s' failed", tc[i].name)
+				if shimErr == nil {
+					assert.Equal(strings.ToUpper(tc[i].shimLogLevel), flogging.GetModuleLevel("shim"), "Test case '%s' failed", tc[i].name)
+				} else {
+					assert.Equal(strings.ToUpper(tc[i].ccLogLevel), flogging.GetModuleLevel("shim"), "Test case '%s' failed", tc[i].name)
+				}
+			} else {
+				assert.Equal(flogging.DefaultLevel(), flogging.GetModuleLevel("ccLogger"), "Test case '%s' failed", tc[i].name)
+				if shimErr == nil {
+					assert.Equal(strings.ToUpper(tc[i].shimLogLevel), flogging.GetModuleLevel("shim"), "Test case '%s' failed", tc[i].name)
+				} else {
+					assert.Equal(flogging.DefaultLevel(), flogging.GetModuleLevel("shim"), "Test case '%s' failed", tc[i].name)
+				}
+			}
+		})
+	}
+}

sampleconfig/core.yaml

@@ -30,9 +30,10 @@ logging:
     gossip:     warning
     ledger:     info
     msp:        warning
-    policies:     warning
+    policies:   warning
     grpc:       error
 
+    # Format for the peer logs
     format: '%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message}'
 
 ###############################################################################
@@ -332,9 +333,14 @@ chaincode:
         vscc: enable
         qscc: enable
 
-    # logging section for the chaincode container
-    logLevel: warning
-    logFormat: '%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message}'
+    # Logging section for the chaincode container
+    logging:
+      # Default level for all loggers within the chaincode container
+      level:  info
+      # Override default level for the 'shim' module
+      shim:   warning
+      # Format for the chaincode container logs
+      format: '%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message}'
 
 ###############################################################################
 #