diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/Connection.cs b/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/Connection.cs index f92f419bf8..3f61f8530c 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/Connection.cs +++ b/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); } diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/Frame.cs b/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/Frame.cs index eabcf12081..725e284bc6 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/Frame.cs +++ b/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; } diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs b/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs index 2d0eecad6e..a59b010e32 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs +++ b/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 /// 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"); diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/SocketOutput.cs b/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/SocketOutput.cs index 86b274dd12..4a6cac5006 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/SocketOutput.cs +++ b/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) diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/Constants.cs b/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/Constants.cs index ddc9f767b9..77968bca17 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/Constants.cs +++ b/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(); /// @@ -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)) { diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/IKestrelTrace.cs b/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/IKestrelTrace.cs index 2be2acbfc3..2645aa8e88 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/IKestrelTrace.cs +++ b/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); diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/KestrelTrace.cs b/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/KestrelTrace.cs index fcdc3f9208..181e6380a2 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/KestrelTrace.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel/Internal/Infrastructure/KestrelTrace.cs @@ -27,6 +27,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal private static readonly Action _connectionHeadResponseBodyWrite; private static readonly Action _notAllConnectionsClosedGracefully; private static readonly Action _connectionBadRequest; + private static readonly Action _connectionReset; + private static readonly Action _requestProcessingError; protected readonly ILogger _logger; @@ -45,11 +47,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal // ConnectionWrite: Reserved: 11 // ConnectionWriteCallback: Reserved: 12 _applicationError = LoggerMessage.Define(LogLevel.Error, 13, @"Connection id ""{ConnectionId}"": An unhandled exception was thrown by the application."); - _connectionError = LoggerMessage.Define(LogLevel.Information, 14, @"Connection id ""{ConnectionId}"" communication error"); + _connectionError = LoggerMessage.Define(LogLevel.Information, 14, @"Connection id ""{ConnectionId}"" communication error."); _connectionDisconnectedWrite = LoggerMessage.Define(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(LogLevel.Information, 17, @"Connection id ""{ConnectionId}"" bad request data: ""{message}"""); _connectionHeadResponseBodyWrite = LoggerMessage.Define(LogLevel.Debug, 18, @"Connection id ""{ConnectionId}"" write of ""{count}"" body bytes to non-body HEAD response."); + _connectionReset = LoggerMessage.Define(LogLevel.Debug, 19, @"Connection id ""{ConnectionId}"" reset."); + _requestProcessingError = LoggerMessage.Define(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(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { _logger.Log(logLevel, eventId, state, exception, formatter); diff --git a/src/Microsoft.AspNetCore.Server.Kestrel/KestrelServer.cs b/src/Microsoft.AspNetCore.Server.Kestrel/KestrelServer.cs index d26fa002b0..e7e4e38d62 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel/KestrelServer.cs +++ b/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."); diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs index d1ce7b8951..645f7c5205 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs +++ b/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 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(); } } }