Skip to content
This repository was archived by the owner on Sep 30, 2024. It is now read-only.

[Backport 5.1] grpc: tweak internal error logic to log initial request for all error types (if enabled)#55232

Merged
coury-clark merged 1 commit into
5.1from
backport-55130-to-5.1
Jul 24, 2023
Merged

[Backport 5.1] grpc: tweak internal error logic to log initial request for all error types (if enabled)#55232
coury-clark merged 1 commit into
5.1from
backport-55130-to-5.1

Conversation

@github-actions

@github-actions github-actions Bot commented Jul 24, 2023

Copy link
Copy Markdown
Contributor

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), then it won't be turned into JSON at all. (An error message will be returned instead).

[       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 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:

diff --git a/cmd/gitserver/server/server_grpc.go b/cmd/gitserver/server/server_grpc.go
index 003fe482bc..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 --git a/cmd/gitserver/server/server_grpc.go b/cmd/gitserver/server/server_grpc.go
index 003fe482bc..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}}}}"}


Backport c6194a2 from #55130

@github-actions github-actions Bot requested a review from ggilmore July 24, 2023 15:01
@sourcegraph-bot

sourcegraph-bot commented Jul 24, 2023

Copy link
Copy Markdown
Contributor

📖 Storybook live preview

@ggilmore ggilmore requested a review from a team July 24, 2023 15:35
@coury-clark coury-clark merged commit 908c820 into 5.1 Jul 24, 2023
@coury-clark coury-clark deleted the backport-55130-to-5.1 branch July 24, 2023 15:37
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Reviewers

2 more reviewers

@coury-clark coury-clark coury-clark approved these changes

@ggilmore ggilmore ggilmore approved these changes

Reviewers whose approvals may not affect merge requirements

Assignees

No one assigned

Labels

backports cla-signed

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

3 participants

@sourcegraph-bot @coury-clark @ggilmore