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);
}
}
}
}
