From eea0c6490e1c65d91044b82269a98a790e8b172a Mon Sep 17 00:00:00 2001 From: Nate McMaster Date: Mon, 3 Jul 2017 11:37:23 -0700 Subject: [PATCH] Fix flaky test: ConnectionResetMidRequestIsLoggedAsDebug (#1933) --- ...spNetCore.Server.Kestrel.Core.Tests.csproj | 1 - ...Core.Server.Kestrel.FunctionalTests.csproj | 1 - .../RequestTests.cs | 26 ++++++++++++------- ...erver.Kestrel.Transport.Libuv.Tests.csproj | 1 - 4 files changed, 17 insertions(+), 12 deletions(-) diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.Core.Tests/Microsoft.AspNetCore.Server.Kestrel.Core.Tests.csproj b/test/Microsoft.AspNetCore.Server.Kestrel.Core.Tests/Microsoft.AspNetCore.Server.Kestrel.Core.Tests.csproj index fba2976f4e..d4f68d8023 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.Core.Tests/Microsoft.AspNetCore.Server.Kestrel.Core.Tests.csproj +++ b/test/Microsoft.AspNetCore.Server.Kestrel.Core.Tests/Microsoft.AspNetCore.Server.Kestrel.Core.Tests.csproj @@ -12,7 +12,6 @@ Remove when fixed. --> true - win7-x64 diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.csproj b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.csproj index a7766fba47..e96a61c766 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.csproj +++ b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.csproj @@ -12,7 +12,6 @@ Remove when fixed. --> true - win7-x64 diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs index a130aadde3..4fb7a4bc86 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs +++ b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs @@ -28,6 +28,7 @@ using Moq; using Newtonsoft.Json; using Newtonsoft.Json.Linq; using Xunit; +using Xunit.Abstractions; namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests { @@ -37,6 +38,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests private const int _connectionResetEventId = 19; private const int _semaphoreWaitTimeout = 2500; + private readonly ITestOutputHelper _output; + + public RequestTests(ITestOutputHelper output) + { + _output = output; + } + public static TheoryData ConnectionAdapterData => new TheoryData { new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0)), @@ -385,6 +393,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests { var requestStarted = new SemaphoreSlim(0); var connectionReset = new SemaphoreSlim(0); + var connectionClosing = new SemaphoreSlim(0); var loggedHigherThanDebug = false; var mockLogger = new Mock(); @@ -395,6 +404,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests .Setup(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny>())) .Callback>((logLevel, eventId, state, exception, formatter) => { + _output.WriteLine(logLevel + ": " + formatter(state, exception)); + if (eventId.Id == _connectionResetEventId) { connectionReset.Release(); @@ -417,20 +428,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests using (var server = new TestServer(async context => { requestStarted.Release(); - await context.Request.Body.ReadAsync(new byte[1], 0, 1); + await connectionClosing.WaitAsync(); }, new TestServiceContext(mockLoggerFactory.Object))) { using (var connection = server.CreateConnection()) { - await connection.Send( - "GET / HTTP/1.1", - "Host:", - "", - ""); + await connection.SendEmptyGet(); // Wait until connection is established - Assert.True(await requestStarted.WaitAsync(TimeSpan.FromSeconds(10))); + Assert.True(await requestStarted.WaitAsync(TimeSpan.FromSeconds(30)), "request should have started"); // Force a reset connection.Socket.LingerState = new LingerOption(true, 0); @@ -440,10 +447,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests // 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(TimeSpan.FromSeconds(10))); + Assert.True(await connectionReset.WaitAsync(TimeSpan.FromSeconds(30)), "Connection reset event should have been logged"); + connectionClosing.Release(); } - Assert.False(loggedHigherThanDebug); + Assert.False(loggedHigherThanDebug, "Logged event should not have been higher than debug."); } [Fact] diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests.csproj b/test/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests.csproj index d6e8bf6ba9..a4fa5d8d2b 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests.csproj +++ b/test/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests.csproj @@ -13,7 +13,6 @@ Remove when fixed. --> true - win7-x64