[FAB-12303] info logging for chaincode invokes

Fabric operators need some minimal visibility into chaincode execution
information, without turning on full peer debug.

Message should include context information such as channel and txid, as
well as execution time.

This change adds the following two info messages per chaincode invoke:

[endorser] callChaincode -> INFO 001 [channel][9b5836e1] Entry chaincode: name:"chaincode-name" version:"chaincode-version"
[endorser] callChaincode -> INFO 002 [channel][9b5836e1] Exit chaincode: name:"chaincode-name" version:"chaincode-version"  (5.003ms)

Change-Id: I0d116628efb6291f564989a5ff51af5bc4cca6dd
Signed-off-by: David Enyeart <enyeart@us.ibm.com>
Signed-off-by: Matthew Sykes <sykesmat@us.ibm.com>

Author: sykesm

core/endorser/endorser.go

@@ -9,6 +9,7 @@ package endorser
 import (
 	"context"
 	"fmt"
+	"time"
 
 	"github.com/golang/protobuf/proto"
 	"github.com/hyperledger/fabric/common/channelconfig"
@@ -25,6 +26,7 @@ import (
 	"github.com/hyperledger/fabric/protos/transientstore"
 	putils "github.com/hyperledger/fabric/protos/utils"
 	"github.com/pkg/errors"
+	"go.uber.org/zap"
 )
 
 var endorserLogger = flogging.MustGetLogger("endorser")
@@ -125,8 +127,13 @@ func NewEndorserServer(privDist privateDataDistributor, s Support, pr *platforms
 
 // call specified chaincode (system or user)
 func (e *Endorser) callChaincode(txParams *ccprovider.TransactionParams, version string, input *pb.ChaincodeInput, cid *pb.ChaincodeID) (*pb.Response, *pb.ChaincodeEvent, error) {
-	endorserLogger.Debugf("[%s][%s] Entry chaincode: %s version: %s", txParams.ChannelID, txParams.TxID, cid, version)
-	defer endorserLogger.Debugf("[%s][%s] Exit", txParams.ChannelID, txParams.TxID)
+	endorserLogger.Infof("[%s][%s] Entry chaincode: %s", txParams.ChannelID, shorttxid(txParams.TxID), cid)
+	defer func(start time.Time) {
+		logger := endorserLogger.WithOptions(zap.AddCallerSkip(1))
+		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
 	var res *pb.Response
 	var ccevent *pb.ChaincodeEvent

core/endorser/endorser_test.go

@@ -12,7 +12,10 @@ import (
 	"os"
 	"testing"
 
+	. "github.com/onsi/gomega"
+
 	"github.com/golang/protobuf/proto"
+	"github.com/hyperledger/fabric/common/flogging"
 	mc "github.com/hyperledger/fabric/common/mocks/config"
 	"github.com/hyperledger/fabric/common/mocks/resourcesconfig"
 	"github.com/hyperledger/fabric/common/util"
@@ -33,6 +36,7 @@ import (
 	pb "github.com/hyperledger/fabric/protos/peer"
 	"github.com/hyperledger/fabric/protos/transientstore"
 	"github.com/hyperledger/fabric/protos/utils"
+	"github.com/onsi/gomega/gbytes"
 	"github.com/pkg/errors"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/mock"
@@ -450,6 +454,34 @@ func TestEndorserGoodPath(t *testing.T) {
 	assert.EqualValues(t, 200, pResp.Response.Status)
 }
 
+func TestEndorserChaincodeCallLogging(t *testing.T) {
+	gt := NewGomegaWithT(t)
+	m := &mock.Mock{}
+	m.On("Sign", mock.Anything).Return([]byte{1, 2, 3, 4, 5}, nil)
+	m.On("Serialize").Return([]byte{1, 1, 1}, nil)
+	m.On("GetTxSimulator", mock.Anything, mock.Anything).Return(newMockTxSim(), nil)
+	support := &em.MockSupport{
+		Mock: m,
+		GetApplicationConfigBoolRv: true,
+		GetApplicationConfigRv:     &mc.MockApplication{CapabilitiesRv: &mc.MockApplicationCapabilities{}},
+		GetTransactionByIDErr:      errors.New(""),
+		ChaincodeDefinitionRv:      &ccprovider.ChaincodeData{Escc: "ESCC"},
+		ExecuteResp:                &pb.Response{Status: 200, Payload: utils.MarshalOrPanic(&pb.ProposalResponse{Response: &pb.Response{}})},
+	}
+	attachPluginEndorser(support)
+	es := endorser.NewEndorserServer(pvtEmptyDistributor, support, platforms.NewRegistry(&golang.Platform{}))
+
+	buf := gbytes.NewBuffer()
+	flogging.Global.SetWriter(buf)
+	defer flogging.Global.SetWriter(os.Stderr)
+
+	es.ProcessProposal(context.Background(), getSignedProp("chaincode-name", "chaincode-version", 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"  (.*ms)`))
+}
+
 func TestEndorserLSCC(t *testing.T) {
 	m := &mock.Mock{}
 	m.On("Sign", mock.Anything).Return([]byte{1, 2, 3, 4, 5}, nil)