Skip to content

Commit 94a8167

Browse files
JamesNKJamesNK
authored
Change some gRPC client error logs to debug level (#2106)
1 parent e270f81 commit 94a8167

File tree

3 files changed

+107
-25
lines changed

3 files changed

+107
-25
lines changed

‎src/Grpc.Net.Client/Internal/GrpcCall.cs‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -503,7 +503,7 @@ private async Task RunCall(HttpRequestMessage request, TimeSpan? timeout)
503503
}
504504
else
505505
{
506-
GrpcCallLog.ErrorStartingCall(Logger, ex);
506+
GrpcCallLog.ErrorStartingCall(Logger);
507507
throw;
508508
}
509509
}
@@ -900,7 +900,7 @@ private bool FinishCall(HttpRequestMessage request, bool diagnosticSourceEnabled
900900
}
901901
}
902902

903-
GrpcCallLog.GrpcStatusError(Logger, status.StatusCode, status.Detail);
903+
GrpcCallLog.GrpcStatusError(Logger, status.StatusCode, status.Detail, status.DebugException);
904904
if (GrpcEventSource.Log.IsEnabled())
905905
{
906906
GrpcEventSource.Log.CallFailed(status.StatusCode);

‎src/Grpc.Net.Client/Internal/GrpcCallLog.cs‎

Lines changed: 8 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
#region Copyright notice and license
1+
#region Copyright notice and license
22

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

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

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

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

53-
private static readonly Action<ILogger, Exception?> _errorValidatingResponseHeaders =
54-
LoggerMessage.Define(LogLevel.Error, new EventId(10, "ErrorValidatingResponseHeaders"), "Error validating response headers.");
55-
56-
private static readonly Action<ILogger, Exception?> _errorFetchingGrpcStatus =
57-
LoggerMessage.Define(LogLevel.Error, new EventId(11, "ErrorFetchingGrpcStatus"), "Error fetching gRPC status.");
53+
// 10, 11 unused.
5854

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

121-
public static void GrpcStatusError(ILogger logger, StatusCode status, string message)
117+
public static void GrpcStatusError(ILogger logger, StatusCode status, string message, Exception? debugException)
122118
{
123-
_grpcStatusError(logger, status, message, null);
119+
_grpcStatusError(logger, status, message, debugException);
124120
}
125121

126122
public static void FinishedCall(ILogger logger)
@@ -133,9 +129,9 @@ public static void StartingDeadlineTimeout(ILogger logger, TimeSpan deadlineTime
133129
_startingDeadlineTimeout(logger, deadlineTimeout, null);
134130
}
135131

136-
public static void ErrorStartingCall(ILogger logger, Exception ex)
132+
public static void ErrorStartingCall(ILogger logger)
137133
{
138-
_errorStartingCall(logger, ex);
134+
_errorStartingCall(logger, null);
139135
}
140136

141137
public static void DeadlineExceeded(ILogger logger)
@@ -153,16 +149,6 @@ public static void MessageNotReturned(ILogger logger)
153149
_messageNotReturned(logger, null);
154150
}
155151

156-
public static void ErrorValidatingResponseHeaders(ILogger logger, Exception ex)
157-
{
158-
_errorValidatingResponseHeaders(logger, ex);
159-
}
160-
161-
public static void ErrorFetchingGrpcStatus(ILogger logger, Exception ex)
162-
{
163-
_errorFetchingGrpcStatus(logger, ex);
164-
}
165-
166152
public static void CallCredentialsNotUsed(ILogger logger)
167153
{
168154
_callCredentialsNotUsed(logger, null);

‎test/Grpc.Net.Client.Tests/LoggingTests.cs‎

Lines changed: 97 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
#region Copyright notice and license
1+
#region Copyright notice and license
22

33
// Copyright 2019 The gRPC Authors
44
//
@@ -80,4 +80,100 @@ static void AssertScope(WriteContext log)
8080
Assert.AreEqual(new Uri("/ServiceName/MethodName", UriKind.Relative), scope[1].Value);
8181
}
8282
}
83+
84+
[Test]
85+
public async Task AsyncUnaryCall_RequestFailure_LogToFactory()
86+
{
87+
// Arrange
88+
var httpClient = ClientTestHelpers.CreateTestClient(request =>
89+
{
90+
return Task.FromException<HttpResponseMessage>(new Exception("An error occurred."));
91+
});
92+
93+
var testSink = new TestSink();
94+
var loggerFactory = new TestLoggerFactory(testSink, true);
95+
96+
var invoker = HttpClientCallInvokerFactory.Create(httpClient, loggerFactory);
97+
98+
// Act
99+
var ex = await ExceptionAssert.ThrowsAsync<RpcException>(() => invoker.AsyncUnaryCall<HelloRequest, HelloReply>(ClientTestHelpers.ServiceMethod, string.Empty, new CallOptions(), new HelloRequest()).ResponseAsync);
100+
var debugException = ex.Status.DebugException;
101+
102+
// Assert
103+
Assert.NotNull(debugException);
104+
105+
var log = testSink.Writes.Single(w => w.EventId.Name == "StartingCall");
106+
Assert.AreEqual("Starting gRPC call. Method type: 'Unary', URI: 'https://localhost/ServiceName/MethodName'.", log.State.ToString());
107+
AssertScope(log);
108+
109+
log = testSink.Writes.Single(w => w.EventId.Name == "ErrorStartingCall");
110+
Assert.AreEqual("Error starting gRPC call.", log.State.ToString());
111+
Assert.Null(log.Exception);
112+
AssertScope(log);
113+
114+
log = testSink.Writes.Single(w => w.EventId.Name == "GrpcStatusError");
115+
Assert.AreEqual("Call failed with gRPC error status. Status code: 'Internal', Message: 'Error starting gRPC call. Exception: An error occurred.'.", log.State.ToString());
116+
Assert.AreEqual(debugException, log.Exception);
117+
AssertScope(log);
118+
119+
log = testSink.Writes.Single(w => w.EventId.Name == "FinishedCall");
120+
Assert.AreEqual("Finished gRPC call.", log.State.ToString());
121+
AssertScope(log);
122+
123+
static void AssertScope(WriteContext log)
124+
{
125+
var scope = (IReadOnlyList<KeyValuePair<string, object>>)log.Scope;
126+
Assert.AreEqual(MethodType.Unary, scope[0].Value);
127+
Assert.AreEqual(new Uri("/ServiceName/MethodName", UriKind.Relative), scope[1].Value);
128+
}
129+
}
130+
131+
[Test]
132+
public async Task AsyncUnaryCall_CredentialsFailure_LogToFactory()
133+
{
134+
// Arrange
135+
var httpClient = ClientTestHelpers.CreateTestClient(request =>
136+
{
137+
return Task.FromException<HttpResponseMessage>(new Exception("An error occurred."));
138+
});
139+
140+
var testSink = new TestSink();
141+
var loggerFactory = new TestLoggerFactory(testSink, true);
142+
143+
var invoker = HttpClientCallInvokerFactory.Create(httpClient, loggerFactory, configure: o =>
144+
{
145+
var credentials = CallCredentials.FromInterceptor((c, m) =>
146+
{
147+
return Task.FromException(new Exception("Credentials error."));
148+
});
149+
o.Credentials = ChannelCredentials.Create(ChannelCredentials.SecureSsl, credentials);
150+
});
151+
152+
// Act
153+
var ex = await ExceptionAssert.ThrowsAsync<RpcException>(() => invoker.AsyncUnaryCall<HelloRequest, HelloReply>(ClientTestHelpers.ServiceMethod, string.Empty, new CallOptions(), new HelloRequest()).ResponseAsync);
154+
var debugException = ex.Status.DebugException;
155+
156+
// Assert
157+
Assert.NotNull(debugException);
158+
159+
var log = testSink.Writes.Single(w => w.EventId.Name == "StartingCall");
160+
Assert.AreEqual("Starting gRPC call. Method type: 'Unary', URI: 'https://localhost/ServiceName/MethodName'.", log.State.ToString());
161+
AssertScope(log);
162+
163+
log = testSink.Writes.Single(w => w.EventId.Name == "GrpcStatusError");
164+
Assert.AreEqual("Call failed with gRPC error status. Status code: 'Internal', Message: 'Error starting gRPC call. Exception: Credentials error.'.", log.State.ToString());
165+
Assert.AreEqual(debugException, log.Exception);
166+
AssertScope(log);
167+
168+
log = testSink.Writes.Single(w => w.EventId.Name == "FinishedCall");
169+
Assert.AreEqual("Finished gRPC call.", log.State.ToString());
170+
AssertScope(log);
171+
172+
static void AssertScope(WriteContext log)
173+
{
174+
var scope = (IReadOnlyList<KeyValuePair<string, object>>)log.Scope;
175+
Assert.AreEqual(MethodType.Unary, scope[0].Value);
176+
Assert.AreEqual(new Uri("/ServiceName/MethodName", UriKind.Relative), scope[1].Value);
177+
}
178+
}
83179
}

0 commit comments

Comments
 (0)