diff --git a/src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs b/src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs index 13ad97fa11..bef321b8bf 100644 --- a/src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs +++ b/src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs @@ -109,7 +109,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal _connectionKeepAlive(_logger, connectionId, null); } - public void ConnectionRejected(string connectionId) + public virtual void ConnectionRejected(string connectionId) { _connectionRejected(_logger, connectionId, null); } @@ -129,12 +129,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal _connectionHeadResponseBodyWrite(_logger, connectionId, count, null); } - public void NotAllConnectionsClosedGracefully() + public virtual void NotAllConnectionsClosedGracefully() { _notAllConnectionsClosedGracefully(_logger, null); } - public void ConnectionBadRequest(string connectionId, BadHttpRequestException ex) + public virtual void ConnectionBadRequest(string connectionId, BadHttpRequestException ex) { _connectionBadRequest(_logger, connectionId, ex.Message, ex); } @@ -144,7 +144,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal _requestProcessingError(_logger, connectionId, ex); } - public void NotAllConnectionsAborted() + public virtual void NotAllConnectionsAborted() { _notAllConnectionsAborted(_logger, null); } @@ -169,27 +169,27 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal _requestBodyDone(_logger, connectionId, traceIdentifier, null); } - public void RequestBodyMininumDataRateNotSatisfied(string connectionId, string traceIdentifier, double rate) + public virtual void RequestBodyMininumDataRateNotSatisfied(string connectionId, string traceIdentifier, double rate) { _requestBodyMinimumDataRateNotSatisfied(_logger, connectionId, traceIdentifier, rate, null); } - public void ResponseMininumDataRateNotSatisfied(string connectionId, string traceIdentifier) + public virtual void ResponseMininumDataRateNotSatisfied(string connectionId, string traceIdentifier) { _responseMinimumDataRateNotSatisfied(_logger, connectionId, traceIdentifier, null); } - public void Http2ConnectionError(string connectionId, Http2ConnectionErrorException ex) + public virtual void Http2ConnectionError(string connectionId, Http2ConnectionErrorException ex) { _http2ConnectionError(_logger, connectionId, ex); } - public void Http2StreamError(string connectionId, Http2StreamErrorException ex) + public virtual void Http2StreamError(string connectionId, Http2StreamErrorException ex) { _http2StreamError(_logger, connectionId, ex); } - public void HPackDecodingError(string connectionId, int streamId, HPackDecodingException ex) + public virtual void HPackDecodingError(string connectionId, int streamId, HPackDecodingException ex) { _hpackDecodingError(_logger, connectionId, streamId, ex); } diff --git a/test/Kestrel.Core.Tests/HttpConnectionTests.cs b/test/Kestrel.Core.Tests/HttpConnectionTests.cs index 4eebb7a7ae..a5c53eafde 100644 --- a/test/Kestrel.Core.Tests/HttpConnectionTests.cs +++ b/test/Kestrel.Core.Tests/HttpConnectionTests.cs @@ -1,4 +1,4 @@ -// Copyright (c) .NET Foundation. All rights reserved. +// Copyright (c) .NET Foundation. All rights reserved. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; diff --git a/test/Kestrel.FunctionalTests/ResponseTests.cs b/test/Kestrel.FunctionalTests/ResponseTests.cs index 7879e4d727..8fc7a16052 100644 --- a/test/Kestrel.FunctionalTests/ResponseTests.cs +++ b/test/Kestrel.FunctionalTests/ResponseTests.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; +using System.Diagnostics; using System.IO; using System.Linq; using System.Net; @@ -19,23 +20,24 @@ using Microsoft.AspNetCore.Hosting; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Http.Features; using Microsoft.AspNetCore.Server.Kestrel.Core; +using Microsoft.AspNetCore.Server.Kestrel.Core.Adapter.Internal; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Server.Kestrel.Https; using Microsoft.AspNetCore.Server.Kestrel.Https.Internal; using Microsoft.AspNetCore.Testing; -using Microsoft.AspNetCore.Testing.xunit; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Testing; using Microsoft.Extensions.Primitives; using Moq; using Xunit; -using Xunit.Sdk; +using Xunit.Abstractions; namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests { - public class ResponseTests + public class ResponseTests : LoggedTest { public static TheoryData ConnectionAdapterData => new TheoryData { @@ -46,6 +48,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } }; + public ResponseTests(ITestOutputHelper outputHelper) : base(outputHelper) { } + [Fact] public async Task LargeDownload() { @@ -2447,73 +2451,94 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests [Fact] public void ConnectionClosedWhenResponseDoesNotSatisfyMinimumDataRate() { - var chunkSize = 64 * 1024; - var chunks = 128; - var responseSize = chunks * chunkSize; - - var requestAborted = new ManualResetEventSlim(); - var messageLogged = new ManualResetEventSlim(); - var mockKestrelTrace = new Mock(); - mockKestrelTrace - .Setup(trace => trace.ResponseMininumDataRateNotSatisfied(It.IsAny(), It.IsAny())) - .Callback(() => messageLogged.Set()); - - var testContext = new TestServiceContext + using (StartLog(out var loggerFactory)) { - Log = mockKestrelTrace.Object, - SystemClock = new SystemClock(), - ServerOptions = + var logger = loggerFactory.CreateLogger($"{typeof(ResponseTests).FullName}.{nameof(ConnectionClosedWhenResponseDoesNotSatisfyMinimumDataRate)}"); + + var chunkSize = 64 * 1024; + var chunks = 128; + var responseSize = chunks * chunkSize; + + var requestAborted = new ManualResetEventSlim(); + var messageLogged = new ManualResetEventSlim(); + var mockKestrelTrace = new Mock(loggerFactory.CreateLogger("Microsoft.AspNetCore.Server.Kestrel")) { CallBase = true }; + mockKestrelTrace + .Setup(trace => trace.ResponseMininumDataRateNotSatisfied(It.IsAny(), It.IsAny())) + .Callback(() => messageLogged.Set()); + + var testContext = new TestServiceContext { - Limits = + LoggerFactory = loggerFactory, + Log = mockKestrelTrace.Object, + SystemClock = new SystemClock(), + ServerOptions = { - MinResponseDataRate = new MinDataRate(bytesPerSecond: double.MaxValue, gracePeriod: TimeSpan.FromSeconds(2)) - } - } - }; - - using (var server = new TestServer(async context => - { - context.RequestAborted.Register(() => requestAborted.Set()); - - context.Response.ContentLength = responseSize; - - for (var i = 0; i < chunks; i++) - { - await context.Response.WriteAsync(new string('a', chunkSize), context.RequestAborted); - } - }, testContext)) - { - using (var socket = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp)) - { - socket.ReceiveBufferSize = 1; - - socket.Connect(new IPEndPoint(IPAddress.Loopback, server.Port)); - socket.Send(Encoding.ASCII.GetBytes("GET / HTTP/1.1\r\nHost: \r\n\r\n")); - - Assert.True(messageLogged.Wait(TimeSpan.FromSeconds(60)), "The expected message was not logged within the timeout period."); - Assert.True(requestAborted.Wait(TimeSpan.FromSeconds(60)), "The request was not aborted within the timeout period."); - - var totalReceived = 0; - var received = 0; - - try - { - var buffer = new byte[chunkSize]; - - do + Limits = { - received = socket.Receive(buffer); - totalReceived += received; - } while (received > 0 && totalReceived < responseSize); - } - catch (SocketException) { } - catch (IOException) - { - // Socket.Receive could throw, and that is fine + MinResponseDataRate = new MinDataRate(bytesPerSecond: double.MaxValue, gracePeriod: TimeSpan.FromSeconds(2)) + } } + }; - // Since we expect writes to be cut off by the rate control, we should never see the entire response - Assert.NotEqual(responseSize, totalReceived); + var listenOptions = new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0)); + listenOptions.ConnectionAdapters.Add(new LoggingConnectionAdapter(loggerFactory.CreateLogger())); + + var appLogger = loggerFactory.CreateLogger("App"); + async Task App(HttpContext context) + { + appLogger.LogInformation("Request received"); + context.RequestAborted.Register(() => requestAborted.Set()); + + context.Response.ContentLength = responseSize; + + for (var i = 0; i < chunks; i++) + { + await context.Response.WriteAsync(new string('a', chunkSize), context.RequestAborted); + appLogger.LogInformation("Wrote chunk of {chunkSize} bytes", chunkSize); + } + } + + using (var server = new TestServer(App, testContext, listenOptions)) + { + using (var socket = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp)) + { + socket.ReceiveBufferSize = 1; + + socket.Connect(new IPEndPoint(IPAddress.Loopback, server.Port)); + logger.LogInformation("Sending request"); + socket.Send(Encoding.ASCII.GetBytes("GET / HTTP/1.1\r\nHost: \r\n\r\n")); + logger.LogInformation("Sent request"); + + var sw = Stopwatch.StartNew(); + logger.LogInformation("Waiting for connection to abort."); + Assert.True(messageLogged.Wait(TimeSpan.FromSeconds(120)), "The expected message was not logged within the timeout period."); + Assert.True(requestAborted.Wait(TimeSpan.FromSeconds(120)), "The request was not aborted within the timeout period."); + sw.Stop(); + logger.LogInformation("Connection was aborted after {totalMilliseconds}ms.", sw.ElapsedMilliseconds); + + var totalReceived = 0; + var received = 0; + + try + { + var buffer = new byte[chunkSize]; + + do + { + received = socket.Receive(buffer); + totalReceived += received; + } while (received > 0 && totalReceived < responseSize); + } + catch (SocketException) { } + catch (IOException) + { + // Socket.Receive could throw, and that is fine + } + + // Since we expect writes to be cut off by the rate control, we should never see the entire response + logger.LogInformation("Received {totalReceived} bytes", totalReceived); + Assert.NotEqual(responseSize, totalReceived); + } } } } diff --git a/test/Kestrel.FunctionalTests/TestHelpers/TestServer.cs b/test/Kestrel.FunctionalTests/TestHelpers/TestServer.cs index f0972bb4fd..0aff951af4 100644 --- a/test/Kestrel.FunctionalTests/TestHelpers/TestServer.cs +++ b/test/Kestrel.FunctionalTests/TestHelpers/TestServer.cs @@ -49,30 +49,30 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests Context = context; _host = TransportSelector.GetWebHostBuilder() - .UseKestrel(o => - { - o.ListenOptions.Add(_listenOptions); - }) - .ConfigureServices(services => - { - services.AddSingleton(this); - services.AddSingleton(context.LoggerFactory); - services.AddSingleton(sp => - { - // Manually configure options on the TestServiceContext. - // We're doing this so we can use the same instance that was passed in - var configureOptions = sp.GetServices>(); - foreach (var c in configureOptions) - { - c.Configure(context.ServerOptions); - } - return new KestrelServer(sp.GetRequiredService(), context); - }); + .UseKestrel(o => + { + o.ListenOptions.Add(_listenOptions); + }) + .ConfigureServices(services => + { + services.AddSingleton(this); + services.AddSingleton(context.LoggerFactory); + services.AddSingleton(sp => + { + // Manually configure options on the TestServiceContext. + // We're doing this so we can use the same instance that was passed in + var configureOptions = sp.GetServices>(); + foreach (var c in configureOptions) + { + c.Configure(context.ServerOptions); + } + return new KestrelServer(sp.GetRequiredService(), context); + }); - configureServices(services); - }) - .UseSetting(WebHostDefaults.ApplicationKey, typeof(TestServer).GetTypeInfo().Assembly.FullName) - .Build(); + configureServices(services); + }) + .UseSetting(WebHostDefaults.ApplicationKey, typeof(TestServer).GetTypeInfo().Assembly.FullName) + .Build(); _host.Start(); }