Skip to content

Commit ed01b60

Browse files
Avoid logging bad requests as application errors if the connection was aborted (#60359)
1 parent 47a6f75 commit ed01b60

File tree

3 files changed

+74
-1
lines changed

3 files changed

+74
-1
lines changed

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

Lines changed: 9 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -702,7 +702,15 @@ private async Task ProcessRequests<TContext>(IHttpApplication<TContext> applicat
702702
// This has to be caught here so StatusCode is set properly before disposing the HttpContext
703703
// (DisposeContext logs StatusCode).
704704
SetBadRequestState(ex);
705-
ReportApplicationError(ex);
705+
706+
if (!_connectionAborted)
707+
{
708+
// Only report bad requests as error-level logs here if the connection hasn't been aborted. This
709+
// prevents noise in the logs for common types of client errors, and we already have a mechanism
710+
// for logging these at a higher level if needed by increasing the log level for
711+
// "Microsoft.AspNetCore.Server.Kestrel.BadRequests".
712+
ReportApplicationError(ex);
713+
}
706714
}
707715
catch (Exception ex)
708716
{

src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs

Lines changed: 62 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -399,6 +399,68 @@ await connection.Receive(
399399
Assert.False(loggedHigherThanDebug);
400400
}
401401

402+
[Fact]
403+
public async Task IncompleteRequestBodyDoesNotLogAsApplicationError()
404+
{
405+
var appErrorLogged = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
406+
var badRequestLogged = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
407+
var connectionStoppedLogged = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
408+
409+
const int badRequestEventId = 17;
410+
const int appErrorEventId = 13;
411+
const int connectionStopEventId = 2;
412+
413+
// Listen for the expected log message
414+
TestSink.MessageLogged += context =>
415+
{
416+
if (context.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.BadRequests"
417+
&& context.EventId == badRequestEventId
418+
&& context.LogLevel == LogLevel.Debug)
419+
{
420+
badRequestLogged.TrySetResult();
421+
}
422+
else if (context.LoggerName == "Microsoft.AspNetCore.Server.Kestrel"
423+
&& context.EventId.Id == appErrorEventId
424+
&& context.LogLevel > LogLevel.Debug)
425+
{
426+
appErrorLogged.TrySetResult();
427+
}
428+
else if (context.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Connections"
429+
&& context.EventId == connectionStopEventId)
430+
{
431+
connectionStoppedLogged.TrySetResult();
432+
}
433+
};
434+
435+
await using var server = new TestServer(async context =>
436+
{
437+
var buffer = new byte[1024];
438+
439+
// Attempt to read more of the body than will show up.
440+
await context.Request.Body.ReadAsync(buffer, 0, buffer.Length);
441+
}, new TestServiceContext(LoggerFactory));
442+
443+
using (var connection = server.CreateConnection())
444+
{
445+
await connection.Send(
446+
"POST / HTTP/1.1",
447+
"Host:",
448+
"Connection: keep-alive",
449+
"Content-Type: application/json",
450+
"Content-Length: 100", // Declare a larger body than will be sent
451+
"",
452+
"");
453+
}
454+
455+
await connectionStoppedLogged.Task.DefaultTimeout();
456+
457+
// Bad request log message should have fired.
458+
await badRequestLogged.Task.DefaultTimeout();
459+
460+
// App error log message should not have fired.
461+
Assert.False(appErrorLogged.Task.IsCompleted);
462+
}
463+
402464
[Fact]
403465
public async Task ConnectionResetBetweenRequestsIsLoggedAsDebug()
404466
{

src/Servers/Kestrel/test/InMemory.FunctionalTests/ChunkedRequestTests.cs

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -740,6 +740,9 @@ await connection.ReceiveEnd(
740740
"",
741741
"");
742742
}
743+
744+
// The 400 response should have been logged by default at Error level since the connection wasn't aborted when the bad request was handled.
745+
Assert.Contains(TestSink.Writes, w => w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel" && w.EventId.Id == 13 && w.LogLevel > LogLevel.Debug);
743746
}
744747
}
745748

0 commit comments

Comments
 (0)