From a91c63304fb48858dfecf0cc169396d635dbb5c8 Mon Sep 17 00:00:00 2001 From: andrew-coleman Date: Thu, 19 May 2022 16:56:43 +0100 Subject: [PATCH] Improve response mismatch logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This commit addresses some comments (https://github.com/hyperledger/fabric/pull/3420#pullrequestreview-978439334) 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 --- internal/pkg/gateway/api_test.go | 36 +++++++++++++++++++++++++-- internal/pkg/gateway/apiutils.go | 24 +++++++++--------- internal/pkg/gateway/apiutils_test.go | 30 +++++++++++----------- internal/pkg/gateway/endorsement.go | 16 +++++++----- 4 files changed, 71 insertions(+), 35 deletions(-) diff --git a/internal/pkg/gateway/api_test.go b/internal/pkg/gateway/api_test.go index 5984169fdeb..356a59a0b49 100644 --- a/internal/pkg/gateway/api_test.go +++ b/internal/pkg/gateway/api_test.go @@ -769,8 +769,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") { @@ -785,6 +783,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) }, diff --git a/internal/pkg/gateway/apiutils.go b/internal/pkg/gateway/apiutils.go index 366bd7ac7a4..343dcedd44c 100644 --- a/internal/pkg/gateway/apiutils.go +++ b/internal/pkg/gateway/apiutils.go @@ -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), } } @@ -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), } } @@ -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), } } @@ -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), } } diff --git a/internal/pkg/gateway/apiutils_test.go b/internal/pkg/gateway/apiutils_test.go index ebdc2f4bdc0..6de16531f27 100644 --- a/internal/pkg/gateway/apiutils_test.go +++ b/internal/pkg/gateway/apiutils_test.go @@ -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()) } @@ -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()) } @@ -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()) } @@ -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()) } @@ -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()) } @@ -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: > > identities: ", "actual value", "rule: > > identities: "}, - {"type", "missing metadata write (SBE policy)", "namespace", "ns1", "key", "key2", "name", "VALIDATION_PARAMETER", "expected value", "rule: > > identities: ", "actual value", ""}, + {"type", "write metadata mismatch (SBE policy)", "namespace", "ns1", "key", "key1", "name", "VALIDATION_PARAMETER", "initial-endorser-value", "rule: > > identities: ", "invoked-endorser-value", "rule: > > identities: "}, + {"type", "missing metadata write (SBE policy)", "namespace", "ns1", "key", "key2", "name", "VALIDATION_PARAMETER", "initial-endorser-value", "rule: > > identities: ", "invoked-endorser-value", ""}, } require.ElementsMatch(t, expected, diff.details()) } @@ -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()) } @@ -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()) } @@ -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()) } diff --git a/internal/pkg/gateway/endorsement.go b/internal/pkg/gateway/endorsement.go index 0174a63aadb..0738b452675 100644 --- a/internal/pkg/gateway/endorsement.go +++ b/internal/pkg/gateway/endorsement.go @@ -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" ) @@ -36,6 +37,7 @@ type plan struct { completedLayout *layout errorDetails []proto.Message planLock sync.Mutex + mismatchLogger *flogging.FabricLogger } // construct and initialise an endorsement plan @@ -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...) } } }