Make connection reset logs less scary

- Particularly between requests, connection resets aren't that abnormal.

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/Connection.cs

@@ -262,7 +262,17 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
             {
                 Exception uvError;
                 handle.Libuv.Check(status, out uvError);
-                Log.ConnectionError(ConnectionId, uvError);
+
+                // Log connection resets at a lower (Debug) level.
+                if (status == Constants.ECONNRESET)
+                {
+                    Log.ConnectionReset(ConnectionId);
+                }
+                else
+                {
+                    Log.ConnectionError(ConnectionId, uvError);
+                }
+
                 error = new IOException(uvError.Message, uvError);
             }
 

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/Frame.cs

@@ -117,7 +117,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
         private KestrelServerOptions ServerOptions { get; }
         private IPEndPoint LocalEndPoint => ConnectionContext.LocalEndPoint;
         private IPEndPoint RemoteEndPoint => ConnectionContext.RemoteEndPoint;
-        private string ConnectionId => ConnectionContext.ConnectionId;
+        protected string ConnectionId => ConnectionContext.ConnectionId;
 
         public string ConnectionIdFeature { get; set; }
         public IPAddress RemoteIpAddress { get; set; }

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs

@@ -2,10 +2,12 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
+using System.IO;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Hosting.Server;
-using Microsoft.AspNetCore.Http;
+using Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure;
+using Microsoft.AspNetCore.Server.Kestrel.Internal.Networking;
 using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
@@ -29,21 +31,30 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
         /// </summary>
         public override async Task RequestProcessingAsync()
         {
+            var requestLineStatus = RequestLineStatus.Empty;
+
             try
             {
                 while (!_requestProcessingStopping)
                 {
                     ConnectionControl.SetTimeout(_keepAliveMilliseconds, TimeoutAction.CloseConnection);
 
-                    while (!_requestProcessingStopping && TakeStartLine(SocketInput) != RequestLineStatus.Done)
+                    while (!_requestProcessingStopping)
                     {
+                        requestLineStatus = TakeStartLine(SocketInput);
+
+                        if (requestLineStatus == RequestLineStatus.Done)
+                        {
+                            break;
+                        }
+
                         if (SocketInput.CheckFinOrThrow())
                         {
                             // We need to attempt to consume start lines and headers even after
                             // SocketInput.RemoteIntakeFin is set to true to ensure we don't close a
                             // connection without giving the application a chance to respond to a request
                             // sent immediately before the a FIN from the client.
-                            var requestLineStatus = TakeStartLine(SocketInput);
+                            requestLineStatus = TakeStartLine(SocketInput);
 
                             if (requestLineStatus == RequestLineStatus.Empty)
                             {
@@ -188,6 +199,15 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
                 // SetBadRequestState logs the error.
                 SetBadRequestState(ex);
             }
+            catch (IOException ex) when (ex.InnerException is UvException)
+            {
+                // Don't log ECONNRESET errors made between requests. Browsers like IE will reset connections regularly.
+                if (requestLineStatus != RequestLineStatus.Empty ||
+                    ((UvException)ex.InnerException).StatusCode != Constants.ECONNRESET)
+                {
+                    Log.RequestProcessingError(ConnectionId, ex);
+                }
+            }
             catch (Exception ex)
             {
                 Log.LogWarning(0, ex, "Connection processing ended abnormally");

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/SocketOutput.cs

@@ -393,7 +393,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
             else
             {
                 CompleteAllWrites();
-                _log.ConnectionError(_connectionId, error);
+
+                // Log connection resets at a lower (Debug) level.
+                if (status == Constants.ECONNRESET)
+                {
+                    _log.ConnectionReset(_connectionId);
+                }
+                else
+                {
+                    _log.ConnectionError(_connectionId, error);
+                }
             }
 
             if (!_postingWrite && _nextWriteContext != null)

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/Constants.cs

@@ -10,6 +10,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure
         public const int ListenBacklog = 128;
 
         public const int EOF = -4095;
+        public static readonly int? ECONNRESET = GetECONNRESET();
         public static readonly int? EADDRINUSE = GetEADDRINUSE();
 
         /// <summary>
@@ -19,11 +20,28 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure
 
         public const string ServerName = "Kestrel";
 
+        private static int? GetECONNRESET()
+        {
+            if (RuntimeInformation.IsOSPlatform(OSPlatform.Windows))
+            {
+                return -4077;
+            }
+            else if (RuntimeInformation.IsOSPlatform(OSPlatform.Linux))
+            {
+                return -104;
+            }
+            else if (RuntimeInformation.IsOSPlatform(OSPlatform.OSX))
+            {
+                return -54;
+            }
+            return null;
+        }
+
         private static int? GetEADDRINUSE()
         {
             if (RuntimeInformation.IsOSPlatform(OSPlatform.Windows))
             {
-               return -4091;
+                return -4091;
             }
             else if (RuntimeInformation.IsOSPlatform(OSPlatform.Linux))
             {

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/IKestrelTrace.cs

@@ -31,6 +31,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure
 
         void ConnectionError(string connectionId, Exception ex);
 
+        void ConnectionReset(string connectionId);
+
+        void RequestProcessingError(string connectionId, Exception ex);
+
         void ConnectionDisconnectedWrite(string connectionId, int count, Exception ex);
 
         void ConnectionHeadResponseBodyWrite(string connectionId, long count);

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/KestrelTrace.cs

@@ -27,6 +27,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal
         private static readonly Action<ILogger, string, long, Exception> _connectionHeadResponseBodyWrite;
         private static readonly Action<ILogger, Exception> _notAllConnectionsClosedGracefully;
         private static readonly Action<ILogger, string, string, Exception> _connectionBadRequest;
+        private static readonly Action<ILogger, string, Exception> _connectionReset;
+        private static readonly Action<ILogger, string, Exception> _requestProcessingError;
 
         protected readonly ILogger _logger;
 
@@ -45,11 +47,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal
             // ConnectionWrite: Reserved: 11
             // ConnectionWriteCallback: Reserved: 12
             _applicationError = LoggerMessage.Define<string>(LogLevel.Error, 13, @"Connection id ""{ConnectionId}"": An unhandled exception was thrown by the application.");
-            _connectionError = LoggerMessage.Define<string>(LogLevel.Information, 14, @"Connection id ""{ConnectionId}"" communication error");
+            _connectionError = LoggerMessage.Define<string>(LogLevel.Information, 14, @"Connection id ""{ConnectionId}"" communication error.");
             _connectionDisconnectedWrite = LoggerMessage.Define<string, int>(LogLevel.Debug, 15, @"Connection id ""{ConnectionId}"" write of ""{count}"" bytes to disconnected client.");
             _notAllConnectionsClosedGracefully = LoggerMessage.Define(LogLevel.Debug, 16, "Some connections failed to close gracefully during server shutdown.");
             _connectionBadRequest = LoggerMessage.Define<string, string>(LogLevel.Information, 17, @"Connection id ""{ConnectionId}"" bad request data: ""{message}""");
             _connectionHeadResponseBodyWrite = LoggerMessage.Define<string, long>(LogLevel.Debug, 18, @"Connection id ""{ConnectionId}"" write of ""{count}"" body bytes to non-body HEAD response.");
+            _connectionReset = LoggerMessage.Define<string>(LogLevel.Debug, 19, @"Connection id ""{ConnectionId}"" reset.");
+            _requestProcessingError = LoggerMessage.Define<string>(LogLevel.Information, 20, @"Connection id ""{ConnectionId}"" request processing ended abnormally.");
         }
 
         public KestrelTrace(ILogger logger)
@@ -150,6 +154,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal
             _connectionBadRequest(_logger, connectionId, ex.Message, ex);
         }
 
+        public virtual void ConnectionReset(string connectionId)
+        {
+            _connectionReset(_logger, connectionId, null);
+        }
+
+        public virtual void RequestProcessingError(string connectionId, Exception ex)
+        {
+            _requestProcessingError(_logger, connectionId, ex);
+        }
+
         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);

src/Microsoft.AspNetCore.Server.Kestrel/KestrelServer.cs

@@ -100,6 +100,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel
                         "ThreadCount must be positive.");
                 }
 
+                if (!Constants.ECONNRESET.HasValue)
+                {
+                    _logger.LogWarning("Unable to determine ECONNRESET value on this platform.");
+                }
+
                 if (!Constants.EADDRINUSE.HasValue)
                 {
                     _logger.LogWarning("Unable to determine EADDRINUSE value on this platform.");

test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs

@@ -17,6 +17,7 @@ using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Http.Features;
 using Microsoft.AspNetCore.Server.Kestrel.Internal.Networking;
 using Microsoft.AspNetCore.Testing.xunit;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Logging.Testing;
 using Newtonsoft.Json;
 using Newtonsoft.Json.Linq;
@@ -233,12 +234,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests
         }
 
         [Fact]
-        public async Task ConnectionResetAbortsRequest()
+        public async Task ConnectionResetPriorToRequestIsLoggedAsDebug()
         {
             var connectionStarted = new SemaphoreSlim(0);
-            var connectionErrorLogged = new SemaphoreSlim(0);
+            var connectionResetLogged = new SemaphoreSlim(0);
             var testSink = new ConnectionErrorTestSink(
-                () => connectionStarted.Release(), () => connectionErrorLogged.Release());
+                () => connectionStarted.Release(), () => connectionResetLogged.Release(), () => { });
             var builder = new WebHostBuilder()
                 .UseLoggerFactory(new TestLoggerFactory(testSink, true))
                 .UseKestrel()
@@ -257,16 +258,118 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests
                     socket.Connect(new IPEndPoint(IPAddress.Loopback, host.GetPort()));
                     // Wait until connection is established
                     Assert.True(await connectionStarted.WaitAsync(_semaphoreWaitTimeout));
+
                     // Force a reset
                     socket.LingerState = new LingerOption(true, 0);
                 }
 
                 // Wait until connection error is logged
-                Assert.True(await connectionErrorLogged.WaitAsync(_semaphoreWaitTimeout));
+                Assert.True(await connectionResetLogged.WaitAsync(_semaphoreWaitTimeout));
+
+                // Check the no log level higher than Debug was used for a reset before a request
+                Assert.Equal(LogLevel.Debug, testSink.MaxLogLevel);
 
                 // Check for expected message
-                Assert.NotNull(testSink.ConnectionErrorMessage);
-                Assert.Contains("ECONNRESET", testSink.ConnectionErrorMessage);
+                Assert.NotNull(testSink.ConnectionResetMessage);
+                Assert.Contains("reset", testSink.ConnectionResetMessage);
+            }
+        }
+
+        [Fact]
+        public async Task ConnectionResetBetweenRequestsIsLoggedAsDebug()
+        {
+            var connectionStarted = new SemaphoreSlim(0);
+            var connectionResetLogged = new SemaphoreSlim(0);
+            var testSink = new ConnectionErrorTestSink(
+                () => { }, () => connectionResetLogged.Release(), () => { });
+            var builder = new WebHostBuilder()
+                .UseLoggerFactory(new TestLoggerFactory(testSink, true))
+                .UseKestrel()
+                .UseUrls($"http://127.0.0.1:0")
+                .Configure(app => app.Run(context =>
+                {
+                    connectionStarted.Release();
+                    return Task.FromResult(0);
+                }));
+
+            using (var host = builder.Build())
+            {
+                host.Start();
+
+                using (var socket = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp))
+                {
+                    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
+                    Assert.True(await connectionStarted.WaitAsync(_semaphoreWaitTimeout));
+
+                    // Force a reset
+                    socket.LingerState = new LingerOption(true, 0);
+                }
+
+                // Wait until connection error is logged
+                Assert.True(await connectionResetLogged.WaitAsync(_semaphoreWaitTimeout));
+
+                // Check the no log level higher than Debug was used for a reset between a requests
+                Assert.Equal(LogLevel.Debug, testSink.MaxLogLevel);
+
+                // Check for expected message
+                Assert.NotNull(testSink.ConnectionResetMessage);
+                Assert.Contains("reset", testSink.ConnectionResetMessage);
+            }
+        }
+
+        [Fact]
+        public async Task ConnectionResetMidRequestIsLoggedAsInformation()
+        {
+            var connectionStarted = new SemaphoreSlim(0);
+            var connectionResetLogged = new SemaphoreSlim(0);
+            var requestProcessingErrorLogged = new SemaphoreSlim(0);
+            var testSink = new ConnectionErrorTestSink(
+                () => connectionStarted.Release(), () => connectionResetLogged.Release(), () => requestProcessingErrorLogged.Release());
+            var builder = new WebHostBuilder()
+                .UseLoggerFactory(new TestLoggerFactory(testSink, true))
+                .UseKestrel()
+                .UseUrls($"http://127.0.0.1:0")
+                .Configure(app => app.Run(context =>
+                {
+                    return Task.FromResult(0);
+                }));
+
+            using (var host = builder.Build())
+            {
+                host.Start();
+
+                using (var socket = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp))
+                {
+                    socket.Connect(new IPEndPoint(IPAddress.Loopback, host.GetPort()));
+                    socket.Send(Encoding.ASCII.GetBytes("GET"));
+
+                    // Wait until connection is established
+                    Assert.True(await connectionStarted.WaitAsync(_semaphoreWaitTimeout));
+
+                    // Ensure "GET" has been processed
+                    // Sadly, there is no event/log for starting request line processing
+                    await Task.Delay(1000);
+
+                    // Force a reset, give some time for the "GET" to be processed
+                    socket.LingerState = new LingerOption(true, 0);
+                }
+
+                // Wait until connection error and request processingError is logged
+                var waitAsyncResults = await Task.WhenAll(connectionResetLogged.WaitAsync(_semaphoreWaitTimeout), requestProcessingErrorLogged.WaitAsync(_semaphoreWaitTimeout));
+
+                Assert.All(waitAsyncResults, Assert.True);
+
+                // Check the no log level lower than Information was used for a reset mid-request
+                Assert.Equal(LogLevel.Information, testSink.MaxLogLevel);
+
+                // Check for expected message
+                Assert.NotNull(testSink.ConnectionResetMessage);
+                Assert.Contains("reset", testSink.ConnectionResetMessage);
+                Assert.NotNull(testSink.RequestProcessingErrorMessage);
+                Assert.Contains("abnormal", testSink.RequestProcessingErrorMessage);
             }
         }
 
@@ -357,15 +460,24 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests
         private class ConnectionErrorTestSink : ITestSink
         {
             private readonly Action _connectionStarted;
-            private readonly Action _connectionErrorLogged;
+            private readonly Action _connectionResetLogged;
+            private readonly Action _requestProcessingErrorLogged;
 
-            public ConnectionErrorTestSink(Action connectionStarted, Action connectionErrorLogged)
+            public ConnectionErrorTestSink(
+                Action connectionStarted,
+                Action connectionResetLogged,
+                Action requestProcessingErrorLogged)
             {
                 _connectionStarted = connectionStarted;
-                _connectionErrorLogged = connectionErrorLogged;
+                _connectionResetLogged = connectionResetLogged;
+                _requestProcessingErrorLogged = requestProcessingErrorLogged;
             }
 
-            public string ConnectionErrorMessage { get; set; }
+            public LogLevel MaxLogLevel { get; set; }
+
+            public string ConnectionResetMessage { get; set; }
+
+            public string RequestProcessingErrorMessage { get; set; }
 
             public Func<BeginScopeContext, bool> BeginEnabled { get; set; }
 
@@ -381,17 +493,28 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests
 
             public void Write(WriteContext context)
             {
+                if (context.LoggerName == "Microsoft.AspNetCore.Server.Kestrel" && context.LogLevel > MaxLogLevel)
+                {
+                    MaxLogLevel = context.LogLevel;
+                }
+
                 const int connectionStartEventId = 1;
-                const int connectionErrorEventId = 14;
+                const int connectionResetEventId = 19;
+                const int requestProcessingErrorEventId = 20;
 
                 if (context.EventId.Id == connectionStartEventId)
                 {
                     _connectionStarted();
                 }
-                else if (context.EventId.Id == connectionErrorEventId)
+                else if (context.EventId.Id == connectionResetEventId)
                 {
-                    ConnectionErrorMessage = context.Exception?.Message;
-                    _connectionErrorLogged();
+                    ConnectionResetMessage = context.Formatter(context.State, context.Exception);
+                    _connectionResetLogged();
+                }
+                else if (context.EventId.Id == requestProcessingErrorEventId)
+                {
+                    RequestProcessingErrorMessage = context.Formatter(context.State, context.Exception);
+                    _requestProcessingErrorLogged();
                 }
             }
         }