From 97b7f6d4d7d05b58f39471300732651c0281a083 Mon Sep 17 00:00:00 2001 From: James Newton-King Date: Thu, 3 Nov 2022 09:29:52 +0800 Subject: [PATCH] Improve logging message when gRPC status OK in header (#1931) --- global.json | 3 +-- src/Grpc.Net.Client/Internal/GrpcCall.cs | 7 ++++--- src/Grpc.Net.Client/Internal/GrpcCallLog.cs | 9 +++++++++ test/FunctionalTests/Client/UnaryTests.cs | 7 ++++--- test/Grpc.Net.Client.Tests/AsyncUnaryCallTests.cs | 4 ++-- test/Grpc.Net.Client.Tests/Retry/RetryTests.cs | 2 +- 6 files changed, 21 insertions(+), 11 deletions(-) diff --git a/global.json b/global.json index 4a113d505..76bca39fb 100644 --- a/global.json +++ b/global.json @@ -1,6 +1,5 @@ { "sdk": { - "version": "7.0.100-rc.2.22477.23", - "rollForward": "latestMinor" + "version": "7.0.100-rc.2.22477.23" } } diff --git a/src/Grpc.Net.Client/Internal/GrpcCall.cs b/src/Grpc.Net.Client/Internal/GrpcCall.cs index 8dc36d1f3..6811e8785 100644 --- a/src/Grpc.Net.Client/Internal/GrpcCall.cs +++ b/src/Grpc.Net.Client/Internal/GrpcCall.cs @@ -514,12 +514,13 @@ private async Task RunCall(HttpRequestMessage request, TimeSpan? timeout) else { // The server should never return StatusCode.OK in the header for a unary call. - // If it does then throw an error that no message was returned from the server. - GrpcCallLog.MessageNotReturned(Logger); + // If it does then throw an error that explains why the server response is invalid. + GrpcCallLog.InvalidGrpcStatusInHeader(Logger); // Change the status code to a more accurate status. // This is consistent with Grpc.Core client behavior. - status = new Status(StatusCode.Internal, "Failed to deserialize response message."); + status = new Status(StatusCode.Internal, "Failed to deserialize response message. The response header contains a gRPC status of OK, which means any message returned to the client for this call should be ignored. " + + "A unary or client streaming gRPC call must have a response message, which makes this response invalid."); finished = FinishCall(request, diagnosticSourceEnabled, activity, status.Value); } diff --git a/src/Grpc.Net.Client/Internal/GrpcCallLog.cs b/src/Grpc.Net.Client/Internal/GrpcCallLog.cs index 9c2feec3f..907b4e044 100644 --- a/src/Grpc.Net.Client/Internal/GrpcCallLog.cs +++ b/src/Grpc.Net.Client/Internal/GrpcCallLog.cs @@ -104,6 +104,10 @@ internal static class GrpcCallLog private static readonly Action _errorExceedingDeadline = LoggerMessage.Define(LogLevel.Error, new EventId(27, "ErrorExceedingDeadline"), "Error exceeding deadline."); + private static readonly Action _invalidGrpcStatusInHeader = + LoggerMessage.Define(LogLevel.Error, new EventId(28, "InvalidGrpcStatusInHeader"), "Header contains an OK gRPC status. This is invalid for unary or client streaming calls because a status in the header indicates there is no response body. " + + "A message in the response body is required for unary and client streaming calls."); + public static void StartingCall(ILogger logger, MethodType methodType, Uri uri) { _startingCall(logger, methodType, uri, null); @@ -238,4 +242,9 @@ public static void ErrorExceedingDeadline(ILogger logger, Exception ex) { _errorExceedingDeadline(logger, ex); } + + public static void InvalidGrpcStatusInHeader(ILogger logger) + { + _invalidGrpcStatusInHeader(logger, null); + } } diff --git a/test/FunctionalTests/Client/UnaryTests.cs b/test/FunctionalTests/Client/UnaryTests.cs index 427326489..f5e954f5e 100644 --- a/test/FunctionalTests/Client/UnaryTests.cs +++ b/test/FunctionalTests/Client/UnaryTests.cs @@ -36,7 +36,8 @@ public async Task ThrowErrorWithOK_ClientThrowsFailedToDeserializeError() { SetExpectedErrorsFilter(writeContext => { - if (writeContext.State.ToString() == "Message not returned from unary or client streaming call.") + if (writeContext.State.ToString() == "Header contains an OK gRPC status. This is invalid for unary or client streaming calls because a status in the header indicates there is no response body. " + + "A message in the response body is required for unary and client streaming calls.") { return true; } @@ -61,10 +62,10 @@ Task UnaryThrowError(HelloRequest request, ServerCallContext context var ex = await ExceptionAssert.ThrowsAsync(() => call.ResponseAsync).DefaultTimeout(); Assert.AreEqual(StatusCode.Internal, ex.Status.StatusCode); - Assert.AreEqual("Failed to deserialize response message.", ex.Status.Detail); + StringAssert.StartsWith("Failed to deserialize response message.", ex.Status.Detail); Assert.AreEqual(StatusCode.Internal, call.GetStatus().StatusCode); - Assert.AreEqual("Failed to deserialize response message.", call.GetStatus().Detail); + StringAssert.StartsWith("Failed to deserialize response message.", call.GetStatus().Detail); } #if NET5_0_OR_GREATER diff --git a/test/Grpc.Net.Client.Tests/AsyncUnaryCallTests.cs b/test/Grpc.Net.Client.Tests/AsyncUnaryCallTests.cs index 4a56a8d9f..f78c898a3 100644 --- a/test/Grpc.Net.Client.Tests/AsyncUnaryCallTests.cs +++ b/test/Grpc.Net.Client.Tests/AsyncUnaryCallTests.cs @@ -221,10 +221,10 @@ public async Task AsyncUnaryCall_SuccessTrailersOnly_ThrowNoMessageError() Assert.IsFalse(responseMessage!.TrailingHeaders().Any()); // sanity check that there are no trailers Assert.AreEqual(StatusCode.Internal, ex.Status.StatusCode); - Assert.AreEqual("Failed to deserialize response message.", ex.Status.Detail); + StringAssert.StartsWith("Failed to deserialize response message.", ex.Status.Detail); Assert.AreEqual(StatusCode.Internal, call.GetStatus().StatusCode); - Assert.AreEqual("Failed to deserialize response message.", call.GetStatus().Detail); + StringAssert.StartsWith("Failed to deserialize response message.", call.GetStatus().Detail); Assert.AreEqual(0, headers.Count); Assert.AreEqual(0, call.GetTrailers().Count); diff --git a/test/Grpc.Net.Client.Tests/Retry/RetryTests.cs b/test/Grpc.Net.Client.Tests/Retry/RetryTests.cs index 04bea0fe1..f3db8143a 100644 --- a/test/Grpc.Net.Client.Tests/Retry/RetryTests.cs +++ b/test/Grpc.Net.Client.Tests/Retry/RetryTests.cs @@ -816,7 +816,7 @@ public async Task AsyncUnaryCall_NoMessagesSuccess_Failure() var ex = await ExceptionAssert.ThrowsAsync(() => call.ResponseAsync).DefaultTimeout(); // Assert - Assert.AreEqual("Failed to deserialize response message.", ex.Status.Detail); + StringAssert.StartsWith("Failed to deserialize response message.", ex.Status.Detail); Assert.AreEqual(StatusCode.Internal, ex.StatusCode); var log = testSink.Writes.Single(w => w.EventId.Name == "CallCommited");