From 3e6303b6c15c571a0eca618042add2f246fe1ead Mon Sep 17 00:00:00 2001 From: Cesar Blum Silveira Date: Thu, 23 Mar 2017 21:52:29 -0700 Subject: [PATCH] Fix flakiness in connection reset logging tests. --- .../RequestTests.cs | 83 +++++++++++++------ 1 file changed, 59 insertions(+), 24 deletions(-) diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs index 55c4e326bc..10a718c1e8 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs +++ b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs @@ -30,6 +30,7 @@ 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; @@ -241,7 +242,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests [Fact] public async Task ConnectionResetPriorToRequestIsLoggedAsDebug() { - var connectionStartedTcs = new TaskCompletionSource(); + var connectionStarted = new SemaphoreSlim(0); + var connectionReset = new SemaphoreSlim(0); var mockLogger = new Mock(); mockLogger @@ -251,7 +253,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests .Setup(logger => logger.Log(LogLevel.Debug, _connectionStartedEventId, It.IsAny(), null, It.IsAny>())) .Callback(() => { - connectionStartedTcs.SetResult(null); + connectionStarted.Release(); + }); + mockLogger + .Setup(logger => logger.Log(LogLevel.Debug, _connectionResetEventId, It.IsAny(), null, It.IsAny>())) + .Callback(() => + { + connectionReset.Release(); }); var mockLoggerFactory = new Mock(); @@ -266,10 +274,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests .UseLoggerFactory(mockLoggerFactory.Object) .UseKestrel() .UseUrls($"http://127.0.0.1:0") - .Configure(app => app.Run(context => - { - return TaskCache.CompletedTask; - })); + .Configure(app => app.Run(context => TaskCache.CompletedTask)); using (var host = builder.Build()) { @@ -280,23 +285,42 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests socket.Connect(new IPEndPoint(IPAddress.Loopback, host.GetPort())); // Wait until connection is established - await connectionStartedTcs.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); + await connectionStarted.WaitAsync(TimeSpan.FromSeconds(10)); // Force a reset socket.LingerState = new LingerOption(true, 0); } - } - mockLogger.Verify(logger => logger.Log(LogLevel.Debug, _connectionResetEventId, It.IsAny(), null, It.IsAny>())); + // 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. + await connectionReset.WaitAsync(TimeSpan.FromSeconds(10)); + } } [Fact] public async Task ConnectionResetBetweenRequestsIsLoggedAsDebug() { + var requestDone = new SemaphoreSlim(0); + var connectionReset = new SemaphoreSlim(0); + 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(() => + { + requestDone.Release(); + }); + mockLogger + .Setup(logger => logger.Log(LogLevel.Debug, _connectionResetEventId, It.IsAny(), null, It.IsAny>())) + .Callback(() => + { + connectionReset.Release(); + }); var mockLoggerFactory = new Mock(); mockLoggerFactory @@ -306,17 +330,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests .Setup(factory => factory.CreateLogger(It.IsNotIn(new[] { "Microsoft.AspNetCore.Server.Kestrel" }))) .Returns(Mock.Of()); - var connectionStartedTcs = new TaskCompletionSource(); var builder = new WebHostBuilder() .UseLoggerFactory(mockLoggerFactory.Object) .UseKestrel() .UseUrls($"http://127.0.0.1:0") - .Configure(app => app.Run(context => - { - connectionStartedTcs.SetResult(null); - return TaskCache.CompletedTask; - })); + .Configure(app => app.Run(context => TaskCache.CompletedTask)); using (var host = builder.Build()) { @@ -327,24 +346,36 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests socket.Connect(new IPEndPoint(IPAddress.Loopback, host.GetPort())); socket.Send(Encoding.ASCII.GetBytes("GET / HTTP/1.1\r\n\r\n")); - // Wait until connection is established - await connectionStartedTcs.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); + // Wait until request is done being processed + await requestDone.WaitAsync(TimeSpan.FromSeconds(10)); // Force a reset socket.LingerState = new LingerOption(true, 0); } - } - mockLogger.Verify(logger => logger.Log(LogLevel.Debug, _connectionResetEventId, It.IsAny(), null, It.IsAny>())); + // 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. + await connectionReset.WaitAsync(TimeSpan.FromSeconds(10)); + } } [Fact] public async Task ConnectionResetMidRequestIsLoggedAsDebug() { + var connectionReset = new SemaphoreSlim(0); + 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(); + }); var mockLoggerFactory = new Mock(); mockLoggerFactory @@ -354,7 +385,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests .Setup(factory => factory.CreateLogger(It.IsNotIn(new[] { "Microsoft.AspNetCore.Server.Kestrel" }))) .Returns(Mock.Of()); - var connectionStartedTcs = new TaskCompletionSource(); + var requestStarted = new SemaphoreSlim(0); var builder = new WebHostBuilder() .UseLoggerFactory(mockLoggerFactory.Object) @@ -362,7 +393,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests .UseUrls($"http://127.0.0.1:0") .Configure(app => app.Run(async context => { - connectionStartedTcs.SetResult(null); + requestStarted.Release(); await context.Request.Body.ReadAsync(new byte[1], 0, 1); })); @@ -376,14 +407,18 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests socket.Send(Encoding.ASCII.GetBytes("GET / HTTP/1.1\r\n\r\n")); // Wait until connection is established - await connectionStartedTcs.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); + await requestStarted.WaitAsync(TimeSpan.FromSeconds(10)); // Force a reset socket.LingerState = new LingerOption(true, 0); } - } - mockLogger.Verify(logger => logger.Log(LogLevel.Debug, _connectionResetEventId, It.IsAny(), null, It.IsAny>())); + // 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. + await connectionReset.WaitAsync(TimeSpan.FromSeconds(10)); + } } [Fact]