Add logging for identity, policy, and signature troubleshooting (rele…

…ase-2.2) (#3483)

Backport #3006

Most identity, policy, and signature issues return a fairly generic error
message to the user, e.g. "not authorized".
This is often intentional so as to not disclose information to malicious users that
may be probing for information about the system.

This commit adds logging on the orderer and peer side so that identity issues
can more easily be troubleshooted by users setting up sample networks,
and by administrators and SREs in production networks.

For any identity, policy, or signature error, the failed policy and passed identity is now logged in a warning message.
Additionally, the identity of every signature that is verified can be seen if tracing is enabled.

The new logging can help with the following types of issue resolution:
User cert and MSP membership errors
Determine which user is unauthorized to perform an action
Determine which MSPs and user signatures are included in a config transaction that was invalidated
Determine which peers participated in an endorsement invalidation
Determine which peer signature doesn't match the others in a proposal response

Signed-off-by: David Enyeart <enyeart@us.ibm.com>

common/configtx/update.go

@@ -95,6 +95,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

@@ -369,12 +369,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
 		}
 

common/policies/policy_test.go

@@ -302,6 +302,7 @@ func TestSignatureSetToValidIdentitiesDeserializeErr(t *testing.T) {
 	client1, err := ca.NewClientCertKeyPair()
 	assert.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 {
 		assert.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"
@@ -267,7 +268,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

@@ -177,14 +177,14 @@ 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 genericAuthError
 	}
 
 	// 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
 	}
 
@@ -195,7 +195,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,12 +11,15 @@ 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/msp/mgmt"
 	"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 {
@@ -121,6 +124,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)
 	}
 
@@ -133,6 +137,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)
 	}
 
@@ -167,6 +172,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)
 	}
 

discovery/support/acl/support.go

@@ -98,6 +98,7 @@ 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)

msp/identities.go

@@ -181,8 +181,9 @@ 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)

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

@@ -74,7 +74,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,34 @@ func EnvelopeAsSignedData(env *common.Envelope) ([]*SignedData, error) {
 		Signature: env.Signature,
 	}}, nil
 }
+
+// LogMessageForSerializedIdentity returns a logging string with serialized 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)
+}
+
+// LogMessageForSerializedIdentities returns a logging string with information from serialized identities included in SignedData
+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
+}

protoutil/testdata/peer-expired.pem

@@ -0,0 +1,14 @@
+-----BEGIN CERTIFICATE-----
+MIICGTCCAcCgAwIBAgIRAKLReasLg2oNMbOafRp0a/EwCgYIKoZIzj0EAwIwczEL
+MAkGA1UEBhMCVVMxEzARBgNVBAgTCkNhbGlmb3JuaWExFjAUBgNVBAcTDVNhbiBG
+cmFuY2lzY28xGTAXBgNVBAoTEG9yZzEuZXhhbXBsZS5jb20xHDAaBgNVBAMTE2Nh
+Lm9yZzEuZXhhbXBsZS5jb20wHhcNODkxMjE1MDc1NTAwWhcNODkxMjE1MDgwMDAw
+WjBbMQswCQYDVQQGEwJVUzETMBEGA1UECBMKQ2FsaWZvcm5pYTEWMBQGA1UEBxMN
+U2FuIEZyYW5jaXNjbzEfMB0GA1UEAxMWcGVlcjAub3JnMS5leGFtcGxlLmNvbTBZ
+MBMGByqGSM49AgEGCCqGSM49AwEHA0IABGRKxsl6MGrNEgyj78c1uVDgR0lqHvuf
+jBS/hlMbOqkF9f+oj1Hfr2oAQYMgj6hwiePxzXTRyk+NboqgVgccstujTTBLMA4G
+A1UdDwEB/wQEAwIHgDAMBgNVHRMBAf8EAjAAMCsGA1UdIwQkMCKAIEIBuSbFuduz
+ktspAE6FAP7r1N5ClHZM1B/fSiRh9BXGMAoGCCqGSM49BAMCA0cAMEQCIFWScCx8
+KIAmvO0qN2qPdG8UeeSr10gvdHl7vohRlDMXAiBt1Pks8/McNoUNI1Q5kInsWroH
+1pE6XdTNIOsKDKnd5g==
+-----END CERTIFICATE-----