Add ability to customize chaincode container log format

This change adds a parameter to core.yaml called "chaincode.logFormat"
which can be used to set the log format for chaincode containers. It
also replaces "logging.chaincode" with a new parameter called
"chaincode.logLevel" to keep the chaincode logging parameters grouped
together.

https://jira.hyperledger.org/browse/FAB-1936

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

Author: wlahti

core/chaincode/chaincode_support.go

@@ -173,7 +173,7 @@ func NewChaincodeSupport(getPeerEndpoint func() (*pb.PeerEndpoint, error), userr
 	replacer := strings.NewReplacer(".", "_")
 	viper.SetEnvKeyReplacer(replacer)
 
-	chaincodeLogLevelString := viper.GetString("logging.chaincode")
+	chaincodeLogLevelString := viper.GetString("chaincode.logLevel")
 	chaincodeLogLevel, err := logging.LogLevel(chaincodeLogLevelString)
 
 	if err == nil {
@@ -182,6 +182,7 @@ func NewChaincodeSupport(getPeerEndpoint func() (*pb.PeerEndpoint, error), userr
 		chaincodeLogger.Warningf("Chaincode logging level %s is invalid; defaulting to %s", chaincodeLogLevelString, flogging.DefaultLevel().String())
 		theChaincodeSupport.chaincodeLogLevel = flogging.DefaultLevel().String()
 	}
+	theChaincodeSupport.logFormat = viper.GetString("chaincode.logFormat")
 
 	return theChaincodeSupport
 }
@@ -206,6 +207,7 @@ type ChaincodeSupport struct {
 	peerTLSSvrHostOrd string
 	keepalive         time.Duration
 	chaincodeLogLevel string
+	logFormat         string
 }
 
 // DuplicateChaincodeHandlerError returned if attempt to register same chaincodeID while a stream already exists.
@@ -345,7 +347,11 @@ func (chaincodeSupport *ChaincodeSupport) getArgsAndEnv(cccid *ccprovider.CCCont
 	}
 
 	if chaincodeSupport.chaincodeLogLevel != "" {
-		envs = append(envs, "CORE_LOGGING_CHAINCODE="+chaincodeSupport.chaincodeLogLevel)
+		envs = append(envs, "CORE_CHAINCODE_LOGLEVEL="+chaincodeSupport.chaincodeLogLevel)
+	}
+
+	if chaincodeSupport.logFormat != "" {
+		envs = append(envs, "CORE_CHAINCODE_LOGFORMAT="+chaincodeSupport.logFormat)
 	}
 	switch cLang {
 	case pb.ChaincodeSpec_GOLANG, pb.ChaincodeSpec_CAR:

core/chaincode/shim/chaincode.go

@@ -30,6 +30,7 @@ import (
 	"github.com/golang/protobuf/proto"
 	"github.com/golang/protobuf/ptypes/timestamp"
 	"github.com/hyperledger/fabric/bccsp/factory"
+	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/hyperledger/fabric/core/comm"
 	pb "github.com/hyperledger/fabric/protos/peer"
 	"github.com/hyperledger/fabric/protos/utils"
@@ -41,6 +42,7 @@ import (
 
 // Logger for the shim package.
 var chaincodeLogger = logging.MustGetLogger("shim")
+var logOutput = os.Stderr
 
 const (
 	minUnicodeRuneValue = 0            //U+0000
@@ -70,12 +72,7 @@ var peerAddress string
 func Start(cc Chaincode) error {
 	// If Start() is called, we assume this is a standalone chaincode and set
 	// up formatted logging.
-	format := logging.MustStringFormatter("%{time:15:04:05.000} [%{module}] %{level:.4s} : %{message}")
-	backend := logging.NewLogBackend(os.Stderr, "", 0)
-	backendFormatter := logging.NewBackendFormatter(backend, format)
-	logging.SetBackend(backendFormatter).SetLevel(logging.Level(shimLoggingLevel), "shim")
-
-	SetChaincodeLoggingLevel()
+	SetupChaincodeLogging()
 
 	err := factory.InitFactories(&factory.DefaultOpts)
 	if err != nil {
@@ -121,18 +118,23 @@ func IsEnabledForLogLevel(logLevel string) bool {
 	return chaincodeLogger.IsEnabledFor(lvl)
 }
 
-// SetChaincodeLoggingLevel sets the chaincode logging level to the value
-// of CORE_LOGGING_CHAINCODE set from core.yaml by chaincode_support.go
-func SetChaincodeLoggingLevel() {
+// SetupChaincodeLogging sets the chaincode logging format and the level
+// to the values of CORE_CHAINCODE_LOGFORMAT and CORE_CHAINCODE_LOGLEVEL set
+// from core.yaml by chaincode_support.go
+func SetupChaincodeLogging() {
 	viper.SetEnvPrefix("CORE")
 	viper.AutomaticEnv()
 	replacer := strings.NewReplacer(".", "_")
 	viper.SetEnvKeyReplacer(replacer)
 
-	chaincodeLogLevelString := viper.GetString("logging.chaincode")
+	logFormat := viper.GetString("chaincode.logFormat")
+	flogging.SetLoggingFormat(logFormat, logOutput)
+
+	chaincodeLogLevelString := viper.GetString("chaincode.logLevel")
 	if chaincodeLogLevelString == "" {
 		shimLogLevelDefault := logging.Level(shimLoggingLevel)
 		chaincodeLogger.Infof("Chaincode log level not provided; defaulting to: %s", shimLogLevelDefault)
+		SetLoggingLevel(shimLoggingLevel)
 	} else {
 		chaincodeLogLevel, err := LogLevel(chaincodeLogLevelString)
 		if err == nil {
@@ -620,7 +622,7 @@ const (
 	LogCritical = LoggingLevel(logging.CRITICAL)
 )
 
-var shimLoggingLevel = LogDebug // Necessary for correct initialization; See Start()
+var shimLoggingLevel = LogInfo // Necessary for correct initialization; See Start()
 
 // SetLoggingLevel allows a Go language chaincode to set the logging level of
 // its shim.

core/chaincode/shim/mockstub_test.go

@@ -81,14 +81,34 @@ func TestMockStateRangeQueryIterator_openEnded(t *testing.T) {
 	}
 }
 
-// TestSetChaincodeLoggingLevel uses the utlity function defined in chaincode.go to
-// set the chaincodeLogger's logging level
-func TestSetChaincodeLoggingLevel(t *testing.T) {
+// TestSetupChaincodeLogging uses the utlity function defined in chaincode.go to
+// set the chaincodeLogger's logging format and level
+func TestSetupChaincodeLogging_blankLevel(t *testing.T) {
+	// set log level to a non-default level
+	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)
+
+	SetupChaincodeLogging()
+
+	if !IsEnabledForLogLevel("info") {
+		t.FailNow()
+	}
+}
+
+// TestSetupChaincodeLogging uses the utlity function defined in chaincode.go to
+// set the chaincodeLogger's logging format and level
+func TestSetupChaincodeLogging(t *testing.T) {
 	// set log level to a non-default level
 	testLogLevelString := "debug"
-	viper.Set("logging.chaincode", 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)
 
-	SetChaincodeLoggingLevel()
+	SetupChaincodeLogging()
 
 	if !IsEnabledForLogLevel(testLogLevelString) {
 		t.FailNow()

peer/core.yaml

@@ -32,7 +32,6 @@ logging:
     peer:       warning
     node:       info
     network:    warning
-    chaincode:  warning
     version:    warning
     protoutils: debug
     error:      warning
@@ -336,6 +335,10 @@ 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}'
+
 ###############################################################################
 #
 #    Ledger section - ledger configuration encompases both the blockchain