From 6c0af445e536b3752ea4e34462aebf82f85efa6d Mon Sep 17 00:00:00 2001 From: Stephen Halter Date: Wed, 24 May 2017 15:45:54 -0700 Subject: [PATCH] Fix flaky test and improve TestServer (#1859) --- .../FrameConnectionManagerTests.cs | 47 ++--- .../RequestTests.cs | 184 +++++++++--------- .../ResponseTests.cs | 4 +- .../TestServer.cs | 20 +- test/shared/KestrelTestLoggerFactory.cs | 5 + test/shared/TestApplicationErrorLogger.cs | 6 - test/shared/TestConnection.cs | 33 +++- test/shared/TestServiceContext.cs | 16 +- 8 files changed, 152 insertions(+), 163 deletions(-) diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/FrameConnectionManagerTests.cs b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/FrameConnectionManagerTests.cs index 15093ec9c0..ab292378b0 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/FrameConnectionManagerTests.cs +++ b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/FrameConnectionManagerTests.cs @@ -5,11 +5,9 @@ using System; using System.Diagnostics; using System.Threading; using System.Threading.Tasks; -using Microsoft.AspNetCore.Builder; -using Microsoft.AspNetCore.Hosting; +using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Testing; using Microsoft.AspNetCore.Testing.xunit; -using Microsoft.Extensions.Logging; using Moq; using Xunit; @@ -17,7 +15,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests { public class FrameConnectionManagerTests { - private const int _applicationNeverCompletedId = 23; [ConditionalFact] [NoDebuggerCondition] @@ -31,45 +28,23 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests var logWh = new SemaphoreSlim(0); var appStartedWh = new SemaphoreSlim(0); - var mockLogger = new Mock(); - mockLogger - .Setup(logger => logger.IsEnabled(It.IsAny())) - .Returns(true); - mockLogger - .Setup(logger => logger.Log(LogLevel.Critical, _applicationNeverCompletedId, It.IsAny(), null, - It.IsAny>())) + var mockTrace = new Mock(); + mockTrace + .Setup(trace => trace.ApplicationNeverCompleted(It.IsAny())) .Callback(() => { logWh.Release(); }); - var mockLoggerFactory = new Mock(); - mockLoggerFactory - .Setup(factory => factory.CreateLogger("Microsoft.AspNetCore.Server.Kestrel")) - .Returns(mockLogger.Object); - mockLoggerFactory - .Setup(factory => factory.CreateLogger(It.IsNotIn("Microsoft.AspNetCore.Server.Kestrel"))) - .Returns(Mock.Of()); - - var builder = new WebHostBuilder() - .UseLoggerFactory(mockLoggerFactory.Object) - .UseKestrel() - .UseUrls("http://127.0.0.1:0") - .Configure(app => + using (var server = new TestServer(context => { - app.Run(context => - { - appStartedWh.Release(); - var tcs = new TaskCompletionSource(); - return tcs.Task; - }); - }); - - using (var host = builder.Build()) + appStartedWh.Release(); + var tcs = new TaskCompletionSource(); + return tcs.Task; + }, + new TestServiceContext(new KestrelTestLoggerFactory(), mockTrace.Object))) { - host.Start(); - - using (var connection = new TestConnection(host.GetPort())) + using (var connection = server.CreateConnection()) { await connection.Send("GET / HTTP/1.1", "Host:", diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs index 0fb5db7212..b8f65c99b9 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs +++ b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs @@ -19,7 +19,6 @@ using Microsoft.AspNetCore.Http.Features; using Microsoft.AspNetCore.Server.Kestrel.Core; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Transport.Abstractions; -using Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal.Networking; using Microsoft.AspNetCore.Testing; using Microsoft.AspNetCore.Testing.xunit; using Microsoft.Extensions.Internal; @@ -34,7 +33,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests public class RequestTests { private const int _connectionStartedEventId = 1; - private const int _connectionKeepAliveEventId = 9; private const int _connectionResetEventId = 19; private const int _semaphoreWaitTimeout = 2500; @@ -257,54 +255,48 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests { var connectionStarted = new SemaphoreSlim(0); var connectionReset = new SemaphoreSlim(0); + var loggedHigherThanDebug = false; var mockLogger = new Mock(); mockLogger .Setup(logger => logger.IsEnabled(It.IsAny())) .Returns(true); mockLogger - .Setup(logger => logger.Log(LogLevel.Debug, _connectionStartedEventId, It.IsAny(), null, It.IsAny>())) - .Callback(() => + .Setup(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny>())) + .Callback>((logLevel, eventId, state, exception, formatter) => { - connectionStarted.Release(); - }); - mockLogger - .Setup(logger => logger.Log(LogLevel.Debug, _connectionResetEventId, It.IsAny(), null, It.IsAny>())) - .Callback(() => - { - connectionReset.Release(); + if (eventId.Id == _connectionStartedEventId) + { + connectionStarted.Release(); + } + else if (eventId.Id == _connectionResetEventId) + { + connectionReset.Release(); + } + + if (logLevel > LogLevel.Debug) + { + loggedHigherThanDebug = true; + } }); var mockLoggerFactory = new Mock(); mockLoggerFactory - .Setup(factory => factory.CreateLogger("Microsoft.AspNetCore.Server.Kestrel")) - .Returns(mockLogger.Object); - mockLoggerFactory - .Setup(factory => factory.CreateLogger("Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv")) - .Returns(mockLogger.Object); - mockLoggerFactory - .Setup(factory => factory.CreateLogger(It.IsNotIn("Microsoft.AspNetCore.Server.Kestrel", "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv"))) + .Setup(factory => factory.CreateLogger(It.IsAny())) .Returns(Mock.Of()); + mockLoggerFactory + .Setup(factory => factory.CreateLogger(It.IsIn("Microsoft.AspNetCore.Server.Kestrel", "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv"))) + .Returns(mockLogger.Object); - var builder = new WebHostBuilder() - .UseLoggerFactory(mockLoggerFactory.Object) - .UseKestrel() - .UseUrls("http://127.0.0.1:0") - .Configure(app => app.Run(context => TaskCache.CompletedTask)); - - using (var host = builder.Build()) + using (var server = new TestServer(context => TaskCache.CompletedTask, new TestServiceContext(mockLoggerFactory.Object))) { - host.Start(); - - using (var socket = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp)) + using (var connection = server.CreateConnection()) { - socket.Connect(new IPEndPoint(IPAddress.Loopback, host.GetPort())); - // Wait until connection is established Assert.True(await connectionStarted.WaitAsync(TimeSpan.FromSeconds(10))); // Force a reset - socket.LingerState = new LingerOption(true, 0); + connection.Socket.LingerState = new LingerOption(true, 0); } // If the reset is correctly logged as Debug, the wait below should complete shortly. @@ -313,63 +305,64 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests // and therefore not logged. Assert.True(await connectionReset.WaitAsync(TimeSpan.FromSeconds(10))); } + + Assert.False(loggedHigherThanDebug); } - [Fact(Skip= "https://github.com/aspnet/KestrelHttpServer/issues/1835")] + [Fact] public async Task ConnectionResetBetweenRequestsIsLoggedAsDebug() { - var requestDone = new SemaphoreSlim(0); var connectionReset = new SemaphoreSlim(0); + var loggedHigherThanDebug = false; var mockLogger = new Mock(); mockLogger .Setup(logger => logger.IsEnabled(It.IsAny())) .Returns(true); mockLogger - .Setup(logger => logger.Log(LogLevel.Debug, _connectionKeepAliveEventId, It.IsAny(), null, It.IsAny>())) - .Callback(() => + .Setup(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny>())) + .Callback>((logLevel, eventId, state, exception, formatter) => { - requestDone.Release(); - }); - mockLogger - .Setup(logger => logger.Log(LogLevel.Debug, _connectionResetEventId, It.IsAny(), null, It.IsAny>())) - .Callback(() => - { - connectionReset.Release(); + if (eventId.Id == _connectionResetEventId) + { + connectionReset.Release(); + } + + if (logLevel > LogLevel.Debug) + { + loggedHigherThanDebug = true; + } }); var mockLoggerFactory = new Mock(); mockLoggerFactory - .Setup(factory => factory.CreateLogger("Microsoft.AspNetCore.Server.Kestrel")) - .Returns(mockLogger.Object); - mockLoggerFactory - .Setup(factory => factory.CreateLogger("Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv")) - .Returns(mockLogger.Object); - mockLoggerFactory - .Setup(factory => factory.CreateLogger(It.IsNotIn("Microsoft.AspNetCore.Server.Kestrel", "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv"))) + .Setup(factory => factory.CreateLogger(It.IsAny())) .Returns(Mock.Of()); + mockLoggerFactory + .Setup(factory => factory.CreateLogger(It.IsIn("Microsoft.AspNetCore.Server.Kestrel", "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv"))) + .Returns(mockLogger.Object); - - var builder = new WebHostBuilder() - .UseLoggerFactory(mockLoggerFactory.Object) - .UseKestrel() - .UseUrls("http://127.0.0.1:0") - .Configure(app => app.Run(context => TaskCache.CompletedTask)); - - using (var host = builder.Build()) + using (var server = new TestServer(context => TaskCache.CompletedTask, new TestServiceContext(mockLoggerFactory.Object))) { - host.Start(); - - using (var socket = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp)) + using (var connection = server.CreateConnection()) { - socket.Connect(new IPEndPoint(IPAddress.Loopback, host.GetPort())); - socket.Send(Encoding.ASCII.GetBytes("GET / HTTP/1.1\r\nHost:\r\n\r\n")); + await connection.Send( + "GET / HTTP/1.1", + "Host:", + "", + ""); - // Wait until request is done being processed - Assert.True(await requestDone.WaitAsync(TimeSpan.FromSeconds(10))); + // 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", + "", + ""); // Force a reset - socket.LingerState = new LingerOption(true, 0); + connection.Socket.LingerState = new LingerOption(true, 0); } // If the reset is correctly logged as Debug, the wait below should complete shortly. @@ -378,61 +371,64 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests // and therefore not logged. Assert.True(await connectionReset.WaitAsync(TimeSpan.FromSeconds(10))); } + + Assert.False(loggedHigherThanDebug); } [Fact] public async Task ConnectionResetMidRequestIsLoggedAsDebug() { + var requestStarted = new SemaphoreSlim(0); var connectionReset = new SemaphoreSlim(0); + var loggedHigherThanDebug = false; var mockLogger = new Mock(); mockLogger .Setup(logger => logger.IsEnabled(It.IsAny())) .Returns(true); mockLogger - .Setup(logger => logger.Log(LogLevel.Debug, _connectionResetEventId, It.IsAny(), null, It.IsAny>())) - .Callback(() => - { - connectionReset.Release(); - }); + .Setup(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny>())) + .Callback>((logLevel, eventId, state, exception, formatter) => + { + if (eventId.Id == _connectionResetEventId) + { + connectionReset.Release(); + } + + if (logLevel > LogLevel.Debug) + { + loggedHigherThanDebug = true; + } + }); var mockLoggerFactory = new Mock(); mockLoggerFactory - .Setup(factory => factory.CreateLogger("Microsoft.AspNetCore.Server.Kestrel")) - .Returns(mockLogger.Object); - mockLoggerFactory - .Setup(factory => factory.CreateLogger("Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv")) - .Returns(mockLogger.Object); - mockLoggerFactory - .Setup(factory => factory.CreateLogger(It.IsNotIn("Microsoft.AspNetCore.Server.Kestrel", "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv"))) + .Setup(factory => factory.CreateLogger(It.IsAny())) .Returns(Mock.Of()); + mockLoggerFactory + .Setup(factory => factory.CreateLogger(It.IsIn("Microsoft.AspNetCore.Server.Kestrel", "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv"))) + .Returns(mockLogger.Object); - var requestStarted = new SemaphoreSlim(0); - - var builder = new WebHostBuilder() - .UseLoggerFactory(mockLoggerFactory.Object) - .UseKestrel() - .UseUrls("http://127.0.0.1:0") - .Configure(app => app.Run(async context => + using (var server = new TestServer(async context => { requestStarted.Release(); await context.Request.Body.ReadAsync(new byte[1], 0, 1); - })); - - using (var host = builder.Build()) + }, + new TestServiceContext(mockLoggerFactory.Object))) { - host.Start(); - - using (var socket = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp)) + using (var connection = server.CreateConnection()) { - socket.Connect(new IPEndPoint(IPAddress.Loopback, host.GetPort())); - socket.Send(Encoding.ASCII.GetBytes("GET / HTTP/1.1\r\nHost:\r\n\r\n")); + await connection.Send( + "GET / HTTP/1.1", + "Host:", + "", + ""); // Wait until connection is established Assert.True(await requestStarted.WaitAsync(TimeSpan.FromSeconds(10))); // Force a reset - socket.LingerState = new LingerOption(true, 0); + connection.Socket.LingerState = new LingerOption(true, 0); } // If the reset is correctly logged as Debug, the wait below should complete shortly. @@ -441,6 +437,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests // and therefore not logged. Assert.True(await connectionReset.WaitAsync(TimeSpan.FromSeconds(10))); } + + Assert.False(loggedHigherThanDebug); } [Fact] diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/ResponseTests.cs b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/ResponseTests.cs index 8fafc71d63..5966eab03f 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/ResponseTests.cs +++ b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/ResponseTests.cs @@ -20,6 +20,7 @@ using Microsoft.AspNetCore.Server.Kestrel.Core.Internal; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Internal; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Primitives; @@ -300,7 +301,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests disposedTcs.TrySetResult(c.Response.StatusCode); }); - using (var server = new TestServer(handler, new TestServiceContext(), mockHttpContextFactory.Object)) + using (var server = new TestServer(handler, new TestServiceContext(), new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0)), + services => services.AddSingleton(mockHttpContextFactory.Object))) { if (!sendMalformedRequest) { diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/TestServer.cs b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/TestServer.cs index 930c21cd08..ee2deb0b5e 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/TestServer.cs +++ b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/TestServer.cs @@ -34,21 +34,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } public TestServer(RequestDelegate app, TestServiceContext context) - : this(app, context, httpContextFactory: null) - { - } - - public TestServer(RequestDelegate app, TestServiceContext context, IHttpContextFactory httpContextFactory) - : this(app, context, new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0)), httpContextFactory) + : this(app, context, new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0))) { } public TestServer(RequestDelegate app, TestServiceContext context, ListenOptions listenOptions) - : this(app, context, listenOptions, null) + : this(app, context, listenOptions, _ => { }) { } - public TestServer(RequestDelegate app, TestServiceContext context, ListenOptions listenOptions, IHttpContextFactory httpContextFactory) + public TestServer(RequestDelegate app, TestServiceContext context, ListenOptions listenOptions, Action configureServices) { _app = app; _listenOptions = listenOptions; @@ -61,13 +56,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests }) .ConfigureServices(services => { - if (httpContextFactory != null) - { - services.AddSingleton(httpContextFactory); - } - services.AddSingleton(this); - services.AddSingleton(new KestrelTestLoggerFactory(context.ErrorLogger)); + services.AddSingleton(context.LoggerFactory); services.AddSingleton(sp => { // Manually configure options on the TestServiceContext. @@ -79,6 +69,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } return new KestrelServer(sp.GetRequiredService(), context); }); + + configureServices(services); }) .UseSetting(WebHostDefaults.ApplicationKey, typeof(TestServer).GetTypeInfo().Assembly.FullName) .Build(); diff --git a/test/shared/KestrelTestLoggerFactory.cs b/test/shared/KestrelTestLoggerFactory.cs index e8dbbd3408..80a94b0d1a 100644 --- a/test/shared/KestrelTestLoggerFactory.cs +++ b/test/shared/KestrelTestLoggerFactory.cs @@ -10,6 +10,11 @@ namespace Microsoft.AspNetCore.Testing { private readonly ILogger _testLogger; + public KestrelTestLoggerFactory() + : this(new TestApplicationErrorLogger()) + { + } + public KestrelTestLoggerFactory(ILogger testLogger) { _testLogger = testLogger; diff --git a/test/shared/TestApplicationErrorLogger.cs b/test/shared/TestApplicationErrorLogger.cs index 404b2cabc8..63f710cd7d 100644 --- a/test/shared/TestApplicationErrorLogger.cs +++ b/test/shared/TestApplicationErrorLogger.cs @@ -15,8 +15,6 @@ namespace Microsoft.AspNetCore.Testing // Application errors are logged using 13 as the eventId. private const int ApplicationErrorEventId = 13; - private TaskCompletionSource _messageLoggedTcs = new TaskCompletionSource(); - public bool ThrowOnCriticalErrors { get; set; } = true; public ConcurrentBag Messages { get; } = new ConcurrentBag(); @@ -27,8 +25,6 @@ namespace Microsoft.AspNetCore.Testing public int ApplicationErrorsLogged => Messages.Count(message => message.EventId.Id == ApplicationErrorEventId); - public Task MessageLoggedTask => _messageLoggedTcs.Task; - public IDisposable BeginScope(TState state) { return new Disposable(() => { }); @@ -60,8 +56,6 @@ namespace Microsoft.AspNetCore.Testing Exception = exception, Message = formatter(state, exception) }); - - _messageLoggedTcs.TrySetResult(null); } public class LogMessage diff --git a/test/shared/TestConnection.cs b/test/shared/TestConnection.cs index 0285a58e46..bc21df517e 100644 --- a/test/shared/TestConnection.cs +++ b/test/shared/TestConnection.cs @@ -17,35 +17,48 @@ namespace Microsoft.AspNetCore.Testing /// public class TestConnection : IDisposable { - private Socket _socket; - private NetworkStream _stream; - private StreamReader _reader; private static readonly TimeSpan Timeout = TimeSpan.FromMinutes(1); + private readonly bool _ownsSocket; + private readonly Socket _socket; + private readonly NetworkStream _stream; + private readonly StreamReader _reader; + public TestConnection(int port) : this(port, AddressFamily.InterNetwork) { } public TestConnection(int port, AddressFamily addressFamily) + : this(CreateConnectedLoopbackSocket(port, addressFamily), ownsSocket: true) { - Create(port, addressFamily); } - public StreamReader Reader => _reader; - - public void Create(int port, AddressFamily addressFamily) + public TestConnection(Socket socket) + : this(socket, ownsSocket: false) { - _socket = CreateConnectedLoopbackSocket(port, addressFamily); + } - _stream = new NetworkStream(_socket, false); + private TestConnection(Socket socket, bool ownsSocket) + { + _ownsSocket = ownsSocket; + _socket = socket; + _stream = new NetworkStream(_socket, ownsSocket: false); _reader = new StreamReader(_stream, Encoding.ASCII); } + public Socket Socket => _socket; + + public StreamReader Reader => _reader; + public void Dispose() { _stream.Dispose(); - _socket.Dispose(); + + if (_ownsSocket) + { + _socket.Dispose(); + } } public async Task SendAll(params string[] lines) diff --git a/test/shared/TestServiceContext.cs b/test/shared/TestServiceContext.cs index b1b28f7014..b06362b3fe 100644 --- a/test/shared/TestServiceContext.cs +++ b/test/shared/TestServiceContext.cs @@ -12,9 +12,19 @@ namespace Microsoft.AspNetCore.Testing public class TestServiceContext : ServiceContext { public TestServiceContext() + : this(new KestrelTestLoggerFactory()) { - ErrorLogger = new TestApplicationErrorLogger(); - Log = new TestKestrelTrace(ErrorLogger); + } + + public TestServiceContext(ILoggerFactory loggerFactory) + : this(loggerFactory, new KestrelTrace(loggerFactory.CreateLogger("Microsoft.AspNetCore.Server.Kestrel"))) + { + } + + public TestServiceContext(ILoggerFactory loggerFactory, IKestrelTrace kestrelTrace) + { + LoggerFactory = loggerFactory; + Log = kestrelTrace; ThreadPool = new LoggingThreadPool(Log); SystemClock = new MockSystemClock(); DateHeaderValueManager = new DateHeaderValueManager(SystemClock); @@ -27,7 +37,7 @@ namespace Microsoft.AspNetCore.Testing }; } - public TestApplicationErrorLogger ErrorLogger { get; } + public ILoggerFactory LoggerFactory { get; } public string DateHeaderValue { get; } }