diff --git a/core/endorser/endorser.go b/core/endorser/endorser.go index 41b25a9562b..4cf93d5c5db 100644 --- a/core/endorser/endorser.go +++ b/core/endorser/endorser.go @@ -104,11 +104,11 @@ type Endorser struct { // call specified chaincode (system or user) func (e *Endorser) callChaincode(txParams *ccprovider.TransactionParams, input *pb.ChaincodeInput, chaincodeName string) (*pb.Response, *pb.ChaincodeEvent, error) { - endorserLogger.Infof("[%s][%s] Entry chaincode: %s", txParams.ChannelID, shorttxid(txParams.TxID), chaincodeName) defer func(start time.Time) { logger := endorserLogger.WithOptions(zap.AddCallerSkip(1)) - elapsedMillisec := time.Since(start).Round(time.Millisecond) / time.Millisecond - logger.Infof("[%s][%s] Exit chaincode: %s (%dms)", txParams.ChannelID, shorttxid(txParams.TxID), chaincodeName, elapsedMillisec) + logger = decorateLogger(logger, txParams) + elapsedMillisec := time.Since(start).Milliseconds() + logger.Infof("finished chaincode: %s duration: %dms", chaincodeName, elapsedMillisec) }(time.Now()) res, ccevent, err := e.Support.Execute(txParams, chaincodeName, input) @@ -167,13 +167,12 @@ func (e *Endorser) callChaincode(txParams *ccprovider.TransactionParams, input * // SimulateProposal simulates the proposal by calling the chaincode func (e *Endorser) SimulateProposal(txParams *ccprovider.TransactionParams, chaincodeName string, chaincodeInput *pb.ChaincodeInput) (*pb.Response, []byte, *pb.ChaincodeEvent, error) { - endorserLogger.Debugf("[%s][%s] Entry chaincode: %s", txParams.ChannelID, shorttxid(txParams.TxID), chaincodeName) - defer endorserLogger.Debugf("[%s][%s] Exit", txParams.ChannelID, shorttxid(txParams.TxID)) + logger := decorateLogger(endorserLogger, txParams) // ---3. execute the proposal and get simulation results res, ccevent, err := e.callChaincode(txParams, chaincodeInput, chaincodeName) if err != nil { - endorserLogger.Errorf("[%s][%s] failed to invoke chaincode %s, error: %+v", txParams.ChannelID, shorttxid(txParams.TxID), chaincodeName, err) + logger.Errorf("failed to invoke chaincode %s, error: %+v", chaincodeName, err) return nil, nil, nil, err } @@ -237,8 +236,6 @@ func (e *Endorser) preProcess(up *UnpackedProposal, channel *Channel) error { return errors.WithMessage(err, "error validating proposal") } - endorserLogger.Debugf("[%s][%s] processing txid: %s", up.ChannelHeader.ChannelId, shorttxid(up.ChannelHeader.TxId), up.ChannelHeader.TxId) - if up.ChannelHeader.ChannelId == "" { // chainless proposals do not/cannot affect ledger and cannot be submitted as transactions // ignore uniqueness checks; also, chainless proposals are not validated using the policies @@ -282,8 +279,7 @@ func (e *Endorser) ProcessProposal(ctx context.Context, signedProp *pb.SignedPro e.Metrics.ProposalsReceived.Add(1) addr := util.ExtractRemoteAddress(ctx) - endorserLogger.Debug("Entering: request from", addr) - defer endorserLogger.Debug("Exit: request from", addr) + endorserLogger.Debug("request from", addr) // variables to capture proposal duration metric success := false @@ -346,6 +342,8 @@ func (e *Endorser) ProcessProposalSuccessfullyOrError(up *UnpackedProposal) (*pb Proposal: up.Proposal, } + logger := decorateLogger(endorserLogger, txParams) + if acquireTxSimulator(up.ChannelHeader.ChannelId, up.ChaincodeName) { txSim, err := e.Support.GetTxSimulator(up.ChannelID(), up.TxID()) if err != nil { @@ -391,7 +389,7 @@ func (e *Endorser) ProcessProposalSuccessfullyOrError(up *UnpackedProposal) (*pb Version: cdLedger.Version, }) if err != nil { - endorserLogger.Warning("Failed marshaling the proposal response payload to bytes", err) + logger.Warning("Failed marshaling the proposal response payload to bytes", err) return nil, errors.WithMessage(err, "failed to create the proposal response") } @@ -417,7 +415,7 @@ func (e *Endorser) ProcessProposalSuccessfullyOrError(up *UnpackedProposal) (*pb case res.Status >= shim.ERRORTHRESHOLD: meterLabels = append(meterLabels, "chaincodeerror", strconv.FormatBool(true)) e.Metrics.EndorsementsFailed.With(meterLabels...).Add(1) - endorserLogger.Debugf("[%s][%s] endorseProposal() resulted in chaincode %s error for txid: %s", up.ChannelID(), shorttxid(up.TxID()), up.ChaincodeName, up.TxID()) + logger.Debugf("chaincode error %d", res.Status) return &pb.ProposalResponse{ Response: res, }, nil @@ -425,7 +423,7 @@ func (e *Endorser) ProcessProposalSuccessfullyOrError(up *UnpackedProposal) (*pb escc := cdLedger.EndorsementPlugin - endorserLogger.Debugf("[%s][%s] escc for chaincode %s is %s", up.ChannelID(), shorttxid(up.TxID()), up.ChaincodeName, escc) + logger.Debugf("escc for chaincode %s is %s", up.ChaincodeName, escc) // Note, mPrpBytes is the same as prpBytes by default endorsement plugin, but others could change it. endorsement, mPrpBytes, err := e.Support.EndorseWithPlugin(escc, up.ChannelID(), prpBytes, up.SignedProposal) @@ -478,3 +476,7 @@ func CreateCCEventBytes(ccevent *pb.ChaincodeEvent) ([]byte, error) { return proto.Marshal(ccevent) } + +func decorateLogger(logger *flogging.FabricLogger, txParams *ccprovider.TransactionParams) *flogging.FabricLogger { + return logger.With("channel", txParams.ChannelID, "txID", shorttxid(txParams.TxID)) +} diff --git a/core/endorser/msgvalidation.go b/core/endorser/msgvalidation.go index 22c45b09f84..814b8dfc984 100644 --- a/core/endorser/msgvalidation.go +++ b/core/endorser/msgvalidation.go @@ -13,6 +13,7 @@ import ( "github.com/hyperledger/fabric-protos-go/common" cb "github.com/hyperledger/fabric-protos-go/common" pb "github.com/hyperledger/fabric-protos-go/peer" + "github.com/hyperledger/fabric/core/common/ccprovider" "github.com/hyperledger/fabric/msp" "github.com/hyperledger/fabric/protoutil" "github.com/pkg/errors" @@ -121,6 +122,11 @@ func UnpackProposal(signedProp *pb.SignedProposal) (*UnpackedProposal, error) { } func (up *UnpackedProposal) Validate(idDeserializer msp.IdentityDeserializer) error { + logger := decorateLogger(endorserLogger, &ccprovider.TransactionParams{ + ChannelID: up.ChannelHeader.ChannelId, + TxID: up.TxID(), + }) + // validate the header type switch common.HeaderType(up.ChannelHeader.Type) { case common.HeaderType_ENDORSER_TRANSACTION: @@ -171,29 +177,29 @@ func (up *UnpackedProposal) Validate(idDeserializer msp.IdentityDeserializer) er // get the identity of the creator creator, err := idDeserializer.DeserializeIdentity(up.SignatureHeader.Creator) if err != nil { - endorserLogger.Warningf("%s access denied: channel [%s]: %s", up.TxID(), up.ChannelID(), err) + logger.Warningf("access denied: channel %s", err) return genericAuthError } - endorserLogger.Debugf("%s creator is %s", up.TxID(), creator.GetIdentifier()) - // ensure that creator is a valid certificate err = creator.Validate() if err != nil { - endorserLogger.Warningf("%s access denied: channel [%s]: identity is not valid: %s", up.TxID(), up.ChannelID(), err) + logger.Warningf("access denied: identity is not valid: %s", err) return genericAuthError } - endorserLogger.Debugf("%s creator is valid", up.TxID()) + logger = logger.With("mspID", creator.GetMSPIdentifier()) + + logger.Debug("creator is valid") // validate the signature err = creator.Verify(up.SignedProposal.ProposalBytes, up.SignedProposal.Signature) if err != nil { - endorserLogger.Warningf("%s access denied: channel [%s]: creator's signature over the proposal is not valid: %s", up.TxID(), up.ChannelID(), err) + logger.Warningf("access denied: creator's signature over the proposal is not valid: %s", err) return genericAuthError } - endorserLogger.Debugf("%s signature is valid", up.TxID()) + logger.Debug("signature is valid") return nil }