Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Change some gRPC client error logs to debug level #2106

Merged
merged 3 commits into from
Apr 29, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions src/Grpc.Net.Client/Internal/GrpcCall.cs
Original file line number Diff line number Diff line change
Expand Up @@ -503,7 +503,7 @@ private async Task RunCall(HttpRequestMessage request, TimeSpan? timeout)
}
else
{
GrpcCallLog.ErrorStartingCall(Logger, ex);
GrpcCallLog.ErrorStartingCall(Logger);
throw;
}
}
Expand Down Expand Up @@ -900,7 +900,7 @@ private bool FinishCall(HttpRequestMessage request, bool diagnosticSourceEnabled
}
}

GrpcCallLog.GrpcStatusError(Logger, status.StatusCode, status.Detail);
GrpcCallLog.GrpcStatusError(Logger, status.StatusCode, status.Detail, status.DebugException);
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.CallFailed(status.StatusCode);
Expand Down
30 changes: 8 additions & 22 deletions src/Grpc.Net.Client/Internal/GrpcCallLog.cs
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
#region Copyright notice and license
#region Copyright notice and license

// Copyright 2019 The gRPC Authors
//
Expand Down Expand Up @@ -39,7 +39,7 @@ internal static class GrpcCallLog
LoggerMessage.Define<TimeSpan>(LogLevel.Trace, new EventId(5, "StartingDeadlineTimeout"), "Starting deadline timeout. Duration: {DeadlineTimeout}.");

private static readonly Action<ILogger, Exception?> _errorStartingCall =
LoggerMessage.Define(LogLevel.Error, new EventId(6, "ErrorStartingCall"), "Error starting gRPC call.");
LoggerMessage.Define(LogLevel.Debug, new EventId(6, "ErrorStartingCall"), "Error starting gRPC call.");

private static readonly Action<ILogger, Exception?> _deadlineExceeded =
LoggerMessage.Define(LogLevel.Warning, new EventId(7, "DeadlineExceeded"), "gRPC call deadline exceeded.");
Expand All @@ -48,13 +48,9 @@ internal static class GrpcCallLog
LoggerMessage.Define(LogLevel.Debug, new EventId(8, "CanceledCall"), "gRPC call canceled.");

private static readonly Action<ILogger, Exception?> _messageNotReturned =
LoggerMessage.Define(LogLevel.Error, new EventId(9, "MessageNotReturned"), "Message not returned from unary or client streaming call.");
LoggerMessage.Define(LogLevel.Debug, new EventId(9, "MessageNotReturned"), "Message not returned from unary or client streaming call.");

private static readonly Action<ILogger, Exception?> _errorValidatingResponseHeaders =
LoggerMessage.Define(LogLevel.Error, new EventId(10, "ErrorValidatingResponseHeaders"), "Error validating response headers.");

private static readonly Action<ILogger, Exception?> _errorFetchingGrpcStatus =
LoggerMessage.Define(LogLevel.Error, new EventId(11, "ErrorFetchingGrpcStatus"), "Error fetching gRPC status.");
// 10, 11 unused.

private static readonly Action<ILogger, Exception?> _callCredentialsNotUsed =
LoggerMessage.Define(LogLevel.Warning, new EventId(12, "CallCredentialsNotUsed"), "The configured CallCredentials were not used because the call does not use TLS.");
Expand Down Expand Up @@ -118,9 +114,9 @@ public static void ResponseHeadersReceived(ILogger logger)
_responseHeadersReceived(logger, null);
}

public static void GrpcStatusError(ILogger logger, StatusCode status, string message)
public static void GrpcStatusError(ILogger logger, StatusCode status, string message, Exception? debugException)
{
_grpcStatusError(logger, status, message, null);
_grpcStatusError(logger, status, message, debugException);
}

public static void FinishedCall(ILogger logger)
Expand All @@ -133,9 +129,9 @@ public static void StartingDeadlineTimeout(ILogger logger, TimeSpan deadlineTime
_startingDeadlineTimeout(logger, deadlineTimeout, null);
}

public static void ErrorStartingCall(ILogger logger, Exception ex)
public static void ErrorStartingCall(ILogger logger)
{
_errorStartingCall(logger, ex);
_errorStartingCall(logger, null);
}

public static void DeadlineExceeded(ILogger logger)
Expand All @@ -153,16 +149,6 @@ public static void MessageNotReturned(ILogger logger)
_messageNotReturned(logger, null);
}

public static void ErrorValidatingResponseHeaders(ILogger logger, Exception ex)
{
_errorValidatingResponseHeaders(logger, ex);
}

public static void ErrorFetchingGrpcStatus(ILogger logger, Exception ex)
{
_errorFetchingGrpcStatus(logger, ex);
}

public static void CallCredentialsNotUsed(ILogger logger)
{
_callCredentialsNotUsed(logger, null);
Expand Down
98 changes: 97 additions & 1 deletion test/Grpc.Net.Client.Tests/LoggingTests.cs
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
#region Copyright notice and license
#region Copyright notice and license

// Copyright 2019 The gRPC Authors
//
Expand Down Expand Up @@ -80,4 +80,100 @@ static void AssertScope(WriteContext log)
Assert.AreEqual(new Uri("/ServiceName/MethodName", UriKind.Relative), scope[1].Value);
}
}

[Test]
public async Task AsyncUnaryCall_RequestFailure_LogToFactory()
{
// Arrange
var httpClient = ClientTestHelpers.CreateTestClient(request =>
{
return Task.FromException<HttpResponseMessage>(new Exception("An error occurred."));
});

var testSink = new TestSink();
var loggerFactory = new TestLoggerFactory(testSink, true);

var invoker = HttpClientCallInvokerFactory.Create(httpClient, loggerFactory);

// Act
var ex = await ExceptionAssert.ThrowsAsync<RpcException>(() => invoker.AsyncUnaryCall<HelloRequest, HelloReply>(ClientTestHelpers.ServiceMethod, string.Empty, new CallOptions(), new HelloRequest()).ResponseAsync);
var debugException = ex.Status.DebugException;

// Assert
Assert.NotNull(debugException);

var log = testSink.Writes.Single(w => w.EventId.Name == "StartingCall");
Assert.AreEqual("Starting gRPC call. Method type: 'Unary', URI: 'https://localhost/ServiceName/MethodName'.", log.State.ToString());
AssertScope(log);

log = testSink.Writes.Single(w => w.EventId.Name == "ErrorStartingCall");
Assert.AreEqual("Error starting gRPC call.", log.State.ToString());
Assert.Null(log.Exception);
AssertScope(log);

log = testSink.Writes.Single(w => w.EventId.Name == "GrpcStatusError");
Assert.AreEqual("Call failed with gRPC error status. Status code: 'Internal', Message: 'Error starting gRPC call. Exception: An error occurred.'.", log.State.ToString());
Assert.AreEqual(debugException, log.Exception);
AssertScope(log);

log = testSink.Writes.Single(w => w.EventId.Name == "FinishedCall");
Assert.AreEqual("Finished gRPC call.", log.State.ToString());
AssertScope(log);

static void AssertScope(WriteContext log)
{
var scope = (IReadOnlyList<KeyValuePair<string, object>>)log.Scope;
Assert.AreEqual(MethodType.Unary, scope[0].Value);
Assert.AreEqual(new Uri("/ServiceName/MethodName", UriKind.Relative), scope[1].Value);
}
}

[Test]
public async Task AsyncUnaryCall_CredentialsFailure_LogToFactory()
{
// Arrange
var httpClient = ClientTestHelpers.CreateTestClient(request =>
{
return Task.FromException<HttpResponseMessage>(new Exception("An error occurred."));
});

var testSink = new TestSink();
var loggerFactory = new TestLoggerFactory(testSink, true);

var invoker = HttpClientCallInvokerFactory.Create(httpClient, loggerFactory, configure: o =>
{
var credentials = CallCredentials.FromInterceptor((c, m) =>
{
return Task.FromException(new Exception("Credentials error."));
});
o.Credentials = ChannelCredentials.Create(ChannelCredentials.SecureSsl, credentials);
});

// Act
var ex = await ExceptionAssert.ThrowsAsync<RpcException>(() => invoker.AsyncUnaryCall<HelloRequest, HelloReply>(ClientTestHelpers.ServiceMethod, string.Empty, new CallOptions(), new HelloRequest()).ResponseAsync);
var debugException = ex.Status.DebugException;

// Assert
Assert.NotNull(debugException);

var log = testSink.Writes.Single(w => w.EventId.Name == "StartingCall");
Assert.AreEqual("Starting gRPC call. Method type: 'Unary', URI: 'https://localhost/ServiceName/MethodName'.", log.State.ToString());
AssertScope(log);

log = testSink.Writes.Single(w => w.EventId.Name == "GrpcStatusError");
Assert.AreEqual("Call failed with gRPC error status. Status code: 'Internal', Message: 'Error starting gRPC call. Exception: Credentials error.'.", log.State.ToString());
Assert.AreEqual(debugException, log.Exception);
AssertScope(log);

log = testSink.Writes.Single(w => w.EventId.Name == "FinishedCall");
Assert.AreEqual("Finished gRPC call.", log.State.ToString());
AssertScope(log);

static void AssertScope(WriteContext log)
{
var scope = (IReadOnlyList<KeyValuePair<string, object>>)log.Scope;
Assert.AreEqual(MethodType.Unary, scope[0].Value);
Assert.AreEqual(new Uri("/ServiceName/MethodName", UriKind.Relative), scope[1].Value);
}
}
}