From 862ab4d82c1ef0206aa7593c52776e393b001372 Mon Sep 17 00:00:00 2001 From: Dave Enyeart Date: Thu, 16 Jun 2022 12:27:54 -0400 Subject: [PATCH] Add logging for identity, policy, and signature troubleshooting (release-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 --- common/configtx/update.go | 1 + common/policies/policy.go | 7 +- common/policies/policy_test.go | 7 +- core/aclmgmt/resourceprovider.go | 6 +- .../statebased/validator_keylevel.go | 12 +++- core/endorser/msgvalidation.go | 6 +- core/policy/policy.go | 6 ++ discovery/support/acl/support.go | 1 + msp/identities.go | 5 +- msp/mspimplvalidate.go | 3 + orderer/common/msgprocessor/sigfilter.go | 2 +- protoutil/signeddata.go | 35 ++++++++++ protoutil/signeddata_test.go | 66 +++++++++++++++++++ protoutil/testdata/peer-expired.pem | 14 ++++ 14 files changed, 156 insertions(+), 15 deletions(-) create mode 100644 protoutil/testdata/peer-expired.pem 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-----