Log when aborting connection due to write timeout.

aspnet · Jul 8, 2017 · 73c73a2 · 73c73a2
1 parent cb8e328
commit 73c73a2
Show file tree

Hide file tree

Showing 5 changed files with 24 additions and 2 deletions.
diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/FrameConnection.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/FrameConnection.cs
@@ -350,7 +350,8 @@ private void CheckForWriteDataRateTimeout(long timestamp)
                 if (_writeTimingWrites > 0 && timestamp > _writeTimingTimeoutTimestamp && !Debugger.IsAttached)
                 {
                     TimedOut = true;
-                    Abort(new TimeoutException("The connection was aborted because the response was not received at the specified minimum data rate."));
+                    Log.ResponseMininumDataRateNotSatisfied(_frame.ConnectionIdFeature, _frame.TraceIdentifier);
+                    Abort(new TimeoutException());
                 }
             }
         }

diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/IKestrelTrace.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/IKestrelTrace.cs
@@ -43,5 +43,7 @@ public interface IKestrelTrace : ILogger
         void RequestBodyDone(string connectionId, string traceIdentifier);
 
         void RequestBodyMininumDataRateNotSatisfied(string connectionId, string traceIdentifier, double rate);
+
+        void ResponseMininumDataRateNotSatisfied(string connectionId, string traceIdentifier);
     }
 }
diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs
@@ -61,7 +61,10 @@ public class KestrelTrace : IKestrelTrace
             LoggerMessage.Define<string, string>(LogLevel.Debug, 26, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": done reading request body.");
 
         private static readonly Action<ILogger, string, string, double, Exception> _requestBodyMinimumDataRateNotSatisfied =
-            LoggerMessage.Define<string, string, double>(LogLevel.Information, 27, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": request body incoming data rate dropped below {Rate} bytes/second.");
+            LoggerMessage.Define<string, string, double>(LogLevel.Information, 27, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the request timed out because it was not sent by the client at a minimum of {Rate} bytes/second.");
+
+        private static readonly Action<ILogger, string, string, Exception> _responseMinimumDataRateNotSatisfied =
+            LoggerMessage.Define<string, string>(LogLevel.Information, 28, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the connection was closed becuase the response was not read by the client at the specified minimum data rate.");
 
         protected readonly ILogger _logger;
 
@@ -160,6 +163,11 @@ public void RequestBodyMininumDataRateNotSatisfied(string connectionId, string t
             _requestBodyMinimumDataRateNotSatisfied(_logger, connectionId, traceIdentifier, rate, null);
         }
 
+        public void ResponseMininumDataRateNotSatisfied(string connectionId, string traceIdentifier)
+        {
+            _responseMinimumDataRateNotSatisfied(_logger, connectionId, traceIdentifier, null);
+        }
+
         public virtual void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
             => _logger.Log(logLevel, eventId, state, exception, formatter);
 

diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/ResponseTests.cs b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/ResponseTests.cs
@@ -2444,8 +2444,16 @@ public async Task ConnectionClosedWhenResponseDoesNotSatisfyMinimumDataRate()
             var chunkSize = 64 * 1024;
             var chunks = 128;
 
+            var messageLogged = new ManualResetEventSlim();
+
+            var mockKestrelTrace = new Mock<IKestrelTrace>();
+            mockKestrelTrace
+                .Setup(trace => trace.ResponseMininumDataRateNotSatisfied(It.IsAny<string>(), It.IsAny<string>()))
+                .Callback(() => messageLogged.Set());
+
             var testContext = new TestServiceContext
             {
+                Log = mockKestrelTrace.Object,
                 SystemClock = new SystemClock(),
                 ServerOptions =
                 {
@@ -2496,6 +2504,8 @@ await connection.Receive(
 
                     await Assert.ThrowsAsync<EqualException>(async () => await connection.Receive(
                         new string('a', chunks * chunkSize)).TimeoutAfter(TimeSpan.FromSeconds(10)));
+
+                    Assert.True(messageLogged.Wait(TimeSpan.FromSeconds(10)));
                 }
             }
         }

diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.Performance/Mocks/MockTrace.cs b/test/Microsoft.AspNetCore.Server.Kestrel.Performance/Mocks/MockTrace.cs
@@ -39,5 +39,6 @@ public void ApplicationNeverCompleted(string connectionId) { }
         public void RequestBodyStart(string connectionId, string traceIdentifier) { }
         public void RequestBodyDone(string connectionId, string traceIdentifier) { }
         public void RequestBodyMininumDataRateNotSatisfied(string connectionId, string traceIdentifier, double rate) { }
+        public void ResponseMininumDataRateNotSatisfied(string connectionId, string traceIdentifier) { }
     }
 }