Log proposal response differences #3420
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
yacovm
reviewed
May 16, 2022
internal/pkg/gateway/api_test.go
Outdated
| 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("info") |
There was a problem hiding this comment.
nit, but - shouldn't you sample what was the spec before and save it rather then defaulting to what you think the spec was before?
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 <[email protected]>
andrew-coleman
force-pushed
the
diff_responses
branch
from
373a201 to
52c7137
Compare
yacovm
approved these changes
May 19, 2022
denyeart
reviewed
May 19, 2022
There was a problem hiding this comment.
The PR looks good overall and will be a great help for users and SREs. I tried it out and here is how the log statements look:
2022-05-19 11:05:16.533 UTC 07e5 WARN [gateway] processEndorsement -> ProposalResponsePayloads do not match (base64) payload1="CiBptArFMIP4q3VTbDedbKaC/UgRP21Y66nYAP70fdS64xLxAQrWARI2CgpfbGlmZWN5Y2xlEigKJgogbmFtZXNwYWNlcy9maWVsZHMvYmFzaWMvU2VxdWVuY2USAggFEpsBCgViYXNpYxKRAQoYChJhc3NldDE2NTI5NTgzMTIxNTcSAggHGnUKEmFzc2V0MTY1Mjk1ODMxMjE1NxpfeyJBcHByYWlzZWRWYWx1ZSI6MTMwMCwiQ29sb3IiOiJ5ZWxsb3ciLCJJRCI6ImFzc2V0MTY1Mjk1ODMxMjE1NyIsIk93bmVyIjoiU2FwdGhhNTkxIiwiU2l6ZSI6NX0aCAjIARoDVG9tIgwSBWJhc2ljGgMxLjA=" payload2="CiBptArFMIP4q3VTbDedbKaC/UgRP21Y66nYAP70fdS64xLxAQrWARI2CgpfbGlmZWN5Y2xlEigKJgogbmFtZXNwYWNlcy9maWVsZHMvYmFzaWMvU2VxdWVuY2USAggFEpsBCgViYXNpYxKRAQoYChJhc3NldDE2NTI5NTgzMTIxNTcSAggHGnUKEmFzc2V0MTY1Mjk1ODMxMjE1NxpfeyJBcHByYWlzZWRWYWx1ZSI6MTMwMCwiQ29sb3IiOiJ5ZWxsb3ciLCJJRCI6ImFzc2V0MTY1Mjk1ODMxMjE1NyIsIk93bmVyIjoiU2FwdGhhMTgwIiwiU2l6ZSI6NX0aCAjIARoDVG9tIgwSBWJhc2ljGgMxLjA="
2022-05-19 11:05:16.534 UTC 07e6 DEBU [gateway] processEndorsement -> Compared to the initial endorser's response, the following debug log entries detail the differences in this endorser's response. address=peer0.org2.example.com:9051 mspid=Org2MSP
2022-05-19 11:05:16.535 UTC 07e7 DEBU [gateway] processEndorsement -> Proposal response mismatch: type="write value mismatch" namespace=basic key=asset1652958312157 expectedvalue="{\"AppraisedValue\":1300,\"Color\":\"yellow\",\"ID\":\"asset1652958312157\",\"Owner\":\"Saptha591\",\"Size\":5}" actualvalue="{\"AppraisedValue\":1300,\"Color\":\"yellow\",\"ID\":\"asset1652958312157\",\"Owner\":\"Saptha180\",\"Size\":5}"
2022-05-19 11:05:16.535 UTC 07e8 INFO [comm.grpc.server] 1 -> unary call completed grpc.service=gateway.Gateway grpc.method=Endorse grpc.request_deadline=2022-05-19T11:05:31.512Z grpc.peer_address=172.21.0.1:62532 error="rpc error: code = Aborted desc = failed to collect enough transaction endorsements, see attached details for more info" grpc.code=Aborted grpc.call_duration=22.5227ms
In the review comments I've added a few suggestions to improve the log statements.
| 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) |
There was a problem hiding this comment.
It's good that you report endorser address and mspid that doesn't match.
Would it be difficult to report the initial endorser's address and/or mspid? It will often be the current peer but not always, right?
There was a problem hiding this comment.
Yes, that would be useful - I'll do this in a followup PR
| "namespace", wd.namespace, | ||
| "key", wd.key, | ||
| "expected value", string(wd.expected), | ||
| "actual value", string(wd.actual), |
There was a problem hiding this comment.
The terms "expected" and "actual" in the log message are misleading. All we know is that two endorsers got different values. We don't know which one is 'right' or 'expected'.
There was a problem hiding this comment.
True, in fact they could both be wrong. I'll change the words to something like 'initial value' and 'this value' while at the same time logging the address/mspid of 'initial endorser' and 'this endorser'. Hopefully that will be clearer.
| @@ -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) { | |||
There was a problem hiding this comment.
In the Warnw message above, users will receive the base64 difference but will typically want to know the actual difference. In the Warnw message, could you advise the user to enable "debug" for "gateway" component to get the actual differences?
Actually, I still think we should report the actual difference by default, but have an option for the user to suppress the difference checking if it is too much for them. Having a different logger such as "gateway.resultschecker" would be an option. We could then log the differences at Warn level and user would have the option to switch "gateway.resultschecker" to Error level.
There was a problem hiding this comment.
Ok, I'll do that. Since the details will be logged by default, I'll remove the base64 encoded responses from the log. These are pretty useless from a usability standpoint anyway.
andrew-coleman
added a commit
to andrew-coleman/fabric
that referenced
this pull request
May 19, 2022
This commit addresses some comments (hyperledger#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 <[email protected]>
andrew-coleman
added a commit
to andrew-coleman/fabric
that referenced
this pull request
May 20, 2022
This commit addresses some comments (hyperledger#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 <[email protected]>
denyeart
pushed a commit
that referenced
this pull request
May 20, 2022
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 <[email protected]>
|
@Mergifyio backport release-2.4 |
mergify bot
pushed a commit
that referenced
this pull request
May 20, 2022
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 <[email protected]> (cherry picked from commit 863cdd7) # Conflicts: # internal/pkg/gateway/api_test.go
✅ Backports have been created
|
andrew-coleman
added a commit
to andrew-coleman/fabric
that referenced
this pull request
May 23, 2022
Cherry-pick of hyperledger#3420 Signed-off-by: andrew-coleman <[email protected]>
denyeart
pushed a commit
that referenced
this pull request
May 23, 2022
Cherry-pick of #3420 Signed-off-by: andrew-coleman <[email protected]>
mergify bot
pushed a commit
that referenced
this pull request
May 23, 2022
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 <[email protected]> (cherry picked from commit a91c633)
denyeart
pushed a commit
that referenced
this pull request
May 23, 2022
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 <[email protected]> (cherry picked from commit a91c633)
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
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 [email protected]