Skip to content

Commit

Permalink
Improve response mismatch logging
Browse files Browse the repository at this point in the history 
This commit addresses some comments (#3420 (review)) made on the original PR for this feature as follows:
- The mismatch details are logged as warnings through a new logger “gateway.responsechecker”.  This is enabled by default but can be disabled by setting the log level to “error” for this logger.
- Each log message contains the address/mspid of the initial endorser and ’this’ endorser.  The ‘expected’ &’ actual’ values have been renamed ‘initial’ and ‘this’ accordingly.
- Spaces in the insert names have been replaced by hyphens for improved readability since the logger removes the spaces in the output.
- The base64 encoded protobuf responses have been removed from the log since they are now redundant.

Signed-off-by: andrew-coleman <andrew_coleman@uk.ibm.com>
(cherry picked from commit a91c633)
  • Loading branch information
@andrew-coleman @mergify
andrew-coleman authored and mergify[bot] committed May 23, 2022
1 parent 29fea4f commit f4e897f
Show file tree
Hide file tree
Showing 4 changed files with 71 additions and 35 deletions.
36 changes: 34 additions & 2 deletions internal/pkg/gateway/api_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -777,8 +777,6 @@ func TestEndorse(t *testing.T) {
},
},
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") {
Expand All @@ -793,6 +791,40 @@ func TestEndorse(t *testing.T) {
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.SetObserver(nil)
},
},
{
name: "non-matching response logging suppressed",
plan: endorsementPlan{
"g1": {{endorser: localhostMock, height: 4}}, // msp1
"g2": {{endorser: peer2Mock, height: 5}}, // msp2
},
localResponse: "different_response",
errCode: codes.Aborted,
errString: "failed to collect enough transaction endorsements",
errDetails: []*pb.ErrorDetail{
{
Address: "peer2:9051",
MspId: "msp2",
Message: "ProposalResponsePayloads do not match",
},
},
postSetup: func(t *testing.T, def *preparedTest) {
def.logLevel = flogging.LoggerLevel("gateway.responsechecker")
flogging.ActivateSpec("error")
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.Empty(t, def.logFields)
flogging.ActivateSpec(def.logLevel)
flogging.SetObserver(nil)
},
Expand Down
24 changes: 12 additions & 12 deletions internal/pkg/gateway/apiutils.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -455,8 +455,8 @@ func (rd *readDifference) info() []interface{} {
"type", description,
"namespace", rd.namespace,
"key", rd.key,
"expected value", fmt.Sprintf("%d", rd.expected),
"actual value", fmt.Sprintf("%d", rd.actual),
"initial-endorser-value", fmt.Sprintf("%d", rd.expected),
"invoked-endorser-value", fmt.Sprintf("%d", rd.actual),
}
}

Expand All @@ -471,8 +471,8 @@ func (wd *writeDifference) info() []interface{} {
"type", description,
"namespace", wd.namespace,
"key", wd.key,
"expected value", string(wd.expected),
"actual value", string(wd.actual),
"initial-endorser-value", string(wd.expected),
"invoked-endorser-value", string(wd.actual),
}
}

Expand All @@ -481,8 +481,8 @@ func (wd *pvtHashDifference) info() []interface{} {
"type", "private collection hash mismatch",
"namespace", wd.namespace,
"collection", wd.key,
"expected hash", hex.EncodeToString(wd.expected),
"actual hash", hex.EncodeToString(wd.actual),
"initial-endorser-hash", hex.EncodeToString(wd.expected),
"invoked-endorser-hash", hex.EncodeToString(wd.actual),
}
}

Expand Down Expand Up @@ -519,24 +519,24 @@ func (md *metadataDifference) info() []interface{} {
"namespace", md.namespace,
"key", md.key,
"name", md.name,
"expected value", expected,
"actual value", actual,
"initial-endorser-value", expected,
"invoked-endorser-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),
"initial-endorser-event", fmt.Sprintf("chaincodeId: %s, name: %s, value: %s", ev.expected.chaincodeId, ev.expected.name, ev.expected.payload),
"invoked-endorser-event", 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),
"initial-endorser-response", fmt.Sprintf("status: %d, message: %s, payload: %s", resp.expected.status, resp.expected.message, resp.expected.payload),
"invoked-endorser-response", fmt.Sprintf("status: %d, message: %s, payload: %s", resp.actual.status, resp.actual.message, resp.actual.payload),
}
}

Expand Down
30 changes: 15 additions & 15 deletions internal/pkg/gateway/apiutils_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -87,7 +87,7 @@ func TestPayloadDifferenceReadVersion(t *testing.T) {
require.NoError(t, err)

expected := [][]interface{}{
{"type", "read value mismatch", "namespace", "ns1", "key", "key2", "expected value", "4", "actual value", "5"},
{"type", "read value mismatch", "namespace", "ns1", "key", "key2", "initial-endorser-value", "4", "invoked-endorser-value", "5"},
}
require.ElementsMatch(t, expected, diff.details())
}
Expand Down Expand Up @@ -123,7 +123,7 @@ func TestPayloadDifferenceReadMissing(t *testing.T) {
require.NoError(t, err)

expected := [][]interface{}{
{"type", "missing read", "namespace", "ns1", "key", "key2", "expected value", "4", "actual value", "0"},
{"type", "missing read", "namespace", "ns1", "key", "key2", "initial-endorser-value", "4", "invoked-endorser-value", "0"},
}
require.ElementsMatch(t, expected, diff.details())
}
Expand Down Expand Up @@ -166,8 +166,8 @@ func TestPayloadDifferenceReadExtra(t *testing.T) {
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"},
{"type", "extraneous read", "namespace", "ns1", "key", "key3", "initial-endorser-value", "0", "invoked-endorser-value", "3"},
{"type", "extraneous read", "namespace", "ns2", "key", "key3b", "initial-endorser-value", "0", "invoked-endorser-value", "5"},
}
require.ElementsMatch(t, expected, diff.details())
}
Expand Down Expand Up @@ -206,9 +206,9 @@ func TestPayloadDifferenceWriteValue(t *testing.T) {
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"},
{"type", "write value mismatch", "namespace", "ns1", "key", "key2", "initial-endorser-value", "value2", "invoked-endorser-value", "value3"},
{"type", "missing write", "namespace", "ns1", "key", "key3", "initial-endorser-value", "value3", "invoked-endorser-value", ""},
{"type", "extraneous write", "namespace", "ns1", "key", "key4", "initial-endorser-value", "", "invoked-endorser-value", "value4"},
}
require.ElementsMatch(t, expected, diff.details())
}
Expand Down Expand Up @@ -245,9 +245,9 @@ func TestPayloadDifferenceMetadata(t *testing.T) {
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"},
{"type", "write metadata mismatch", "namespace", "ns1", "key", "key1", "name", "meta1", "initial-endorser-value", "value1", "invoked-endorser-value", "value2"},
{"type", "missing metadata write", "namespace", "ns2", "key", "key2", "name", "meta2", "initial-endorser-value", "mv1", "invoked-endorser-value", ""},
{"type", "extraneous metadata write", "namespace", "ns3", "key", "key2", "name", "meta2", "initial-endorser-value", "", "invoked-endorser-value", "mv1"},
}
require.ElementsMatch(t, expected, diff.details())
}
Expand Down Expand Up @@ -315,8 +315,8 @@ func TestPayloadDifferenceSBEPolicy(t *testing.T) {
require.NoError(t, err)

expected := [][]interface{}{
{"type", "write metadata mismatch (SBE policy)", "namespace", "ns1", "key", "key1", "name", "VALIDATION_PARAMETER", "expected value", "rule:<n_out_of:<n:1 rules:<signed_by:0 > > > identities:<principal:\"orgA\" > ", "actual value", "rule:<n_out_of:<n:1 rules:<signed_by:0 > > > identities:<principal:\"orgB\" > "},
{"type", "missing metadata write (SBE policy)", "namespace", "ns1", "key", "key2", "name", "VALIDATION_PARAMETER", "expected value", "rule:<n_out_of:<n:1 rules:<signed_by:0 > > > identities:<principal:\"orgA\" > ", "actual value", ""},
{"type", "write metadata mismatch (SBE policy)", "namespace", "ns1", "key", "key1", "name", "VALIDATION_PARAMETER", "initial-endorser-value", "rule:<n_out_of:<n:1 rules:<signed_by:0 > > > identities:<principal:\"orgA\" > ", "invoked-endorser-value", "rule:<n_out_of:<n:1 rules:<signed_by:0 > > > identities:<principal:\"orgB\" > "},
{"type", "missing metadata write (SBE policy)", "namespace", "ns1", "key", "key2", "name", "VALIDATION_PARAMETER", "initial-endorser-value", "rule:<n_out_of:<n:1 rules:<signed_by:0 > > > identities:<principal:\"orgA\" > ", "invoked-endorser-value", ""},
}
require.ElementsMatch(t, expected, diff.details())
}
Expand Down Expand Up @@ -347,7 +347,7 @@ func TestPayloadDifferenceChaincodeResponse(t *testing.T) {
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"},
{"type", "chaincode response mismatch", "initial-endorser-response", "status: 200, message: no error, payload: my_value1", "invoked-endorser-response", "status: 200, message: no error, payload: my_value2"},
}
require.ElementsMatch(t, expected, diff.details())
}
Expand Down Expand Up @@ -386,7 +386,7 @@ func TestPayloadDifferencePrivateData(t *testing.T) {
require.NoError(t, err)

expected := [][]interface{}{
{"type", "private collection hash mismatch", "namespace", "ns1", "collection", "collection1", "expected hash", "010203", "actual hash", "040506"},
{"type", "private collection hash mismatch", "namespace", "ns1", "collection", "collection1", "initial-endorser-hash", "010203", "invoked-endorser-hash", "040506"},
}
require.ElementsMatch(t, expected, diff.details())
}
Expand Down Expand Up @@ -417,7 +417,7 @@ func TestPayloadDifferenceEvent(t *testing.T) {
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"},
{"type", "chaincode event mismatch", "initial-endorser-event", "chaincodeId: ns1, name: my_event, value: my event payload 1", "invoked-endorser-event", "chaincodeId: ns1, name: my_event, value: my event payload 2"},
}
require.ElementsMatch(t, expected, diff.details())
}
Expand Down
16 changes: 10 additions & 6 deletions internal/pkg/gateway/endorsement.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,11 +8,12 @@ package gateway

import (
"bytes"
b64 "encoding/base64"
"fmt"
"sync"

"github.com/golang/protobuf/proto"
"github.com/hyperledger/fabric-protos-go/peer"
"github.com/hyperledger/fabric/common/flogging"
"go.uber.org/zap/zapcore"
)

Expand All @@ -36,6 +37,7 @@ type plan struct {
completedLayout *layout
errorDetails []proto.Message
planLock sync.Mutex
mismatchLogger *flogging.FabricLogger
}

// construct and initialise an endorsement plan
Expand Down Expand Up @@ -112,17 +114,19 @@ func (p *plan) processEndorsement(endorser *endorser, response *peer.ProposalRes
// check the proposal responses are the same
if p.responsePayload == nil {
p.responsePayload = response.GetPayload()
p.mismatchLogger = flogging.MustGetLogger("gateway.responsechecker").With("initial-endorser", fmt.Sprintf("%s (%s)", endorser.address, endorser.mspid))
} 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) {
logger.Warn("ProposalResponsePayloads do not match. See [gateway.responsechecker] log warnings for details.")
if p.mismatchLogger.IsEnabledFor(zapcore.WarnLevel) {
mismatchLogger := p.mismatchLogger.With("invoked-endorser", fmt.Sprintf("%s (%s)", endorser.address, endorser.mspid))
diff, err := payloadDifference(p.responsePayload, response.GetPayload())
if err != nil {
logger.Debugf("Failed to analyse response mismatch: %s", err)
mismatchLogger.Warnf("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)
mismatchLogger.Warn("Compared to the initial endorser's response, the following log entries detail the differences in this invoked endorser's response.")
for _, d := range diff.details() {
logger.Debugw("Proposal response mismatch:", d...)
mismatchLogger.Warnw("Proposal response mismatch:", d...)
}
}
}
Expand Down

0 comments on commit f4e897f

Please sign in to comment.