private async Task TestBadRequest(string request, string expectedResponseStatusCode, string expectedExceptionMessage, string expectedAllowHeader = null) { BadHttpRequestException loggedException = null; var mockKestrelTrace = new Mock <IKestrelTrace>(); mockKestrelTrace .Setup(trace => trace.IsEnabled(LogLevel.Information)) .Returns(true); mockKestrelTrace .Setup(trace => trace.ConnectionBadRequest(It.IsAny <string>(), It.IsAny <BadHttpRequestException>())) .Callback <string, BadHttpRequestException>((connectionId, exception) => loggedException = exception); using (var server = new TestServer(context => Task.CompletedTask, new TestServiceContext(LoggerFactory, mockKestrelTrace.Object))) { using (var connection = server.CreateConnection()) { await connection.SendAll(request); await ReceiveBadRequestResponse(connection, expectedResponseStatusCode, server.Context.DateHeaderValue, expectedAllowHeader); } } mockKestrelTrace.Verify(trace => trace.ConnectionBadRequest(It.IsAny <string>(), It.IsAny <BadHttpRequestException>())); Assert.Equal(expectedExceptionMessage, loggedException.Message); }
public async Task ClientAbortingConnectionImmediatelyIsNotLoggedHigherThanDebug(ListenOptions listenOptions) { // Attempt multiple connections to be extra sure the resets are consistently logged appropriately. const int numConnections = 10; // There's not guarantee that the app even gets invoked in this test. The connection reset can be observed // as early as accept. var testServiceContext = new TestServiceContext(LoggerFactory); await using (var server = new TestServer(context => Task.CompletedTask, testServiceContext, listenOptions)) { for (var i = 0; i < numConnections; i++) { using (var connection = server.CreateConnection()) { await connection.Send( "GET / HTTP/1.1", "Host:", "", ""); connection.Reset(); } } } var transportLogs = TestSink.Writes.Where(w => w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv" || w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets"); // The "Microsoft.AspNetCore.Server.Kestrel" logger may contain info level logs because resetting the connection can cause // partial headers to be read leading to a bad request. var coreLogs = TestSink.Writes.Where(w => w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel"); Assert.Empty(transportLogs.Where(w => w.LogLevel > LogLevel.Debug)); Assert.Empty(coreLogs.Where(w => w.LogLevel > LogLevel.Information)); }
public async Task NonPathRequestTargetSetInRawTarget(HttpMethod method, string requestTarget) { var testContext = new TestServiceContext(LoggerFactory); using (var server = new TestServer(async context => { Assert.Equal(requestTarget, context.Features.Get <IHttpRequestFeature>().RawTarget); Assert.Empty(context.Request.Path.Value); Assert.Empty(context.Request.PathBase.Value); Assert.Empty(context.Request.QueryString.Value); context.Response.Headers["Content-Length"] = new[] { "11" }; await context.Response.WriteAsync("Hello World"); }, testContext)) { using (var connection = server.CreateConnection()) { var host = method == HttpMethod.Connect ? requestTarget : string.Empty; await connection.Send( $"{HttpUtilities.MethodToString(method)} {requestTarget} HTTP/1.1", $"Host: {host}", "", ""); await connection.ReceiveEnd( "HTTP/1.1 200 OK", $"Date: {testContext.DateHeaderValue}", "Content-Length: 11", "", "Hello World"); } } }
public async Task ConnectionClosedTokenFiresOnClientFIN(ListenOptions listenOptions) { var testContext = new TestServiceContext(LoggerFactory) { ExpectedConnectionMiddlewareCount = listenOptions._middleware.Count }; var appStartedTcs = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var connectionClosedTcs = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); using (var server = new TestServer(context => { appStartedTcs.SetResult(null); var connectionLifetimeFeature = context.Features.Get <IConnectionLifetimeFeature>(); connectionLifetimeFeature.ConnectionClosed.Register(() => connectionClosedTcs.SetResult(null)); return(Task.CompletedTask); }, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { await connection.Send( "GET / HTTP/1.1", "Host:", "", ""); await appStartedTcs.Task.DefaultTimeout(); connection.Shutdown(SocketShutdown.Send); await connectionClosedTcs.Task.DefaultTimeout(); } await server.StopAsync(); } }
public async Task ChunkedNotFinalTransferCodingResultsIn400(ListenOptions listenOptions) { var testContext = new TestServiceContext(LoggerFactory); using (var server = new TestServer(httpContext => { return(Task.CompletedTask); }, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { await connection.SendAll( "POST / HTTP/1.1", "Host:", "Transfer-Encoding: not-chunked", "", "C", "hello, world", "0", "", ""); await connection.ReceiveForcedEnd( "HTTP/1.1 400 Bad Request", "Connection: close", $"Date: {testContext.DateHeaderValue}", "Content-Length: 0", "", ""); } // Content-Length should not affect this using (var connection = server.CreateConnection()) { await connection.SendAll( "POST / HTTP/1.1", "Host:", "Transfer-Encoding: not-chunked", "Content-Length: 22", "", "C", "hello, world", "0", "", ""); await connection.ReceiveForcedEnd( "HTTP/1.1 400 Bad Request", "Connection: close", $"Date: {testContext.DateHeaderValue}", "Content-Length: 0", "", ""); } using (var connection = server.CreateConnection()) { await connection.SendAll( "POST / HTTP/1.1", "Host:", "Transfer-Encoding: chunked, not-chunked", "", "C", "hello, world", "0", "", ""); await connection.ReceiveForcedEnd( "HTTP/1.1 400 Bad Request", "Connection: close", $"Date: {testContext.DateHeaderValue}", "Content-Length: 0", "", ""); } // Content-Length should not affect this using (var connection = server.CreateConnection()) { await connection.SendAll( "POST / HTTP/1.1", "Host:", "Transfer-Encoding: chunked, not-chunked", "Content-Length: 22", "", "C", "hello, world", "0", "", ""); await connection.ReceiveForcedEnd( "HTTP/1.1 400 Bad Request", "Connection: close", $"Date: {testContext.DateHeaderValue}", "Content-Length: 0", "", ""); } } }
public async Task ExtensionsAreIgnored(ListenOptions listenOptions) { var testContext = new TestServiceContext(LoggerFactory); var requestCount = 10; var requestsReceived = 0; using (var server = new TestServer(async httpContext => { var response = httpContext.Response; var request = httpContext.Request; var buffer = new byte[200]; while (await request.Body.ReadAsync(buffer, 0, buffer.Length) != 0) { ;// read to end } if (requestsReceived < requestCount) { Assert.Equal(new string('a', requestsReceived), request.Headers["X-Trailer-Header"].ToString()); } else { Assert.True(string.IsNullOrEmpty(request.Headers["X-Trailer-Header"])); } requestsReceived++; response.Headers["Content-Length"] = new[] { "11" }; await response.Body.WriteAsync(Encoding.ASCII.GetBytes("Hello World"), 0, 11); }, testContext, listenOptions)) { var response = string.Join("\r\n", new string[] { "HTTP/1.1 200 OK", $"Date: {testContext.DateHeaderValue}", "Content-Length: 11", "", "Hello World" }); var expectedFullResponse = string.Join("", Enumerable.Repeat(response, requestCount + 1)); IEnumerable <string> sendSequence = new string[] { "POST / HTTP/1.1", "Host:", "Transfer-Encoding: chunked", "", "C;hello there", "HelloChunked", "0;hello there", "" }; for (var i = 1; i < requestCount; i++) { sendSequence = sendSequence.Concat(new string[] { "POST / HTTP/1.1", "Host:", "Transfer-Encoding: chunked", "", "C;hello there", $"HelloChunk{i:00}", "0;hello there", string.Concat("X-Trailer-Header: ", new string('a', i)), "" }); } sendSequence = sendSequence.Concat(new string[] { "POST / HTTP/1.1", "Host:", "Content-Length: 7", "", "Goodbye" }); var fullRequest = sendSequence.ToArray(); using (var connection = server.CreateConnection()) { await connection.Send(fullRequest); await connection.ReceiveEnd(expectedFullResponse); } } }
public async Task ConnectionNotClosedWhenClientSatisfiesMinimumDataRateGivenLargeResponseHeaders() { var headerSize = 1024 * 1024; // 1 MB for each header value var headerCount = 64; // 64 MB of headers per response var requestCount = 4; // Minimum of 256 MB of total response headers var headerValue = new string('a', headerSize); var headerStringValues = new StringValues(Enumerable.Repeat(headerValue, headerCount).ToArray()); var requestAborted = false; var mockKestrelTrace = new Mock <IKestrelTrace>(); var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) { ServerOptions = { Limits = { MinResponseDataRate = new MinDataRate(bytesPerSecond: 240, gracePeriod: TimeSpan.FromSeconds(2)) } } }; testContext.InitializeHeartbeat(); var dateHeaderValueManager = new DateHeaderValueManager(); dateHeaderValueManager.OnHeartbeat(DateTimeOffset.MinValue); testContext.DateHeaderValueManager = dateHeaderValueManager; var listenOptions = new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0)); async Task App(HttpContext context) { context.RequestAborted.Register(() => { requestAborted = true; }); context.Response.Headers[$"X-Custom-Header"] = headerStringValues; context.Response.ContentLength = 0; await context.Response.BodyWriter.FlushAsync(); } using (var server = new TestServer(App, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { for (var i = 0; i < requestCount - 1; i++) { await connection.Send( "GET / HTTP/1.1", "Host:", "", ""); } await connection.Send( "GET / HTTP/1.1", "Host:", "", ""); await connection.Receive( "HTTP/1.1 200 OK", $"Date: {dateHeaderValueManager.GetDateHeaderValues().String}"); var minResponseSize = headerSize * headerCount; var minTotalOutputSize = requestCount * minResponseSize; // Make sure consuming a single set of response headers exceeds the 2 second timeout. var targetBytesPerSecond = minResponseSize / 4; // expectedBytes was determined by manual testing. A constant Date header is used, so this shouldn't change unless // the response header writing logic itself changes. await AssertBytesReceivedAtTargetRate(connection.Stream, expectedBytes : 268_439_596, targetBytesPerSecond); connection.ShutdownSend(); await connection.WaitForConnectionClose(); } await server.StopAsync(); } mockKestrelTrace.Verify(t => t.ResponseMinimumDataRateNotSatisfied(It.IsAny <string>(), It.IsAny <string>()), Times.Never()); mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny <string>()), Times.Once()); Assert.False(requestAborted); }
public async Task HttpsConnectionClosedWhenResponseDoesNotSatisfyMinimumDataRate() { const int chunkSize = 1024; const int chunks = 256 * 1024; var chunkData = new byte[chunkSize]; var certificate = TestResources.GetTestCertificate(); var responseRateTimeoutMessageLogged = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var connectionStopMessageLogged = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var aborted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var appFuncCompleted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var mockKestrelTrace = new Mock <IKestrelTrace>(); mockKestrelTrace .Setup(trace => trace.ResponseMinimumDataRateNotSatisfied(It.IsAny <string>(), It.IsAny <string>())) .Callback(() => responseRateTimeoutMessageLogged.SetResult(null)); mockKestrelTrace .Setup(trace => trace.ConnectionStop(It.IsAny <string>())) .Callback(() => connectionStopMessageLogged.SetResult(null)); var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) { ServerOptions = { Limits = { MinResponseDataRate = new MinDataRate(bytesPerSecond: 1024 * 1024, gracePeriod: TimeSpan.FromSeconds(2)) } } }; testContext.InitializeHeartbeat(); void ConfigureListenOptions(ListenOptions listenOptions) { listenOptions.UseHttps(new HttpsConnectionAdapterOptions { ServerCertificate = certificate }); } using (var server = new TestServer(async context => { context.RequestAborted.Register(() => { aborted.SetResult(null); }); context.Response.ContentLength = chunks * chunkSize; try { for (var i = 0; i < chunks; i++) { await context.Response.BodyWriter.WriteAsync(new Memory <byte>(chunkData, 0, chunkData.Length), context.RequestAborted); } } catch (OperationCanceledException) { appFuncCompleted.SetResult(null); throw; } finally { await aborted.Task.DefaultTimeout(); } }, testContext, ConfigureListenOptions)) { using (var connection = server.CreateConnection()) { using (var sslStream = new SslStream(connection.Stream, false, (sender, cert, chain, errors) => true, null)) { await sslStream.AuthenticateAsClientAsync("localhost", new X509CertificateCollection(), SslProtocols.Tls12 | SslProtocols.Tls11, false); var request = Encoding.ASCII.GetBytes("GET / HTTP/1.1\r\nHost:\r\n\r\n"); await sslStream.WriteAsync(request, 0, request.Length); await aborted.Task.DefaultTimeout(); await responseRateTimeoutMessageLogged.Task.DefaultTimeout(); await connectionStopMessageLogged.Task.DefaultTimeout(); await appFuncCompleted.Task.DefaultTimeout(); await AssertStreamAborted(connection.Stream, chunkSize *chunks); } } await server.StopAsync(); } }
public async Task AppCanHandleClientAbortingConnectionMidResponse(ListenOptions listenOptions) { const int connectionResetEventId = 19; const int connectionFinEventId = 6; const int connectionStopEventId = 2; const int responseBodySegmentSize = 65536; const int responseBodySegmentCount = 100; var requestAborted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var appCompletedTcs = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var scratchBuffer = new byte[responseBodySegmentSize]; using (var server = new TestServer(async context => { context.RequestAborted.Register(() => requestAborted.SetResult(null)); for (var i = 0; i < responseBodySegmentCount; i++) { await context.Response.Body.WriteAsync(scratchBuffer, 0, scratchBuffer.Length); await Task.Delay(10); } await requestAborted.Task.DefaultTimeout(); appCompletedTcs.SetResult(null); }, new TestServiceContext(LoggerFactory), listenOptions)) { using (var connection = server.CreateConnection()) { await connection.Send( "GET / HTTP/1.1", "Host:", "", ""); // Read just part of the response and close the connection. // https://github.com/aspnet/KestrelHttpServer/issues/2554 await connection.Stream.ReadAsync(scratchBuffer, 0, scratchBuffer.Length); connection.Reset(); } await requestAborted.Task.DefaultTimeout(); // After the RequestAborted token is tripped, the connection reset should be logged. // On Linux and macOS, the connection close is still sometimes observed as a FIN despite the LingerState. var presShutdownTransportLogs = TestSink.Writes.Where( w => w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv" || w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets"); var connectionResetLogs = presShutdownTransportLogs.Where( w => w.EventId == connectionResetEventId || (!TestPlatformHelper.IsWindows && w.EventId == connectionFinEventId)); Assert.NotEmpty(connectionResetLogs); // On macOS, the default 5 shutdown timeout is insufficient for the write loop to complete, so give it extra time. await appCompletedTcs.Task.DefaultTimeout(); await server.StopAsync(); } var coreLogs = TestSink.Writes.Where(w => w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel"); Assert.Single(coreLogs.Where(w => w.EventId == connectionStopEventId)); var transportLogs = TestSink.Writes.Where(w => w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel" || w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv" || w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets"); Assert.Empty(transportLogs.Where(w => w.LogLevel > LogLevel.Debug)); }
public async Task ThrowsOnWriteWithRequestAbortedTokenAfterRequestIsAborted(ListenOptions listenOptions) { // This should match _maxBytesPreCompleted in SocketOutput var maxBytesPreCompleted = 65536; // Ensure string is long enough to disable write-behind buffering var largeString = new string('a', maxBytesPreCompleted + 1); var writeTcs = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var requestAbortedWh = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var requestStartWh = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); using (var server = new TestServer(async httpContext => { requestStartWh.SetResult(null); var response = httpContext.Response; var request = httpContext.Request; var lifetime = httpContext.Features.Get <IHttpRequestLifetimeFeature>(); lifetime.RequestAborted.Register(() => requestAbortedWh.SetResult(null)); await requestAbortedWh.Task.DefaultTimeout(); try { await response.WriteAsync(largeString, cancellationToken: lifetime.RequestAborted); } catch (Exception ex) { writeTcs.SetException(ex); throw; } finally { await requestAbortedWh.Task.DefaultTimeout(); } writeTcs.SetException(new Exception("This shouldn't be reached.")); }, new TestServiceContext(LoggerFactory), listenOptions)) { using (var connection = server.CreateConnection()) { await connection.Send( "POST / HTTP/1.1", "Host:", "Content-Length: 0", "", ""); await requestStartWh.Task.DefaultTimeout(); } // Write failed - can throw TaskCanceledException or OperationCanceledException, // depending on how far the canceled write goes. await Assert.ThrowsAnyAsync <OperationCanceledException>(async() => await writeTcs.Task).DefaultTimeout(); // RequestAborted tripped await requestAbortedWh.Task.DefaultTimeout(); await server.StopAsync(); } }
public async Task ConnectionNotClosedWhenClientSatisfiesMinimumDataRateGivenLargeResponseChunks() { var chunkSize = 64 * 128 * 1024; var chunkCount = 4; var chunkData = new byte[chunkSize]; var requestAborted = false; var appFuncCompleted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var mockKestrelTrace = new Mock <IKestrelTrace>(); var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) { ServerOptions = { Limits = { MinResponseDataRate = new MinDataRate(bytesPerSecond: 240, gracePeriod: TimeSpan.FromSeconds(2)) } } }; testContext.InitializeHeartbeat(); var listenOptions = new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0)); async Task App(HttpContext context) { context.RequestAborted.Register(() => { requestAborted = true; }); for (var i = 0; i < chunkCount; i++) { await context.Response.BodyPipe.WriteAsync(new Memory <byte>(chunkData, 0, chunkData.Length), context.RequestAborted); } appFuncCompleted.SetResult(null); } using (var server = new TestServer(App, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { // Close the connection with the last request so AssertStreamCompleted actually completes. await connection.Send( "GET / HTTP/1.1", "Host:", "Connection: close", "", ""); var minTotalOutputSize = chunkCount * chunkSize; // Make sure consuming a single chunk exceeds the 2 second timeout. var targetBytesPerSecond = chunkSize / 4; await AssertStreamCompleted(connection.Stream, minTotalOutputSize, targetBytesPerSecond); await appFuncCompleted.Task.DefaultTimeout(); } await server.StopAsync(); } mockKestrelTrace.Verify(t => t.ResponseMinimumDataRateNotSatisfied(It.IsAny <string>(), It.IsAny <string>()), Times.Never()); mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny <string>()), Times.Once()); Assert.False(requestAborted); }
public async Task WritingToConnectionAfterUnobservedCloseTriggersRequestAbortedToken(ListenOptions listenOptions) { const int connectionPausedEventId = 4; const int maxRequestBufferSize = 4096; var requestAborted = false; var readCallbackUnwired = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var clientClosedConnection = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var writeTcs = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var mockKestrelTrace = new Mock <IKestrelTrace>(); var mockLogger = new Mock <ILogger>(); mockLogger .Setup(logger => logger.IsEnabled(It.IsAny <LogLevel>())) .Returns(true); mockLogger .Setup(logger => logger.Log(It.IsAny <LogLevel>(), It.IsAny <EventId>(), It.IsAny <object>(), It.IsAny <Exception>(), It.IsAny <Func <object, Exception, string> >())) .Callback <LogLevel, EventId, object, Exception, Func <object, Exception, string> >((logLevel, eventId, state, exception, formatter) => { if (eventId.Id == connectionPausedEventId) { readCallbackUnwired.TrySetResult(null); } Logger.Log(logLevel, eventId, state, exception, formatter); }); var mockLoggerFactory = new Mock <ILoggerFactory>(); mockLoggerFactory .Setup(factory => factory.CreateLogger(It.IsAny <string>())) .Returns(Logger); mockLoggerFactory .Setup(factory => factory.CreateLogger(It.IsIn("Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv", "Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets"))) .Returns(mockLogger.Object); var testContext = new TestServiceContext(mockLoggerFactory.Object, mockKestrelTrace.Object) { ServerOptions = { Limits = { MaxRequestBufferSize = maxRequestBufferSize, MaxRequestLineSize = maxRequestBufferSize, MaxRequestHeadersTotalSize = maxRequestBufferSize, } } }; var scratchBuffer = new byte[maxRequestBufferSize * 8]; using (var server = new TestServer(async context => { context.RequestAborted.Register(() => { requestAborted = true; }); await clientClosedConnection.Task; try { for (var i = 0; i < 1000; i++) { await context.Response.Body.WriteAsync(scratchBuffer, 0, scratchBuffer.Length, context.RequestAborted); await Task.Delay(10); } } catch (Exception ex) { writeTcs.SetException(ex); throw; } writeTcs.SetException(new Exception("This shouldn't be reached.")); }, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { await connection.Send( "POST / HTTP/1.1", "Host:", $"Content-Length: {scratchBuffer.Length}", "", ""); var ignore = connection.Stream.WriteAsync(scratchBuffer, 0, scratchBuffer.Length); // Wait until the read callback is no longer hooked up so that the connection disconnect isn't observed. await readCallbackUnwired.Task.DefaultTimeout(); } clientClosedConnection.SetResult(null); await Assert.ThrowsAnyAsync <OperationCanceledException>(() => writeTcs.Task).DefaultTimeout(); } mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny <string>()), Times.Once()); Assert.True(requestAborted); }
public async Task RequestTimesOutWhenRequestBodyNotReceivedAtSpecifiedMinimumRate() { var gracePeriod = TimeSpan.FromSeconds(5); var systemClock = new MockSystemClock(); var serviceContext = new TestServiceContext(LoggerFactory) { SystemClock = systemClock, DateHeaderValueManager = new DateHeaderValueManager(systemClock) }; var appRunningEvent = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); using (var server = new TestServer(context => { context.Features.Get <IHttpMinRequestBodyDataRateFeature>().MinDataRate = new MinDataRate(bytesPerSecond: 1, gracePeriod: gracePeriod); // The server must call Request.Body.ReadAsync() *before* the test sets systemClock.UtcNow (which is triggered by the // server calling appRunningEvent.SetResult(null)). If systemClock.UtcNow is set first, it's possible for the test to fail // due to the following race condition: // // 1. [test] systemClock.UtcNow += gracePeriod + TimeSpan.FromSeconds(1); // 2. [server] Heartbeat._timer is triggered, which calls HttpConnection.Tick() // 3. [server] HttpConnection.Tick() calls HttpConnection.CheckForReadDataRateTimeout() // 4. [server] HttpConnection.CheckForReadDataRateTimeout() is a no-op, since _readTimingEnabled is false, // since Request.Body.ReadAsync() has not been called yet // 5. [server] HttpConnection.Tick() sets _lastTimestamp = timestamp // 6. [server] Request.Body.ReadAsync() is called // 6. [test] systemClock.UtcNow is never updated again, so server timestamp is never updated, // so HttpConnection.CheckForReadDataRateTimeout() is always a no-op until test fails // // This is a pretty tight race, since the once-per-second Heartbeat._timer needs to fire between the test updating // systemClock.UtcNow and the server calling Request.Body.ReadAsync(). But it happened often enough to cause // test flakiness in our CI (https://github.com/aspnet/KestrelHttpServer/issues/2539). // // For verification, I was able to induce the race by adding a sleep in the RequestDelegate: // appRunningEvent.SetResult(null); // Thread.Sleep(5000); // return context.Request.Body.ReadAsync(new byte[1], 0, 1); var readTask = context.Request.Body.ReadAsync(new byte[1], 0, 1); appRunningEvent.SetResult(null); return(readTask); }, serviceContext)) { using (var connection = server.CreateConnection()) { await connection.Send( "POST / HTTP/1.1", "Host:", "Content-Length: 1", "", ""); await appRunningEvent.Task.DefaultTimeout(); systemClock.UtcNow += gracePeriod + TimeSpan.FromSeconds(1); await connection.Receive( "HTTP/1.1 408 Request Timeout", ""); await connection.ReceiveForcedEnd( "Connection: close", $"Date: {serviceContext.DateHeaderValue}", "Content-Length: 0", "", ""); } } }
public async Task ConnectionClosedEvenIfAppSwallowsException() { var gracePeriod = TimeSpan.FromSeconds(5); var systemClock = new MockSystemClock(); var serviceContext = new TestServiceContext(LoggerFactory) { SystemClock = systemClock, DateHeaderValueManager = new DateHeaderValueManager(systemClock) }; var appRunningTcs = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var exceptionSwallowedTcs = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); using (var server = new TestServer(async context => { context.Features.Get <IHttpMinRequestBodyDataRateFeature>().MinDataRate = new MinDataRate(bytesPerSecond: 1, gracePeriod: gracePeriod); // See comment in RequestTimesOutWhenRequestBodyNotReceivedAtSpecifiedMinimumRate for // why we call ReadAsync before setting the appRunningEvent. var readTask = context.Request.Body.ReadAsync(new byte[1], 0, 1); appRunningTcs.SetResult(null); try { await readTask; } catch (BadHttpRequestException ex) when(ex.StatusCode == 408) { exceptionSwallowedTcs.SetResult(null); } catch (Exception ex) { exceptionSwallowedTcs.SetException(ex); } var response = "hello, world"; context.Response.ContentLength = response.Length; await context.Response.WriteAsync("hello, world"); }, serviceContext)) { using (var connection = server.CreateConnection()) { await connection.Send( "POST / HTTP/1.1", "Host:", "Content-Length: 1", "", ""); await appRunningTcs.Task.DefaultTimeout(); systemClock.UtcNow += gracePeriod + TimeSpan.FromSeconds(1); await exceptionSwallowedTcs.Task.DefaultTimeout(); await connection.Receive( "HTTP/1.1 200 OK", ""); await connection.ReceiveForcedEnd( $"Date: {serviceContext.DateHeaderValue}", "Content-Length: 12", "", "hello, world"); } } }
public async Task RequestsCanBeAbortedMidRead(ListenOptions listenOptions) { const int applicationAbortedConnectionId = 34; var testContext = new TestServiceContext(LoggerFactory); var readTcs = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var registrationTcs = new TaskCompletionSource <int>(TaskCreationOptions.RunContinuationsAsynchronously); var requestId = 0; using (var server = new TestServer(async httpContext => { requestId++; var response = httpContext.Response; var request = httpContext.Request; var lifetime = httpContext.Features.Get <IHttpRequestLifetimeFeature>(); lifetime.RequestAborted.Register(() => registrationTcs.TrySetResult(requestId)); if (requestId == 1) { response.Headers["Content-Length"] = new[] { "5" }; await response.WriteAsync("World"); } else { var readTask = request.Body.CopyToAsync(Stream.Null); lifetime.Abort(); try { await readTask; } catch (Exception ex) { readTcs.SetException(ex); throw; } finally { await registrationTcs.Task.DefaultTimeout(); } readTcs.SetException(new Exception("This shouldn't be reached.")); } }, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { // Full request and response await connection.Send( "POST / HTTP/1.1", "Host:", "Content-Length: 5", "", "Hello"); await connection.Receive( "HTTP/1.1 200 OK", $"Date: {testContext.DateHeaderValue}", "Content-Length: 5", "", "World"); // Never send the body so CopyToAsync always fails. await connection.Send("POST / HTTP/1.1", "Host:", "Content-Length: 5", "", ""); await connection.WaitForConnectionClose(); } } await Assert.ThrowsAsync <TaskCanceledException>(async() => await readTcs.Task); // The cancellation token for only the last request should be triggered. var abortedRequestId = await registrationTcs.Task.DefaultTimeout(); Assert.Equal(2, abortedRequestId); Assert.Single(TestSink.Writes.Where(w => w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel" && w.EventId == applicationAbortedConnectionId)); }
public async Task ConnectionNotClosedWhenClientSatisfiesMinimumDataRateGivenLargeResponseHeaders() { var headerSize = 1024 * 1024; // 1 MB for each header value var headerCount = 64; // 64 MB of headers per response var requestCount = 4; // Minimum of 256 MB of total response headers var headerValue = new string('a', headerSize); var headerStringValues = new StringValues(Enumerable.Repeat(headerValue, headerCount).ToArray()); var requestAborted = false; var mockKestrelTrace = new Mock <IKestrelTrace>(); var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) { ServerOptions = { Limits = { MinResponseDataRate = new MinDataRate(bytesPerSecond: 240, gracePeriod: TimeSpan.FromSeconds(2)) } } }; testContext.InitializeHeartbeat(); var listenOptions = new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0)); async Task App(HttpContext context) { context.RequestAborted.Register(() => { requestAborted = true; }); context.Response.Headers[$"X-Custom-Header"] = headerStringValues; context.Response.ContentLength = 0; await context.Response.BodyPipe.FlushAsync(); } using (var server = new TestServer(App, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { for (var i = 0; i < requestCount - 1; i++) { await connection.Send( "GET / HTTP/1.1", "Host:", "", ""); } // Close the connection with the last request so AssertStreamCompleted actually completes. await connection.Send( "GET / HTTP/1.1", "Host:", "Connection: close", "", ""); var responseSize = headerSize * headerCount; var minTotalOutputSize = requestCount * responseSize; // Make sure consuming a single set of response headers exceeds the 2 second timeout. var targetBytesPerSecond = responseSize / 4; await AssertStreamCompleted(connection.Stream, minTotalOutputSize, targetBytesPerSecond); } await server.StopAsync(); } mockKestrelTrace.Verify(t => t.ResponseMinimumDataRateNotSatisfied(It.IsAny <string>(), It.IsAny <string>()), Times.Never()); mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny <string>()), Times.Once()); Assert.False(requestAborted); }
public async Task ServerCanAbortConnectionAfterUnobservedClose(ListenOptions listenOptions) { const int connectionPausedEventId = 4; const int connectionFinSentEventId = 7; const int maxRequestBufferSize = 4096; var readCallbackUnwired = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var clientClosedConnection = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var serverClosedConnection = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var appFuncCompleted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); TestSink.MessageLogged += context => { if (context.LoggerName != "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv" && context.LoggerName != "Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets") { return; } if (context.EventId.Id == connectionPausedEventId) { readCallbackUnwired.TrySetResult(null); } else if (context.EventId == connectionFinSentEventId) { serverClosedConnection.SetResult(null); } }; var mockKestrelTrace = new Mock <IKestrelTrace>(); var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) { ServerOptions = { Limits = { MaxRequestBufferSize = maxRequestBufferSize, MaxRequestLineSize = maxRequestBufferSize, MaxRequestHeadersTotalSize = maxRequestBufferSize, } } }; var scratchBuffer = new byte[maxRequestBufferSize * 8]; using (var server = new TestServer(async context => { await clientClosedConnection.Task; context.Abort(); await serverClosedConnection.Task; appFuncCompleted.SetResult(null); }, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { await connection.Send( "POST / HTTP/1.1", "Host:", $"Content-Length: {scratchBuffer.Length}", "", ""); var ignore = connection.Stream.WriteAsync(scratchBuffer, 0, scratchBuffer.Length); // Wait until the read callback is no longer hooked up so that the connection disconnect isn't observed. await readCallbackUnwired.Task.DefaultTimeout(); } clientClosedConnection.SetResult(null); await appFuncCompleted.Task.DefaultTimeout(); } mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny <string>()), Times.Once()); }
public async Task PerRequestMaxRequestBodySizeGetsReset() { var chunkedPayload = "5;random chunk extension\r\nHello\r\n6\r\n World\r\n0\r\n\r\n"; var globalMaxRequestBodySize = chunkedPayload.Length - 1; var firstRequest = true; BadHttpRequestException requestRejectedEx = null; using (var server = new TestServer(async context => { var feature = context.Features.Get <IHttpMaxRequestBodySizeFeature>(); Assert.Equal(globalMaxRequestBodySize, feature.MaxRequestBodySize); var buffer = new byte[11]; var count = 0; if (firstRequest) { firstRequest = false; feature.MaxRequestBodySize = chunkedPayload.Length; do { count = await context.Request.Body.ReadAsync(buffer, 0, 11); } while (count != 0); } else { requestRejectedEx = await Assert.ThrowsAsync <BadHttpRequestException>(async() => { do { count = await context.Request.Body.ReadAsync(buffer, 0, 11); } while (count != 0); }); throw requestRejectedEx; } }, new TestServiceContext { ServerOptions = { Limits = { MaxRequestBodySize = globalMaxRequestBodySize } } })) { using (var connection = server.CreateConnection()) { await connection.Send( "POST / HTTP/1.1", "Host:", "Transfer-Encoding: chunked", "", chunkedPayload + "POST / HTTP/1.1", "Host:", "Transfer-Encoding: chunked", "", chunkedPayload); await connection.ReceiveForcedEnd( "HTTP/1.1 200 OK", $"Date: {server.Context.DateHeaderValue}", "Content-Length: 0", "", "HTTP/1.1 413 Payload Too Large", "Connection: close", $"Date: {server.Context.DateHeaderValue}", "Content-Length: 0", "", ""); } } Assert.NotNull(requestRejectedEx); Assert.Equal(CoreStrings.BadRequest_RequestBodyTooLarge, requestRejectedEx.Message); }
public async Task WritingToConnectionAfterUnobservedCloseTriggersRequestAbortedToken(ListenOptions listenOptions) { const int connectionPausedEventId = 4; const int maxRequestBufferSize = 4096; var requestAborted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var readCallbackUnwired = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var clientClosedConnection = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var writeTcs = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); TestSink.MessageLogged += context => { if (context.LoggerName != "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv" && context.LoggerName != "Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets") { return; } if (context.EventId.Id == connectionPausedEventId) { readCallbackUnwired.TrySetResult(null); } }; var mockKestrelTrace = new Mock <IKestrelTrace>(); var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) { ServerOptions = { Limits = { MaxRequestBufferSize = maxRequestBufferSize, MaxRequestLineSize = maxRequestBufferSize, MaxRequestHeadersTotalSize = maxRequestBufferSize, } } }; var scratchBuffer = new byte[maxRequestBufferSize * 8]; using (var server = new TestServer(async context => { context.RequestAborted.Register(() => requestAborted.SetResult(null)); await clientClosedConnection.Task; try { for (var i = 0; i < 1000; i++) { await context.Response.BodyWriter.WriteAsync(new Memory <byte>(scratchBuffer, 0, scratchBuffer.Length), context.RequestAborted); await Task.Delay(10); } } catch (Exception ex) { writeTcs.SetException(ex); throw; } finally { await requestAborted.Task.DefaultTimeout(); } writeTcs.SetException(new Exception("This shouldn't be reached.")); }, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { await connection.Send( "POST / HTTP/1.1", "Host:", $"Content-Length: {scratchBuffer.Length}", "", ""); var ignore = connection.Stream.WriteAsync(scratchBuffer, 0, scratchBuffer.Length); // Wait until the read callback is no longer hooked up so that the connection disconnect isn't observed. await readCallbackUnwired.Task.DefaultTimeout(); } clientClosedConnection.SetResult(null); await Assert.ThrowsAnyAsync <OperationCanceledException>(() => writeTcs.Task).DefaultTimeout(); await server.StopAsync(); } mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny <string>()), Times.Once()); Assert.True(requestAborted.Task.IsCompleted); }
public async Task ConnectionResetBetweenRequestsIsLoggedAsDebug() { var connectionReset = new SemaphoreSlim(0); var loggedHigherThanDebug = false; var mockLogger = new Mock <ILogger>(); mockLogger .Setup(logger => logger.IsEnabled(It.IsAny <LogLevel>())) .Returns(true); mockLogger .Setup(logger => logger.Log(It.IsAny <LogLevel>(), It.IsAny <EventId>(), It.IsAny <object>(), It.IsAny <Exception>(), It.IsAny <Func <object, Exception, string> >())) .Callback <LogLevel, EventId, object, Exception, Func <object, Exception, string> >((logLevel, eventId, state, exception, formatter) => { Logger.Log(logLevel, eventId, state, exception, formatter); if (eventId.Id == _connectionResetEventId) { connectionReset.Release(); } if (logLevel > LogLevel.Debug) { loggedHigherThanDebug = true; } }); var mockLoggerFactory = new Mock <ILoggerFactory>(); mockLoggerFactory .Setup(factory => factory.CreateLogger(It.IsAny <string>())) .Returns(Logger); mockLoggerFactory .Setup(factory => factory.CreateLogger(It.IsIn("Microsoft.AspNetCore.Server.Kestrel", "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv", "Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets"))) .Returns(mockLogger.Object); using (var server = new TestServer(context => Task.CompletedTask, new TestServiceContext(mockLoggerFactory.Object))) { using (var connection = server.CreateConnection()) { await connection.Send( "GET / HTTP/1.1", "Host:", "", ""); // Make sure the response is fully received, so a write failure (e.g. EPIPE) doesn't cause // a more critical log message. await connection.Receive( "HTTP/1.1 200 OK", $"Date: {server.Context.DateHeaderValue}", "Content-Length: 0", "", ""); connection.Reset(); // Force a reset } // If the reset is correctly logged as Debug, the wait below should complete shortly. // This check MUST come before disposing the server, otherwise there's a race where the RST // is still in flight when the connection is aborted, leading to the reset never being received // and therefore not logged. Assert.True(await connectionReset.WaitAsync(TestConstants.DefaultTimeout)); } Assert.False(loggedHigherThanDebug); }
public async Task ConnectionClosedWhenResponseDoesNotSatisfyMinimumDataRate() { var logger = LoggerFactory.CreateLogger($"{ typeof(ResponseTests).FullName}.{ nameof(ConnectionClosedWhenResponseDoesNotSatisfyMinimumDataRate)}"); const int chunkSize = 1024; const int chunks = 256 * 1024; var responseSize = chunks * chunkSize; var chunkData = new byte[chunkSize]; var responseRateTimeoutMessageLogged = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var connectionStopMessageLogged = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var requestAborted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var appFuncCompleted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var mockKestrelTrace = new Mock <IKestrelTrace>(); mockKestrelTrace .Setup(trace => trace.ResponseMinimumDataRateNotSatisfied(It.IsAny <string>(), It.IsAny <string>())) .Callback(() => responseRateTimeoutMessageLogged.SetResult(null)); mockKestrelTrace .Setup(trace => trace.ConnectionStop(It.IsAny <string>())) .Callback(() => connectionStopMessageLogged.SetResult(null)); var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) { ServerOptions = { Limits = { MinResponseDataRate = new MinDataRate(bytesPerSecond: 1024 * 1024, gracePeriod: TimeSpan.FromSeconds(2)) } } }; testContext.InitializeHeartbeat(); var appLogger = LoggerFactory.CreateLogger("App"); async Task App(HttpContext context) { appLogger.LogInformation("Request received"); context.RequestAborted.Register(() => requestAborted.SetResult(null)); context.Response.ContentLength = responseSize; var i = 0; try { for (; i < chunks; i++) { await context.Response.BodyWriter.WriteAsync(new Memory <byte>(chunkData, 0, chunkData.Length), context.RequestAborted); await Task.Yield(); } appFuncCompleted.SetException(new Exception("This shouldn't be reached.")); } catch (OperationCanceledException) { appFuncCompleted.SetResult(null); throw; } catch (Exception ex) { appFuncCompleted.SetException(ex); } finally { appLogger.LogInformation("Wrote {total} bytes", chunkSize * i); await requestAborted.Task.DefaultTimeout(); } } using (var server = new TestServer(App, testContext)) { using (var connection = server.CreateConnection()) { logger.LogInformation("Sending request"); await connection.Send( "GET / HTTP/1.1", "Host:", "", ""); logger.LogInformation("Sent request"); var sw = Stopwatch.StartNew(); logger.LogInformation("Waiting for connection to abort."); await requestAborted.Task.DefaultTimeout(); await responseRateTimeoutMessageLogged.Task.DefaultTimeout(); await connectionStopMessageLogged.Task.DefaultTimeout(); await appFuncCompleted.Task.DefaultTimeout(); await AssertStreamAborted(connection.Stream, chunkSize *chunks); sw.Stop(); logger.LogInformation("Connection was aborted after {totalMilliseconds}ms.", sw.ElapsedMilliseconds); } await server.StopAsync(); } }
public async Task ConnectionResetMidRequestIsLoggedAsDebug() { var requestStarted = new SemaphoreSlim(0); var connectionReset = new SemaphoreSlim(0); var connectionClosing = new SemaphoreSlim(0); var loggedHigherThanDebug = false; var mockLogger = new Mock <ILogger>(); mockLogger .Setup(logger => logger.IsEnabled(It.IsAny <LogLevel>())) .Returns(true); mockLogger .Setup(logger => logger.Log(It.IsAny <LogLevel>(), It.IsAny <EventId>(), It.IsAny <object>(), It.IsAny <Exception>(), It.IsAny <Func <object, Exception, string> >())) .Callback <LogLevel, EventId, object, Exception, Func <object, Exception, string> >((logLevel, eventId, state, exception, formatter) => { Logger.Log(logLevel, eventId, state, exception, formatter); if (eventId.Id == _connectionResetEventId) { connectionReset.Release(); } if (logLevel > LogLevel.Debug) { loggedHigherThanDebug = true; } }); var mockLoggerFactory = new Mock <ILoggerFactory>(); mockLoggerFactory .Setup(factory => factory.CreateLogger(It.IsAny <string>())) .Returns(Logger); mockLoggerFactory .Setup(factory => factory.CreateLogger(It.IsIn("Microsoft.AspNetCore.Server.Kestrel", "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv", "Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets"))) .Returns(mockLogger.Object); using (var server = new TestServer(async context => { requestStarted.Release(); await connectionClosing.WaitAsync(); }, new TestServiceContext(mockLoggerFactory.Object))) { using (var connection = server.CreateConnection()) { await connection.SendEmptyGet(); // Wait until connection is established Assert.True(await requestStarted.WaitAsync(TestConstants.DefaultTimeout), "request should have started"); connection.Reset(); } // If the reset is correctly logged as Debug, the wait below should complete shortly. // This check MUST come before disposing the server, otherwise there's a race where the RST // is still in flight when the connection is aborted, leading to the reset never being received // and therefore not logged. Assert.True(await connectionReset.WaitAsync(TestConstants.DefaultTimeout), "Connection reset event should have been logged"); connectionClosing.Release(); } Assert.False(loggedHigherThanDebug, "Logged event should not have been higher than debug."); }
public async Task ConnectionClosedWhenBothRequestAndResponseExperienceBackPressure() { const int bufferSize = 65536; const int bufferCount = 100; var responseSize = bufferCount * bufferSize; var buffer = new byte[bufferSize]; var responseRateTimeoutMessageLogged = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var connectionStopMessageLogged = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var requestAborted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var copyToAsyncCts = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var mockKestrelTrace = new Mock <IKestrelTrace>(); mockKestrelTrace .Setup(trace => trace.ResponseMinimumDataRateNotSatisfied(It.IsAny <string>(), It.IsAny <string>())) .Callback(() => responseRateTimeoutMessageLogged.SetResult(null)); mockKestrelTrace .Setup(trace => trace.ConnectionStop(It.IsAny <string>())) .Callback(() => connectionStopMessageLogged.SetResult(null)); var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) { ServerOptions = { Limits = { MinResponseDataRate = new MinDataRate(bytesPerSecond: 1024 * 1024, gracePeriod: TimeSpan.FromSeconds(2)), MaxRequestBodySize = responseSize } } }; testContext.InitializeHeartbeat(); var listenOptions = new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0)); async Task App(HttpContext context) { context.RequestAborted.Register(() => { requestAborted.SetResult(null); }); try { await context.Request.Body.CopyToAsync(context.Response.Body); } catch (Exception ex) { copyToAsyncCts.SetException(ex); throw; } finally { await requestAborted.Task.DefaultTimeout(); } copyToAsyncCts.SetException(new Exception("This shouldn't be reached.")); } using (var server = new TestServer(App, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { // Close the connection with the last request so AssertStreamCompleted actually completes. await connection.Send( "POST / HTTP/1.1", "Host:", $"Content-Length: {responseSize}", "", ""); var sendTask = Task.Run(async() => { for (var i = 0; i < bufferCount; i++) { await connection.Stream.WriteAsync(buffer, 0, buffer.Length); await Task.Delay(10); } }); await requestAborted.Task.DefaultTimeout(); await responseRateTimeoutMessageLogged.Task.DefaultTimeout(); await connectionStopMessageLogged.Task.DefaultTimeout(); // Expect OperationCanceledException instead of IOException because the server initiated the abort due to a response rate timeout. await Assert.ThrowsAnyAsync <OperationCanceledException>(() => copyToAsyncCts.Task).DefaultTimeout(); await AssertStreamAborted(connection.Stream, responseSize); } await server.StopAsync(); } }
public async Task ServerCanAbortConnectionAfterUnobservedClose(ListenOptions listenOptions) { const int connectionPausedEventId = 4; const int connectionFinSentEventId = 7; const int maxRequestBufferSize = 4096; var readCallbackUnwired = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var clientClosedConnection = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var serverClosedConnection = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var appFuncCompleted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var mockLogger = new Mock <ILogger>(); mockLogger .Setup(logger => logger.IsEnabled(It.IsAny <LogLevel>())) .Returns(true); mockLogger .Setup(logger => logger.Log(It.IsAny <LogLevel>(), It.IsAny <EventId>(), It.IsAny <object>(), It.IsAny <Exception>(), It.IsAny <Func <object, Exception, string> >())) .Callback <LogLevel, EventId, object, Exception, Func <object, Exception, string> >((logLevel, eventId, state, exception, formatter) => { if (eventId.Id == connectionPausedEventId) { readCallbackUnwired.TrySetResult(null); } else if (eventId.Id == connectionFinSentEventId) { serverClosedConnection.SetResult(null); } Logger.Log(logLevel, eventId, state, exception, formatter); }); var mockLoggerFactory = new Mock <ILoggerFactory>(); mockLoggerFactory .Setup(factory => factory.CreateLogger(It.IsAny <string>())) .Returns(Logger); mockLoggerFactory .Setup(factory => factory.CreateLogger(It.IsIn("Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv", "Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets"))) .Returns(mockLogger.Object); var mockKestrelTrace = new Mock <IKestrelTrace>(); var testContext = new TestServiceContext(mockLoggerFactory.Object, mockKestrelTrace.Object) { ServerOptions = { Limits = { MaxRequestBufferSize = maxRequestBufferSize, MaxRequestLineSize = maxRequestBufferSize, MaxRequestHeadersTotalSize = maxRequestBufferSize, } } }; var scratchBuffer = new byte[maxRequestBufferSize * 8]; using (var server = new TestServer(async context => { await clientClosedConnection.Task; context.Abort(); await serverClosedConnection.Task; appFuncCompleted.SetResult(null); }, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { await connection.Send( "POST / HTTP/1.1", "Host:", $"Content-Length: {scratchBuffer.Length}", "", ""); var ignore = connection.Stream.WriteAsync(scratchBuffer, 0, scratchBuffer.Length); // Wait until the read callback is no longer hooked up so that the connection disconnect isn't observed. await readCallbackUnwired.Task.DefaultTimeout(); } clientClosedConnection.SetResult(null); await appFuncCompleted.Task.DefaultTimeout(); } mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny <string>()), Times.Once()); }
public async Task ClientCanReceiveFullConnectionCloseResponseWithoutErrorAtALowDataRate() { var chunkSize = 64 * 128 * 1024; var chunkCount = 4; var chunkData = new byte[chunkSize]; var requestAborted = false; var appFuncCompleted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var mockKestrelTrace = new Mock <IKestrelTrace>(); var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) { ServerOptions = { Limits = { MinResponseDataRate = new MinDataRate(bytesPerSecond: 240, gracePeriod: TimeSpan.FromSeconds(2)) } } }; testContext.InitializeHeartbeat(); var dateHeaderValueManager = new DateHeaderValueManager(); dateHeaderValueManager.OnHeartbeat(DateTimeOffset.MinValue); testContext.DateHeaderValueManager = dateHeaderValueManager; var listenOptions = new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0)); async Task App(HttpContext context) { context.RequestAborted.Register(() => { requestAborted = true; }); for (var i = 0; i < chunkCount; i++) { await context.Response.BodyWriter.WriteAsync(new Memory <byte>(chunkData, 0, chunkData.Length), context.RequestAborted); } appFuncCompleted.SetResult(null); } using (var server = new TestServer(App, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { // Close the connection with the last request so AssertStreamCompleted actually completes. await connection.Send( "GET / HTTP/1.1", "Host:", "Connection: close", "", ""); await connection.Receive( "HTTP/1.1 200 OK", "Connection: close", $"Date: {dateHeaderValueManager.GetDateHeaderValues().String}"); // Make sure consuming a single chunk exceeds the 2 second timeout. var targetBytesPerSecond = chunkSize / 4; // expectedBytes was determined by manual testing. A constant Date header is used, so this shouldn't change unless // the response header writing logic or response body chunking logic itself changes. await AssertStreamCompletedAtTargetRate(connection.Stream, expectedBytes : 33_553_556, targetBytesPerSecond); await appFuncCompleted.Task.DefaultTimeout(); } await server.StopAsync(); } mockKestrelTrace.Verify(t => t.ResponseMinimumDataRateNotSatisfied(It.IsAny <string>(), It.IsAny <string>()), Times.Never()); mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny <string>()), Times.Once()); Assert.False(requestAborted); }
public async Task ConnectionClosedWhenResponseDoesNotSatisfyMinimumDataRate() { using (StartLog(out var loggerFactory, "ConnClosedWhenRespDoesNotSatisfyMin")) { var logger = loggerFactory.CreateLogger($"{ typeof(ResponseTests).FullName}.{ nameof(ConnectionClosedWhenResponseDoesNotSatisfyMinimumDataRate)}"); const int chunkSize = 1024; const int chunks = 256 * 1024; var responseSize = chunks * chunkSize; var chunkData = new byte[chunkSize]; var responseRateTimeoutMessageLogged = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var connectionStopMessageLogged = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var requestAborted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var appFuncCompleted = new TaskCompletionSource <object>(TaskCreationOptions.RunContinuationsAsynchronously); var mockKestrelTrace = new Mock <KestrelTrace>(Logger) { CallBase = true }; mockKestrelTrace .Setup(trace => trace.ResponseMininumDataRateNotSatisfied(It.IsAny <string>(), It.IsAny <string>())) .Callback(() => responseRateTimeoutMessageLogged.SetResult(null)); mockKestrelTrace .Setup(trace => trace.ConnectionStop(It.IsAny <string>())) .Callback(() => connectionStopMessageLogged.SetResult(null)); var testContext = new TestServiceContext { LoggerFactory = loggerFactory, Log = mockKestrelTrace.Object, ServerOptions = { Limits = { MinResponseDataRate = new MinDataRate(bytesPerSecond: 1024 * 1024, gracePeriod: TimeSpan.FromSeconds(2)) } } }; testContext.InitializeHeartbeat(); var listenOptions = new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0)); listenOptions.ConnectionAdapters.Add(new LoggingConnectionAdapter(loggerFactory.CreateLogger <LoggingConnectionAdapter>())); var appLogger = loggerFactory.CreateLogger("App"); async Task App(HttpContext context) { appLogger.LogInformation("Request received"); context.RequestAborted.Register(() => requestAborted.SetResult(null)); context.Response.ContentLength = responseSize; try { for (var i = 0; i < chunks; i++) { await context.Response.Body.WriteAsync(chunkData, 0, chunkData.Length, context.RequestAborted); appLogger.LogInformation("Wrote chunk of {chunkSize} bytes", chunkSize); } } catch (OperationCanceledException) { appFuncCompleted.SetResult(null); throw; } } using (var server = new TestServer(App, testContext, listenOptions)) { using (var connection = server.CreateConnection()) { logger.LogInformation("Sending request"); await connection.Send( "GET / HTTP/1.1", "Host:", "", ""); logger.LogInformation("Sent request"); var sw = Stopwatch.StartNew(); logger.LogInformation("Waiting for connection to abort."); await requestAborted.Task.DefaultTimeout(); await responseRateTimeoutMessageLogged.Task.DefaultTimeout(); await connectionStopMessageLogged.Task.DefaultTimeout(); await appFuncCompleted.Task.DefaultTimeout(); await AssertStreamAborted(connection.Reader.BaseStream, chunkSize *chunks); sw.Stop(); logger.LogInformation("Connection was aborted after {totalMilliseconds}ms.", sw.ElapsedMilliseconds); } } } }