Improve response mismatch logging

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)
hyperledger · May 23, 2022 · 135c268 · 135c268
1 parent 29fea4f
commit 135c268
Show file tree

Hide file tree

Showing 4 changed files with 71 additions and 35 deletions.
diff --git a/internal/pkg/gateway/api_test.go b/internal/pkg/gateway/api_test.go
@@ -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") {
@@ -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)
 			},

diff --git 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
@@ -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:<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())
 }
@@ -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
@@ -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...)
 					}
 				}
 			}