[FAB-12303] info logging for chaincode invokes (ms)

Force the newly added chaincode info log statements to log duration in milliseconds, so that a consistent unit is used in all the log messages for easier log parsing. Change-Id: I65bc418850005a87602340aeaedb47aac1fb2665 Signed-off-by: David Enyeart <enyeart@us.ibm.com>
hyperledger · Oct 8, 2018 · bcc924d · bcc924d
1 parent 389949d
commit bcc924d
Show file tree

Hide file tree

Showing 2 changed files with 3 additions and 2 deletions.
diff --git a/core/endorser/endorser.go b/core/endorser/endorser.go
@@ -130,7 +130,8 @@ func (e *Endorser) callChaincode(txParams *ccprovider.TransactionParams, version
 	endorserLogger.Infof("[%s][%s] Entry chaincode: %s", txParams.ChannelID, shorttxid(txParams.TxID), cid)
 	defer func(start time.Time) {
 		logger := endorserLogger.WithOptions(zap.AddCallerSkip(1))
-		logger.Infof("[%s][%s] Exit chaincode: %s (%s)", txParams.ChannelID, shorttxid(txParams.TxID), cid, time.Since(start))
+		elapsedMilliseconds := time.Since(start).Round(time.Millisecond) / time.Millisecond
+		logger.Infof("[%s][%s] Exit chaincode: %s (%dms)", txParams.ChannelID, shorttxid(txParams.TxID), cid, elapsedMilliseconds)
 	}(time.Now())
 
 	var err error

diff --git a/core/endorser/endorser_test.go b/core/endorser/endorser_test.go
@@ -479,7 +479,7 @@ func TestEndorserChaincodeCallLogging(t *testing.T) {
 
 	t.Logf("contents:\n%s", buf.Contents())
 	gt.Eventually(buf).Should(gbytes.Say(`INFO.*\[testchainid\]\[[[:xdigit:]]{8}\] Entry chaincode: name:"chaincode-name" version:"chaincode-version"`))
-	gt.Eventually(buf).Should(gbytes.Say(`INFO.*\[testchainid\]\[[[:xdigit:]]{8}\] Exit chaincode: name:"chaincode-name" version:"chaincode-version"  (.*s)`))
+	gt.Eventually(buf).Should(gbytes.Say(`INFO.*\[testchainid\]\[[[:xdigit:]]{8}\] Exit chaincode: name:"chaincode-name" version:"chaincode-version"  (.*ms)`))
 }
 
 func TestEndorserLSCC(t *testing.T) {