[FAB-3560] Endorsement failure doesn't return response

This CR ensures that the response is returned when endorsement fails
due to the chaincode returning an ERROR status (currently, status>=500).
The details in the response, including the status code, message, and
payload from the chaincode are vital pieces of information for
understanding the endorsement failure and acting on it, if necessary.

This CR also adds logging messages that were helpful in debugging the
issue and cleans up a few other logging messages.

Change-Id: I7189c1c5c32e0dd6cd128ec122eefa1841c74ab3
Signed-off-by: Will Lahti <[email protected]>

Author: wlahti

core/endorser/endorser.go

@@ -80,21 +80,23 @@ func (*Endorser) checkEsccAndVscc(prop *pb.Proposal) error {
 func (*Endorser) getTxSimulator(ledgername string) (ledger.TxSimulator, error) {
 	lgr := peer.GetLedger(ledgername)
 	if lgr == nil {
-		return nil, fmt.Errorf("chain does not exist(%s)", ledgername)
+		return nil, fmt.Errorf("channel does not exist: %s", ledgername)
 	}
 	return lgr.NewTxSimulator()
 }
 
 func (*Endorser) getHistoryQueryExecutor(ledgername string) (ledger.HistoryQueryExecutor, error) {
 	lgr := peer.GetLedger(ledgername)
 	if lgr == nil {
-		return nil, fmt.Errorf("chain does not exist(%s)", ledgername)
+		return nil, fmt.Errorf("channel does not exist: %s", ledgername)
 	}
 	return lgr.NewHistoryQueryExecutor()
 }
 
 //call specified chaincode (system or user)
 func (e *Endorser) callChaincode(ctxt context.Context, chainID string, version string, txid string, signedProp *pb.SignedProposal, prop *pb.Proposal, cis *pb.ChaincodeInvocationSpec, cid *pb.ChaincodeID, txsim ledger.TxSimulator) (*pb.Response, *pb.ChaincodeEvent, error) {
+	endorserLogger.Debugf("Entry - txid: %s channel id: %s version: %s", txid, chainID, version)
+	defer endorserLogger.Debugf("Exit")
 	var err error
 	var res *pb.Response
 	var ccevent *pb.ChaincodeEvent
@@ -117,9 +119,8 @@ func (e *Endorser) callChaincode(ctxt context.Context, chainID string, version s
 	//per doc anything < 500 can be sent as TX.
 	//fabric errors will always be >= 500 (ie, unambiguous errors )
 	//"lscc" will respond with status 200 or >=500 (ie, unambiguous OK or ERROR)
-	//This leaves all < 500 errors to user chaincodes
 	if res.Status >= shim.ERROR {
-		return nil, nil, fmt.Errorf(string(res.Message))
+		return res, nil, nil
 	}
 
 	//----- BEGIN -  SECTION THAT MAY NEED TO BE DONE IN LSCC ------
@@ -200,6 +201,8 @@ func (e *Endorser) disableJavaCCInst(cid *pb.ChaincodeID, cis *pb.ChaincodeInvoc
 
 //simulate the proposal by calling the chaincode
 func (e *Endorser) simulateProposal(ctx context.Context, chainID string, txid string, signedProp *pb.SignedProposal, prop *pb.Proposal, cid *pb.ChaincodeID, txsim ledger.TxSimulator) (*ccprovider.ChaincodeData, *pb.Response, []byte, *pb.ChaincodeEvent, error) {
+	endorserLogger.Debugf("Entry - txid: %s channel id: %s", txid, chainID)
+	defer endorserLogger.Debugf("Exit")
 	//we do expect the payload to be a ChaincodeInvocationSpec
 	//if we are supporting other payloads in future, this be glaringly point
 	//as something that should change
@@ -263,6 +266,7 @@ func (e *Endorser) simulateProposal(ctx context.Context, chainID string, txid st
 	var ccevent *pb.ChaincodeEvent
 	res, ccevent, err = e.callChaincode(ctx, chainID, version, txid, signedProp, prop, cis, cid, txsim)
 	if err != nil {
+		endorserLogger.Errorf("callChaincode() failed for txid: %s error: %s", txid, err)
 		return nil, nil, nil, nil, err
 	}
 
@@ -286,7 +290,8 @@ func (e *Endorser) getCDSFromLSCC(ctx context.Context, chainID string, txid stri
 
 //endorse the proposal by calling the ESCC
 func (e *Endorser) endorseProposal(ctx context.Context, chainID string, txid string, signedProp *pb.SignedProposal, proposal *pb.Proposal, response *pb.Response, simRes []byte, event *pb.ChaincodeEvent, visibility []byte, ccid *pb.ChaincodeID, txsim ledger.TxSimulator, cd *ccprovider.ChaincodeData) (*pb.ProposalResponse, error) {
-	endorserLogger.Debugf("endorseProposal starts for chainID %s, ccid %s", chainID, ccid)
+	endorserLogger.Debugf("Entry - txid: %s channel id: %s chaincode id: %s", txid, chainID, ccid)
+	defer endorserLogger.Debugf("Exit")
 
 	isSysCC := cd == nil
 	// 1) extract the name of the escc that is requested to endorse this chaincode
@@ -303,7 +308,7 @@ func (e *Endorser) endorseProposal(ctx context.Context, chainID string, txid str
 		}
 	}
 
-	endorserLogger.Debugf("endorseProposal info: escc for cid %s is %s", ccid, escc)
+	endorserLogger.Debugf("info: escc for chaincode id %s is %s", ccid, escc)
 
 	// marshalling event bytes
 	var err error
@@ -353,7 +358,7 @@ func (e *Endorser) endorseProposal(ctx context.Context, chainID string, txid str
 	}
 
 	if res.Status >= shim.ERROR {
-		return nil, fmt.Errorf(string(res.Message))
+		return &pb.ProposalResponse{Response: res}, nil
 	}
 
 	prBytes := res.Payload
@@ -377,6 +382,8 @@ func (e *Endorser) endorseProposal(ctx context.Context, chainID string, txid str
 
 // ProcessProposal process the Proposal
 func (e *Endorser) ProcessProposal(ctx context.Context, signedProp *pb.SignedProposal) (*pb.ProposalResponse, error) {
+	endorserLogger.Debugf("Entry")
+	defer endorserLogger.Debugf("Exit")
 	// at first, we check whether the message is valid
 	prop, hdr, hdrExt, err := validation.ValidateProposalMessage(signedProp)
 	if err != nil {
@@ -395,7 +402,7 @@ func (e *Endorser) ProcessProposal(ctx context.Context, signedProp *pb.SignedPro
 
 	// block invocations to security-sensitive system chaincodes
 	if syscc.IsSysCCAndNotInvokableExternal(hdrExt.ChaincodeId.Name) {
-		endorserLogger.Errorf("ProcessProposal error: an attempt was made by %#v to invoke system chaincode %s",
+		endorserLogger.Errorf("Error: an attempt was made by %#v to invoke system chaincode %s",
 			shdr.Creator, hdrExt.ChaincodeId.Name)
 		err = fmt.Errorf("Chaincode %s cannot be invoked through a proposal", hdrExt.ChaincodeId.Name)
 		return &pb.ProposalResponse{Response: &pb.Response{Status: 500, Message: err.Error()}}, err
@@ -468,6 +475,23 @@ func (e *Endorser) ProcessProposal(ctx context.Context, signedProp *pb.SignedPro
 	if err != nil {
 		return &pb.ProposalResponse{Response: &pb.Response{Status: 500, Message: err.Error()}}, err
 	}
+	if res != nil {
+		if res.Status >= shim.ERROR {
+			endorserLogger.Debugf("simulateProposal() resulted in chaincode error for txid: %s", txid)
+			var cceventBytes []byte
+			if ccevent != nil {
+				cceventBytes, err = putils.GetBytesChaincodeEvent(ccevent)
+				if err != nil {
+					return nil, fmt.Errorf("failed to marshal event bytes - %s", err)
+				}
+			}
+			pResp, err := putils.CreateProposalResponseFailure(prop.Header, prop.Payload, res, simulationResult, cceventBytes, hdrExt.ChaincodeId, hdrExt.PayloadVisibility)
+			if err != nil {
+				return &pb.ProposalResponse{Response: &pb.Response{Status: 500, Message: err.Error()}}, err
+			}
+			return pResp, nil
+		}
+	}
 
 	//2 -- endorse and get a marshalled ProposalResponse message
 	var pResp *pb.ProposalResponse
@@ -481,6 +505,12 @@ func (e *Endorser) ProcessProposal(ctx context.Context, signedProp *pb.SignedPro
 		if err != nil {
 			return &pb.ProposalResponse{Response: &pb.Response{Status: 500, Message: err.Error()}}, err
 		}
+		if pResp != nil {
+			if res.Status >= shim.ERROR {
+				endorserLogger.Debugf("endorseProposal() resulted in chaincode error for txid: %s", txid)
+				return pResp, nil
+			}
+		}
 	}
 
 	// Set the proposal response payload - it

core/endorser/endorser_test.go

@@ -51,6 +51,8 @@ import (
 	"github.com/spf13/viper"
 	"golang.org/x/net/context"
 	"google.golang.org/grpc"
+
+	"github.com/stretchr/testify/assert"
 	"google.golang.org/grpc/credentials"
 )
 
@@ -477,7 +479,21 @@ func TestDeployAndInvoke(t *testing.T) {
 		return
 	}
 
-	fmt.Printf("Invoke test passed\n")
+	// Test chaincode endorsement failure when invalid function name supplied
+	f = "invokeinvalid"
+	invokeArgs = append([]string{f}, args...)
+	spec = &pb.ChaincodeSpec{Type: 1, ChaincodeId: chaincodeID, Input: &pb.ChaincodeInput{Args: util.ToChaincodeArgs(invokeArgs...)}}
+	prop, resp, txid, nonce, err = invoke(chainID, spec)
+	if err != nil {
+		t.Fail()
+		t.Logf("Error invoking transaction: %s", err)
+		chaincode.GetChain().Stop(ctxt, cccid, &pb.ChaincodeDeploymentSpec{ChaincodeSpec: &pb.ChaincodeSpec{ChaincodeId: chaincodeID}})
+		return
+	}
+	if resp != nil {
+		assert.Equal(t, int32(500), resp.Response.Status, "Unexpected response status")
+	}
+
 	t.Logf("Invoke test passed")
 
 	chaincode.GetChain().Stop(ctxt, cccid, &pb.ChaincodeDeploymentSpec{ChaincodeSpec: &pb.ChaincodeSpec{ChaincodeId: chaincodeID}})
@@ -535,7 +551,6 @@ func TestDeployAndUpgrade(t *testing.T) {
 		return
 	}
 
-	fmt.Printf("Upgrade test passed\n")
 	t.Logf("Upgrade test passed")
 
 	chaincode.GetChain().Stop(ctxt, cccid1, &pb.ChaincodeDeploymentSpec{ChaincodeSpec: &pb.ChaincodeSpec{ChaincodeId: chaincodeID1}})
@@ -602,7 +617,6 @@ func TestWritersACLFail(t *testing.T) {
 		return
 	}
 
-	fmt.Println("TestWritersACLFail passed")
 	t.Logf("TestWritersACLFail passed")
 
 	chaincode.GetChain().Stop(ctxt, cccid, &pb.ChaincodeDeploymentSpec{ChaincodeSpec: &pb.ChaincodeSpec{ChaincodeId: chaincodeID}})
@@ -647,7 +661,6 @@ func TestAdminACLFail(t *testing.T) {
 		return
 	}
 
-	fmt.Println("TestAdminACLFail passed")
 	t.Logf("TestATestAdminACLFailCLFail passed")
 
 	chaincode.GetChain().Stop(ctxt, cccid, &pb.ChaincodeDeploymentSpec{ChaincodeSpec: &pb.ChaincodeSpec{ChaincodeId: chaincodeID}})

peer/chaincode/common.go

@@ -26,6 +26,7 @@ import (
 	"github.com/hyperledger/fabric/common/cauthdsl"
 	"github.com/hyperledger/fabric/core/chaincode"
 	"github.com/hyperledger/fabric/core/chaincode/platforms"
+	"github.com/hyperledger/fabric/core/chaincode/shim"
 	"github.com/hyperledger/fabric/core/container"
 	"github.com/hyperledger/fabric/msp"
 	"github.com/hyperledger/fabric/peer/common"
@@ -104,11 +105,24 @@ func chaincodeInvokeOrQuery(cmd *cobra.Command, args []string, invoke bool, cf *
 	proposalResp, err := ChaincodeInvokeOrQuery(spec, chainID, invoke,
 		cf.Signer, cf.EndorserClient, cf.BroadcastClient)
 	if err != nil {
-		return err
+		return fmt.Errorf("%s - %v", err, proposalResp)
 	}
 
 	if invoke {
-		logger.Infof("Invoke result: %v", proposalResp)
+		if proposalResp.Response.Status >= shim.ERROR {
+			logger.Debugf("ESCC invoke result: %v", proposalResp)
+			pRespPayload, err := putils.GetProposalResponsePayload(proposalResp.Payload)
+			if err != nil {
+				return fmt.Errorf("Error while unmarshaling proposal response payload: %s", err)
+			}
+			ca, err := putils.GetChaincodeAction(pRespPayload.Extension)
+			if err != nil {
+				return fmt.Errorf("Error while unmarshaling chaincode action: %s", err)
+			}
+			logger.Warningf("Endorsement failure during invoke. chaincode result: %v", ca.Response)
+		} else {
+			logger.Infof("Invoke result: %v", proposalResp)
+		}
 	} else {
 		if proposalResp == nil {
 			return fmt.Errorf("Error query %s by endorsing: %s", chainFuncName, err)
@@ -309,6 +323,9 @@ func ChaincodeInvokeOrQuery(spec *pb.ChaincodeSpec, cID string, invoke bool,
 
 	if invoke {
 		if proposalResp != nil {
+			if proposalResp.Response.Status >= shim.ERROR {
+				return proposalResp, nil
+			}
 			// assemble a signed transaction (it's an Envelope message)
 			env, err := putils.CreateSignedTx(prop, signer, proposalResp)
 			if err != nil {

peer/chaincode/invoke_test.go

@@ -17,12 +17,19 @@
 package chaincode
 
 import (
+	"bytes"
 	"errors"
+	"fmt"
 	"testing"
 
+	"github.com/hyperledger/fabric/common/flogging"
+	"github.com/hyperledger/fabric/common/util"
 	"github.com/hyperledger/fabric/msp"
 	"github.com/hyperledger/fabric/peer/common"
+	cb "github.com/hyperledger/fabric/protos/common"
 	pb "github.com/hyperledger/fabric/protos/peer"
+	"github.com/hyperledger/fabric/protos/utils"
+	logging "github.com/op/go-logging"
 	"github.com/stretchr/testify/assert"
 )
 
@@ -116,7 +123,7 @@ func TestInvokeCmd(t *testing.T) {
 	assert.NoError(t, err)
 }
 
-func TestInvokeCmdEndorseFail(t *testing.T) {
+func TestInvokeCmdEndorsementError(t *testing.T) {
 	InitMSP()
 	mockCF, err := getMockChaincodeCmdFactoryWithErr()
 	assert.NoError(t, err, "Error getting mock chaincode command factory")
@@ -130,6 +137,35 @@ func TestInvokeCmdEndorseFail(t *testing.T) {
 	assert.Error(t, err, "Expected error executing invoke command")
 }
 
+func TestInvokeCmdEndorsementFailure(t *testing.T) {
+	InitMSP()
+	ccRespStatus := int32(502)
+	ccRespPayload := []byte("Invalid function name")
+	mockCF, err := getMockChaincodeCmdFactoryEndorsementFailure(ccRespStatus, ccRespPayload)
+	assert.NoError(t, err, "Error getting mock chaincode command factory")
+
+	cmd := invokeCmd(mockCF)
+	AddFlags(cmd)
+	args := []string{"-n", "example02", "-p", "github.com/hyperledger/fabric/examples/chaincode/go/chaincode_example02",
+		"-c", "{\"Args\": [\"invokeinvalid\",\"a\",\"b\",\"10\"]}"}
+	cmd.SetArgs(args)
+
+	// set logger to logger with a backend that writes to a byte buffer
+	var buffer bytes.Buffer
+	logger.SetBackend(logging.AddModuleLevel(logging.NewLogBackend(&buffer, "", 0)))
+	// reset the logger after test
+	defer func() {
+		flogging.Reset()
+	}()
+	// make sure buffer is "clean" before running the invoke
+	buffer.Reset()
+
+	err = cmd.Execute()
+	assert.NoError(t, err)
+	assert.Regexp(t, "Endorsement failure during invoke", buffer.String())
+	assert.Regexp(t, fmt.Sprintf("chaincode result: status:%d payload:\"%s\"", ccRespStatus, ccRespPayload), buffer.String())
+}
+
 // Returns mock chaincode command factory
 func getMockChaincodeCmdFactory() (*ChaincodeCmdFactory, error) {
 	signer, err := common.GetDefaultSigner()
@@ -169,3 +205,44 @@ func getMockChaincodeCmdFactoryWithErr() (*ChaincodeCmdFactory, error) {
 	}
 	return mockCF, nil
 }
+
+// Returns mock chaincode command factory
+func getMockChaincodeCmdFactoryEndorsementFailure(ccRespStatus int32, ccRespPayload []byte) (*ChaincodeCmdFactory, error) {
+	signer, err := common.GetDefaultSigner()
+	if err != nil {
+		return nil, err
+	}
+
+	// create a proposal from a ChaincodeInvocationSpec
+	prop, _, err := utils.CreateChaincodeProposal(cb.HeaderType_ENDORSER_TRANSACTION, util.GetTestChainID(), createCIS(), nil)
+	if err != nil {
+		return nil, fmt.Errorf("Could not create chaincode proposal, err %s\n", err)
+	}
+
+	response := &pb.Response{Status: ccRespStatus, Payload: ccRespPayload}
+	result := []byte("res")
+	ccid := &pb.ChaincodeID{Name: "foo", Version: "v1"}
+
+	mockRespFailure, err := utils.CreateProposalResponseFailure(prop.Header, prop.Payload, response, result, nil, ccid, nil)
+	if err != nil {
+
+		return nil, fmt.Errorf("Could not create proposal response failure, err %s\n", err)
+	}
+
+	mockEndorserClient := common.GetMockEndorserClient(mockRespFailure, nil)
+	mockBroadcastClient := common.GetMockBroadcastClient(nil)
+	mockCF := &ChaincodeCmdFactory{
+		EndorserClient:  mockEndorserClient,
+		Signer:          signer,
+		BroadcastClient: mockBroadcastClient,
+	}
+	return mockCF, nil
+}
+
+func createCIS() *pb.ChaincodeInvocationSpec {
+	return &pb.ChaincodeInvocationSpec{
+		ChaincodeSpec: &pb.ChaincodeSpec{
+			Type:        pb.ChaincodeSpec_GOLANG,
+			ChaincodeId: &pb.ChaincodeID{Name: "chaincode_name"},
+			Input:       &pb.ChaincodeInput{Args: [][]byte{[]byte("arg1"), []byte("arg2")}}}}
+}

protos/utils/txutils.go

@@ -225,7 +225,7 @@ func CreateProposalResponse(hdrbytes []byte, payl []byte, response *peer.Respons
 	// get the bytes of the proposal response payload - we need to sign them
 	prpBytes, err := GetBytesProposalResponsePayload(pHashBytes, response, results, events, ccid)
 	if err != nil {
-		return nil, errors.New("Failure while unmarshalling the ProposalResponsePayload")
+		return nil, errors.New("Failure while marshaling the ProposalResponsePayload")
 	}
 
 	// serialize the signing identity
@@ -250,6 +250,35 @@ func CreateProposalResponse(hdrbytes []byte, payl []byte, response *peer.Respons
 	return resp, nil
 }
 
+// CreateProposalResponseFailure creates a proposal response for cases where
+// endorsement proposal fails either due to a endorsement failure or a chaincode
+// failure (chaincode response status >=500)
+func CreateProposalResponseFailure(hdrbytes []byte, payl []byte, response *peer.Response, results []byte, events []byte, ccid *peer.ChaincodeID, visibility []byte) (*peer.ProposalResponse, error) {
+	hdr, err := GetHeader(hdrbytes)
+	if err != nil {
+		return nil, err
+	}
+
+	// obtain the proposal hash given proposal header, payload and the requested visibility
+	pHashBytes, err := GetProposalHash1(hdr, payl, visibility)
+	if err != nil {
+		return nil, fmt.Errorf("Could not compute proposal hash: err %s", err)
+	}
+
+	// get the bytes of the proposal response payload
+	prpBytes, err := GetBytesProposalResponsePayload(pHashBytes, response, results, events, ccid)
+	if err != nil {
+		return nil, errors.New("Failure while marshaling the ProposalResponsePayload")
+	}
+
+	resp := &peer.ProposalResponse{
+		// Timestamp: TODO!
+		Payload:  prpBytes,
+		Response: &peer.Response{Status: 500, Message: "Chaincode Error"}}
+
+	return resp, nil
+}
+
 // GetSignedProposal returns a signed proposal given a Proposal message and a signing identity
 func GetSignedProposal(prop *peer.Proposal, signer msp.SigningIdentity) (*peer.SignedProposal, error) {
 	// check for nil argument