Make transport logs for connection close more detailed and consistent (#2978)

src/Kestrel.Transport.Libuv/Internal/ILibuvTrace.cs

@@ -14,8 +14,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal
 
         void ConnectionWriteFin(string connectionId);
 
-        void ConnectionWroteFin(string connectionId, int status);
-
         void ConnectionWrite(string connectionId, int count);
 
         void ConnectionWriteCallback(string connectionId, int status);
@@ -28,6 +26,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal
 
         void ConnectionResume(string connectionId);
 
-        void ConnectionAborted(string connectionId);
+        void ConnectionAborted(string connectionId, string message);
     }
 }

src/Kestrel.Transport.Libuv/Internal/LibuvConnection.cs

@@ -119,7 +119,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal
 
         public override void Abort(ConnectionAbortedException abortReason)
         {
+            Log.ConnectionAborted(ConnectionId, abortReason?.Message);
+
             _abortReason = abortReason;
+            
+            // Cancel WriteOutputAsync loop after setting _abortReason.
             Output.CancelPendingRead();
 
             // This cancels any pending I/O.

src/Kestrel.Transport.Libuv/Internal/LibuvTrace.cs

@@ -22,9 +22,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal
         private static readonly Action<ILogger, string, Exception> _connectionWriteFin =
             LoggerMessage.Define<string>(LogLevel.Debug, new EventId(7, nameof(ConnectionWriteFin)), @"Connection id ""{ConnectionId}"" sending FIN.");
 
-        private static readonly Action<ILogger, string, int, Exception> _connectionWroteFin =
-            LoggerMessage.Define<string, int>(LogLevel.Debug, new EventId(8, nameof(ConnectionWroteFin)), @"Connection id ""{ConnectionId}"" sent FIN with status ""{Status}"".");
-
         // ConnectionWrite: Reserved: 11
 
         // ConnectionWriteCallback: Reserved: 12
@@ -35,8 +32,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal
         private static readonly Action<ILogger, string, Exception> _connectionReset =
             LoggerMessage.Define<string>(LogLevel.Debug, new EventId(19, nameof(ConnectionReset)), @"Connection id ""{ConnectionId}"" reset.");
 
-        private static readonly Action<ILogger, string, Exception> _connectionAborted =
+        private static readonly Action<ILogger, string, string, Exception> _connectionAborted =
-            LoggerMessage.Define<string>(LogLevel.Debug, new EventId(20, nameof(ConnectionAborted)), @"Connection id ""{ConnectionId}"" aborted.");
+            LoggerMessage.Define<string, string>(LogLevel.Debug, new EventId(20, nameof(ConnectionAborted)), @"Connection id ""{ConnectionId}"" closing because: ""{Message}""");
 
         private readonly ILogger _logger;
 
@@ -61,11 +58,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal
             _connectionWriteFin(_logger, connectionId, null);
         }
 
-        public void ConnectionWroteFin(string connectionId, int status)
-        {
-            _connectionWroteFin(_logger, connectionId, status, null);
-        }
-
         public void ConnectionWrite(string connectionId, int count)
         {
             // Don't log for now since this could be *too* verbose.
@@ -98,9 +90,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal
             _connectionResume(_logger, connectionId, null);
         }
 
-        public void ConnectionAborted(string connectionId)
+        public void ConnectionAborted(string connectionId, string message)
         {
-            _connectionAborted(_logger, connectionId, null);
+            _connectionAborted(_logger, connectionId, message, null);
         }
 
         public IDisposable BeginScope<TState>(TState state) => _logger.BeginScope(state);

src/Kestrel.Transport.Sockets/Internal/ISocketsTrace.cs

@@ -20,6 +20,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal
 
         void ConnectionResume(string connectionId);
 
-        void ConnectionAborted(string connectionId);
+        void ConnectionAborted(string connectionId, string message);
     }
 }

src/Kestrel.Transport.Sockets/Internal/SocketConnection.cs

@@ -92,7 +92,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal
 
         public override void Abort(ConnectionAbortedException abortReason)
         {
-            _trace.ConnectionAborted(ConnectionId);
+            _trace.ConnectionAborted(ConnectionId, abortReason?.Message);
 
             // Try to gracefully close the socket to match libuv behavior.
             Shutdown(abortReason);

src/Kestrel.Transport.Sockets/Internal/SocketsTrace.cs

@@ -22,14 +22,18 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal
         private static readonly Action<ILogger, string, Exception> _connectionWriteFin =
             LoggerMessage.Define<string>(LogLevel.Debug, new EventId(7, nameof(ConnectionWriteFin)), @"Connection id ""{ConnectionId}"" sending FIN.");
 
+        // ConnectionWrite: Reserved: 11
+
+        // ConnectionWriteCallback: Reserved: 12
+
         private static readonly Action<ILogger, string, Exception> _connectionError =
             LoggerMessage.Define<string>(LogLevel.Information, new EventId(14, nameof(ConnectionError)), @"Connection id ""{ConnectionId}"" communication error.");
 
         private static readonly Action<ILogger, string, Exception> _connectionReset =
             LoggerMessage.Define<string>(LogLevel.Debug, new EventId(19, nameof(ConnectionReset)), @"Connection id ""{ConnectionId}"" reset.");
 
-        private static readonly Action<ILogger, string, Exception> _connectionAborted =
+        private static readonly Action<ILogger, string, string, Exception> _connectionAborted =
-            LoggerMessage.Define<string>(LogLevel.Debug, new EventId(20, nameof(ConnectionAborted)), @"Connection id ""{ConnectionId}"" aborted.");
+            LoggerMessage.Define<string, string>(LogLevel.Debug, new EventId(20, nameof(ConnectionAborted)), @"Connection id ""{ConnectionId}"" closing because: ""{Message}""");
 
         private readonly ILogger _logger;
 
@@ -86,9 +90,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal
             _connectionResume(_logger, connectionId, null);
         }
 
-        public void ConnectionAborted(string connectionId)
+        public void ConnectionAborted(string connectionId, string message)
         {
-            _connectionAborted(_logger, connectionId, null);
+            _connectionAborted(_logger, connectionId, message, null);
         }
 
         public IDisposable BeginScope<TState>(TState state) => _logger.BeginScope(state);

test/Kestrel.InMemory.FunctionalTests/TestTransport/InMemoryTransportConnection.cs

@@ -8,6 +8,7 @@ using System.Net;
 using System.Threading;
 using Microsoft.AspNetCore.Connections;
 using Microsoft.AspNetCore.Server.Kestrel.Transport.Abstractions.Internal;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.TestTransport
 {
@@ -15,11 +16,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.TestTrans
     {
         private readonly CancellationTokenSource _connectionClosedTokenSource = new CancellationTokenSource();
 
+        private readonly ILogger _logger;
         private bool _isClosed;
 
-        public InMemoryTransportConnection(MemoryPool<byte> memoryPool)
+        public InMemoryTransportConnection(MemoryPool<byte> memoryPool, ILogger logger)
         {
             MemoryPool = memoryPool;
+            _logger = logger;
 
             LocalAddress = IPAddress.Loopback;
             RemoteAddress = IPAddress.Loopback;
@@ -28,6 +31,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.TestTrans
         }
 
         public override MemoryPool<byte> MemoryPool { get; }
+
         public override PipeScheduler InputWriterScheduler => PipeScheduler.ThreadPool;
         public override PipeScheduler OutputReaderScheduler => PipeScheduler.ThreadPool;
 
@@ -35,6 +39,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.TestTrans
 
         public override void Abort(ConnectionAbortedException abortReason)
         {
+            _logger.LogDebug(@"Connection id ""{ConnectionId}"" closing because: ""{Message}""", ConnectionId, abortReason?.Message);
+
             Input.Complete(abortReason);
 
             AbortReason = abortReason;

test/Kestrel.InMemory.FunctionalTests/TestTransport/TestServer.cs

@@ -96,7 +96,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.TestTrans
 
         public InMemoryConnection CreateConnection()
         {
-            var transportConnection = new InMemoryTransportConnection(_memoryPool);
+            var transportConnection = new InMemoryTransportConnection(_memoryPool, Context.Log);
             _ = HandleConnection(transportConnection);
             return new InMemoryConnection(transportConnection);
         }