From 52c71379cf9cc16aa8049f6b884b0a5ae72a5ba0 Mon Sep 17 00:00:00 2001 From: andrew-coleman Date: Fri, 6 May 2022 10:57:17 +0100 Subject: [PATCH] Log proposal response differences MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit In the gateway, if proposal responses from different endorsing peers don’t match, then it’s very difficult for the end user to diagnose why. This commit adds extra logging to help identify the cause of the mismatch. If the log level is set to ‘debug’ for the ‘gateway’, then the proposal response payloads are unmarshalled and analysed to log specific differences between individual key/values in the read/write sets, SBE policy write differences, event differences and chaincode response differences. For private collections, only the hashes are logged if they are different. Signed-off-by: andrew-coleman --- internal/pkg/gateway/api_test.go | 33 ++ internal/pkg/gateway/apiutils.go | 439 ++++++++++++++++++++++ internal/pkg/gateway/apiutils_test.go | 515 ++++++++++++++++++++++++++ internal/pkg/gateway/endorsement.go | 12 + 4 files changed, 999 insertions(+) create mode 100644 internal/pkg/gateway/apiutils_test.go diff --git a/internal/pkg/gateway/api_test.go b/internal/pkg/gateway/api_test.go index af23e4365f3..5984169fdeb 100644 --- a/internal/pkg/gateway/api_test.go +++ b/internal/pkg/gateway/api_test.go @@ -10,6 +10,7 @@ import ( "context" "fmt" "io" + "strings" "testing" "time" @@ -23,6 +24,8 @@ import ( ab "github.com/hyperledger/fabric-protos-go/orderer" "github.com/hyperledger/fabric-protos-go/peer" "github.com/hyperledger/fabric/common/crypto/tlsgen" + "github.com/hyperledger/fabric/common/flogging" + "github.com/hyperledger/fabric/common/flogging/mock" "github.com/hyperledger/fabric/common/ledger" "github.com/hyperledger/fabric/gossip/api" "github.com/hyperledger/fabric/gossip/common" @@ -37,6 +40,7 @@ import ( "github.com/pkg/errors" "github.com/spf13/viper" "github.com/stretchr/testify/require" + "go.uber.org/zap/zapcore" "google.golang.org/grpc" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" @@ -159,6 +163,8 @@ type preparedTest struct { ledgerProvider *ledgermocks.Provider ledger *ledgermocks.Ledger blockIterator *mocks.ResultsIterator + logLevel string + logFields []string } type contextKey string @@ -762,6 +768,26 @@ func TestEndorse(t *testing.T) { Message: "ProposalResponsePayloads do not match", }, }, + postSetup: func(t *testing.T, def *preparedTest) { + def.logLevel = flogging.LoggerLevel("gateway") + flogging.ActivateSpec("debug") + logObserver := &mock.Observer{} + logObserver.WriteEntryStub = func(entry zapcore.Entry, fields []zapcore.Field) { + if strings.HasPrefix(entry.Message, "Proposal response mismatch") { + for _, field := range fields { + def.logFields = append(def.logFields, field.String) + } + } + } + flogging.SetObserver(logObserver) + }, + postTest: func(t *testing.T, def *preparedTest) { + require.Equal(t, "chaincode response mismatch", def.logFields[0]) + require.Equal(t, "status: 200, message: , payload: different_response", def.logFields[1]) + require.Equal(t, "status: 200, message: , payload: mock_response", def.logFields[2]) + flogging.ActivateSpec(def.logLevel) + flogging.SetObserver(nil) + }, }, { name: "discovery fails", @@ -955,6 +981,9 @@ func TestEndorse(t *testing.T) { if checkError(t, &tt, err) { require.Nil(t, response, "response on error") + if tt.postTest != nil { + tt.postTest(t, test) + } return } @@ -971,6 +1000,10 @@ func TestEndorse(t *testing.T) { // check the correct endorsers (mocks) were called with the right parameters checkEndorsers(t, tt.expectedEndorsers, test) + + if tt.postTest != nil { + tt.postTest(t, test) + } }) } } diff --git a/internal/pkg/gateway/apiutils.go b/internal/pkg/gateway/apiutils.go index bda3743f65d..366bd7ac7a4 100644 --- a/internal/pkg/gateway/apiutils.go +++ b/internal/pkg/gateway/apiutils.go @@ -7,6 +7,8 @@ SPDX-License-Identifier: Apache-2.0 package gateway import ( + "bytes" + "encoding/hex" "fmt" "github.com/golang/protobuf/proto" @@ -125,3 +127,440 @@ func prepareTransaction(header *common.Header, payload *peer.ChaincodeProposalPa return &common.Envelope{Payload: paylBytes}, nil } + +type ( + baseDifference struct { + namespace string + key string + } + readDifference struct { + *baseDifference + expected uint64 + actual uint64 + } + writeDifference struct { + *baseDifference + expected []byte + actual []byte + } + pvtHashDifference struct { + *writeDifference + } + metadataDifference struct { + *writeDifference + name string + } + resultDifference struct { + reads []*readDifference + writes []*writeDifference + metawrites []*metadataDifference + private []*pvtHashDifference + } + ccEvent struct { + chaincodeId string + name string + payload []byte + } + eventDifference struct { + expected *ccEvent + actual *ccEvent + } + response struct { + status int32 + message string + payload []byte + } + responseDifference struct { + expected *response + actual *response + } + prpDifference struct { + results *resultDifference + response *responseDifference + event *eventDifference + } + readset map[string]uint64 + writeset map[string][]byte + metaset map[string]writeset + readwriteset struct { + r readset + w writeset + p writeset + m metaset + } + nsRWsets map[string]readwriteset +) + +func (rwd *resultDifference) addReadDiff(ns string, key string, expected uint64, actual uint64) { + rwd.reads = append(rwd.reads, &readDifference{ + baseDifference: &baseDifference{ + namespace: ns, + key: key, + }, + expected: expected, + actual: actual, + }) +} + +func (rwd *resultDifference) addWriteDiff(ns string, key string, expected []byte, actual []byte) { + rwd.writes = append(rwd.writes, &writeDifference{ + baseDifference: &baseDifference{ + namespace: ns, + key: key, + }, + expected: expected, + actual: actual, + }) +} + +func (rwd *resultDifference) addMetadataWriteDiff(ns string, key string, name string, expected []byte, actual []byte) { + rwd.metawrites = append(rwd.metawrites, &metadataDifference{ + writeDifference: &writeDifference{ + baseDifference: &baseDifference{ + namespace: ns, + key: key, + }, + expected: expected, + actual: actual, + }, + name: name, + }) +} + +func (rwd *resultDifference) addPvtHashDiff(ns string, collection string, expected []byte, actual []byte) { + rwd.private = append(rwd.private, &pvtHashDifference{ + writeDifference: &writeDifference{ + baseDifference: &baseDifference{ + namespace: ns, + key: collection, + }, + expected: expected, + actual: actual, + }, + }) +} + +func payloadDifference(payload1, payload2 []byte) (*prpDifference, error) { + prp1, err := protoutil.UnmarshalProposalResponsePayload(payload1) + if err != nil { + return nil, err + } + prp2, err := protoutil.UnmarshalProposalResponsePayload(payload2) + if err != nil { + return nil, err + } + + ca1, err := protoutil.UnmarshalChaincodeAction(prp1.GetExtension()) + if err != nil { + return nil, err + } + ca2, err := protoutil.UnmarshalChaincodeAction(prp2.GetExtension()) + if err != nil { + return nil, err + } + + rwDiff, err := rwsetDifference(ca1.GetResults(), ca2.GetResults()) + if err != nil { + return nil, err + } + + respDiff := responseDiff(ca1.GetResponse(), ca2.GetResponse()) + + evDiff, err := eventDiff(ca1.GetEvents(), ca2.GetEvents()) + if err != nil { + return nil, err + } + + return &prpDifference{ + results: rwDiff, + response: respDiff, + event: evDiff, + }, nil +} + +func rwsetDifference(rwset1, rwset2 []byte) (*resultDifference, error) { + if bytes.Equal(rwset1, rwset2) { + return nil, nil + } + + txrw1, err := protoutil.UnmarshalTxReadWriteSet(rwset1) + if err != nil { + return nil, err + } + + txrw2, err := protoutil.UnmarshalTxReadWriteSet(rwset2) + if err != nil { + return nil, err + } + + summarySet := nsRWsets{} + rwDiff := &resultDifference{} + + for _, txrw := range txrw1.NsRwset { + reads := readset{} + writes := writeset{} + pvtHashes := writeset{} + metadata := metaset{} + kvrws, err := protoutil.UnmarshalKVRWSet(txrw.Rwset) + if err != nil { + return nil, err + } + for _, r := range kvrws.Reads { + reads[r.Key] = r.Version.BlockNum + } + for _, w := range kvrws.Writes { + writes[w.Key] = w.Value + } + for _, mw := range kvrws.MetadataWrites { + entryset := writeset{} + for _, me := range mw.Entries { + entryset[me.Name] = me.Value + } + metadata[mw.Key] = entryset + } + for _, chrws := range txrw.GetCollectionHashedRwset() { + pvtHashes[chrws.CollectionName] = chrws.PvtRwsetHash + } + summarySet[txrw.Namespace] = readwriteset{r: reads, w: writes, m: metadata, p: pvtHashes} + } + for _, txrw := range txrw2.NsRwset { + var reads readset + var writes writeset + var pvtHashes writeset + var metadata metaset + if rw, ok := summarySet[txrw.Namespace]; ok { + reads = rw.r + writes = rw.w + metadata = rw.m + pvtHashes = rw.p + } + kvrws, err := protoutil.UnmarshalKVRWSet(txrw.Rwset) + if err != nil { + return nil, err + } + for _, r := range kvrws.Reads { + block := reads[r.Key] // missing entry will be represented by the zero value + if block != r.Version.BlockNum { + // state is at different version (or not present in rwset1 if block is zero) + rwDiff.addReadDiff(txrw.Namespace, r.Key, block, r.Version.BlockNum) + } + delete(reads, r.Key) + } + for _, w := range kvrws.Writes { + value := writes[w.Key] + if !bytes.Equal(value, w.Value) { + // state writes different value (or not present in rwset1 if value is nil) + rwDiff.addWriteDiff(txrw.Namespace, w.Key, value, w.Value) + } + delete(writes, w.Key) + } + for _, mw := range kvrws.MetadataWrites { + expected := metadata[mw.Key] + for _, e := range mw.Entries { + value := expected[e.Name] + if !bytes.Equal(value, e.Value) { + rwDiff.addMetadataWriteDiff(txrw.Namespace, mw.Key, e.Name, value, e.Value) + } + delete(expected, e.Name) + } + } + for _, chrws := range txrw.GetCollectionHashedRwset() { + hash := pvtHashes[chrws.CollectionName] + if !bytes.Equal(hash, chrws.PvtRwsetHash) { + // state writes different value (or not present in rwset1 if value is nil) + rwDiff.addPvtHashDiff(txrw.Namespace, chrws.CollectionName, hash, chrws.PvtRwsetHash) + } + delete(pvtHashes, chrws.CollectionName) + } + } + // whatever is left in the summary set is present in rwset1 but not rwset2 + for ns, rw := range summarySet { + for key, block := range rw.r { + rwDiff.addReadDiff(ns, key, block, 0) + } + for key, value := range rw.w { + rwDiff.addWriteDiff(ns, key, value, nil) + } + for key, entries := range rw.m { + for name, value := range entries { + rwDiff.addMetadataWriteDiff(ns, key, name, value, nil) + } + } + for coll, hash := range rw.p { + rwDiff.addPvtHashDiff(ns, coll, hash, nil) + } + } + + return rwDiff, nil +} + +func responseDiff(resp1, resp2 *peer.Response) *responseDifference { + if resp1.GetStatus() == resp2.GetStatus() && + resp1.GetMessage() == resp2.GetMessage() && + bytes.Equal(resp1.GetPayload(), resp2.GetPayload()) { + return nil + } + return &responseDifference{ + expected: &response{ + status: resp1.GetStatus(), + message: resp1.GetMessage(), + payload: resp1.GetPayload(), + }, + actual: &response{ + status: resp2.GetStatus(), + message: resp2.GetMessage(), + payload: resp2.GetPayload(), + }, + } +} + +func eventDiff(ev1, ev2 []byte) (*eventDifference, error) { + if bytes.Equal(ev1, ev2) { + return nil, nil + } + + expected, err := protoutil.UnmarshalChaincodeEvents(ev1) + if err != nil { + return nil, err + } + + actual, err := protoutil.UnmarshalChaincodeEvents(ev2) + if err != nil { + return nil, err + } + + return &eventDifference{ + expected: &ccEvent{ + chaincodeId: expected.GetChaincodeId(), + name: expected.GetEventName(), + payload: expected.GetPayload(), + }, + actual: &ccEvent{ + chaincodeId: actual.GetChaincodeId(), + name: actual.GetEventName(), + payload: actual.GetPayload(), + }, + }, nil +} + +// returns key/value pairs for passing to the logger.Debugw function +func (rd *readDifference) info() []interface{} { + description := "read value mismatch" + if rd.expected == 0 { + description = "extraneous read" + } else if rd.actual == 0 { + description = "missing read" + } + return []interface{}{ + "type", description, + "namespace", rd.namespace, + "key", rd.key, + "expected value", fmt.Sprintf("%d", rd.expected), + "actual value", fmt.Sprintf("%d", rd.actual), + } +} + +func (wd *writeDifference) info() []interface{} { + description := "write value mismatch" + if wd.expected == nil { + description = "extraneous write" + } else if wd.actual == nil { + description = "missing write" + } + return []interface{}{ + "type", description, + "namespace", wd.namespace, + "key", wd.key, + "expected value", string(wd.expected), + "actual value", string(wd.actual), + } +} + +func (wd *pvtHashDifference) info() []interface{} { + return []interface{}{ + "type", "private collection hash mismatch", + "namespace", wd.namespace, + "collection", wd.key, + "expected hash", hex.EncodeToString(wd.expected), + "actual hash", hex.EncodeToString(wd.actual), + } +} + +func (md *metadataDifference) info() []interface{} { + description := "write metadata mismatch" + if md.expected == nil { + description = "extraneous metadata write" + } else if md.actual == nil { + description = "missing metadata write" + } + var expected string + var actual string + if md.name == "VALIDATION_PARAMETER" { + // this is a SBE policy - unmarshall it + description += " (SBE policy)" + sbeA, err := protoutil.UnmarshalSignaturePolicy(md.expected) + if err != nil { + expected = fmt.Sprintf("Error unmarshalling SBE policy: %s", err) + } else { + expected = fmt.Sprintf("%v", sbeA) + } + sbeB, err := protoutil.UnmarshalSignaturePolicy(md.actual) + if err != nil { + actual = fmt.Sprintf("Error unmarshalling SBE policy: %s", err) + } else { + actual = fmt.Sprintf("%v", sbeB) + } + } else { + expected = string(md.expected) + actual = string(md.actual) + } + return []interface{}{ + "type", description, + "namespace", md.namespace, + "key", md.key, + "name", md.name, + "expected value", expected, + "actual value", actual, + } +} + +func (ev *eventDifference) info() []interface{} { + return []interface{}{ + "type", "chaincode event mismatch", + "expected", fmt.Sprintf("chaincodeId: %s, name: %s, value: %s", ev.expected.chaincodeId, ev.expected.name, ev.expected.payload), + "actual", fmt.Sprintf("chaincodeId: %s, name: %s, value: %s", ev.actual.chaincodeId, ev.actual.name, ev.actual.payload), + } +} + +func (resp *responseDifference) info() []interface{} { + return []interface{}{ + "type", "chaincode response mismatch", + "expected", fmt.Sprintf("status: %d, message: %s, payload: %s", resp.expected.status, resp.expected.message, resp.expected.payload), + "actual", fmt.Sprintf("status: %d, message: %s, payload: %s", resp.actual.status, resp.actual.message, resp.actual.payload), + } +} + +func (diff *prpDifference) details() [][]interface{} { + var details [][]interface{} + if diff.results != nil { + for _, rd := range diff.results.reads { + details = append(details, rd.info()) + } + for _, wd := range diff.results.writes { + details = append(details, wd.info()) + } + for _, md := range diff.results.metawrites { + details = append(details, md.info()) + } + for _, pd := range diff.results.private { + details = append(details, pd.info()) + } + } + if diff.event != nil { + details = append(details, diff.event.info()) + } + if diff.response != nil { + details = append(details, diff.response.info()) + } + return details +} diff --git a/internal/pkg/gateway/apiutils_test.go b/internal/pkg/gateway/apiutils_test.go new file mode 100644 index 00000000000..ebdc2f4bdc0 --- /dev/null +++ b/internal/pkg/gateway/apiutils_test.go @@ -0,0 +1,515 @@ +/* +Copyright 2022 IBM All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package gateway + +import ( + "testing" + + "github.com/hyperledger/fabric-protos-go/common" + "github.com/hyperledger/fabric-protos-go/ledger/rwset" + "github.com/hyperledger/fabric-protos-go/ledger/rwset/kvrwset" + "github.com/hyperledger/fabric-protos-go/msp" + "github.com/hyperledger/fabric-protos-go/peer" + "github.com/stretchr/testify/require" +) + +type readT struct { + namespace string + key string + block uint64 +} + +type writeT struct { + namespace string + key string + value []byte +} + +type metaWriteT struct { + namespace string + key string + name string + value []byte +} + +type pvtCollectionT struct { + namespace string + collection string + hash []byte +} + +type responseT struct { + status int32 + message string + payload []byte +} + +type eventT struct { + namespace string + name string + payload []byte + txid string +} + +func TestPayloadDifferenceReadVersion(t *testing.T) { + rpl1 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{ + {namespace: "ns1", key: "key1", block: 4}, + {namespace: "ns1", key: "key2", block: 4}, + }, + []*writeT{}, + []*metaWriteT{}, + []*pvtCollectionT{}, + nil, + ) + + rpl2 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{ + {namespace: "ns1", key: "key1", block: 4}, + {namespace: "ns1", key: "key2", block: 5}, + }, + []*writeT{}, + []*metaWriteT{}, + []*pvtCollectionT{}, + nil, + ) + + rpl1Bytes := marshal(rpl1, t) + rpl2Bytes := marshal(rpl2, t) + + diff, err := payloadDifference(rpl1Bytes, rpl2Bytes) + require.NoError(t, err) + + expected := [][]interface{}{ + {"type", "read value mismatch", "namespace", "ns1", "key", "key2", "expected value", "4", "actual value", "5"}, + } + require.ElementsMatch(t, expected, diff.details()) +} + +func TestPayloadDifferenceReadMissing(t *testing.T) { + rpl1 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{ + {namespace: "ns1", key: "key1", block: 4}, + {namespace: "ns1", key: "key2", block: 4}, + }, + []*writeT{}, + []*metaWriteT{}, + []*pvtCollectionT{}, + nil, + ) + + rpl2 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{ + {namespace: "ns1", key: "key1", block: 4}, + }, + []*writeT{}, + []*metaWriteT{}, + []*pvtCollectionT{}, + nil, + ) + + rpl1Bytes := marshal(rpl1, t) + rpl2Bytes := marshal(rpl2, t) + + diff, err := payloadDifference(rpl1Bytes, rpl2Bytes) + require.NoError(t, err) + + expected := [][]interface{}{ + {"type", "missing read", "namespace", "ns1", "key", "key2", "expected value", "4", "actual value", "0"}, + } + require.ElementsMatch(t, expected, diff.details()) +} + +func TestPayloadDifferenceReadExtra(t *testing.T) { + rpl1 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{ + {namespace: "ns1", key: "key1", block: 4}, + {namespace: "ns1", key: "key2", block: 5}, + {namespace: "ns2", key: "key1b", block: 4}, + {namespace: "ns2", key: "key2b", block: 5}, + }, + []*writeT{}, + []*metaWriteT{}, + []*pvtCollectionT{}, + nil, + ) + + rpl2 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{ + {namespace: "ns1", key: "key1", block: 4}, + {namespace: "ns1", key: "key2", block: 5}, + {namespace: "ns1", key: "key3", block: 3}, + {namespace: "ns2", key: "key1b", block: 4}, + {namespace: "ns2", key: "key2b", block: 5}, + {namespace: "ns2", key: "key3b", block: 5}, + }, + []*writeT{}, + []*metaWriteT{}, + []*pvtCollectionT{}, + nil, + ) + + rpl1Bytes := marshal(rpl1, t) + rpl2Bytes := marshal(rpl2, t) + + diff, err := payloadDifference(rpl1Bytes, rpl2Bytes) + require.NoError(t, err) + + expected := [][]interface{}{ + {"type", "extraneous read", "namespace", "ns1", "key", "key3", "expected value", "0", "actual value", "3"}, + {"type", "extraneous read", "namespace", "ns2", "key", "key3b", "expected value", "0", "actual value", "5"}, + } + require.ElementsMatch(t, expected, diff.details()) +} + +func TestPayloadDifferenceWriteValue(t *testing.T) { + rpl1 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{}, + []*writeT{ + {namespace: "ns1", key: "key1", value: []byte("value1")}, + {namespace: "ns1", key: "key2", value: []byte("value2")}, + {namespace: "ns1", key: "key3", value: []byte("value3")}, + }, + []*metaWriteT{}, + []*pvtCollectionT{}, + nil, + ) + + rpl2 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{}, + []*writeT{ + {namespace: "ns1", key: "key1", value: []byte("value1")}, + {namespace: "ns1", key: "key2", value: []byte("value3")}, + {namespace: "ns1", key: "key4", value: []byte("value4")}, + }, + []*metaWriteT{}, + []*pvtCollectionT{}, + nil, + ) + + rpl1Bytes := marshal(rpl1, t) + rpl2Bytes := marshal(rpl2, t) + + diff, err := payloadDifference(rpl1Bytes, rpl2Bytes) + require.NoError(t, err) + + expected := [][]interface{}{ + {"type", "write value mismatch", "namespace", "ns1", "key", "key2", "expected value", "value2", "actual value", "value3"}, + {"type", "missing write", "namespace", "ns1", "key", "key3", "expected value", "value3", "actual value", ""}, + {"type", "extraneous write", "namespace", "ns1", "key", "key4", "expected value", "", "actual value", "value4"}, + } + require.ElementsMatch(t, expected, diff.details()) +} + +func TestPayloadDifferenceMetadata(t *testing.T) { + rpl1 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{}, + []*writeT{}, + []*metaWriteT{ + {namespace: "ns1", key: "key1", name: "meta1", value: []byte("value1")}, + {namespace: "ns2", key: "key2", name: "meta2", value: []byte("mv1")}, + }, + []*pvtCollectionT{}, + nil, + ) + + rpl2 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{}, + []*writeT{}, + []*metaWriteT{ + {namespace: "ns1", key: "key1", name: "meta1", value: []byte("value2")}, + {namespace: "ns3", key: "key2", name: "meta2", value: []byte("mv1")}, + }, + []*pvtCollectionT{}, + nil, + ) + + rpl1Bytes := marshal(rpl1, t) + rpl2Bytes := marshal(rpl2, t) + + diff, err := payloadDifference(rpl1Bytes, rpl2Bytes) + require.NoError(t, err) + + expected := [][]interface{}{ + {"type", "write metadata mismatch", "namespace", "ns1", "key", "key1", "name", "meta1", "expected value", "value1", "actual value", "value2"}, + {"type", "missing metadata write", "namespace", "ns2", "key", "key2", "name", "meta2", "expected value", "mv1", "actual value", ""}, + {"type", "extraneous metadata write", "namespace", "ns3", "key", "key2", "name", "meta2", "expected value", "", "actual value", "mv1"}, + } + require.ElementsMatch(t, expected, diff.details()) +} + +func TestPayloadDifferenceSBEPolicy(t *testing.T) { + sbe1 := &common.SignaturePolicyEnvelope{ + Rule: &common.SignaturePolicy{ + Type: &common.SignaturePolicy_NOutOf_{ + NOutOf: &common.SignaturePolicy_NOutOf{ + N: 1, + Rules: []*common.SignaturePolicy{ + {Type: &common.SignaturePolicy_SignedBy{SignedBy: 0}}, + }, + }, + }, + }, + Identities: []*msp.MSPPrincipal{ + {Principal: []byte("orgA")}, + }, + } + + sbe2 := &common.SignaturePolicyEnvelope{ + Rule: &common.SignaturePolicy{ + Type: &common.SignaturePolicy_NOutOf_{ + NOutOf: &common.SignaturePolicy_NOutOf{ + N: 1, + Rules: []*common.SignaturePolicy{ + {Type: &common.SignaturePolicy_SignedBy{SignedBy: 0}}, + }, + }, + }, + }, + Identities: []*msp.MSPPrincipal{ + {Principal: []byte("orgB")}, + }, + } + + rpl1 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{}, + []*writeT{}, + []*metaWriteT{ + {namespace: "ns1", key: "key1", name: "VALIDATION_PARAMETER", value: marshal(sbe1, t)}, + {namespace: "ns1", key: "key2", name: "VALIDATION_PARAMETER", value: marshal(sbe1, t)}, + }, + []*pvtCollectionT{}, + nil, + ) + + rpl2 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{}, + []*writeT{}, + []*metaWriteT{ + {namespace: "ns1", key: "key1", name: "VALIDATION_PARAMETER", value: marshal(sbe2, t)}, + }, + []*pvtCollectionT{}, + nil, + ) + + rpl1Bytes := marshal(rpl1, t) + rpl2Bytes := marshal(rpl2, t) + + diff, err := payloadDifference(rpl1Bytes, rpl2Bytes) + require.NoError(t, err) + + expected := [][]interface{}{ + {"type", "write metadata mismatch (SBE policy)", "namespace", "ns1", "key", "key1", "name", "VALIDATION_PARAMETER", "expected value", "rule: > > identities: ", "actual value", "rule: > > identities: "}, + {"type", "missing metadata write (SBE policy)", "namespace", "ns1", "key", "key2", "name", "VALIDATION_PARAMETER", "expected value", "rule: > > identities: ", "actual value", ""}, + } + require.ElementsMatch(t, expected, diff.details()) +} + +func TestPayloadDifferenceChaincodeResponse(t *testing.T) { + rpl1 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value1"), status: 200, message: "no error"}, + []*readT{}, + []*writeT{}, + []*metaWriteT{}, + []*pvtCollectionT{}, + nil, + ) + + rpl2 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value2"), status: 200, message: "no error"}, + []*readT{}, + []*writeT{}, + []*metaWriteT{}, + []*pvtCollectionT{}, + nil, + ) + + rpl1Bytes := marshal(rpl1, t) + rpl2Bytes := marshal(rpl2, t) + + diff, err := payloadDifference(rpl1Bytes, rpl2Bytes) + require.NoError(t, err) + + expected := [][]interface{}{ + {"type", "chaincode response mismatch", "expected", "status: 200, message: no error, payload: my_value1", "actual", "status: 200, message: no error, payload: my_value2"}, + } + require.ElementsMatch(t, expected, diff.details()) +} + +func TestPayloadDifferencePrivateData(t *testing.T) { + rpl1 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{}, + []*writeT{ + {namespace: "ns1", key: "key1", value: []byte("value1")}, + }, + []*metaWriteT{}, + []*pvtCollectionT{ + {namespace: "ns1", collection: "collection1", hash: []byte{1, 2, 3}}, + }, + nil, + ) + + rpl2 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{}, + []*writeT{ + {namespace: "ns1", key: "key1", value: []byte("value1")}, + }, + []*metaWriteT{}, + []*pvtCollectionT{ + {namespace: "ns1", collection: "collection1", hash: []byte{4, 5, 6}}, + }, + nil, + ) + + rpl1Bytes := marshal(rpl1, t) + rpl2Bytes := marshal(rpl2, t) + + diff, err := payloadDifference(rpl1Bytes, rpl2Bytes) + require.NoError(t, err) + + expected := [][]interface{}{ + {"type", "private collection hash mismatch", "namespace", "ns1", "collection", "collection1", "expected hash", "010203", "actual hash", "040506"}, + } + require.ElementsMatch(t, expected, diff.details()) +} + +func TestPayloadDifferenceEvent(t *testing.T) { + rpl1 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{}, + []*writeT{}, + []*metaWriteT{}, + []*pvtCollectionT{}, + &eventT{namespace: "ns1", name: "my_event", payload: []byte("my event payload 1")}, + ) + + rpl2 := createProposalResponsePayload( + t, &responseT{payload: []byte("my_value"), status: 200, message: "no error"}, + []*readT{}, + []*writeT{}, + []*metaWriteT{}, + []*pvtCollectionT{}, + &eventT{namespace: "ns1", name: "my_event", payload: []byte("my event payload 2")}, + ) + + rpl1Bytes := marshal(rpl1, t) + rpl2Bytes := marshal(rpl2, t) + + diff, err := payloadDifference(rpl1Bytes, rpl2Bytes) + require.NoError(t, err) + + expected := [][]interface{}{ + {"type", "chaincode event mismatch", "expected", "chaincodeId: ns1, name: my_event, value: my event payload 1", "actual", "chaincodeId: ns1, name: my_event, value: my event payload 2"}, + } + require.ElementsMatch(t, expected, diff.details()) +} + +func createProposalResponsePayload(t *testing.T, response *responseT, reads []*readT, writes []*writeT, metaWrites []*metaWriteT, pvtData []*pvtCollectionT, event *eventT) *peer.ProposalResponsePayload { + resp := &peer.Response{ + Status: response.status, + Payload: response.payload, + Message: response.message, + } + + rwset := &rwset.TxReadWriteSet{ + DataModel: rwset.TxReadWriteSet_KV, + NsRwset: collateReadWriteSets(t, reads, writes, metaWrites, pvtData), + } + + action := &peer.ChaincodeAction{ + Response: resp, + Results: marshal(rwset, t), + } + + if event != nil { + ccEvent := &peer.ChaincodeEvent{ + ChaincodeId: event.namespace, + TxId: event.txid, + EventName: event.name, + Payload: event.payload, + } + + action.Events = marshal(ccEvent, t) + } + + payload := &peer.ProposalResponsePayload{ + ProposalHash: []byte{}, + Extension: marshal(action, t), + } + + return payload +} + +func collateReadWriteSets(t *testing.T, reads []*readT, writes []*writeT, metaWrites []*metaWriteT, pvtData []*pvtCollectionT) []*rwset.NsReadWriteSet { + grouped := map[string]*kvrwset.KVRWSet{} + collections := map[string][]*rwset.CollectionHashedReadWriteSet{} + + for _, r := range reads { + rwset := grouped[r.namespace] + if rwset == nil { + rwset = &kvrwset.KVRWSet{} + grouped[r.namespace] = rwset + } + rwset.Reads = append(rwset.Reads, &kvrwset.KVRead{ + Key: r.key, + Version: &kvrwset.Version{BlockNum: r.block}, + }) + } + for _, w := range writes { + rwset := grouped[w.namespace] + if rwset == nil { + rwset = &kvrwset.KVRWSet{} + grouped[w.namespace] = rwset + } + rwset.Writes = append(rwset.Writes, &kvrwset.KVWrite{ + Key: w.key, + Value: w.value, + }) + } + for _, mw := range metaWrites { + rwset := grouped[mw.namespace] + if rwset == nil { + rwset = &kvrwset.KVRWSet{} + grouped[mw.namespace] = rwset + } + rwset.MetadataWrites = append(rwset.MetadataWrites, &kvrwset.KVMetadataWrite{ + Key: mw.key, + Entries: []*kvrwset.KVMetadataEntry{{Name: mw.name, Value: mw.value}}, // support single entry for now + }) + } + + for _, pd := range pvtData { + collections[pd.namespace] = append(collections[pd.namespace], &rwset.CollectionHashedReadWriteSet{ + CollectionName: pd.collection, + PvtRwsetHash: pd.hash, + }) + } + + var rwsets []*rwset.NsReadWriteSet + for ns, rws := range grouped { + rwsets = append(rwsets, &rwset.NsReadWriteSet{ + Namespace: ns, + Rwset: marshal(rws, t), + CollectionHashedRwset: collections[ns], + }) + } + return rwsets +} diff --git a/internal/pkg/gateway/endorsement.go b/internal/pkg/gateway/endorsement.go index b3d3d4359af..0174a63aadb 100644 --- a/internal/pkg/gateway/endorsement.go +++ b/internal/pkg/gateway/endorsement.go @@ -13,6 +13,7 @@ import ( "github.com/golang/protobuf/proto" "github.com/hyperledger/fabric-protos-go/peer" + "go.uber.org/zap/zapcore" ) type layout struct { @@ -114,6 +115,17 @@ func (p *plan) processEndorsement(endorser *endorser, response *peer.ProposalRes } else { if !bytes.Equal(p.responsePayload, response.GetPayload()) { logger.Warnw("ProposalResponsePayloads do not match (base64)", "payload1", b64.StdEncoding.EncodeToString(p.responsePayload), "payload2", b64.StdEncoding.EncodeToString(response.GetPayload())) + if logger.IsEnabledFor(zapcore.DebugLevel) { + diff, err := payloadDifference(p.responsePayload, response.GetPayload()) + if err != nil { + logger.Debugf("Failed to analyse response mismatch: %s", err) + } else { + logger.Debugw("Compared to the initial endorser's response, the following debug log entries detail the differences in this endorser's response.", "address", endorser.address, "mspid", endorser.mspid) + for _, d := range diff.details() { + logger.Debugw("Proposal response mismatch:", d...) + } + } + } p.errorDetails = append(p.errorDetails, errorDetail(endorser.endpointConfig, "ProposalResponsePayloads do not match")) return false }