Add some tracing and increase timeout for flaky test (#2130)

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);
         }

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;

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<ListenOptions> ConnectionAdapterData => new TheoryData<ListenOptions>
         {
@@ -46,6 +48,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests
             }
         };
 
+        public ResponseTests(ITestOutputHelper outputHelper) : base(outputHelper) { }
+
         [Fact]
         public async Task LargeDownload()
         {
@@ -2447,19 +2451,24 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests
         [Fact]
         public void ConnectionClosedWhenResponseDoesNotSatisfyMinimumDataRate()
         {
+            using (StartLog(out var loggerFactory))
+            {
+                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<IKestrelTrace>();
+                var mockKestrelTrace = new Mock<KestrelTrace>(loggerFactory.CreateLogger("Microsoft.AspNetCore.Server.Kestrel")) { CallBase = true };
                 mockKestrelTrace
                     .Setup(trace => trace.ResponseMininumDataRateNotSatisfied(It.IsAny<string>(), It.IsAny<string>()))
                     .Callback(() => messageLogged.Set());
 
                 var testContext = new TestServiceContext
                 {
+                    LoggerFactory = loggerFactory,
                     Log = mockKestrelTrace.Object,
                     SystemClock = new SystemClock(),
                     ServerOptions =
@@ -2471,8 +2480,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests
                     }
                 };
 
-            using (var server = new TestServer(async context =>
+                var listenOptions = new ListenOptions(new IPEndPoint(IPAddress.Loopback, 0));
+                listenOptions.ConnectionAdapters.Add(new LoggingConnectionAdapter(loggerFactory.CreateLogger<LoggingConnectionAdapter>()));
+
+                var appLogger = loggerFactory.CreateLogger("App");
+                async Task App(HttpContext context)
                 {
+                    appLogger.LogInformation("Request received");
                     context.RequestAborted.Register(() => requestAborted.Set());
 
                     context.Response.ContentLength = responseSize;
@@ -2480,18 +2494,27 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests
                     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);
                     }
-            }, testContext))
+                }
+
+                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");
 
-                    Assert.True(messageLogged.Wait(TimeSpan.FromSeconds(60)), "The expected message was not logged within the timeout period.");
+                        var sw = Stopwatch.StartNew();
-                    Assert.True(requestAborted.Wait(TimeSpan.FromSeconds(60)), "The request was not aborted within the timeout period.");
+                        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;
@@ -2513,10 +2536,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests
                         }
 
                         // 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);
                     }
                 }
             }
+        }
 
         [Fact]
         public async Task HttpsConnectionClosedWhenResponseDoesNotSatisfyMinimumDataRate()