This repository was archived by the owner on Sep 30, 2024. It is now read-only.
grpc: tweak internal error logic to log initial request for all error types (if enabled)#55130
Merged
grpc: tweak internal error logic to log initial request for all error types (if enabled)#55130
Conversation
ggilmore
force-pushed
the
fix-proto-log-size
branch
from
86c11bb to
9216936
Compare
camdencheek
approved these changes
Jul 20, 2023
ggilmore
force-pushed
the
fix-proto-log-size
branch
3 times, most recently
from
97fe5de to
0def139
Compare
ggilmore
force-pushed
the
fix-proto-log-size
branch
from
0def139 to
29f55f5
Compare
coury-clark
pushed a commit
that referenced
this pull request
Jul 24, 2023
…t for all error types (if enabled) (#55232) ## overview This PR tweaks the internal error interceptor implementation to be able to print the initial request message for _all_ internal error types, not just utf-8 errors. This feature is still off by default for security / privacy reasons. It can be enabled via the `SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_ENABLED` environment variable. ## notes ### size limits If the protobuf message that we're trying to log is quite large (hundreds of megabytes or gigabyte+), rendering the JSON representation of the message could be quite expensive. (The JSON form of the message is larger than the original protobuf message, so attempting to log a large message could result in excessive memory usage. Ex: a 5 GB proto message could result in a 6 gigabyte JSON string, resulting in 11 GB of total allocations). To solve this, I introduced an environment variable `SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_HANDLING_MAX_MESSAGE_SIZE_BYTES`. If the protobuf message is larger than this (calculated using [`proto.Size`](https://pkg.go.dev/google.golang.org/protobuf/proto#Size)), then it won't be turned into JSON at all. (An error message will be returned instead). ```text [ frontend] ERROR gitserver.client.gRPC.internal.error.reporter.streamingMethod.postMessageReceive internalerrs/logging.go:238 grpc: received message larger than max (105906242 vs. 4194304) {"grpcService": "gitserver.v1.GitserverService", "grpcMethod": "Search", "grpcCode": "ResourceExhausted", "error": "failed to marshal protobuf message (key: \"initialRequestJSON\") to bytes: message too large (size \"106 MB\", limit \"105 MB\")"} ``` The default value is 100 MB. ### environment variable name changes Since we log in more cases then just for non-uft8 string errors now, I tweak the names of the environment variables to reflect that: | before | after | |:-----------------------------------------------------------------------------:|:--------------------------------------------------------------------------------:| | SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_NON_UTF8_PROTOBUF_MESSAGES_ENABLED | SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_ENABLED | | SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_NON_UTF8_PROTOBUF_MESSAGES_MAX_SIZE_BYTES | SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_JSON_TRUNCATION_SIZE_BYTES | (The `SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_HANDLING_MAX_MESSAGE_SIZE_BYTES` environment variable didn't exist before, since the concept of skipping logging a message in the first place because it was too large didn't exist until now). Since I changed the environment variables name, this will mean that that any instances that had the message logging feature enabled will have it disabled. Luckily, this only affects sourcegraph.com. After this PR is merged and lands, I'll adjust sourcegraph.com to change the appropriate environment variable names (in the same way as I did it in this PR sourcegraph/deploy-sourcegraph-cloud#17936) ## Test plan Local testing. I applied the following diff to force a non-utf8 error, ran a search for `context:global test type:diff`, and saw the same logs as I expected before: ```diff diff --git a/cmd/gitserver/server/server_grpc.go b/cmd/gitserver/server/server_grpc.go index 003fe48..0307c4fdd8 100644 --- a/cmd/gitserver/server/server_grpc.go +++ b/cmd/gitserver/server/server_grpc.go @@ -310,8 +310,12 @@ func (gs *GRPCServer) Search(req *proto.SearchRequest, ss proto.GitserverService } onMatch := func(match *protocol.CommitMatch) error { + + m := match.ToProto() + m.Oid = strings.Repeat("\xc5", 1*1024*1024) return ss.Send(&proto.SearchResponse{ - Message: &proto.SearchResponse_Match{Match: match.ToProto()}, + + Message: &proto.SearchResponse_Match{Match: m}, }) } ``` ``` [ frontend] ERROR gitserver.client.gRPC.internal.error.reporter.streamingMethod.postMessageReceive internalerrs/logging.go:244 grpc: error while marshaling: string field contains invalid UTF-8 {"grpcService": "gitserver.v1.GitserverService", "grpcMethod": "Search", "grpcCode": "Internal", "initialRequestJSON": "{\"repo\":\"github.com/sourcegraph-testing/etcd\",\"revisions\":[{}],\"limit\":50000,\"include_diff\":true,\"query\":{\"Value\":{\"DiffMatches\":{\"expr\":\"test\",\"ignore_case\":true}}}}", "nonUTF8StringFields": [], "messageJSON": "{\"Message\":null}"} [ gitserver-1] ERROR gitserver.gRPC.internal.error.reporter.streamingMethod.postMessageSend internalerrs/logging.go:244 grpc: error while marshaling: string field contains invalid UTF-8 {"grpcService": "gitserver.v1.GitserverService", "grpcMethod": "Search", "grpcCode": "Internal", "initialRequestJSON": "{\"repo\":\"github.com/Eltecz/STM32G4_OSC\",\"revisions\":[{}],\"limit\":50000,\"include_diff\":true,\"query\":{\"Value\":{\"DiffMatches\":{\"expr\":\"test\",\"ignore_case\":true}}}}", "nonUTF8StringFields": ["match.oid"], "messageJSON": "{\"Message\":{\"Match\":{\"oid\":\"\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd...(truncated 6294534 bytes)"} ``` In order to test the `SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_HANDLING_MAX_MESSAGE_SIZE_BYTES` feature, I manually set it to 100 bytes and re-ran the same search: ``` [ frontend] ERROR gitserver.client.gRPC.internal.error.reporter.streamingMethod.postMessageReceive internalerrs/logging.go:244 grpc: error while marshaling: string field contains invalid UTF-8 {"grpcService": "gitserver.v1.GitserverService", "grpcMethod": "Search", "grpcCode": "Internal", "initialRequestJSON": "{\"repo\":\"github.com/sourcegraph-testing/titan\",\"revisions\":[{}],\"limit\":50000,\"include_diff\":true,\"query\":{\"Value\":{\"DiffMatches\":{\"expr\":\"test\",\"ignore_case\":true}}}}", "nonUTF8StringFields": [], "messageJSON": "{\"Message\":null}"} [ gitserver-1] ERROR gitserver.gRPC.internal.error.reporter.streamingMethod.postMessageSend internalerrs/logging.go:244 grpc: error while marshaling: string field contains invalid UTF-8 {"grpcService": "gitserver.v1.GitserverService", "grpcMethod": "Search", "grpcCode": "Internal", "initialRequestJSON": "{\"repo\":\"github.com/sourcegraph-testing/tidb\",\"revisions\":[{}],\"limit\":50000,\"include_diff\":true,\"query\":{\"Value\":{\"DiffMatches\":{\"expr\":\"test\",\"ignore_case\":true}}}}", "nonUTF8StringFields": ["match.oid"], "error": "failed to marshal protobuf message (key: \"messageJSON\") to to string: message too large (size \"1.1 MB\", limit \"100 B\")"} ``` I tested that JSON truncation still worked by setting `SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_JSON_TRUNCATION_SIZE_BYTES` to 100 bytes and re-running the same search: ``` [ gitserver-1] ERROR gitserver.gRPC.internal.error.reporter.streamingMethod.postMessageSend internalerrs/logging.go:244 grpc: error while marshaling: string field contains invalid UTF-8 {"grpcService": "gitserver.v1.GitserverService", "grpcMethod": "Search", "grpcCode": "Internal", "initialRequestJSON": "{\"repo\":\"github.com/sourcegraph-testing/titan\",\"revisions\":[{}],\"limit\":50000,\"include_diff\":true,\"q...(truncated 67 bytes)", "nonUTF8StringFields": ["match.oid"], "messageJSON": "{\"Message\":{\"Match\":{\"oid\":\"\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd\\ufffd...(truncated 6291941 bytes)"} [ frontend] ERROR gitserver.client.gRPC.internal.error.reporter.streamingMethod.postMessageReceive internalerrs/logging.go:244 grpc: error while marshaling: string field contains invalid UTF-8 {"grpcService": "gitserver.v1.GitserverService", "grpcMethod": "Search", "grpcCode": "Internal", "initialRequestJSON": "{\"repo\":\"github.com/sourcegraph-testing/titan\",\"revisions\":[{}],\"limit\":50000,\"include_diff\":true,\"q...(truncated 67 bytes)", "nonUTF8StringFields": [], "messageJSON": "{\"Message\":null}"} ``` I tested that disabling the feature still worked by setting `SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_ENABLED` to `false` and re-running the same test: ``` [ gitserver-0] ERROR gitserver.gRPC.internal.error.reporter.streamingMethod.postMessageSend internalerrs/logging.go:244 grpc: error while marshaling: string field contains invalid UTF-8 {"grpcService": "gitserver.v1.GitserverService", "grpcMethod": "Search", "grpcCode": "Internal", "nonUTF8StringFields": ["match.oid"]} [ frontend] ERROR gitserver.client.gRPC.internal.error.reporter.streamingMethod.postMessageReceive internalerrs/logging.go:244 grpc: error while marshaling: string field contains invalid UTF-8 {"grpcService": "gitserver.v1.GitserverService", "grpcMethod": "Search", "grpcCode": "Internal", "nonUTF8StringFields": []} ``` Lastly, I checked to make sure that the new logic did actually print proto messages for other kinds of internal errors. I applied the following diff to induce a "message size too large" error: ```diff diff --git a/cmd/gitserver/server/server_grpc.go b/cmd/gitserver/server/server_grpc.go index 003fe48..5b93dbcac4 100644 --- a/cmd/gitserver/server/server_grpc.go +++ b/cmd/gitserver/server/server_grpc.go @@ -310,8 +310,12 @@ func (gs *GRPCServer) Search(req *proto.SearchRequest, ss proto.GitserverService } onMatch := func(match *protocol.CommitMatch) error { + + m := match.ToProto() + m.Oid = strings.Repeat("a", 100*1024*1024) return ss.Send(&proto.SearchResponse{ - Message: &proto.SearchResponse_Match{Match: match.ToProto()}, + + Message: &proto.SearchResponse_Match{Match: m}, }) } ``` After re-running the same search, I saw the following expected log messages: ``` [ frontend] ERROR gitserver.client.gRPC.internal.error.reporter.streamingMethod.postMessageReceive internalerrs/logging.go:244 grpc: received message larger than max (104858917 vs. 67108864) {"grpcService": "gitserver.v1.GitserverService", "grpcMethod": "Search", "grpcCode": "ResourceExhausted", "initialRequestJSON": "{\"repo\":\"github.com/hashicorp/go-multierror\",\"revisions\":[{}],\"limit\":500,\"include_diff\":true,\"query\":{\"Value\":{\"DiffMatches\":{\"expr\":\"test\",\"ignore_case\":true}}}}"} ``` <br> Backport c6194a2 from #55130 Co-authored-by: Geoffrey Gilmore <geoffrey@sourcegraph.com>
ggilmore
referenced
this pull request
Jul 25, 2023
Update changelog for https://github.com/sourcegraph/sourcegraph/pull/55130 and https://github.com/sourcegraph/sourcegraph/pull/55209 5.1 backports.
Merged
MaedahBatool
pushed a commit
that referenced
this pull request
Jul 28, 2023
… types (if enabled) (#55130)
This file contains hidden or 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
Sign up for free
to subscribe to this conversation on GitHub.
Already have an account?
Sign in.
3 participants
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.
overview
This PR tweaks the internal error interceptor implementation to be able to print the initial request message for all internal error types, not just utf-8 errors.
This feature is still off by default for security / privacy reasons. It can be enabled via the
SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_ENABLEDenvironment variable.notes
size limits
If the protobuf message that we're trying to log is quite large (hundreds of megabytes or gigabyte+), rendering the JSON representation of the message could be quite expensive. (The JSON form of the message is larger than the original protobuf message, so attempting to log a large message could result in excessive memory usage. Ex: a 5 GB proto message could result in a 6 gigabyte JSON string, resulting in 11 GB of total allocations).
To solve this, I introduced an environment variable
SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_HANDLING_MAX_MESSAGE_SIZE_BYTES. If the protobuf message is larger than this (calculated usingproto.Size), then it won't be turned into JSON at all. (An error message will be returned instead).The default value is 100 MB.
environment variable name changes
Since we log in more cases then just for non-uft8 string errors now, I tweak the names of the environment variables to reflect that:
(The
SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_HANDLING_MAX_MESSAGE_SIZE_BYTESenvironment variable didn't exist before, since the concept of skipping logging a message in the first place because it was too large didn't exist until now).Since I changed the environment variables name, this will mean that that any instances that had the message logging feature enabled will have it disabled. Luckily, this only affects sourcegraph.com. After this PR is merged and lands, I'll adjust sourcegraph.com to change the appropriate environment variable names (in the same way as I did it in this PR https://github.com/sourcegraph/deploy-sourcegraph-cloud/pull/17936)
Test plan
Local testing.
I applied the following diff to force a non-utf8 error, ran a search for
context:global test type:diff, and saw the same logs as I expected before:In order to test the
SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_HANDLING_MAX_MESSAGE_SIZE_BYTESfeature, I manually set it to 100 bytes and re-ran the same search:I tested that JSON truncation still worked by setting
SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_JSON_TRUNCATION_SIZE_BYTESto 100 bytes and re-running the same search:I tested that disabling the feature still worked by setting
SRC_GRPC_INTERNAL_ERROR_LOGGING_LOG_PROTOBUF_MESSAGES_ENABLEDtofalseand re-running the same test:Lastly, I checked to make sure that the new logic did actually print proto messages for other kinds of internal errors. I applied the following diff to induce a "message size too large" error:
After re-running the same search, I saw the following expected log messages: