[FAB-3232] Fix chaincode container logging

This CR fixes the logging setup for chaincode containers. Previously, the code would only set the level for the 'shim' module and all other loggers in the scope of the container would use the default. With this change in place, CORE_CHAINCODE_LOGGING_LEVEL can be used to set the default logging level for all modules within a chaincode container and CORE_CHAINCODE_LOGGING_SHIM can be used to override the level for the 'shim' logging module. Change-Id: I019fd3995e2af25a170d751628293fb215a748bf Signed-off-by: Will Lahti <wtlahti@us.ibm.com>
hyperledger · May 5, 2017 · bd861de · bd861de
1 parent 58f33ec
commit bd861de
Show file tree

Hide file tree

Showing 6 changed files with 126 additions and 30 deletions.
diff --git a/core/chaincode/chaincode_support.go b/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:

diff --git a/core/chaincode/chaincodetest.yaml b/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}'
 
 ###############################################################################
 #

diff --git a/core/chaincode/shim/chaincode.go b/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")

diff --git a/core/chaincode/shim/mockstub_test.go b/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()
 	}
 }

diff --git a/core/chaincode/shim/shim_test.go b/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)
+				}
+			}
+		})
+	}
+}
diff --git a/sampleconfig/core.yaml b/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}'
 
 ###############################################################################
 #