diff --git a/common/configtx/update.go b/common/configtx/update.go index fd31b76deff..44da00e2b3f 100644 --- a/common/configtx/update.go +++ b/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) } } diff --git a/common/policies/policy.go b/common/policies/policy.go index 1012fbce941..c78c6421348 100644 --- a/common/policies/policy.go +++ b/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 } diff --git a/common/policies/policy_test.go b/common/policies/policy_test.go index 0f7aea637d9..673e5fc64a7 100644 --- a/common/policies/policy_test.go +++ b/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)) } diff --git a/core/aclmgmt/resourceprovider.go b/core/aclmgmt/resourceprovider.go index 0ca4e31cde3..87748332c76 100644 --- a/core/aclmgmt/resourceprovider.go +++ b/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 ---------- diff --git a/core/common/validation/statebased/validator_keylevel.go b/core/common/validation/statebased/validator_keylevel.go index f760254ee38..1157ea01051 100644 --- a/core/common/validation/statebased/validator_keylevel.go +++ b/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 diff --git a/core/endorser/msgvalidation.go b/core/endorser/msgvalidation.go index 814b8dfc984..b7a2716ace9 100644 --- a/core/endorser/msgvalidation.go +++ b/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 } diff --git a/core/policy/policy.go b/core/policy/policy.go index 7c97e7c4a16..1c7ad56c119 100644 --- a/core/policy/policy.go +++ b/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) } diff --git a/discovery/support/acl/support.go b/discovery/support/acl/support.go index 69aab23b00c..f7dfc9f2f01 100644 --- a/discovery/support/acl/support.go +++ b/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) diff --git a/msp/identities.go b/msp/identities.go index a1facc0ac5a..1240cc04d9a 100644 --- a/msp/identities.go +++ b/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) diff --git a/msp/mspimplvalidate.go b/msp/mspimplvalidate.go index 23f5d3ccf5b..2f331e1c94c 100644 --- a/msp/mspimplvalidate.go +++ b/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 } diff --git a/orderer/common/msgprocessor/sigfilter.go b/orderer/common/msgprocessor/sigfilter.go index 01d7a58f352..ec0b946c8b0 100644 --- a/orderer/common/msgprocessor/sigfilter.go +++ b/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 diff --git a/protoutil/signeddata.go b/protoutil/signeddata.go index b4a48841fb1..59a3973fe12 100644 --- a/protoutil/signeddata.go +++ b/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, ", ") +} diff --git a/protoutil/signeddata_test.go b/protoutil/signeddata_test.go index 6fd4b000ea3..1fdf5aa5681 100644 --- a/protoutil/signeddata_test.go +++ b/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 +} diff --git a/protoutil/testdata/peer-expired.pem b/protoutil/testdata/peer-expired.pem new file mode 100644 index 00000000000..16b9ae402c6 --- /dev/null +++ b/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-----