Skip to content

Commit

Permalink
Improve logging message when gRPC status OK in header (#1931)
Browse files Browse the repository at this point in the history
  • Loading branch information
JamesNK authored Nov 3, 2022
1 parent 0828c03 commit 97b7f6d
Show file tree
Hide file tree
Showing 6 changed files with 21 additions and 11 deletions.
3 changes: 1 addition & 2 deletions global.json
Original file line number Diff line number Diff line change
@@ -1,6 +1,5 @@
{
"sdk": {
"version": "7.0.100-rc.2.22477.23",
"rollForward": "latestMinor"
"version": "7.0.100-rc.2.22477.23"
}
}
7 changes: 4 additions & 3 deletions src/Grpc.Net.Client/Internal/GrpcCall.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
Expand Down
9 changes: 9 additions & 0 deletions src/Grpc.Net.Client/Internal/GrpcCallLog.cs
Original file line number Diff line number Diff line change
Expand Up @@ -104,6 +104,10 @@ internal static class GrpcCallLog
private static readonly Action<ILogger, Exception> _errorExceedingDeadline =
LoggerMessage.Define(LogLevel.Error, new EventId(27, "ErrorExceedingDeadline"), "Error exceeding deadline.");

private static readonly Action<ILogger, Exception?> _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);
Expand Down Expand Up @@ -238,4 +242,9 @@ public static void ErrorExceedingDeadline(ILogger logger, Exception ex)
{
_errorExceedingDeadline(logger, ex);
}

public static void InvalidGrpcStatusInHeader(ILogger logger)
{
_invalidGrpcStatusInHeader(logger, null);
}
}
7 changes: 4 additions & 3 deletions test/FunctionalTests/Client/UnaryTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand All @@ -61,10 +62,10 @@ Task<HelloReply> UnaryThrowError(HelloRequest request, ServerCallContext context
var ex = await ExceptionAssert.ThrowsAsync<RpcException>(() => 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
Expand Down
4 changes: 2 additions & 2 deletions test/Grpc.Net.Client.Tests/AsyncUnaryCallTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
2 changes: 1 addition & 1 deletion test/Grpc.Net.Client.Tests/Retry/RetryTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -816,7 +816,7 @@ public async Task AsyncUnaryCall_NoMessagesSuccess_Failure()
var ex = await ExceptionAssert.ThrowsAsync<RpcException>(() => 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");
Expand Down

0 comments on commit 97b7f6d

Please sign in to comment.