Fix flakiness in connection reset logging tests.

Author: Cesar Blum Silveira

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 @@ public void CanUpgradeRequestWithConnectionKeepAliveUpgradeHeader()
         [Fact]
         public async Task ConnectionResetPriorToRequestIsLoggedAsDebug()
         {
-            var connectionStartedTcs = new TaskCompletionSource<object>();
+            var connectionStarted = new SemaphoreSlim(0);
+            var connectionReset = new SemaphoreSlim(0);
 
             var mockLogger = new Mock<ILogger>();
             mockLogger
@@ -251,7 +253,13 @@ public async Task ConnectionResetPriorToRequestIsLoggedAsDebug()
                 .Setup(logger => logger.Log(LogLevel.Debug, _connectionStartedEventId, It.IsAny<object>(), null, It.IsAny<Func<object, Exception, string>>()))
                 .Callback(() =>
                 {
-                    connectionStartedTcs.SetResult(null);
+                    connectionStarted.Release();
+                });
+            mockLogger
+                .Setup(logger => logger.Log(LogLevel.Debug, _connectionResetEventId, It.IsAny<object>(), null, It.IsAny<Func<object, Exception, string>>()))
+                .Callback(() =>
+                {
+                    connectionReset.Release();
                 });
 
             var mockLoggerFactory = new Mock<ILoggerFactory>();
@@ -266,10 +274,7 @@ public async Task ConnectionResetPriorToRequestIsLoggedAsDebug()
                 .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 @@ public async Task ConnectionResetPriorToRequestIsLoggedAsDebug()
                     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<object>(), null, It.IsAny<Func<object, Exception, string>>()));
+                // 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<ILogger>();
             mockLogger
                 .Setup(logger => logger.IsEnabled(It.IsAny<LogLevel>()))
                 .Returns(true);
+            mockLogger
+                .Setup(logger => logger.Log(LogLevel.Debug, _connectionKeepAliveEventId, It.IsAny<object>(), null, It.IsAny<Func<object, Exception, string>>()))
+                .Callback(() =>
+                {
+                    requestDone.Release();
+                });
+            mockLogger
+                .Setup(logger => logger.Log(LogLevel.Debug, _connectionResetEventId, It.IsAny<object>(), null, It.IsAny<Func<object, Exception, string>>()))
+                .Callback(() =>
+                {
+                    connectionReset.Release();
+                });
 
             var mockLoggerFactory = new Mock<ILoggerFactory>();
             mockLoggerFactory
@@ -306,17 +330,12 @@ public async Task ConnectionResetBetweenRequestsIsLoggedAsDebug()
                 .Setup(factory => factory.CreateLogger(It.IsNotIn(new[] { "Microsoft.AspNetCore.Server.Kestrel" })))
                 .Returns(Mock.Of<ILogger>());
 
-            var connectionStartedTcs = new TaskCompletionSource<object>();
 
             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 @@ public async Task ConnectionResetBetweenRequestsIsLoggedAsDebug()
                     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<object>(), null, It.IsAny<Func<object, Exception, string>>()));
+                // 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<ILogger>();
             mockLogger
                 .Setup(logger => logger.IsEnabled(It.IsAny<LogLevel>()))
                 .Returns(true);
+            mockLogger
+                 .Setup(logger => logger.Log(LogLevel.Debug, _connectionResetEventId, It.IsAny<object>(), null, It.IsAny<Func<object, Exception, string>>()))
+                 .Callback(() =>
+                 {
+                     connectionReset.Release();
+                 });
 
             var mockLoggerFactory = new Mock<ILoggerFactory>();
             mockLoggerFactory
@@ -354,15 +385,15 @@ public async Task ConnectionResetMidRequestIsLoggedAsDebug()
                 .Setup(factory => factory.CreateLogger(It.IsNotIn(new[] { "Microsoft.AspNetCore.Server.Kestrel" })))
                 .Returns(Mock.Of<ILogger>());
 
-            var connectionStartedTcs = new TaskCompletionSource<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 =>
                 {
-                    connectionStartedTcs.SetResult(null);
+                    requestStarted.Release();
                     await context.Request.Body.ReadAsync(new byte[1], 0, 1);
                 }));
 
@@ -376,14 +407,18 @@ public async Task ConnectionResetMidRequestIsLoggedAsDebug()
                     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<object>(), null, It.IsAny<Func<object, Exception, string>>()));
+                // 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]