diff --git a/src/Kestrel.Core/Internal/Http/HttpProtocol.cs b/src/Kestrel.Core/Internal/Http/HttpProtocol.cs index 2d722efa3e..cc34dfef3c 100644 --- a/src/Kestrel.Core/Internal/Http/HttpProtocol.cs +++ b/src/Kestrel.Core/Internal/Http/HttpProtocol.cs @@ -517,19 +517,19 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http // If _requestAbort is set, the connection has already been closed. if (_requestAborted == 0) { - if (HasResponseStarted) - { - // If the response has already started, call ProduceEnd() before - // consuming the rest of the request body to prevent - // delaying clients waiting for the chunk terminator: - // - // https://github.com/dotnet/corefx/issues/17330#issuecomment-288248663 - // - // ProduceEnd() must be called before _application.DisposeContext(), to ensure - // HttpContext.Response.StatusCode is correctly set when - // IHttpContextFactory.Dispose(HttpContext) is called. - await ProduceEnd(); - } + // Call ProduceEnd() before consuming the rest of the request body to prevent + // delaying clients waiting for the chunk terminator: + // + // https://github.com/dotnet/corefx/issues/17330#issuecomment-288248663 + // + // This also prevents the 100 Continue response from being sent if the app + // never tried to read the body. + // https://github.com/aspnet/KestrelHttpServer/issues/2102 + // + // ProduceEnd() must be called before _application.DisposeContext(), to ensure + // HttpContext.Response.StatusCode is correctly set when + // IHttpContextFactory.Dispose(HttpContext) is called. + await ProduceEnd(); // ForZeroContentLength does not complete the reader nor the writer if (!messageBody.IsEmpty && _keepAlive) @@ -537,11 +537,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http // Finish reading the request body in case the app did not. await messageBody.ConsumeAsync(); } - - if (!HasResponseStarted) - { - await ProduceEnd(); - } } else if (!HasResponseStarted) { diff --git a/test/Kestrel.FunctionalTests/MaxRequestBodySizeTests.cs b/test/Kestrel.FunctionalTests/MaxRequestBodySizeTests.cs index 925fc11f63..8c68fe3c39 100644 --- a/test/Kestrel.FunctionalTests/MaxRequestBodySizeTests.cs +++ b/test/Kestrel.FunctionalTests/MaxRequestBodySizeTests.cs @@ -2,6 +2,7 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; +using System.IO; using System.Text; using System.Threading.Tasks; using Microsoft.AspNetCore.Http.Features; @@ -140,7 +141,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests [Fact] public async Task DoesNotRejectBodylessGetRequestWithZeroMaxRequestBodySize() { - using (var server = new TestServer(context => Task.CompletedTask, + using (var server = new TestServer(context => context.Request.Body.CopyToAsync(Stream.Null), new TestServiceContext { ServerOptions = { Limits = { MaxRequestBodySize = 0 } } })) { using (var connection = server.CreateConnection()) diff --git a/test/Kestrel.FunctionalTests/RequestBodyTimeoutTests.cs b/test/Kestrel.FunctionalTests/RequestBodyTimeoutTests.cs index 073b646e2d..a9593afe79 100644 --- a/test/Kestrel.FunctionalTests/RequestBodyTimeoutTests.cs +++ b/test/Kestrel.FunctionalTests/RequestBodyTimeoutTests.cs @@ -7,9 +7,12 @@ using System.Threading.Tasks; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Server.Kestrel.Core; using Microsoft.AspNetCore.Server.Kestrel.Core.Features; +using Microsoft.AspNetCore.Server.Kestrel.Core.Internal; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Testing; using Xunit; namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests @@ -66,12 +69,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests [Fact] public async Task RequestTimesOutWhenNotDrainedWithinDrainTimeoutPeriod() { + var sink = new TestSink(); + var logger = new TestLogger("TestLogger", sink, enabled: true); + // This test requires a real clock since we can't control when the drain timeout is set var systemClock = new SystemClock(); var serviceContext = new TestServiceContext { SystemClock = systemClock, - DateHeaderValueManager = new DateHeaderValueManager(systemClock) + DateHeaderValueManager = new DateHeaderValueManager(systemClock), + Log = new KestrelTrace(logger) }; var appRunningEvent = new ManualResetEventSlim(); @@ -96,17 +103,20 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests Assert.True(appRunningEvent.Wait(TimeSpan.FromSeconds(10))); await connection.Receive( - "HTTP/1.1 408 Request Timeout", - "Connection: close", + "HTTP/1.1 200 OK", ""); await connection.ReceiveStartsWith( "Date: "); + // Disconnected due to the timeout await connection.ReceiveForcedEnd( "Content-Length: 0", "", ""); } } + + Assert.Contains(sink.Writes, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information && w.Exception is BadHttpRequestException + && ((BadHttpRequestException)w.Exception).StatusCode == StatusCodes.Status408RequestTimeout); } [Fact] diff --git a/test/Kestrel.FunctionalTests/ResponseTests.cs b/test/Kestrel.FunctionalTests/ResponseTests.cs index 8fc7a16052..a43f9cb746 100644 --- a/test/Kestrel.FunctionalTests/ResponseTests.cs +++ b/test/Kestrel.FunctionalTests/ResponseTests.cs @@ -257,8 +257,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests { return Task.CompletedTask; }, - expectedClientStatusCode: null, - expectedServerStatusCode: HttpStatusCode.BadRequest, + expectedClientStatusCode: HttpStatusCode.OK, + expectedServerStatusCode: HttpStatusCode.OK, sendMalformedRequest: true); } @@ -289,8 +289,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests { } }, - expectedClientStatusCode: null, - expectedServerStatusCode: HttpStatusCode.BadRequest, + expectedClientStatusCode: HttpStatusCode.OK, + expectedServerStatusCode: HttpStatusCode.OK, sendMalformedRequest: true); } @@ -311,8 +311,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests disposedTcs.TrySetResult(c.Response.StatusCode); }); - using (var server = new TestServer(handler, new TestServiceContext(), new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0)), - services => services.AddSingleton(mockHttpContextFactory.Object))) + var sink = new TestSink(); + var logger = new TestLogger("TestLogger", sink, enabled: true); + + using (var server = new TestServer(handler, new TestServiceContext() { Log = new KestrelTrace(logger) }, + new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0)), + services => services.AddSingleton(mockHttpContextFactory.Object))) { if (!sendMalformedRequest) { @@ -342,32 +346,57 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "Transfer-Encoding: chunked", "", "gg"); - await connection.ReceiveForcedEnd( - "HTTP/1.1 400 Bad Request", - "Connection: close", - $"Date: {server.Context.DateHeaderValue}", - "Content-Length: 0", - "", - ""); + if (expectedClientStatusCode == HttpStatusCode.OK) + { + await connection.ReceiveForcedEnd( + "HTTP/1.1 200 OK", + $"Date: {server.Context.DateHeaderValue}", + "Content-Length: 0", + "", + ""); + } + else + { + await connection.ReceiveForcedEnd( + "HTTP/1.1 400 Bad Request", + "Connection: close", + $"Date: {server.Context.DateHeaderValue}", + "Content-Length: 0", + "", + ""); + } } } var disposedStatusCode = await disposedTcs.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); Assert.Equal(expectedServerStatusCode, (HttpStatusCode)disposedStatusCode); } + + if (sendMalformedRequest) + { + Assert.Contains(sink.Writes, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information && w.Exception is BadHttpRequestException + && ((BadHttpRequestException)w.Exception).StatusCode == StatusCodes.Status400BadRequest); + } + else + { + Assert.DoesNotContain(sink.Writes, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information && w.Exception is BadHttpRequestException + && ((BadHttpRequestException)w.Exception).StatusCode == StatusCodes.Status400BadRequest); + } } // https://github.com/aspnet/KestrelHttpServer/pull/1111/files#r80584475 explains the reason for this test. [Fact] - public async Task SingleErrorResponseSentWhenAppSwallowsBadRequestException() + public async Task NoErrorResponseSentWhenAppSwallowsBadRequestException() { BadHttpRequestException readException = null; + var sink = new TestSink(); + var logger = new TestLogger("TestLogger", sink, enabled: true); using (var server = new TestServer(async httpContext => { readException = await Assert.ThrowsAsync( async () => await httpContext.Request.Body.ReadAsync(new byte[1], 0, 1)); - })) + }, new TestServiceContext() { Log = new KestrelTrace(logger) })) { using (var connection = server.CreateConnection()) { @@ -378,8 +407,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "", "gg"); await connection.ReceiveForcedEnd( - "HTTP/1.1 400 Bad Request", - "Connection: close", + "HTTP/1.1 200 OK", $"Date: {server.Context.DateHeaderValue}", "Content-Length: 0", "", @@ -388,6 +416,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } Assert.NotNull(readException); + + Assert.Contains(sink.Writes, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information && w.Exception is BadHttpRequestException + && ((BadHttpRequestException)w.Exception).StatusCode == StatusCodes.Status400BadRequest); } [Fact] @@ -1474,9 +1505,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } [Fact] - public async Task WhenResponseNotStartedResponseEndedAfterConsumingRequestBody() + public async Task WhenResponseNotStartedResponseEndedBeforeConsumingRequestBody() { - using (var server = new TestServer(httpContext => Task.CompletedTask)) + var sink = new TestSink(); + var logger = new TestLogger("TestLogger", sink, enabled: true); + + using (var server = new TestServer(httpContext => Task.CompletedTask, + new TestServiceContext() { Log = new KestrelTrace(logger) })) { using (var connection = server.CreateConnection()) { @@ -1487,27 +1522,32 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "", "gg"); - // If the expected behavior is regressed, this will receive - // a success response because the server flushed the response - // before reading the malformed chunk header in the request. + // This will receive a success response because the server flushed the response + // before reading the malformed chunk header in the request, but then it will close + // the connection. await connection.ReceiveForcedEnd( - "HTTP/1.1 400 Bad Request", - "Connection: close", + "HTTP/1.1 200 OK", $"Date: {server.Context.DateHeaderValue}", "Content-Length: 0", "", ""); } } + + Assert.Contains(sink.Writes, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information && w.Exception is BadHttpRequestException + && ((BadHttpRequestException)w.Exception).StatusCode == StatusCodes.Status400BadRequest); } [Fact] public async Task Sending100ContinueDoesNotStartResponse() { + var sink = new TestSink(); + var logger = new TestLogger("TestLogger", sink, enabled: true); + using (var server = new TestServer(httpContext => { return httpContext.Request.Body.ReadAsync(new byte[1], 0, 1); - })) + }, new TestServiceContext() { Log = new KestrelTrace(logger) })) { using (var connection = server.CreateConnection()) { @@ -1530,6 +1570,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "a", ""); + await connection.Receive( + "HTTP/1.1 200 OK", + $"Date: {server.Context.DateHeaderValue}", + "Content-Length: 0", + "", + ""); + // This will be consumed by Http1Connection when it attempts to // consume the request body and will cause an error. await connection.Send( @@ -1538,15 +1585,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests // If 100 Continue sets HttpProtocol.HasResponseStarted to true, // a success response will be produced before the server sees the // bad chunk header above, making this test fail. - await connection.ReceiveForcedEnd( - "HTTP/1.1 400 Bad Request", - "Connection: close", - $"Date: {server.Context.DateHeaderValue}", - "Content-Length: 0", - "", - ""); + await connection.ReceiveEnd(); } } + + Assert.Contains(sink.Writes, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information && w.Exception is BadHttpRequestException + && ((BadHttpRequestException)w.Exception).StatusCode == StatusCodes.Status400BadRequest); } [Fact]