diff --git a/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs b/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs index eaae71743b57..9bf5cebb6a62 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs @@ -702,7 +702,15 @@ private async Task ProcessRequests(IHttpApplication applicat // This has to be caught here so StatusCode is set properly before disposing the HttpContext // (DisposeContext logs StatusCode). SetBadRequestState(ex); - ReportApplicationError(ex); + + if (!_connectionAborted) + { + // Only report bad requests as error-level logs here if the connection hasn't been aborted. This + // prevents noise in the logs for common types of client errors, and we already have a mechanism + // for logging these at a higher level if needed by increasing the log level for + // "Microsoft.AspNetCore.Server.Kestrel.BadRequests". + ReportApplicationError(ex); + } } catch (Exception ex) { diff --git a/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs b/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs index cc88914c123e..bdae9d88ccb8 100644 --- a/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs +++ b/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs @@ -399,6 +399,68 @@ await connection.Receive( Assert.False(loggedHigherThanDebug); } + [Fact] + public async Task IncompleteRequestBodyDoesNotLogAsApplicationError() + { + var appErrorLogged = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var badRequestLogged = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var connectionStoppedLogged = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + + const int badRequestEventId = 17; + const int appErrorEventId = 13; + const int connectionStopEventId = 2; + + // Listen for the expected log message + TestSink.MessageLogged += context => + { + if (context.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.BadRequests" + && context.EventId == badRequestEventId + && context.LogLevel == LogLevel.Debug) + { + badRequestLogged.TrySetResult(); + } + else if (context.LoggerName == "Microsoft.AspNetCore.Server.Kestrel" + && context.EventId.Id == appErrorEventId + && context.LogLevel > LogLevel.Debug) + { + appErrorLogged.TrySetResult(); + } + else if (context.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Connections" + && context.EventId == connectionStopEventId) + { + connectionStoppedLogged.TrySetResult(); + } + }; + + await using var server = new TestServer(async context => + { + var buffer = new byte[1024]; + + // Attempt to read more of the body than will show up. + await context.Request.Body.ReadAsync(buffer, 0, buffer.Length); + }, new TestServiceContext(LoggerFactory)); + + using (var connection = server.CreateConnection()) + { + await connection.Send( + "POST / HTTP/1.1", + "Host:", + "Connection: keep-alive", + "Content-Type: application/json", + "Content-Length: 100", // Declare a larger body than will be sent + "", + ""); + } + + await connectionStoppedLogged.Task.DefaultTimeout(); + + // Bad request log message should have fired. + await badRequestLogged.Task.DefaultTimeout(); + + // App error log message should not have fired. + Assert.False(appErrorLogged.Task.IsCompleted); + } + [Fact] public async Task ConnectionResetBetweenRequestsIsLoggedAsDebug() { diff --git a/src/Servers/Kestrel/test/InMemory.FunctionalTests/ChunkedRequestTests.cs b/src/Servers/Kestrel/test/InMemory.FunctionalTests/ChunkedRequestTests.cs index f5ee2b28228e..5140f2c7e649 100644 --- a/src/Servers/Kestrel/test/InMemory.FunctionalTests/ChunkedRequestTests.cs +++ b/src/Servers/Kestrel/test/InMemory.FunctionalTests/ChunkedRequestTests.cs @@ -740,6 +740,9 @@ await connection.ReceiveEnd( "", ""); } + + // The 400 response should have been logged by default at Error level since the connection wasn't aborted when the bad request was handled. + Assert.Contains(TestSink.Writes, w => w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel" && w.EventId.Id == 13 && w.LogLevel > LogLevel.Debug); } }