Add logging for identity, policy, and signature troubleshooting

common/configtx/update.go

@@ -94,6 +94,7 @@ func (vi *ValidatorImpl) verifyDeltaSet(deltaSet map[string]comparable, signedDa
 
 		// Ensure the policy is satisfied
 		if err := policy.EvaluateSignedData(signedData); err != nil {
+			logger.Warnw("policy not satisfied for channel configuration update", "key", key, "policy", policy, "signingIdenties", protoutil.LogMessageForSerializedIdentities(signedData))
 			return errors.Wrapf(err, "policy for %s not satisfied", key)
 		}
 	}

common/policies/policy.go

@@ -7,8 +7,6 @@ SPDX-License-Identifier: Apache-2.0
 package policies
 
 import (
-	"crypto/x509"
-	"encoding/pem"
 	"fmt"
 	"strings"
 
@@ -369,12 +367,7 @@ func SignatureSetToValidIdentities(signedData []*protoutil.SignedData, identityD
 	for i, sd := range signedData {
 		identity, err := identityDeserializer.DeserializeIdentity(sd.Identity)
 		if err != nil {
-			logMsg, err2 := logMessageForSerializedIdentity(sd.Identity)
-			if err2 != nil {
-				logger.Warnw("invalid identity", "identity-error", err2.Error(), "error", err.Error())
-				continue
-			}
-			logger.Warnw(fmt.Sprintf("invalid identity: %s", logMsg), "error", err.Error())
+			logger.Warnw("invalid identity", "error", err.Error(), "identity", protoutil.LogMessageForSerializedIdentity(sd.Identity))
 			continue
 		}
 
@@ -400,22 +393,3 @@ func SignatureSetToValidIdentities(signedData []*protoutil.SignedData, identityD
 
 	return identities
 }
-
-func logMessageForSerializedIdentity(serializedIdentity []byte) (string, error) {
-	id := &msp.SerializedIdentity{}
-	err := proto.Unmarshal(serializedIdentity, id)
-	if err != nil {
-		return "", errors.Wrap(err, "unmarshalling serialized identity")
-	}
-	pemBlock, _ := pem.Decode(id.IdBytes)
-	if pemBlock == nil {
-		// not all identities are certificates so simply log the serialized
-		// identity bytes
-		return fmt.Sprintf("serialized-identity=%x", serializedIdentity), nil
-	}
-	cert, err := x509.ParseCertificate(pemBlock.Bytes)
-	if err != nil {
-		return "", errors.Wrap(err, "parsing certificate")
-	}
-	return fmt.Sprintf("certificate subject=%s serialnumber=%d", cert.Subject, cert.SerialNumber), nil
-}

common/policies/policy_test.go

@@ -302,6 +302,7 @@ func TestSignatureSetToValidIdentitiesDeserializeErr(t *testing.T) {
 	client1, err := ca.NewClientCertKeyPair()
 	require.NoError(t, err)
 	id := &msp.SerializedIdentity{
+		Mspid:   "MyMSP",
 		IdBytes: client1.Cert,
 	}
 	idBytes, err := proto.Marshal(id)
@@ -328,7 +329,7 @@ func TestSignatureSetToValidIdentitiesDeserializeErr(t *testing.T) {
 					Identity: idBytes,
 				},
 			},
-			expectedLogEntryContains: []string{"invalid identity", fmt.Sprintf("certificate subject=%s serialnumber=%d", client1.TLSCert.Subject, client1.TLSCert.SerialNumber), "error=mango"},
+			expectedLogEntryContains: []string{"invalid identity", fmt.Sprintf("mspid=MyMSP subject=%s issuer=%s serialnumber=%d", client1.TLSCert.Subject, client1.TLSCert.Issuer, client1.TLSCert.SerialNumber), "error=mango"},
 		},
 	}
 
@@ -370,6 +371,10 @@ func TestSignatureSetToValidIdentitiesVerifyErr(t *testing.T) {
 
 func assertLogContains(t *testing.T, r *floggingtest.Recorder, ss ...string) {
 	defer r.Reset()
+	entries := r.Entries()
+	for _, entry := range entries {
+		fmt.Println(entry)
+	}
 	for _, s := range ss {
 		require.NotEmpty(t, r.EntriesContaining(s))
 	}

core/aclmgmt/resourceprovider.go

@@ -64,7 +64,11 @@ func (pe *policyEvaluatorImpl) Evaluate(polName string, sd []*protoutil.SignedDa
 		return PolicyNotFound(polName)
 	}
 
-	return policy.EvaluateSignedData(sd)
+	err := policy.EvaluateSignedData(sd)
+	if err != nil {
+		aclLogger.Warnw("EvaluateSignedData policy check failed", "error", err, "policyName", polName, policy, "policy", "signingIdentities", protoutil.LogMessageForSerializedIdentities(sd))
+	}
+	return err
 }
 
 //------ resourcePolicyProvider ----------

core/common/validation/statebased/validator_keylevel.go

@@ -9,6 +9,7 @@ package statebased
 import (
 	"sync"
 
+	"github.com/golang/protobuf/proto"
 	"github.com/hyperledger/fabric-protos-go/common"
 	"github.com/hyperledger/fabric-protos-go/peer"
 	commonerrors "github.com/hyperledger/fabric/common/errors"
@@ -268,7 +269,16 @@ func (klv *KeyLevelValidator) Validate(cc string, blockNum, txNum uint64, rwsetB
 	}
 
 	// return the decision of the policy evaluator
-	return policyEvaluator.Evaluate(blockNum, txNum, rwset.NsRwSets, cc, signatureSet)
+	err := policyEvaluator.Evaluate(blockNum, txNum, rwset.NsRwSets, cc, signatureSet)
+	if err != nil {
+		// If endorsement policy check fails, log the endorsement policy and endorser identities.
+		// No need to handle Unmarshal() errors since it will simply result in endorsementPolicy being empty in the log message.
+		endorsementPolicy := &peer.ApplicationPolicy{}
+		proto.Unmarshal(ccEP, endorsementPolicy)
+		logger.Warnw("Endorsment policy failure", "error", err, "chaincode", cc, "endorsementPolicy", endorsementPolicy, "endorsingIdentities", protoutil.LogMessageForSerializedIdentities(signatureSet))
+
+	}
+	return err
 }
 
 // PostValidate implements the function of the StateBasedValidator interface

core/endorser/msgvalidation.go

@@ -169,15 +169,15 @@ func (up *UnpackedProposal) Validate(idDeserializer msp.IdentityDeserializer) er
 	// get the identity of the creator
 	creator, err := idDeserializer.DeserializeIdentity(up.SignatureHeader.Creator)
 	if err != nil {
-		logger.Warningf("access denied: channel %s", err)
+		logger.Warnw("access denied", "error", err, "identity", protoutil.LogMessageForSerializedIdentity(up.SignatureHeader.Creator))
 		return errors.Errorf("access denied: channel [%s] creator org unknown, creator is malformed", up.ChannelID())
 	}
 
 	genericAuthError := errors.Errorf("access denied: channel [%s] creator org [%s]", up.ChannelID(), creator.GetMSPIdentifier())
 	// ensure that creator is a valid certificate
 	err = creator.Validate()
 	if err != nil {
-		logger.Warningf("access denied: identity is not valid: %s", err)
+		logger.Warnw("access denied: identity is not valid", "error", err, "identity", protoutil.LogMessageForSerializedIdentity(up.SignatureHeader.Creator))
 		return genericAuthError
 	}
 
@@ -188,7 +188,7 @@ func (up *UnpackedProposal) Validate(idDeserializer msp.IdentityDeserializer) er
 	// validate the signature
 	err = creator.Verify(up.SignedProposal.ProposalBytes, up.SignedProposal.Signature)
 	if err != nil {
-		logger.Warningf("access denied: creator's signature over the proposal is not valid: %s", err)
+		logger.Warnw("access denied: creator's signature over the proposal is not valid", "error", err, "identity", protoutil.LogMessageForSerializedIdentity(up.SignatureHeader.Creator))
 		return genericAuthError
 	}
 

core/policy/policy.go

@@ -11,11 +11,14 @@ import (
 	"fmt"
 
 	pb "github.com/hyperledger/fabric-protos-go/peer"
+	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/hyperledger/fabric/common/policies"
 	"github.com/hyperledger/fabric/msp"
 	"github.com/hyperledger/fabric/protoutil"
 )
 
+var logger = flogging.MustGetLogger("policy")
+
 // PolicyChecker offers methods to check a signed proposal against a specific policy
 // defined in a channel or not.
 type PolicyChecker interface {
@@ -128,6 +131,7 @@ func (p *policyChecker) CheckPolicyNoChannel(policyName string, signedProp *pb.S
 	// Deserialize proposal's creator with the local MSP
 	id, err := p.localMSP.DeserializeIdentity(shdr.Creator)
 	if err != nil {
+		logger.Warnw("Failed deserializing proposal creator during channelless check policy", "error", err, "policyName", policyName, "identity", protoutil.LogMessageForSerializedIdentity(shdr.Creator))
 		return fmt.Errorf("Failed deserializing proposal creator during channelless check policy with policy [%s]: [%s]", policyName, err)
 	}
 
@@ -140,6 +144,7 @@ func (p *policyChecker) CheckPolicyNoChannel(policyName string, signedProp *pb.S
 	// Verify that proposal's creator satisfies the principal
 	err = id.SatisfiesPrincipal(principal)
 	if err != nil {
+		logger.Warnw("Failed verifying that proposal's creator satisfies local MSP principal during channelless check policy", "error", err, "policyName", policyName, "requiredPrincipal", principal, "signingIdentity", protoutil.LogMessageForSerializedIdentity(shdr.Creator))
 		return fmt.Errorf("Failed verifying that proposal's creator satisfies local MSP principal during channelless check policy with policy [%s]: [%s]", policyName, err)
 	}
 
@@ -174,6 +179,7 @@ func (p *policyChecker) CheckPolicyBySignedData(channelID, policyName string, sd
 	// Evaluate the policy
 	err := policy.EvaluateSignedData(sd)
 	if err != nil {
+		logger.Warnw("Failed evaluating policy on signed data", "error", err, "policyName", policyName, "identities", protoutil.LogMessageForSerializedIdentities(sd))
 		return fmt.Errorf("Failed evaluating policy on signed data during check policy on channel [%s] with policy [%s]: [%s]", channelID, policyName, err)
 	}
 
@@ -195,6 +201,7 @@ func (p *policyChecker) CheckPolicyNoChannelBySignedData(policyName string, sign
 		// Deserialize identity with the local MSP
 		id, err := p.localMSP.DeserializeIdentity(data.Identity)
 		if err != nil {
+			logger.Warnw("Failed deserializing signed data identity during channelless check policy", "error", err, "policyName", policyName, "identity", protoutil.LogMessageForSerializedIdentity(data.Identity))
 			return fmt.Errorf("failed deserializing signed data identity during channelless check policy with policy [%s]: [%s]", policyName, err)
 		}
 
@@ -207,6 +214,7 @@ func (p *policyChecker) CheckPolicyNoChannelBySignedData(policyName string, sign
 		// Verify that proposal's creator satisfies the principal
 		err = id.SatisfiesPrincipal(principal)
 		if err != nil {
+			logger.Warnw("failed verifying that the signed data identity satisfies local MSP principal during channelless check policy", "error", err, "policyName", policyName, "requiredPrincipal", principal, "identity", protoutil.LogMessageForSerializedIdentity(data.Identity))
 			return fmt.Errorf("failed verifying that the signed data identity satisfies local MSP principal during channelless check policy with policy [%s]: [%s]", policyName, err)
 		}
 

discovery/support/acl/support.go

@@ -96,9 +96,14 @@ func (s *DiscoverySupport) SatisfiesPrincipal(channel string, rawIdentity []byte
 	}
 	identity, err := mspMgr.DeserializeIdentity(rawIdentity)
 	if err != nil {
+		logger.Warnw("failed deserializing identity", "error", err, "identity", protoutil.LogMessageForSerializedIdentity(rawIdentity))
 		return errors.Wrap(err, "failed deserializing identity")
 	}
-	return identity.SatisfiesPrincipal(principal)
+	err = identity.SatisfiesPrincipal(principal)
+	if err != nil {
+		logger.Warnw("identity does not satisfy principal", "error", err, "requiredPrincipal", principal, "identity", protoutil.LogMessageForSerializedIdentity(rawIdentity))
+	}
+	return err
 }
 
 // ChannelPolicyManagerGetter is a support interface

msp/identities.go

@@ -182,14 +182,16 @@ func (id *identity) Verify(msg []byte, sig []byte) error {
 	}
 
 	if mspIdentityLogger.IsEnabledFor(zapcore.DebugLevel) {
-		mspIdentityLogger.Debugf("Verify: digest = %s", hex.Dump(digest))
-		mspIdentityLogger.Debugf("Verify: sig = %s", hex.Dump(sig))
+		mspIdentityLogger.Debugf("Verify: signer identity (certificate subject=%s issuer=%s serialnumber=%d)", id.cert.Subject, id.cert.Issuer, id.cert.SerialNumber)
+		// mspIdentityLogger.Debugf("Verify: digest = %s", hex.Dump(digest))
+		// mspIdentityLogger.Debugf("Verify: sig = %s", hex.Dump(sig))
 	}
 
 	valid, err := id.msp.bccsp.Verify(id.pk, sig, digest, nil)
 	if err != nil {
 		return errors.WithMessage(err, "could not determine the validity of the signature")
 	} else if !valid {
+		mspIdentityLogger.Warnf("The signature is invalid for (certificate subject=%s issuer=%s serialnumber=%d)", id.cert.Subject, id.cert.Issuer, id.cert.SerialNumber)
 		return errors.New("The signature is invalid")
 	}
 

msp/mspimplvalidate.go

@@ -32,18 +32,21 @@ func (msp *bccspmsp) validateIdentity(id *identity) error {
 	validationChain, err := msp.getCertificationChainForBCCSPIdentity(id)
 	if err != nil {
 		id.validationErr = errors.WithMessage(err, "could not obtain certification chain")
+		mspLogger.Warnf("Could not validate identity: %s (certificate subject=%s issuer=%s serialnumber=%d)", id.validationErr, id.cert.Subject, id.cert.Issuer, id.cert.SerialNumber)
 		return id.validationErr
 	}
 
 	err = msp.validateIdentityAgainstChain(id, validationChain)
 	if err != nil {
 		id.validationErr = errors.WithMessage(err, "could not validate identity against certification chain")
+		mspLogger.Warnf("Could not validate identity: %s (certificate subject=%s issuer=%s serialnumber=%d)", id.validationErr, id.cert.Subject, id.cert.Issuer, id.cert.SerialNumber)
 		return id.validationErr
 	}
 
 	err = msp.internalValidateIdentityOusFunc(id)
 	if err != nil {
 		id.validationErr = errors.WithMessage(err, "could not validate identity's OUs")
+		mspLogger.Warnf("Could not validate identity: %s (certificate subject=%s issuer=%s serialnumber=%d)", id.validationErr, id.cert.Subject, id.cert.Issuer, id.cert.SerialNumber)
 		return id.validationErr
 	}
 

orderer/common/msgprocessor/sigfilter.go

@@ -73,7 +73,7 @@ func (sf *SigFilter) Apply(message *cb.Envelope) error {
 
 	err = policy.EvaluateSignedData(signedData)
 	if err != nil {
-		logger.Debugf("SigFilter evaluation failed: %s, policyName: %s, ConsensusState: %s", err.Error(), policyName, ordererConf.ConsensusState())
+		logger.Warnw("SigFilter evaluation failed", "error", err.Error(), "ConsensusState", ordererConf.ConsensusState(), "policyName", policyName, "signingIdentity", protoutil.LogMessageForSerializedIdentities(signedData))
 		return errors.Wrap(errors.WithStack(ErrPermissionDenied), err.Error())
 	}
 	return nil

protoutil/signeddata.go

@@ -8,10 +8,14 @@ package protoutil
 
 import (
 	"bytes"
+	"crypto/x509"
+	"encoding/pem"
 	"fmt"
+	"strings"
 
 	"github.com/golang/protobuf/proto"
 	"github.com/hyperledger/fabric-protos-go/common"
+	"github.com/hyperledger/fabric-protos-go/msp"
 )
 
 // SignedData is used to represent the general triplet required to verify a signature
@@ -80,3 +84,33 @@ func EnvelopeAsSignedData(env *common.Envelope) ([]*SignedData, error) {
 		Signature: env.Signature,
 	}}, nil
 }
+
+// LogMessageForSerializedIdentity returns a string with seriealized identity information,
+// or a string indicating why the serialized identity information cannot be returned.
+// Any errors are intentially returned in the return strings so that the function can be used in single-line log messages with minimal clutter.
+func LogMessageForSerializedIdentity(serializedIdentity []byte) string {
+	id := &msp.SerializedIdentity{}
+	err := proto.Unmarshal(serializedIdentity, id)
+	if err != nil {
+		return fmt.Sprintf("Could not unmarshal serialized identity: %s", err)
+	}
+	pemBlock, _ := pem.Decode(id.IdBytes)
+	if pemBlock == nil {
+		// not all identities are certificates so simply log the serialized
+		// identity bytes
+		return fmt.Sprintf("serialized-identity=%x", serializedIdentity)
+	}
+	cert, err := x509.ParseCertificate(pemBlock.Bytes)
+	if err != nil {
+		return fmt.Sprintf("Could not parse certificate: %s", err)
+	}
+	return fmt.Sprintf("(mspid=%s subject=%s issuer=%s serialnumber=%d)", id.Mspid, cert.Subject, cert.Issuer, cert.SerialNumber)
+}
+
+func LogMessageForSerializedIdentities(signedData []*SignedData) (logMsg string) {
+	var identityMessages []string
+	for _, sd := range signedData {
+		identityMessages = append(identityMessages, LogMessageForSerializedIdentity(sd.Identity))
+	}
+	return strings.Join(identityMessages, ", ")
+}

protoutil/signeddata_test.go

@@ -8,11 +8,17 @@ package protoutil_test
 
 import (
 	"bytes"
+	"encoding/pem"
+	"io/ioutil"
+	"path/filepath"
 	"testing"
 
 	"github.com/golang/protobuf/proto"
 	"github.com/hyperledger/fabric-protos-go/common"
+	"github.com/hyperledger/fabric-protos-go/msp"
 	"github.com/hyperledger/fabric/protoutil"
+	"github.com/pkg/errors"
+	"github.com/stretchr/testify/require"
 )
 
 // More duplicate utility which should go away, but the utils are a bit of a mess right now with import cycles
@@ -115,3 +121,63 @@ func TestEnvelopeAsSignedData(t *testing.T) {
 		t.Errorf("Wrong data bytes")
 	}
 }
+
+func TestLogMessageForSerializedIdentity(t *testing.T) {
+	pem, err := readPemFile(filepath.Join("testdata", "peer-expired.pem"))
+	require.NoError(t, err, "Unexpected error reading pem file")
+
+	serializedIdentity := &msp.SerializedIdentity{
+		Mspid:   "MyMSP",
+		IdBytes: pem,
+	}
+
+	serializedIdentityBytes, err := proto.Marshal(serializedIdentity)
+	require.NoError(t, err, "Unexpected error marshaling")
+
+	identityLogMessage := protoutil.LogMessageForSerializedIdentity(serializedIdentityBytes)
+
+	expected := "(mspid=MyMSP subject=CN=peer0.org1.example.com,L=San Francisco,ST=California,C=US issuer=CN=ca.org1.example.com,O=org1.example.com,L=San Francisco,ST=California,C=US serialnumber=216422593083731187380743188920914963441)"
+	require.Equal(t, expected, identityLogMessage)
+
+	signedDatas := []*protoutil.SignedData{
+		{
+			Data:      nil,
+			Identity:  serializedIdentityBytes,
+			Signature: nil,
+		},
+		{
+			Data:      nil,
+			Identity:  serializedIdentityBytes,
+			Signature: nil,
+		},
+	}
+
+	identitiesLogMessage := protoutil.LogMessageForSerializedIdentities(signedDatas)
+
+	expected =
+		"(mspid=MyMSP subject=CN=peer0.org1.example.com,L=San Francisco,ST=California,C=US issuer=CN=ca.org1.example.com,O=org1.example.com,L=San Francisco,ST=California,C=US serialnumber=216422593083731187380743188920914963441), " +
+			"(mspid=MyMSP subject=CN=peer0.org1.example.com,L=San Francisco,ST=California,C=US issuer=CN=ca.org1.example.com,O=org1.example.com,L=San Francisco,ST=California,C=US serialnumber=216422593083731187380743188920914963441)"
+	require.Equal(t, expected, identitiesLogMessage)
+}
+
+func readFile(file string) ([]byte, error) {
+	fileCont, err := ioutil.ReadFile(file)
+	if err != nil {
+		return nil, errors.Wrapf(err, "could not read file %s", file)
+	}
+	return fileCont, nil
+}
+
+func readPemFile(file string) ([]byte, error) {
+	bytes, err := readFile(file)
+	if err != nil {
+		return nil, errors.Wrapf(err, "reading from file %s failed", file)
+	}
+
+	b, _ := pem.Decode(bytes)
+	if b == nil {
+		return nil, errors.Errorf("no pem content for file %s", file)
+	}
+
+	return bytes, nil
+}