From 424e95ccbb2099242a2c71b2d0154eb537b3cb41 Mon Sep 17 00:00:00 2001 From: Yash Tibrewal Date: Wed, 13 Mar 2024 15:33:16 -0700 Subject: [PATCH] [Max Message Limits] Improve logging to determine client/server (#36103) Will help debugging errors like #35805 Closes #36103 COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/36103 from yashykt:HelpDebugMessageSizeLimits 5507a257f39d7264e8ccc838437f97a2602c6d19 PiperOrigin-RevId: 615564790 --- .../message_compress/compression_filter.cc | 15 ++++++------ .../message_compress/compression_filter.h | 3 ++- .../legacy_compression_filter.cc | 13 +++++++---- .../legacy_compression_filter.h | 3 ++- .../message_size/message_size_filter.cc | 23 +++++++++++-------- .../tests/InteropTests/InteropTests.m | 2 +- test/core/end2end/tests/max_message_length.cc | 14 ++++++----- 7 files changed, 43 insertions(+), 30 deletions(-) diff --git a/src/core/ext/filters/http/message_compress/compression_filter.cc b/src/core/ext/filters/http/message_compress/compression_filter.cc index 1ffee085230..c9b3acaf1f7 100644 --- a/src/core/ext/filters/http/message_compress/compression_filter.cc +++ b/src/core/ext/filters/http/message_compress/compression_filter.cc @@ -169,7 +169,7 @@ MessageHandle ChannelCompression::CompressMessage( } absl::StatusOr ChannelCompression::DecompressMessage( - MessageHandle message, DecompressArgs args) const { + bool is_client, MessageHandle message, DecompressArgs args) const { if (GRPC_TRACE_FLAG_ENABLED(grpc_compression_trace)) { gpr_log(GPR_INFO, "DecompressMessage: len=%" PRIdPTR " max=%d alg=%d", message->payload()->Length(), @@ -186,8 +186,9 @@ absl::StatusOr ChannelCompression::DecompressMessage( message->payload()->Length() > static_cast(*args.max_recv_message_length)) { return absl::ResourceExhaustedError(absl::StrFormat( - "Received message larger than max (%u vs. %d)", - message->payload()->Length(), *args.max_recv_message_length)); + "%s: Received message larger than max (%u vs. %d)", + is_client ? "CLIENT" : "SERVER", message->payload()->Length(), + *args.max_recv_message_length)); } // Check if decompression is enabled (if not, we can just pass the message // up). @@ -264,8 +265,8 @@ void ClientCompressionFilter::Call::OnServerInitialMetadata( absl::StatusOr ClientCompressionFilter::Call::OnServerToClientMessage( MessageHandle message, ClientCompressionFilter* filter) { - return filter->compression_engine_.DecompressMessage(std::move(message), - decompress_args_); + return filter->compression_engine_.DecompressMessage( + /*is_client=*/true, std::move(message), decompress_args_); } void ServerCompressionFilter::Call::OnClientInitialMetadata( @@ -276,8 +277,8 @@ void ServerCompressionFilter::Call::OnClientInitialMetadata( absl::StatusOr ServerCompressionFilter::Call::OnClientToServerMessage( MessageHandle message, ServerCompressionFilter* filter) { - return filter->compression_engine_.DecompressMessage(std::move(message), - decompress_args_); + return filter->compression_engine_.DecompressMessage( + /*is_client=*/false, std::move(message), decompress_args_); } void ServerCompressionFilter::Call::OnServerInitialMetadata( diff --git a/src/core/ext/filters/http/message_compress/compression_filter.h b/src/core/ext/filters/http/message_compress/compression_filter.h index 40e88d9b5a8..adf9fb49355 100644 --- a/src/core/ext/filters/http/message_compress/compression_filter.h +++ b/src/core/ext/filters/http/message_compress/compression_filter.h @@ -87,7 +87,8 @@ class ChannelCompression { MessageHandle CompressMessage(MessageHandle message, grpc_compression_algorithm algorithm) const; // Decompress one message synchronously. - absl::StatusOr DecompressMessage(MessageHandle message, + absl::StatusOr DecompressMessage(bool is_client, + MessageHandle message, DecompressArgs args) const; private: diff --git a/src/core/ext/filters/http/message_compress/legacy_compression_filter.cc b/src/core/ext/filters/http/message_compress/legacy_compression_filter.cc index 8f62d610b33..9fe6746a48d 100644 --- a/src/core/ext/filters/http/message_compress/legacy_compression_filter.cc +++ b/src/core/ext/filters/http/message_compress/legacy_compression_filter.cc @@ -166,7 +166,7 @@ MessageHandle LegacyCompressionFilter::CompressMessage( } absl::StatusOr LegacyCompressionFilter::DecompressMessage( - MessageHandle message, DecompressArgs args) const { + bool is_client, MessageHandle message, DecompressArgs args) const { if (GRPC_TRACE_FLAG_ENABLED(grpc_compression_trace)) { gpr_log(GPR_INFO, "DecompressMessage: len=%" PRIdPTR " max=%d alg=%d", message->payload()->Length(), @@ -183,8 +183,9 @@ absl::StatusOr LegacyCompressionFilter::DecompressMessage( message->payload()->Length() > static_cast(*args.max_recv_message_length)) { return absl::ResourceExhaustedError(absl::StrFormat( - "Received message larger than max (%u vs. %d)", - message->payload()->Length(), *args.max_recv_message_length)); + "%s: Received message larger than max (%u vs. %d)", + is_client ? "CLIENT" : "SERVER", message->payload()->Length(), + *args.max_recv_message_length)); } // Check if decompression is enabled (if not, we can just pass the message // up). @@ -266,7 +267,8 @@ LegacyClientCompressionFilter::MakeCallPromise( call_args.server_to_client_messages->InterceptAndMap( [decompress_err, decompress_args, this](MessageHandle message) -> absl::optional { - auto r = DecompressMessage(std::move(message), *decompress_args); + auto r = DecompressMessage(/*is_client=*/true, std::move(message), + *decompress_args); if (!r.ok()) { decompress_err->Set(ServerMetadataFromStatus(r.status())); return absl::nullopt; @@ -288,7 +290,8 @@ LegacyServerCompressionFilter::MakeCallPromise( call_args.client_to_server_messages->InterceptAndMap( [decompress_err, decompress_args, this](MessageHandle message) -> absl::optional { - auto r = DecompressMessage(std::move(message), decompress_args); + auto r = DecompressMessage(/*is_client=*/false, std::move(message), + decompress_args); if (grpc_call_trace.enabled()) { gpr_log(GPR_DEBUG, "%s[compression] DecompressMessage returned %s", GetContext()->DebugTag().c_str(), diff --git a/src/core/ext/filters/http/message_compress/legacy_compression_filter.h b/src/core/ext/filters/http/message_compress/legacy_compression_filter.h index 0926bc09ed9..f2212e2d61c 100644 --- a/src/core/ext/filters/http/message_compress/legacy_compression_filter.h +++ b/src/core/ext/filters/http/message_compress/legacy_compression_filter.h @@ -87,7 +87,8 @@ class LegacyCompressionFilter : public ChannelFilter { MessageHandle CompressMessage(MessageHandle message, grpc_compression_algorithm algorithm) const; // Decompress one message synchronously. - absl::StatusOr DecompressMessage(MessageHandle message, + absl::StatusOr DecompressMessage(bool is_client, + MessageHandle message, DecompressArgs args) const; private: diff --git a/src/core/ext/filters/message_size/message_size_filter.cc b/src/core/ext/filters/message_size/message_size_filter.cc index c9fe96cc41c..df1b4b53306 100644 --- a/src/core/ext/filters/message_size/message_size_filter.cc +++ b/src/core/ext/filters/message_size/message_size_filter.cc @@ -160,7 +160,7 @@ absl::StatusOr ServerMessageSizeFilter::Create( namespace { ServerMetadataHandle CheckPayload(const Message& msg, absl::optional max_length, - bool is_send) { + bool is_client, bool is_send) { if (!max_length.has_value()) return nullptr; if (GRPC_TRACE_FLAG_ENABLED(grpc_call_trace)) { gpr_log(GPR_INFO, "%s[message_size] %s len:%" PRIdPTR " max:%d", @@ -170,10 +170,11 @@ ServerMetadataHandle CheckPayload(const Message& msg, if (msg.payload()->Length() <= *max_length) return nullptr; auto r = GetContext()->MakePooled(GetContext()); r->Set(GrpcStatusMetadata(), GRPC_STATUS_RESOURCE_EXHAUSTED); - r->Set(GrpcMessageMetadata(), Slice::FromCopiedString(absl::StrFormat( - "%s message larger than max (%u vs. %d)", - is_send ? "Sent" : "Received", - msg.payload()->Length(), *max_length))); + r->Set(GrpcMessageMetadata(), + Slice::FromCopiedString(absl::StrFormat( + "%s: %s message larger than max (%u vs. %d)", + is_client ? "CLIENT" : "SERVER", is_send ? "Sent" : "Received", + msg.payload()->Length(), *max_length))); return r; } } // namespace @@ -207,22 +208,26 @@ ClientMessageSizeFilter::Call::Call(ClientMessageSizeFilter* filter) ServerMetadataHandle ServerMessageSizeFilter::Call::OnClientToServerMessage( const Message& message, ServerMessageSizeFilter* filter) { - return CheckPayload(message, filter->parsed_config_.max_recv_size(), false); + return CheckPayload(message, filter->parsed_config_.max_recv_size(), + /*is_client=*/false, false); } ServerMetadataHandle ServerMessageSizeFilter::Call::OnServerToClientMessage( const Message& message, ServerMessageSizeFilter* filter) { - return CheckPayload(message, filter->parsed_config_.max_send_size(), true); + return CheckPayload(message, filter->parsed_config_.max_send_size(), + /*is_client=*/false, true); } ServerMetadataHandle ClientMessageSizeFilter::Call::OnClientToServerMessage( const Message& message) { - return CheckPayload(message, limits_.max_send_size(), true); + return CheckPayload(message, limits_.max_send_size(), /*is_client=*/true, + true); } ServerMetadataHandle ClientMessageSizeFilter::Call::OnServerToClientMessage( const Message& message) { - return CheckPayload(message, limits_.max_recv_size(), false); + return CheckPayload(message, limits_.max_recv_size(), /*is_client=*/true, + false); } namespace { diff --git a/src/objective-c/tests/InteropTests/InteropTests.m b/src/objective-c/tests/InteropTests/InteropTests.m index 24122b9a30f..2e6ddf69dd8 100644 --- a/src/objective-c/tests/InteropTests/InteropTests.m +++ b/src/objective-c/tests/InteropTests/InteropTests.m @@ -958,7 +958,7 @@ static dispatch_once_t initGlobalInterceptorFactory; // https://github.com/protocolbuffers/protobuf/blob/master/src/google/protobuf/field_mask.proto XCTAssertEqualObjects( error.localizedDescription, - @"Received message larger than max (4194305 vs. 4194304)"); + @"CLIENT: Received message larger than max (4194305 vs. 4194304)"); [expectation fulfill]; }]; waiterBlock(@[ expectation ], GRPCInteropTestTimeoutDefault); diff --git a/test/core/end2end/tests/max_message_length.cc b/test/core/end2end/tests/max_message_length.cc index 9cabffd6d68..f57963dc725 100644 --- a/test/core/end2end/tests/max_message_length.cc +++ b/test/core/end2end/tests/max_message_length.cc @@ -45,7 +45,8 @@ void TestMaxMessageLengthOnClientOnRequest(CoreEnd2endTest& test) { test.Expect(1, true); test.Step(); EXPECT_EQ(server_status.status(), GRPC_STATUS_RESOURCE_EXHAUSTED); - EXPECT_EQ(server_status.message(), "Sent message larger than max (11 vs. 5)"); + EXPECT_EQ(server_status.message(), + "CLIENT: Sent message larger than max (11 vs. 5)"); } void TestMaxMessageLengthOnServerOnRequest(CoreEnd2endTest& test) { @@ -71,7 +72,7 @@ void TestMaxMessageLengthOnServerOnRequest(CoreEnd2endTest& test) { EXPECT_TRUE(client_close.was_cancelled()); EXPECT_EQ(server_status.status(), GRPC_STATUS_RESOURCE_EXHAUSTED); EXPECT_EQ(server_status.message(), - "Received message larger than max (11 vs. 5)"); + "SERVER: Received message larger than max (11 vs. 5)"); } void TestMaxMessageLengthOnClientOnResponse(CoreEnd2endTest& test) { @@ -100,7 +101,7 @@ void TestMaxMessageLengthOnClientOnResponse(CoreEnd2endTest& test) { EXPECT_EQ(s.method(), "/service/method"); EXPECT_EQ(server_status.status(), GRPC_STATUS_RESOURCE_EXHAUSTED); EXPECT_EQ(server_status.message(), - "Received message larger than max (11 vs. 5)"); + "CLIENT: Received message larger than max (11 vs. 5)"); } void TestMaxMessageLengthOnServerOnResponse(CoreEnd2endTest& test) { @@ -128,7 +129,8 @@ void TestMaxMessageLengthOnServerOnResponse(CoreEnd2endTest& test) { test.Step(); EXPECT_EQ(s.method(), "/service/method"); EXPECT_EQ(server_status.status(), GRPC_STATUS_RESOURCE_EXHAUSTED); - EXPECT_EQ(server_status.message(), "Sent message larger than max (11 vs. 5)"); + EXPECT_EQ(server_status.message(), + "SERVER: Sent message larger than max (11 vs. 5)"); } CORE_END2END_TEST(CoreEnd2endTest, @@ -276,7 +278,7 @@ CORE_END2END_TEST(Http2Test, MaxMessageLengthOnServerOnRequestWithCompression) { EXPECT_TRUE(client_close.was_cancelled()); EXPECT_EQ(server_status.status(), GRPC_STATUS_RESOURCE_EXHAUSTED); EXPECT_THAT(server_status.message(), - StartsWith("Received message larger than max")); + StartsWith("SERVER: Received message larger than max")); } CORE_END2END_TEST(Http2Test, @@ -311,7 +313,7 @@ CORE_END2END_TEST(Http2Test, EXPECT_EQ(s.method(), "/service/method"); EXPECT_EQ(server_status.status(), GRPC_STATUS_RESOURCE_EXHAUSTED); EXPECT_THAT(server_status.message(), - StartsWith("Received message larger than max")); + StartsWith("CLIENT: Received message larger than max")); } } // namespace