Skip to content

Commit 9c19577

Browse files
halter73halter73
authored
Log client errors as Debug (#12262)
1 parent 771989b commit 9c19577

File tree

10 files changed

+41
-34
lines changed

10 files changed

+41
-34
lines changed

‎src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -571,6 +571,10 @@ public async Task ProcessRequestsAsync<TContext>(IHttpApplication<TContext> appl
571571
{
572572
Log.RequestProcessingError(ConnectionId, ex);
573573
}
574+
catch (ConnectionAbortedException ex)
575+
{
576+
Log.RequestProcessingError(ConnectionId, ex);
577+
}
574578
catch (Exception ex)
575579
{
576580
Log.LogWarning(0, ex, CoreStrings.RequestProcessingEndError);

‎src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -244,6 +244,11 @@ public async Task ProcessRequestsAsync<TContext>(IHttpApplication<TContext> appl
244244
Log.RequestProcessingError(ConnectionId, ex);
245245
error = ex;
246246
}
247+
catch (ConnectionAbortedException ex)
248+
{
249+
Log.RequestProcessingError(ConnectionId, ex);
250+
error = ex;
251+
}
247252
catch (Http2ConnectionErrorException ex)
248253
{
249254
Log.Http2ConnectionError(ConnectionId, ex);

‎src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -37,13 +37,13 @@ internal class KestrelTrace : IKestrelTrace
3737
LoggerMessage.Define(LogLevel.Debug, new EventId(16, nameof(NotAllConnectionsClosedGracefully)), "Some connections failed to close gracefully during server shutdown.");
3838

3939
private static readonly Action<ILogger, string, string, Exception> _connectionBadRequest =
40-
LoggerMessage.Define<string, string>(LogLevel.Information, new EventId(17, nameof(ConnectionBadRequest)), @"Connection id ""{ConnectionId}"" bad request data: ""{message}""");
40+
LoggerMessage.Define<string, string>(LogLevel.Debug, new EventId(17, nameof(ConnectionBadRequest)), @"Connection id ""{ConnectionId}"" bad request data: ""{message}""");
4141

4242
private static readonly Action<ILogger, string, long, Exception> _connectionHeadResponseBodyWrite =
4343
LoggerMessage.Define<string, long>(LogLevel.Debug, new EventId(18, nameof(ConnectionHeadResponseBodyWrite)), @"Connection id ""{ConnectionId}"" write of ""{count}"" body bytes to non-body HEAD response.");
4444

4545
private static readonly Action<ILogger, string, Exception> _requestProcessingError =
46-
LoggerMessage.Define<string>(LogLevel.Information, new EventId(20, nameof(RequestProcessingError)), @"Connection id ""{ConnectionId}"" request processing ended abnormally.");
46+
LoggerMessage.Define<string>(LogLevel.Debug, new EventId(20, nameof(RequestProcessingError)), @"Connection id ""{ConnectionId}"" request processing ended abnormally.");
4747

4848
private static readonly Action<ILogger, Exception> _notAllConnectionsAborted =
4949
LoggerMessage.Define(LogLevel.Debug, new EventId(21, nameof(NotAllConnectionsAborted)), "Some connections failed to abort during server shutdown.");
@@ -64,19 +64,19 @@ internal class KestrelTrace : IKestrelTrace
6464
LoggerMessage.Define<string, string>(LogLevel.Debug, new EventId(26, nameof(RequestBodyDone)), @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": done reading request body.");
6565

6666
private static readonly Action<ILogger, string, string, double, Exception> _requestBodyMinimumDataRateNotSatisfied =
67-
LoggerMessage.Define<string, string, double>(LogLevel.Information, new EventId(27, nameof(RequestBodyMinimumDataRateNotSatisfied)), @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the request timed out because it was not sent by the client at a minimum of {Rate} bytes/second.");
67+
LoggerMessage.Define<string, string, double>(LogLevel.Debug, new EventId(27, nameof(RequestBodyMinimumDataRateNotSatisfied)), @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the request timed out because it was not sent by the client at a minimum of {Rate} bytes/second.");
6868

6969
private static readonly Action<ILogger, string, string, Exception> _responseMinimumDataRateNotSatisfied =
70-
LoggerMessage.Define<string, string>(LogLevel.Information, new EventId(28, nameof(ResponseMinimumDataRateNotSatisfied)), @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the connection was closed because the response was not read by the client at the specified minimum data rate.");
70+
LoggerMessage.Define<string, string>(LogLevel.Debug, new EventId(28, nameof(ResponseMinimumDataRateNotSatisfied)), @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the connection was closed because the response was not read by the client at the specified minimum data rate.");
7171

7272
private static readonly Action<ILogger, string, Exception> _http2ConnectionError =
73-
LoggerMessage.Define<string>(LogLevel.Information, new EventId(29, nameof(Http2ConnectionError)), @"Connection id ""{ConnectionId}"": HTTP/2 connection error.");
73+
LoggerMessage.Define<string>(LogLevel.Debug, new EventId(29, nameof(Http2ConnectionError)), @"Connection id ""{ConnectionId}"": HTTP/2 connection error.");
7474

7575
private static readonly Action<ILogger, string, Exception> _http2StreamError =
76-
LoggerMessage.Define<string>(LogLevel.Information, new EventId(30, nameof(Http2StreamError)), @"Connection id ""{ConnectionId}"": HTTP/2 stream error.");
76+
LoggerMessage.Define<string>(LogLevel.Debug, new EventId(30, nameof(Http2StreamError)), @"Connection id ""{ConnectionId}"": HTTP/2 stream error.");
7777

7878
private static readonly Action<ILogger, string, int, Exception> _hpackDecodingError =
79-
LoggerMessage.Define<string, int>(LogLevel.Information, new EventId(31, nameof(HPackDecodingError)), @"Connection id ""{ConnectionId}"": HPACK decoding error while decoding headers for stream ID {StreamId}.");
79+
LoggerMessage.Define<string, int>(LogLevel.Debug, new EventId(31, nameof(HPackDecodingError)), @"Connection id ""{ConnectionId}"": HPACK decoding error while decoding headers for stream ID {StreamId}.");
8080

8181
private static readonly Action<ILogger, string, string, Exception> _requestBodyNotEntirelyRead =
8282
LoggerMessage.Define<string, string>(LogLevel.Information, new EventId(32, nameof(RequestBodyNotEntirelyRead)), @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the application completed without reading the entire request body.");

‎src/Servers/Kestrel/Core/src/Internal/Infrastructure/PipeWriterHelpers/ConcurrentPipeWriter.cs

Lines changed: 9 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -46,9 +46,10 @@ internal sealed class ConcurrentPipeWriter : PipeWriter
4646
private TaskCompletionSource<FlushResult> _currentFlushTcs;
4747
private bool _bufferedWritePending;
4848

49-
// We're trusting the Http2FrameWriter and Http1OutputProducer to not call into the PipeWriter after calling Abort() or Complete()
50-
// If an abort occurs while a flush is in progress, we clean up after the flush completes, and don't flush again.
49+
// We're trusting the Http2FrameWriter and Http1OutputProducer to not call into the PipeWriter after calling Abort() or Complete().
50+
// If an Abort() is called while a flush is in progress, we clean up after the next flush completes, and don't flush again.
5151
private bool _aborted;
52+
// If an Complete() is called while a flush is in progress, we clean up after the flush loop completes, and call Complete() on the inner PipeWriter.
5253
private Exception _completeException;
5354

5455
public ConcurrentPipeWriter(PipeWriter innerPipeWriter, MemoryPool<byte> pool, object sync)
@@ -123,7 +124,7 @@ public override ValueTask<FlushResult> FlushAsync(CancellationToken cancellation
123124
return flushTask;
124125
}
125126

126-
// Use a TCS instead of something resettable so it can be awaited by multiple awaiters.
127+
// Use a TCS instead of something custom so it can be awaited by multiple awaiters.
127128
_currentFlushTcs = new TaskCompletionSource<FlushResult>(TaskCreationOptions.RunContinuationsAsynchronously);
128129
var result = new ValueTask<FlushResult>(_currentFlushTcs.Task);
129130

@@ -153,7 +154,7 @@ private async Task FlushAsyncAwaited(ValueTask<FlushResult> flushTask, Cancellat
153154

154155
if (flushResult.IsCanceled)
155156
{
156-
// Complete anyone currently awaiting a flush since CancelPendingFlush() was called
157+
// Complete anyone currently awaiting a flush with the canceled FlushResult since CancelPendingFlush() was called.
157158
_currentFlushTcs.SetResult(flushResult);
158159
// Reset _currentFlushTcs, so we don't enter passthrough mode while we're still flushing.
159160
_currentFlushTcs = new TaskCompletionSource<FlushResult>(TaskCreationOptions.RunContinuationsAsynchronously);
@@ -176,18 +177,15 @@ private async Task FlushAsyncAwaited(ValueTask<FlushResult> flushTask, Cancellat
176177

177178
public override void CancelPendingFlush()
178179
{
179-
// We propagate IsCanceled when we do multiple flushes in a loop. If FlushResult.IsCanceled is true with more data pending to flush,
180-
// _currentFlushTcs with canceled flush task, but rekick the FlushAsync loop.
180+
// FlushAsyncAwaited never ignores a canceled FlushResult.
181181
_innerPipeWriter.CancelPendingFlush();
182182
}
183183

184+
// To return all the segments without completing the inner pipe, call Abort().
184185
public override void Complete(Exception exception = null)
185186
{
186-
// We store the complete exception or s sentinel exception instance in a field if a flush was ongoing.
187-
// We call the inner Complete() method after the flush loop ended.
188-
189-
// To simply ensure everything gets returned after the PipeWriter is left in some unknown state (say GetMemory() was
190-
// called but not Advance(), or there's a flush pending), but you don't want to complete the inner pipe, just call Abort().
187+
// Store the exception or sentinel in a field so that if a flush is ongoing, we call the
188+
// inner Complete() method with the correct exception or lack thereof once the flush loop ends.
191189
_completeException = exception ?? _successfullyCompletedSentinel;
192190

193191
if (_currentFlushTcs == null)

‎src/Servers/Kestrel/Transport.Libuv/src/Internal/LibuvTrace.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,7 @@ internal class LibuvTrace : ILibuvTrace
2727
// ConnectionWriteCallback: Reserved: 12
2828

2929
private static readonly Action<ILogger, string, Exception> _connectionError =
30-
LoggerMessage.Define<string>(LogLevel.Information, new EventId(14, nameof(ConnectionError)), @"Connection id ""{ConnectionId}"" communication error.");
30+
LoggerMessage.Define<string>(LogLevel.Debug, new EventId(14, nameof(ConnectionError)), @"Connection id ""{ConnectionId}"" communication error.");
3131

3232
private static readonly Action<ILogger, string, Exception> _connectionReset =
3333
LoggerMessage.Define<string>(LogLevel.Debug, new EventId(19, nameof(ConnectionReset)), @"Connection id ""{ConnectionId}"" reset.");

‎src/Servers/Kestrel/Transport.Sockets/src/Internal/SocketsTrace.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,7 @@ internal class SocketsTrace : ISocketsTrace
2727
// ConnectionWriteCallback: Reserved: 12
2828

2929
private static readonly Action<ILogger, string, Exception> _connectionError =
30-
LoggerMessage.Define<string>(LogLevel.Information, new EventId(14, nameof(ConnectionError)), @"Connection id ""{ConnectionId}"" communication error.");
30+
LoggerMessage.Define<string>(LogLevel.Debug, new EventId(14, nameof(ConnectionError)), @"Connection id ""{ConnectionId}"" communication error.");
3131

3232
private static readonly Action<ILogger, string, Exception> _connectionReset =
3333
LoggerMessage.Define<string>(LogLevel.Debug, new EventId(19, nameof(ConnectionReset)), @"Connection id ""{ConnectionId}"" reset.");

‎src/Servers/Kestrel/test/InMemory.FunctionalTests/BadHttpRequestTests.cs

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -151,7 +151,7 @@ public Task BadRequestFor11BadHostHeaderFormat()
151151
}
152152

153153
[Fact]
154-
public async Task BadRequestLogsAreNotHigherThanInformation()
154+
public async Task BadRequestLogsAreNotHigherThanDebug()
155155
{
156156
await using (var server = new TestServer(async context =>
157157
{
@@ -168,8 +168,8 @@ await connection.SendAll(
168168
}
169169
}
170170

171-
Assert.All(TestSink.Writes, w => Assert.InRange(w.LogLevel, LogLevel.Trace, LogLevel.Information));
172-
Assert.Contains(TestSink.Writes, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information);
171+
Assert.All(TestSink.Writes, w => Assert.InRange(w.LogLevel, LogLevel.Trace, LogLevel.Debug));
172+
Assert.Contains(TestSink.Writes, w => w.EventId.Id == 17);
173173
}
174174

175175
[Fact]

‎src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -3731,7 +3731,7 @@ public async Task IgnoreNewStreamsDuringClosedConnection()
37313731
}
37323732

37333733
[Fact]
3734-
public void IOExceptionDuringFrameProcessingLoggedAsInfo()
3734+
public void IOExceptionDuringFrameProcessingIsNotLoggedHigherThanDebug()
37353735
{
37363736
CreateConnection();
37373737

@@ -3740,9 +3740,10 @@ public void IOExceptionDuringFrameProcessingLoggedAsInfo()
37403740

37413741
Assert.Equal(TaskStatus.RanToCompletion, _connection.ProcessRequestsAsync(new DummyApplication(_noopApplication)).Status);
37423742

3743-
var logMessage = TestApplicationErrorLogger.Messages.Single(m => m.LogLevel >= LogLevel.Information);
3743+
Assert.All(TestApplicationErrorLogger.Messages, w => Assert.InRange(w.LogLevel, LogLevel.Trace, LogLevel.Debug));
3744+
3745+
var logMessage = TestApplicationErrorLogger.Messages.Single(m => m.EventId == 20);
37443746

3745-
Assert.Equal(LogLevel.Information, logMessage.LogLevel);
37463747
Assert.Equal("Connection id \"(null)\" request processing ended abnormally.", logMessage.Message);
37473748
Assert.Same(ioException, logMessage.Exception);
37483749
}

‎src/Servers/Kestrel/test/InMemory.FunctionalTests/ResponseDrainingTests.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -77,7 +77,7 @@ await connection.Send(
7777
Assert.NotNull(transportConnection.AbortReason);
7878
Assert.Equal(CoreStrings.ConnectionTimedBecauseResponseMininumDataRateNotSatisfied, transportConnection.AbortReason.Message);
7979

80-
Assert.Single(TestApplicationErrorLogger.Messages, w => w.EventId.Id == 28 && w.LogLevel == LogLevel.Information);
80+
Assert.Single(TestApplicationErrorLogger.Messages, w => w.EventId.Id == 28 && w.LogLevel <= LogLevel.Debug);
8181
}
8282
}
8383
}

‎src/Servers/Kestrel/test/InMemory.FunctionalTests/ResponseTests.cs

Lines changed: 6 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -431,7 +431,7 @@ await connection.ReceiveEnd(
431431

432432
Assert.NotNull(readException);
433433

434-
Assert.Contains(TestSink.Writes, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information && w.Exception is BadHttpRequestException
434+
Assert.Contains(TestSink.Writes, w => w.EventId.Id == 17 && w.LogLevel <= LogLevel.Debug && w.Exception is BadHttpRequestException
435435
&& ((BadHttpRequestException)w.Exception).StatusCode == StatusCodes.Status400BadRequest);
436436
}
437437

@@ -1750,7 +1750,7 @@ await connection.ReceiveEnd(
17501750
}
17511751
}
17521752

1753-
Assert.Contains(TestApplicationErrorLogger.Messages, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information && w.Exception is BadHttpRequestException
1753+
Assert.Contains(TestApplicationErrorLogger.Messages, w => w.EventId.Id == 17 && w.LogLevel <= LogLevel.Debug && w.Exception is BadHttpRequestException
17541754
&& ((BadHttpRequestException)w.Exception).StatusCode == StatusCodes.Status400BadRequest);
17551755
}
17561756

@@ -1802,7 +1802,7 @@ await connection.Send(
18021802
{
18031803
while (TestApplicationErrorLogger.Messages.TryDequeue(out var message))
18041804
{
1805-
if (message.EventId.Id == 17 && message.LogLevel == LogLevel.Information && message.Exception is BadHttpRequestException
1805+
if (message.EventId.Id == 17 && message.LogLevel <= LogLevel.Debug && message.Exception is BadHttpRequestException
18061806
&& ((BadHttpRequestException)message.Exception).StatusCode == StatusCodes.Status400BadRequest)
18071807
{
18081808
foundMessage = true;
@@ -1863,7 +1863,7 @@ await connection.ReceiveEnd(
18631863
}
18641864
}
18651865

1866-
Assert.Contains(TestApplicationErrorLogger.Messages, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information && w.Exception is BadHttpRequestException
1866+
Assert.Contains(TestApplicationErrorLogger.Messages, w => w.EventId.Id == 17 && w.LogLevel <= LogLevel.Debug && w.Exception is BadHttpRequestException
18671867
&& ((BadHttpRequestException)w.Exception).StatusCode == StatusCodes.Status400BadRequest);
18681868
}
18691869

@@ -4118,13 +4118,12 @@ await connection.ReceiveEnd(
41184118

41194119
if (sendMalformedRequest)
41204120
{
4121-
Assert.Contains(testSink.Writes, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information && w.Exception is BadHttpRequestException
4121+
Assert.Contains(testSink.Writes, w => w.EventId.Id == 17 && w.LogLevel <= LogLevel.Debug && w.Exception is BadHttpRequestException
41224122
&& ((BadHttpRequestException)w.Exception).StatusCode == StatusCodes.Status400BadRequest);
41234123
}
41244124
else
41254125
{
4126-
Assert.DoesNotContain(testSink.Writes, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information && w.Exception is BadHttpRequestException
4127-
&& ((BadHttpRequestException)w.Exception).StatusCode == StatusCodes.Status400BadRequest);
4126+
Assert.DoesNotContain(testSink.Writes, w => w.EventId.Id == 17);
41284127
}
41294128
}
41304129

0 commit comments

Comments
 (0)