From a9d6cf13eb96b17b1cba15f80936516a02a31a32 Mon Sep 17 00:00:00 2001 From: Stephen Halter Date: Tue, 22 May 2018 16:38:21 -0700 Subject: [PATCH] Consistently handle connection resets (#2547) --- .../Internal/ConnectionDispatcher.cs | 4 - src/Kestrel.Core/Internal/HttpConnection.cs | 5 + .../Internal/LibuvConnection.cs | 81 ++++--- .../Internal/LibuvConstants.cs | 65 +++++- .../Internal/LibuvOutputConsumer.cs | 6 +- .../Internal/Listener.cs | 5 + .../Internal/ListenerContext.cs | 21 +- .../Internal/ListenerSecondary.cs | 14 +- .../Internal/SocketConnection.cs | 37 +++- .../SocketTransport.cs | 9 +- .../Http1ConnectionTests.cs | 6 +- .../Http2ConnectionTests.cs | 8 +- test/Kestrel.Core.Tests/KestrelServerTests.cs | 8 +- test/Kestrel.Core.Tests/MessageBodyTests.cs | 2 +- .../ConnectionLimitTests.cs | 8 +- .../EventSourceTests.cs | 2 +- .../HttpProtocolSelectionTests.cs | 2 +- test/Kestrel.FunctionalTests/HttpsTests.cs | 10 +- .../LoggingConnectionAdapterTests.cs | 2 +- test/Kestrel.FunctionalTests/RequestTests.cs | 57 ++--- test/Kestrel.FunctionalTests/ResponseTests.cs | 202 +++++++++++------- .../HostNameIsReachableAttribute.cs | 2 +- test/Kestrel.FunctionalTests/UpgradeTests.cs | 14 +- .../LibuvConnectionTests.cs | 12 +- .../LibuvOutputConsumerTests.cs | 8 +- test/shared/TaskTimeoutExtensions.cs | 20 ++ test/shared/TestConnection.cs | 10 +- 27 files changed, 405 insertions(+), 215 deletions(-) create mode 100644 test/shared/TaskTimeoutExtensions.cs diff --git a/src/Kestrel.Core/Internal/ConnectionDispatcher.cs b/src/Kestrel.Core/Internal/ConnectionDispatcher.cs index 09c9c08df9..90aedba443 100644 --- a/src/Kestrel.Core/Internal/ConnectionDispatcher.cs +++ b/src/Kestrel.Core/Internal/ConnectionDispatcher.cs @@ -51,8 +51,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal { using (BeginConnectionScope(connectionContext)) { - Log.ConnectionStart(connectionContext.ConnectionId); - try { await _connectionDelegate(connectionContext); @@ -61,8 +59,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal { Log.LogCritical(0, ex, $"{nameof(ConnectionDispatcher)}.{nameof(Execute)}() {connectionContext.ConnectionId}"); } - - Log.ConnectionStop(connectionContext.ConnectionId); } } diff --git a/src/Kestrel.Core/Internal/HttpConnection.cs b/src/Kestrel.Core/Internal/HttpConnection.cs index c53c66d16a..54201f30ce 100644 --- a/src/Kestrel.Core/Internal/HttpConnection.cs +++ b/src/Kestrel.Core/Internal/HttpConnection.cs @@ -105,6 +105,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal { try { + // TODO: When we start tracking all connection middleware for shutdown, go back + // to logging connections tart and stop in ConnectionDispatcher so we get these + // logs for all connection middleware. + Log.ConnectionStart(ConnectionId); KestrelEventSource.Log.ConnectionStart(this); AdaptedPipeline adaptedPipeline = null; @@ -196,6 +200,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal _context.ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne(); } + Log.ConnectionStop(ConnectionId); KestrelEventSource.Log.ConnectionStop(this); } } diff --git a/src/Kestrel.Transport.Libuv/Internal/LibuvConnection.cs b/src/Kestrel.Transport.Libuv/Internal/LibuvConnection.cs index db18aed00b..a01b019b9d 100644 --- a/src/Kestrel.Transport.Libuv/Internal/LibuvConnection.cs +++ b/src/Kestrel.Transport.Libuv/Internal/LibuvConnection.cs @@ -5,6 +5,7 @@ using System; using System.Buffers; using System.IO; using System.IO.Pipelines; +using System.Net; using System.Threading; using System.Threading.Tasks; using Microsoft.AspNetCore.Connections; @@ -29,24 +30,17 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal private MemoryHandle _bufferHandle; - public LibuvConnection(UvStreamHandle socket, ILibuvTrace log, LibuvThread thread) + public LibuvConnection(UvStreamHandle socket, ILibuvTrace log, LibuvThread thread, IPEndPoint remoteEndPoint, IPEndPoint localEndPoint) { _socket = socket; - if (_socket is UvTcpHandle tcpHandle) - { - var remoteEndPoint = tcpHandle.GetPeerIPEndPoint(); - var localEndPoint = tcpHandle.GetSockIPEndPoint(); + RemoteAddress = remoteEndPoint?.Address; + RemotePort = remoteEndPoint?.Port ?? 0; - RemoteAddress = remoteEndPoint.Address; - RemotePort = remoteEndPoint.Port; - - LocalAddress = localEndPoint.Address; - LocalPort = localEndPoint.Port; - - ConnectionClosed = _connectionClosedTokenSource.Token; - } + LocalAddress = localEndPoint?.Address; + LocalPort = localEndPoint?.Port ?? 0; + ConnectionClosed = _connectionClosedTokenSource.Token; Log = log; Thread = thread; } @@ -68,7 +62,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal StartReading(); - Exception error = null; + Exception inputError = null; + Exception outputError = null; try { @@ -79,13 +74,27 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal } catch (UvException ex) { - error = new IOException(ex.Message, ex); + // The connection reset/error has already been logged by LibuvOutputConsumer + if (ex.StatusCode == LibuvConstants.ECANCELED) + { + // Connection was aborted. + } + else if (LibuvConstants.IsConnectionReset(ex.StatusCode)) + { + // Don't cause writes to throw for connection resets. + inputError = new ConnectionResetException(ex.Message, ex); + } + else + { + inputError = ex; + outputError = ex; + } } finally { // Now, complete the input so that no more reads can happen - Input.Complete(error ?? new ConnectionAbortedException()); - Output.Complete(error); + Input.Complete(inputError ?? new ConnectionAbortedException()); + Output.Complete(outputError); // Make sure it isn't possible for a paused read to resume reading after calling uv_close // on the stream handle @@ -164,7 +173,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal // Given a negative status, it's possible that OnAlloc wasn't called. _socket.ReadStop(); - IOException error = null; + Exception error = null; if (status == LibuvConstants.EOF) { @@ -173,18 +182,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal else { handle.Libuv.Check(status, out var uvError); - - // Log connection resets at a lower (Debug) level. - if (LibuvConstants.IsConnectionReset(status)) - { - Log.ConnectionReset(ConnectionId); - error = new ConnectionResetException(uvError.Message, uvError); - } - else - { - Log.ConnectionError(ConnectionId, uvError); - error = new IOException(uvError.Message, uvError); - } + error = LogAndWrapReadError(uvError); } // Complete after aborting the connection @@ -217,10 +215,27 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal { // ReadStart() can throw a UvException in some cases (e.g. socket is no longer connected). // This should be treated the same as OnRead() seeing a negative status. - Log.ConnectionReadFin(ConnectionId); - var error = new IOException(ex.Message, ex); + Input.Complete(LogAndWrapReadError(ex)); + } + } - Input.Complete(error); + private Exception LogAndWrapReadError(UvException uvError) + { + if (uvError.StatusCode == LibuvConstants.ECANCELED) + { + // The operation was canceled by the server not the client. No need for additional logs. + return new ConnectionAbortedException(uvError.Message, uvError); + } + else if (LibuvConstants.IsConnectionReset(uvError.StatusCode)) + { + // Log connection resets at a lower (Debug) level. + Log.ConnectionReset(ConnectionId); + return new ConnectionResetException(uvError.Message, uvError); + } + else + { + Log.ConnectionError(ConnectionId, uvError); + return new IOException(uvError.Message, uvError); } } diff --git a/src/Kestrel.Transport.Libuv/Internal/LibuvConstants.cs b/src/Kestrel.Transport.Libuv/Internal/LibuvConstants.cs index 650700ec00..d1657b63b8 100644 --- a/src/Kestrel.Transport.Libuv/Internal/LibuvConstants.cs +++ b/src/Kestrel.Transport.Libuv/Internal/LibuvConstants.cs @@ -15,11 +15,14 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal public static readonly int? EADDRINUSE = GetEADDRINUSE(); public static readonly int? ENOTSUP = GetENOTSUP(); public static readonly int? EPIPE = GetEPIPE(); + public static readonly int? ECANCELED = GetECANCELED(); + public static readonly int? ENOTCONN = GetENOTCONN(); + public static readonly int? EINVAL = GetEINVAL(); [MethodImpl(MethodImplOptions.AggressiveInlining)] public static bool IsConnectionReset(int errno) { - return errno == ECONNRESET || errno == EPIPE; + return errno == ECONNRESET || errno == EPIPE || errno == ENOTCONN | errno == EINVAL; } private static int? GetECONNRESET() @@ -41,11 +44,52 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal private static int? GetEPIPE() { - if (RuntimeInformation.IsOSPlatform(OSPlatform.Linux)) + if (RuntimeInformation.IsOSPlatform(OSPlatform.Windows)) + { + return -4047; + } + else if (RuntimeInformation.IsOSPlatform(OSPlatform.Linux)) { return -32; } + else if (RuntimeInformation.IsOSPlatform(OSPlatform.OSX)) + { + return -32; + } + return null; + } + private static int? GetENOTCONN() + { + if (RuntimeInformation.IsOSPlatform(OSPlatform.Windows)) + { + return -4053; + } + else if (RuntimeInformation.IsOSPlatform(OSPlatform.Linux)) + { + return -107; + } + else if (RuntimeInformation.IsOSPlatform(OSPlatform.OSX)) + { + return -57; + } + return null; + } + + private static int? GetEINVAL() + { + if (RuntimeInformation.IsOSPlatform(OSPlatform.Windows)) + { + return -4071; + } + else if (RuntimeInformation.IsOSPlatform(OSPlatform.Linux)) + { + return -22; + } + else if (RuntimeInformation.IsOSPlatform(OSPlatform.OSX)) + { + return -22; + } return null; } @@ -78,5 +122,22 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal } return null; } + + private static int? GetECANCELED() + { + if (RuntimeInformation.IsOSPlatform(OSPlatform.Windows)) + { + return -4081; + } + else if (RuntimeInformation.IsOSPlatform(OSPlatform.Linux)) + { + return -125; + } + else if (RuntimeInformation.IsOSPlatform(OSPlatform.OSX)) + { + return -89; + } + return null; + } } } diff --git a/src/Kestrel.Transport.Libuv/Internal/LibuvOutputConsumer.cs b/src/Kestrel.Transport.Libuv/Internal/LibuvOutputConsumer.cs index 94195a3ffc..1482bd3359 100644 --- a/src/Kestrel.Transport.Libuv/Internal/LibuvOutputConsumer.cs +++ b/src/Kestrel.Transport.Libuv/Internal/LibuvOutputConsumer.cs @@ -120,7 +120,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal else { // Log connection resets at a lower (Debug) level. - if (LibuvConstants.IsConnectionReset(status)) + if (status == LibuvConstants.ECANCELED) + { + // Connection was aborted. + } + else if (LibuvConstants.IsConnectionReset(status)) { _log.ConnectionReset(_connectionId); } diff --git a/src/Kestrel.Transport.Libuv/Internal/Listener.cs b/src/Kestrel.Transport.Libuv/Internal/Listener.cs index c6e9e2b493..5a89ebe545 100644 --- a/src/Kestrel.Transport.Libuv/Internal/Listener.cs +++ b/src/Kestrel.Transport.Libuv/Internal/Listener.cs @@ -172,6 +172,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal listenSocket.Accept(acceptSocket); DispatchConnection(acceptSocket); } + catch (UvException ex) when (LibuvConstants.IsConnectionReset(ex.StatusCode)) + { + Log.ConnectionReset("(null)"); + acceptSocket?.Dispose(); + } catch (UvException ex) { Log.LogError(0, ex, "Listener.OnConnection"); diff --git a/src/Kestrel.Transport.Libuv/Internal/ListenerContext.cs b/src/Kestrel.Transport.Libuv/Internal/ListenerContext.cs index b8d5d7087e..1a822dec7b 100644 --- a/src/Kestrel.Transport.Libuv/Internal/ListenerContext.cs +++ b/src/Kestrel.Transport.Libuv/Internal/ListenerContext.cs @@ -2,6 +2,7 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; +using System.Net; using System.Threading.Tasks; using Microsoft.AspNetCore.Server.Kestrel.Transport.Abstractions.Internal; using Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal.Networking; @@ -44,7 +45,25 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal { try { - var connection = new LibuvConnection(socket, TransportContext.Log, Thread); + IPEndPoint remoteEndPoint = null; + IPEndPoint localEndPoint = null; + + if (socket is UvTcpHandle tcpHandle) + { + try + { + remoteEndPoint = tcpHandle.GetPeerIPEndPoint(); + localEndPoint = tcpHandle.GetSockIPEndPoint(); + } + catch (UvException ex) when (LibuvConstants.IsConnectionReset(ex.StatusCode)) + { + TransportContext.Log.ConnectionReset("(null)"); + socket.Dispose(); + return; + } + } + + var connection = new LibuvConnection(socket, TransportContext.Log, Thread, remoteEndPoint, localEndPoint); var middlewareTask = TransportContext.ConnectionDispatcher.OnConnection(connection); var transportTask = connection.Start(); diff --git a/src/Kestrel.Transport.Libuv/Internal/ListenerSecondary.cs b/src/Kestrel.Transport.Libuv/Internal/ListenerSecondary.cs index 7c265ad228..2ef1ec2a12 100644 --- a/src/Kestrel.Transport.Libuv/Internal/ListenerSecondary.cs +++ b/src/Kestrel.Transport.Libuv/Internal/ListenerSecondary.cs @@ -151,17 +151,21 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal try { DispatchPipe.Accept(acceptSocket); + + // REVIEW: This task should be tracked by the server for graceful shutdown + // Today it's handled specifically for http but not for aribitrary middleware + _ = HandleConnectionAsync(acceptSocket); + } + catch (UvException ex) when (LibuvConstants.IsConnectionReset(ex.StatusCode)) + { + Log.ConnectionReset("(null)"); + acceptSocket.Dispose(); } catch (UvException ex) { Log.LogError(0, ex, "DispatchPipe.Accept"); acceptSocket.Dispose(); - return; } - - // REVIEW: This task should be tracked by the server for graceful shutdown - // Today it's handled specifically for http but not for aribitrary middleware - _ = HandleConnectionAsync(acceptSocket); } private void FreeBuffer() diff --git a/src/Kestrel.Transport.Sockets/Internal/SocketConnection.cs b/src/Kestrel.Transport.Sockets/Internal/SocketConnection.cs index b59390ed71..7423b0d67a 100644 --- a/src/Kestrel.Transport.Sockets/Internal/SocketConnection.cs +++ b/src/Kestrel.Transport.Sockets/Internal/SocketConnection.cs @@ -105,15 +105,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal { await ProcessReceives(); } - catch (SocketException ex) when (ex.SocketErrorCode == SocketError.ConnectionReset) + catch (SocketException ex) when (IsConnectionResetError(ex.SocketErrorCode)) { - error = new ConnectionResetException(ex.Message, ex); - _trace.ConnectionReset(ConnectionId); + // A connection reset can be reported as SocketError.ConnectionAborted on Windows + if (!_aborted) + { + error = new ConnectionResetException(ex.Message, ex); + _trace.ConnectionReset(ConnectionId); + } } - catch (SocketException ex) when (ex.SocketErrorCode == SocketError.OperationAborted || - ex.SocketErrorCode == SocketError.ConnectionAborted || - ex.SocketErrorCode == SocketError.Interrupted || - ex.SocketErrorCode == SocketError.InvalidArgument) + catch (SocketException ex) when (IsConnectionAbortError(ex.SocketErrorCode)) { if (!_aborted) { @@ -197,7 +198,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal { await ProcessSends(); } - catch (SocketException ex) when (ex.SocketErrorCode == SocketError.OperationAborted) + catch (SocketException ex) when (IsConnectionResetError(ex.SocketErrorCode)) + { + // A connection reset can be reported as SocketError.ConnectionAborted on Windows + error = null; + _trace.ConnectionReset(ConnectionId); + } + catch (SocketException ex) when (IsConnectionAbortError(ex.SocketErrorCode)) { error = null; } @@ -293,5 +300,19 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal _trace.LogError(0, ex, $"Unexpected exception in {nameof(SocketConnection)}.{nameof(CancelConnectionClosedToken)}."); } } + + private static bool IsConnectionResetError(SocketError errorCode) + { + return errorCode == SocketError.ConnectionReset || + errorCode == SocketError.ConnectionAborted || + errorCode == SocketError.Shutdown; + } + + private static bool IsConnectionAbortError(SocketError errorCode) + { + return errorCode == SocketError.OperationAborted || + errorCode == SocketError.Interrupted || + errorCode == SocketError.InvalidArgument; + } } } diff --git a/src/Kestrel.Transport.Sockets/SocketTransport.cs b/src/Kestrel.Transport.Sockets/SocketTransport.cs index f3745e95a6..d410033816 100644 --- a/src/Kestrel.Transport.Sockets/SocketTransport.cs +++ b/src/Kestrel.Transport.Sockets/SocketTransport.cs @@ -159,18 +159,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets var connection = new SocketConnection(acceptSocket, _memoryPool, _schedulers[schedulerIndex], _trace); // REVIEW: This task should be tracked by the server for graceful shutdown - // Today it's handled specifically for http but not for aribitrary middleware + // Today it's handled specifically for http but not for arbitrary middleware _ = HandleConnectionAsync(connection); } - catch (SocketException ex) when (ex.SocketErrorCode == SocketError.ConnectionReset) + catch (SocketException) when (!_unbinding) { - // REVIEW: Should there be a separate log message for a connection reset this early? _trace.ConnectionReset(connectionId: "(null)"); } - catch (SocketException ex) when (!_unbinding) - { - _trace.ConnectionError(connectionId: "(null)", ex); - } } } } diff --git a/test/Kestrel.Core.Tests/Http1ConnectionTests.cs b/test/Kestrel.Core.Tests/Http1ConnectionTests.cs index b1dc3b91aa..d5237fb3e9 100644 --- a/test/Kestrel.Core.Tests/Http1ConnectionTests.cs +++ b/test/Kestrel.Core.Tests/Http1ConnectionTests.cs @@ -596,7 +596,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests _http1Connection.StopProcessingNextRequest(); Assert.IsNotType>(requestProcessingTask); - await requestProcessingTask.TimeoutAfter(TestConstants.DefaultTimeout); + await requestProcessingTask.DefaultTimeout(); _application.Output.Complete(); } @@ -732,7 +732,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests Assert.Equal(header0Count + header1Count, _http1Connection.RequestHeaders.Count); await _application.Output.WriteAsync(Encoding.ASCII.GetBytes("\r\n")); - await requestProcessingTask.TimeoutAfter(TestConstants.DefaultTimeout); + await requestProcessingTask.DefaultTimeout(); } [Theory] @@ -809,7 +809,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests var data = Encoding.ASCII.GetBytes("POST / HTTP/1.1\r\nHost:\r\nConnection: close\r\ncontent-length: 1\r\n\r\n"); await _application.Output.WriteAsync(data); - await requestProcessingTask.TimeoutAfter(TestConstants.DefaultTimeout); + await requestProcessingTask.DefaultTimeout(); mockMessageBody.Verify(body => body.ConsumeAsync(), Times.Once); } diff --git a/test/Kestrel.Core.Tests/Http2ConnectionTests.cs b/test/Kestrel.Core.Tests/Http2ConnectionTests.cs index 43cd9078d2..c4836e60b7 100644 --- a/test/Kestrel.Core.Tests/Http2ConnectionTests.cs +++ b/test/Kestrel.Core.Tests/Http2ConnectionTests.cs @@ -213,7 +213,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests sem.Release(); }); - await sem.WaitAsync().TimeoutAfter(TestConstants.DefaultTimeout); + await sem.WaitAsync().DefaultTimeout(); }; _largeHeadersApplication = context => @@ -241,7 +241,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests sem.Release(); }); - await sem.WaitAsync().TimeoutAfter(TestConstants.DefaultTimeout); + await sem.WaitAsync().DefaultTimeout(); _runningStreams[streamIdFeature.StreamId].TrySetResult(null); }; @@ -261,7 +261,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests sem.Release(); }); - await sem.WaitAsync().TimeoutAfter(TestConstants.DefaultTimeout); + await sem.WaitAsync().DefaultTimeout(); await context.Response.Body.FlushAsync(); @@ -2463,7 +2463,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests private Task WaitForAllStreamsAsync() { - return Task.WhenAll(_runningStreams.Values.Select(tcs => tcs.Task)).TimeoutAfter(TestConstants.DefaultTimeout); + return Task.WhenAll(_runningStreams.Values.Select(tcs => tcs.Task)).DefaultTimeout(); } private Task SendAsync(ReadOnlySpan span) diff --git a/test/Kestrel.Core.Tests/KestrelServerTests.cs b/test/Kestrel.Core.Tests/KestrelServerTests.cs index 16e1ce179d..5ac0fbd5cd 100644 --- a/test/Kestrel.Core.Tests/KestrelServerTests.cs +++ b/test/Kestrel.Core.Tests/KestrelServerTests.cs @@ -263,7 +263,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests unbind.Release(); stop.Release(); - await Task.WhenAll(new[] { stopTask1, stopTask2, stopTask3 }).TimeoutAfter(TestConstants.DefaultTimeout); + await Task.WhenAll(new[] { stopTask1, stopTask2, stopTask3 }).DefaultTimeout(); mockTransport.Verify(transport => transport.UnbindAsync(), Times.Once); mockTransport.Verify(transport => transport.StopAsync(), Times.Once); @@ -377,9 +377,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests unbindTcs.SetResult(null); // If stopTask2 is completed inline by the first call to StopAsync, stopTask1 will never complete. - await stopTask1.TimeoutAfter(TestConstants.DefaultTimeout); - await stopTask2.TimeoutAfter(TestConstants.DefaultTimeout); - await continuationTask.TimeoutAfter(TestConstants.DefaultTimeout); + await stopTask1.DefaultTimeout(); + await stopTask2.DefaultTimeout(); + await continuationTask.DefaultTimeout(); mockTransport.Verify(transport => transport.UnbindAsync(), Times.Once); } diff --git a/test/Kestrel.Core.Tests/MessageBodyTests.cs b/test/Kestrel.Core.Tests/MessageBodyTests.cs index b92f429400..4b6792894c 100644 --- a/test/Kestrel.Core.Tests/MessageBodyTests.cs +++ b/test/Kestrel.Core.Tests/MessageBodyTests.cs @@ -148,7 +148,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests input.Add("\r\r\r\nHello\r\n0\r\n\r\n"); - Assert.Equal(5, await readTask.TimeoutAfter(TestConstants.DefaultTimeout)); + Assert.Equal(5, await readTask.DefaultTimeout()); Assert.Equal(0, await stream.ReadAsync(buffer, 0, buffer.Length)); await body.StopAsync(); diff --git a/test/Kestrel.FunctionalTests/ConnectionLimitTests.cs b/test/Kestrel.FunctionalTests/ConnectionLimitTests.cs index 1a93a8d5c8..3e4fb75822 100644 --- a/test/Kestrel.FunctionalTests/ConnectionLimitTests.cs +++ b/test/Kestrel.FunctionalTests/ConnectionLimitTests.cs @@ -39,11 +39,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests { await connection.SendEmptyGetAsKeepAlive(); ; await connection.Receive("HTTP/1.1 200 OK"); - Assert.True(await lockedTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout)); + Assert.True(await lockedTcs.Task.DefaultTimeout()); requestTcs.TrySetResult(null); } - await releasedTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await releasedTcs.Task.DefaultTimeout(); } [Fact] @@ -87,7 +87,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests catch { } // connection should close without sending any data - await rejected.WaitForConnectionClose().TimeoutAfter(TestConstants.DefaultTimeout); + await rejected.WaitForConnectionClose().DefaultTimeout(); } } } @@ -127,7 +127,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests catch { } // connection should close without sending any data - await connection.WaitForConnectionClose().TimeoutAfter(TestConstants.DefaultTimeout); + await connection.WaitForConnectionClose().DefaultTimeout(); } } diff --git a/test/Kestrel.FunctionalTests/EventSourceTests.cs b/test/Kestrel.FunctionalTests/EventSourceTests.cs index 9d776a4bdd..299c530ec6 100644 --- a/test/Kestrel.FunctionalTests/EventSourceTests.cs +++ b/test/Kestrel.FunctionalTests/EventSourceTests.cs @@ -44,7 +44,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "Host:", "", "") - .TimeoutAfter(TestConstants.DefaultTimeout); + .DefaultTimeout(); await connection.Receive("HTTP/1.1 200"); } } diff --git a/test/Kestrel.FunctionalTests/HttpProtocolSelectionTests.cs b/test/Kestrel.FunctionalTests/HttpProtocolSelectionTests.cs index c5e4f34fbd..e7bdaadcbf 100644 --- a/test/Kestrel.FunctionalTests/HttpProtocolSelectionTests.cs +++ b/test/Kestrel.FunctionalTests/HttpProtocolSelectionTests.cs @@ -85,7 +85,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests using (var connection = new TestConnection(host.GetPort())) { - await connection.WaitForConnectionClose().TimeoutAfter(TestConstants.DefaultTimeout); + await connection.WaitForConnectionClose().DefaultTimeout(); } } diff --git a/test/Kestrel.FunctionalTests/HttpsTests.cs b/test/Kestrel.FunctionalTests/HttpsTests.cs index 30ae3470ed..8ca3718481 100644 --- a/test/Kestrel.FunctionalTests/HttpsTests.cs +++ b/test/Kestrel.FunctionalTests/HttpsTests.cs @@ -141,7 +141,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests // Close socket immediately } - await loggerProvider.FilterLogger.LogTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await loggerProvider.FilterLogger.LogTcs.Task.DefaultTimeout(); } Assert.Equal(1, loggerProvider.FilterLogger.LastEventId.Id); @@ -178,7 +178,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests await stream.WriteAsync(new byte[10], 0, 10); } - await loggerProvider.FilterLogger.LogTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await loggerProvider.FilterLogger.LogTcs.Task.DefaultTimeout(); } Assert.Equal(1, loggerProvider.FilterLogger.LastEventId.Id); @@ -307,7 +307,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } } - await tcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await tcs.Task.DefaultTimeout(); } // Regression test for https://github.com/aspnet/KestrelHttpServer/issues/1693 @@ -406,11 +406,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests using (var stream = new NetworkStream(socket, ownsSocket: false)) { // No data should be sent and the connection should be closed in well under 30 seconds. - Assert.Equal(0, await stream.ReadAsync(new byte[1], 0, 1).TimeoutAfter(TestConstants.DefaultTimeout)); + Assert.Equal(0, await stream.ReadAsync(new byte[1], 0, 1).DefaultTimeout()); } } - await loggerProvider.FilterLogger.LogTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await loggerProvider.FilterLogger.LogTcs.Task.DefaultTimeout(); Assert.Equal(2, loggerProvider.FilterLogger.LastEventId); Assert.Equal(LogLevel.Debug, loggerProvider.FilterLogger.LastLogLevel); } diff --git a/test/Kestrel.FunctionalTests/LoggingConnectionAdapterTests.cs b/test/Kestrel.FunctionalTests/LoggingConnectionAdapterTests.cs index df211ed170..728d9a16fb 100644 --- a/test/Kestrel.FunctionalTests/LoggingConnectionAdapterTests.cs +++ b/test/Kestrel.FunctionalTests/LoggingConnectionAdapterTests.cs @@ -44,7 +44,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests await host.StartAsync(); var response = await HttpClientSlim.GetStringAsync($"https://localhost:{host.GetPort()}/", validateCertificate: false) - .TimeoutAfter(TimeSpan.FromSeconds(10)); + .DefaultTimeout(); Assert.Equal("Hello World!", response); } diff --git a/test/Kestrel.FunctionalTests/RequestTests.cs b/test/Kestrel.FunctionalTests/RequestTests.cs index 568f13e299..05d7d51a7a 100644 --- a/test/Kestrel.FunctionalTests/RequestTests.cs +++ b/test/Kestrel.FunctionalTests/RequestTests.cs @@ -312,8 +312,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests // Wait until connection is established Assert.True(await connectionStarted.WaitAsync(TestConstants.DefaultTimeout)); - // Force a reset - connection.Socket.LingerState = new LingerOption(true, 0); + connection.Reset(); } // If the reset is correctly logged as Debug, the wait below should complete shortly. @@ -381,8 +380,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "", ""); + connection.Reset(); // Force a reset - connection.Socket.LingerState = new LingerOption(true, 0); } // If the reset is correctly logged as Debug, the wait below should complete shortly. @@ -450,8 +449,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests // Wait until connection is established Assert.True(await requestStarted.WaitAsync(TestConstants.DefaultTimeout), "request should have started"); - // Force a reset - connection.Socket.LingerState = new LingerOption(true, 0); + connection.Reset(); } // If the reset is correctly logged as Debug, the wait below should complete shortly. @@ -528,7 +526,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests var token = context.RequestAborted; token.Register(() => requestAborted.Release(2)); - await requestAborted.WaitAsync().TimeoutAfter(TestConstants.DefaultTimeout); + await requestAborted.WaitAsync().DefaultTimeout(); })); using (var host = builder.Build()) @@ -541,7 +539,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests socket.Send(Encoding.ASCII.GetBytes("GET / HTTP/1.1\r\nHost:\r\n\r\n")); await appStarted.WaitAsync(); socket.Shutdown(SocketShutdown.Send); - await requestAborted.WaitAsync().TimeoutAfter(TestConstants.DefaultTimeout); + await requestAborted.WaitAsync().DefaultTimeout(); } } } @@ -578,8 +576,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests public async Task ConnectionClosedTokenFiresOnClientFIN(ListenOptions listenOptions) { var testContext = new TestServiceContext(LoggerFactory); - var appStartedTcs = new TaskCompletionSource(); - var connectionClosedTcs = new TaskCompletionSource(); + var appStartedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var connectionClosedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); using (var server = new TestServer(context => { @@ -599,11 +597,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "", ""); - await appStartedTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await appStartedTcs.Task.DefaultTimeout(); - connection.Socket.Shutdown(SocketShutdown.Send); + connection.Shutdown(SocketShutdown.Send); - await connectionClosedTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await connectionClosedTcs.Task.DefaultTimeout(); } } } @@ -613,7 +611,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests public async Task ConnectionClosedTokenFiresOnServerFIN(ListenOptions listenOptions) { var testContext = new TestServiceContext(LoggerFactory); - var connectionClosedTcs = new TaskCompletionSource(); + var connectionClosedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); using (var server = new TestServer(context => { @@ -632,7 +630,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "", ""); - await connectionClosedTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await connectionClosedTcs.Task.DefaultTimeout(); await connection.ReceiveEnd($"HTTP/1.1 200 OK", "Connection: close", @@ -649,7 +647,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests public async Task ConnectionClosedTokenFiresOnServerAbort(ListenOptions listenOptions) { var testContext = new TestServiceContext(LoggerFactory); - var connectionClosedTcs = new TaskCompletionSource(); + var connectionClosedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); using (var server = new TestServer(context => { @@ -669,7 +667,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "", ""); - await connectionClosedTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await connectionClosedTcs.Task.DefaultTimeout(); await connection.ReceiveForcedEnd(); } } @@ -728,9 +726,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "", "4", "Done") - .TimeoutAfter(TestConstants.DefaultTimeout); + .DefaultTimeout(); - await Task.WhenAll(pathTcs.Task, rawTargetTcs.Task, queryTcs.Task).TimeoutAfter(TestConstants.DefaultTimeout); + await Task.WhenAll(pathTcs.Task, rawTargetTcs.Task, queryTcs.Task).DefaultTimeout(); Assert.Equal(new PathString(expectedPath), pathTcs.Task.Result); Assert.Equal(requestUrl, rawTargetTcs.Task.Result); if (queryValue == null) @@ -756,7 +754,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests }, new TestServiceContext(LoggerFactory))) { var requestId = await HttpClientSlim.GetStringAsync($"http://{server.EndPoint}") - .TimeoutAfter(TestConstants.DefaultTimeout); + .DefaultTimeout(); Assert.Equal(knownId, requestId); } } @@ -797,7 +795,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests $"Date: {server.Context.DateHeaderValue}", $"Content-Length: {identifierLength}", "", - "").TimeoutAfter(TestConstants.DefaultTimeout); + "").DefaultTimeout(); var read = await connection.Reader.ReadAsync(buffer, 0, identifierLength); Assert.Equal(identifierLength, read); @@ -1058,7 +1056,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests using (var server = new TestServer(async httpContext => { // This will hang if 0 content length is not assumed by the server - Assert.Equal(0, await httpContext.Request.Body.ReadAsync(new byte[1], 0, 1).TimeoutAfter(TestConstants.DefaultTimeout)); + Assert.Equal(0, await httpContext.Request.Body.ReadAsync(new byte[1], 0, 1).DefaultTimeout()); }, testContext, listenOptions)) { using (var connection = server.CreateConnection()) @@ -1291,12 +1289,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests var ignore = connection.Stream.WriteAsync(scratchBuffer, 0, scratchBuffer.Length); // Wait until the read callback is no longer hooked up so that the connection disconnect isn't observed. - await readCallbackUnwired.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await readCallbackUnwired.Task.DefaultTimeout(); } clientClosedConnection.SetResult(null); - await appFuncCompleted.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await appFuncCompleted.Task.DefaultTimeout(); } mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny()), Times.Once()); @@ -1306,7 +1304,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests [MemberData(nameof(ConnectionAdapterData))] public async Task AppCanHandleClientAbortingConnectionMidRequest(ListenOptions listenOptions) { - var readTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var readTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var appStartedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var mockKestrelTrace = new Mock(Logger) { CallBase = true }; var testContext = new TestServiceContext() @@ -1318,6 +1317,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests using (var server = new TestServer(async context => { + appStartedTcs.SetResult(null); + try { await context.Request.Body.CopyToAsync(Stream.Null);; @@ -1341,10 +1342,14 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "", ""); + await appStartedTcs.Task.DefaultTimeout(); + await connection.Stream.WriteAsync(scratchBuffer, 0, scratchBuffer.Length); + + connection.Reset(); } - await Assert.ThrowsAnyAsync(() => readTcs.Task).TimeoutAfter(TestConstants.DefaultTimeout); + await Assert.ThrowsAnyAsync(() => readTcs.Task).DefaultTimeout(); } mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny()), Times.Once()); @@ -1418,7 +1423,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests var read = 0; while (read < message.Length) { - read += await duplexStream.ReadAsync(buffer, read, buffer.Length - read).TimeoutAfter(TestConstants.DefaultTimeout); + read += await duplexStream.ReadAsync(buffer, read, buffer.Length - read).DefaultTimeout(); } await duplexStream.WriteAsync(buffer, 0, read); diff --git a/test/Kestrel.FunctionalTests/ResponseTests.cs b/test/Kestrel.FunctionalTests/ResponseTests.cs index d0d7c4e986..99e2113b6c 100644 --- a/test/Kestrel.FunctionalTests/ResponseTests.cs +++ b/test/Kestrel.FunctionalTests/ResponseTests.cs @@ -33,7 +33,6 @@ using Microsoft.Extensions.Logging.Testing; using Microsoft.Extensions.Primitives; using Moq; using Xunit; -using Xunit.Abstractions; namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests { @@ -177,7 +176,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests Assert.Equal(HttpStatusCode.InternalServerError, response.StatusCode); Assert.False(onStartingCalled); - await onCompletedTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await onCompletedTcs.Task.DefaultTimeout(); } } } @@ -404,7 +403,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } } - await onCompletedTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await onCompletedTcs.Task.DefaultTimeout(); } private static async Task ResponseStatusCodeSetBeforeHttpContextDispose( @@ -480,7 +479,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } } - var disposedStatusCode = await disposedTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + var disposedStatusCode = await disposedTcs.Task.DefaultTimeout(); Assert.Equal(expectedServerStatusCode, (HttpStatusCode)disposedStatusCode); } @@ -648,7 +647,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests // Wait for message to be logged before disposing the socket. // Disposing the socket will abort the connection and HttpProtocol._requestAborted // might be 1 by the time ProduceEnd() gets called and the message is logged. - await logTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await logTcs.Task.DefaultTimeout(); } } @@ -686,7 +685,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "", "hello,"); - await connection.WaitForConnectionClose().TimeoutAfter(TestConstants.DefaultTimeout); + await connection.WaitForConnectionClose().DefaultTimeout(); } } @@ -844,10 +843,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "hello, world"); // Wait for error message to be logged. - await logTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await logTcs.Task.DefaultTimeout(); // The server should close the connection in this situation. - await connection.WaitForConnectionClose().TimeoutAfter(TestConstants.DefaultTimeout); + await connection.WaitForConnectionClose().DefaultTimeout(); } } @@ -1211,12 +1210,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests requestStarted.Wait(); connection.Shutdown(SocketShutdown.Send); - await connection.WaitForConnectionClose().TimeoutAfter(TestConstants.DefaultTimeout); + await connection.WaitForConnectionClose().DefaultTimeout(); } connectionClosed.Set(); - await tcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await tcs.Task.DefaultTimeout(); } } @@ -1250,7 +1249,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "Transfer-Encoding: chunked", "", "gg"); - await responseWritten.WaitAsync().TimeoutAfter(TestConstants.DefaultTimeout); + await responseWritten.WaitAsync().DefaultTimeout(); await connection.ReceiveEnd( "HTTP/1.1 400 Bad Request", $"Date: {server.Context.DateHeaderValue}", @@ -1861,7 +1860,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests using (var server = new TestServer(async httpContext => { - Assert.Equal(0, await httpContext.Request.Body.ReadAsync(new byte[1], 0, 1).TimeoutAfter(TestConstants.DefaultTimeout)); + Assert.Equal(0, await httpContext.Request.Body.ReadAsync(new byte[1], 0, 1).DefaultTimeout()); }, testContext, listenOptions)) { using (var connection = server.CreateConnection()) @@ -2322,7 +2321,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests // Write failed - can throw TaskCanceledException or OperationCanceledException, // dependending on how far the canceled write goes. - await Assert.ThrowsAnyAsync(async () => await writeTcs.Task).TimeoutAfter(TestConstants.DefaultTimeout); + await Assert.ThrowsAnyAsync(async () => await writeTcs.Task).DefaultTimeout(); // RequestAborted tripped Assert.True(requestAbortedWh.Wait(TestConstants.DefaultTimeout)); @@ -2339,7 +2338,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests var requestAborted = false; var readCallbackUnwired = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var clientClosedConnection = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var writeTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var writeTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var mockKestrelTrace = new Mock(Logger) { CallBase = true }; var mockLogger = new Mock(); @@ -2421,12 +2420,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests var ignore = connection.Stream.WriteAsync(scratchBuffer, 0, scratchBuffer.Length); // Wait until the read callback is no longer hooked up so that the connection disconnect isn't observed. - await readCallbackUnwired.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await readCallbackUnwired.Task.DefaultTimeout(); } clientClosedConnection.SetResult(null); - await Assert.ThrowsAnyAsync(() => writeTcs.Task).TimeoutAfter(TestConstants.DefaultTimeout); + await Assert.ThrowsAnyAsync(() => writeTcs.Task).DefaultTimeout(); } mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny()), Times.Once()); @@ -2437,18 +2436,15 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests [MemberData(nameof(ConnectionAdapterData))] public async Task AppCanHandleClientAbortingConnectionMidResponse(ListenOptions listenOptions) { + const int connectionResetEventId = 19; + const int connectionFinEventId = 6; + //const int connectionStopEventId = 2; + const int responseBodySegmentSize = 65536; const int responseBodySegmentCount = 100; - const int responseBodySize = responseBodySegmentSize * responseBodySegmentCount; - var requestAborted = false; var appCompletedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - - var mockKestrelTrace = new Mock(Logger) { CallBase = true }; - var testContext = new TestServiceContext() - { - Log = mockKestrelTrace.Object, - }; + var requestAborted = false; var scratchBuffer = new byte[responseBodySegmentSize]; @@ -2459,23 +2455,14 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests requestAborted = true; }); - context.Response.ContentLength = responseBodySize; - - try + for (var i = 0; i < responseBodySegmentCount; i++) { - for (var i = 0; i < responseBodySegmentCount; i++) - { - await context.Response.Body.WriteAsync(scratchBuffer, 0, scratchBuffer.Length); - await Task.Delay(10); - } + await context.Response.Body.WriteAsync(scratchBuffer, 0, scratchBuffer.Length); + await Task.Delay(10); } - finally - { - // WriteAsync shouldn't throw without a CancellationToken passed in. Unfortunately a ECONNRESET UvException sometimes gets thrown. - // This will be fixed by https://github.com/aspnet/KestrelHttpServer/pull/2547 - appCompletedTcs.SetResult(null); - } - }, testContext, listenOptions)) + + appCompletedTcs.SetResult(null); + }, new TestServiceContext(LoggerFactory), listenOptions)) { using (var connection = server.CreateConnection()) { @@ -2485,23 +2472,69 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "", ""); - var readCount = 0; - // Read just part of the response and close the connection. // https://github.com/aspnet/KestrelHttpServer/issues/2554 - for (var i = 0; i < responseBodySegmentCount / 10; i++) + await connection.Stream.ReadAsync(scratchBuffer, 0, scratchBuffer.Length); + + connection.Reset(); + } + + await appCompletedTcs.Task.DefaultTimeout(); + + // After the app is done with the write loop, the connection reset should be logged. + // On Linux and macOS, the connection close is still sometimes observed as a FIN despite the LingerState. + var presShutdownTransportLogs = TestSink.Writes.Where( + w => w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv" || + w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets"); + var connectionResetLogs = presShutdownTransportLogs.Where( + w => w.EventId == connectionResetEventId || + (!TestPlatformHelper.IsWindows && w.EventId == connectionFinEventId)); + + Assert.NotEmpty(connectionResetLogs); + } + + // TODO: Figure out what the following assertion is flaky. The server shouldn't shutdown before all + // the connections are closed, yet sometimes the connection stop log isn't observed here. + //var coreLogs = TestSink.Writes.Where(w => w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel"); + //Assert.Single(coreLogs.Where(w => w.EventId == connectionStopEventId)); + + Assert.True(requestAborted, "RequestAborted token didn't fire."); + + var transportLogs = TestSink.Writes.Where(w => w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv" || + w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets"); + Assert.Empty(transportLogs.Where(w => w.LogLevel > LogLevel.Debug)); + } + + [Theory] + [MemberData(nameof(ConnectionAdapterData))] + public async Task ClientAbortingConnectionImmediatelyIsNotLoggedHigherThanDebug(ListenOptions listenOptions) + { + // Attempt multiple connections to be extra sure the resets are consistently logged appropriately. + const int numConnections = 10; + + // There's not guarantee that the app even gets invoked in this test. The connection reset can be observed + // as early as accept. + using (var server = new TestServer(context => Task.CompletedTask, new TestServiceContext(LoggerFactory), listenOptions)) + { + for (var i = 0; i < numConnections; i++) + { + using (var connection = server.CreateConnection()) { - readCount += await connection.Stream.ReadAsync(scratchBuffer, 0, scratchBuffer.Length); + await connection.Send( + "GET / HTTP/1.1", + "Host:", + "", + ""); + + connection.Reset(); } - - connection.Socket.Shutdown(SocketShutdown.Send); - - await appCompletedTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); } } - mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny()), Times.Once()); - Assert.True(requestAborted); + var transportLogs = TestSink.Writes.Where(w => w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv" || + w.LoggerName == "Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets"); + + Assert.Empty(transportLogs.Where(w => w.LogLevel > LogLevel.Debug)); } [Theory] @@ -2655,7 +2688,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "hello, world"); // Wait for all callbacks to be called. - await onStartingTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await onStartingTcs.Task.DefaultTimeout(); } } @@ -2707,7 +2740,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests "hello, world"); // Wait for all callbacks to be called. - await onCompletedTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await onCompletedTcs.Task.DefaultTimeout(); } } @@ -2816,10 +2849,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests var responseSize = chunks * chunkSize; var chunkData = new byte[chunkSize]; - var responseRateTimeoutMessageLogged = new TaskCompletionSource(); - var connectionStopMessageLogged = new TaskCompletionSource(); - var requestAborted = new TaskCompletionSource(); - var appFuncCompleted = new TaskCompletionSource(); + var responseRateTimeoutMessageLogged = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var connectionStopMessageLogged = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var requestAborted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var appFuncCompleted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var mockKestrelTrace = new Mock(); mockKestrelTrace @@ -2885,10 +2918,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests var sw = Stopwatch.StartNew(); logger.LogInformation("Waiting for connection to abort."); - await requestAborted.Task.TimeoutAfter(TimeSpan.FromSeconds(60)); - await responseRateTimeoutMessageLogged.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); - await connectionStopMessageLogged.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); - await appFuncCompleted.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); + await requestAborted.Task.DefaultTimeout(); + await responseRateTimeoutMessageLogged.Task.DefaultTimeout(); + await connectionStopMessageLogged.Task.DefaultTimeout(); + await appFuncCompleted.Task.DefaultTimeout(); await AssertStreamAborted(connection.Reader.BaseStream, chunkSize * chunks); sw.Stop(); @@ -2907,10 +2940,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests var certificate = new X509Certificate2(TestResources.TestCertificatePath, "testPassword"); - var responseRateTimeoutMessageLogged = new TaskCompletionSource(); - var connectionStopMessageLogged = new TaskCompletionSource(); - var aborted = new TaskCompletionSource(); - var appFuncCompleted = new TaskCompletionSource(); + var responseRateTimeoutMessageLogged = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var connectionStopMessageLogged = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var aborted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var appFuncCompleted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var mockKestrelTrace = new Mock(); mockKestrelTrace @@ -2972,10 +3005,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests var request = Encoding.ASCII.GetBytes("GET / HTTP/1.1\r\nHost:\r\n\r\n"); await sslStream.WriteAsync(request, 0, request.Length); - await aborted.Task.TimeoutAfter(TimeSpan.FromSeconds(60)); - await responseRateTimeoutMessageLogged.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); - await connectionStopMessageLogged.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); - await appFuncCompleted.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); + await aborted.Task.DefaultTimeout(); + await responseRateTimeoutMessageLogged.Task.DefaultTimeout(); + await connectionStopMessageLogged.Task.DefaultTimeout(); + await appFuncCompleted.Task.DefaultTimeout(); // Temporary workaround for a deadlock when reading from an aborted client SslStream on Mac and Linux. if (TestPlatformHelper.IsWindows) @@ -2994,15 +3027,15 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests [Fact] public async Task ConnectionClosedWhenBothRequestAndResponseExperienceBackPressure() { - const int bufferSize = 1024; - const int bufferCount = 256 * 1024; + const int bufferSize = 65536; + const int bufferCount = 100; var responseSize = bufferCount * bufferSize; var buffer = new byte[bufferSize]; - var responseRateTimeoutMessageLogged = new TaskCompletionSource(); - var connectionStopMessageLogged = new TaskCompletionSource(); - var requestAborted = new TaskCompletionSource(); - var appFuncCompleted = new TaskCompletionSource(); + var responseRateTimeoutMessageLogged = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var connectionStopMessageLogged = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var requestAborted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var copyToAsyncCts = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var mockKestrelTrace = new Mock(); mockKestrelTrace @@ -3040,13 +3073,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests { await context.Request.Body.CopyToAsync(context.Response.Body); } - catch + catch (Exception ex) { - // This should always throw an OperationCanceledException. Unfortunately a ECONNRESET UvException sometimes gets thrown. - // This will be fixed by https://github.com/aspnet/KestrelHttpServer/pull/2547 - appFuncCompleted.SetResult(null); + copyToAsyncCts.SetException(ex); throw; } + + copyToAsyncCts.SetException(new Exception("This shouldn't be reached.")); } using (var server = new TestServer(App, testContext, listenOptions)) @@ -3066,13 +3099,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests for (var i = 0; i < bufferCount; i++) { await connection.Stream.WriteAsync(buffer, 0, buffer.Length); + await Task.Delay(10); } }); - await requestAborted.Task.TimeoutAfter(TimeSpan.FromSeconds(60)); - await responseRateTimeoutMessageLogged.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); - await connectionStopMessageLogged.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); - await appFuncCompleted.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); + await requestAborted.Task.DefaultTimeout(); + await responseRateTimeoutMessageLogged.Task.DefaultTimeout(); + await connectionStopMessageLogged.Task.DefaultTimeout(); + + // Expect OperationCanceledException instead of IOException because the server initiated the abort due to a response rate timeout. + await Assert.ThrowsAnyAsync(() => copyToAsyncCts.Task).DefaultTimeout(); await AssertStreamAborted(connection.Stream, responseSize); } } @@ -3136,7 +3172,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests // Make sure consuming a single chunk exceeds the 2 second timeout. var targetBytesPerSecond = chunkSize / 4; await AssertStreamCompleted(connection.Reader.BaseStream, minTotalOutputSize, targetBytesPerSecond); - await appFuncCompleted.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); + await appFuncCompleted.Task.DefaultTimeout(); mockKestrelTrace.Verify(t => t.ResponseMininumDataRateNotSatisfied(It.IsAny(), It.IsAny()), Times.Never()); mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny()), Times.Once()); @@ -3258,7 +3294,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests { while (totalReceived < totalBytes) { - var bytes = await stream.ReadAsync(receiveBuffer, 0, receiveBuffer.Length).TimeoutAfter(TimeSpan.FromSeconds(10)); + var bytes = await stream.ReadAsync(receiveBuffer, 0, receiveBuffer.Length).DefaultTimeout(); if (bytes == 0) { diff --git a/test/Kestrel.FunctionalTests/TestHelpers/HostNameIsReachableAttribute.cs b/test/Kestrel.FunctionalTests/TestHelpers/HostNameIsReachableAttribute.cs index bd120b6356..5a83bd7c3f 100644 --- a/test/Kestrel.FunctionalTests/TestHelpers/HostNameIsReachableAttribute.cs +++ b/test/Kestrel.FunctionalTests/TestHelpers/HostNameIsReachableAttribute.cs @@ -61,7 +61,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests public static async Task ConnectToHost(string hostName, int port) { - var tcs = new TaskCompletionSource(); + var tcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var socketArgs = new SocketAsyncEventArgs(); socketArgs.RemoteEndPoint = new DnsEndPoint(hostName, port); diff --git a/test/Kestrel.FunctionalTests/UpgradeTests.cs b/test/Kestrel.FunctionalTests/UpgradeTests.cs index d7a0f5073f..2b4027d37c 100644 --- a/test/Kestrel.FunctionalTests/UpgradeTests.cs +++ b/test/Kestrel.FunctionalTests/UpgradeTests.cs @@ -47,7 +47,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests ""); await connection.Receive("New protocol data"); - await upgrade.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await upgrade.Task.DefaultTimeout(); } } } @@ -67,7 +67,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests var stream = await feature.UpgradeAsync(); var buffer = new byte[128]; - var read = await context.Request.Body.ReadAsync(buffer, 0, 128).TimeoutAfter(TestConstants.DefaultTimeout); + var read = await context.Request.Body.ReadAsync(buffer, 0, 128).DefaultTimeout(); Assert.Equal(0, read); using (var reader = new StreamReader(stream)) @@ -101,7 +101,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests await connection.Send(send + "\r\n"); await connection.Receive(recv); - await upgrade.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await upgrade.Task.DefaultTimeout(); } } } @@ -138,10 +138,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests $"Date: {server.Context.DateHeaderValue}", "", ""); - await connection.WaitForConnectionClose().TimeoutAfter(TestConstants.DefaultTimeout); + await connection.WaitForConnectionClose().DefaultTimeout(); } - var ex = await Assert.ThrowsAsync(async () => await upgradeTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout)); + var ex = await Assert.ThrowsAsync(async () => await upgradeTcs.Task.DefaultTimeout()); Assert.Equal(CoreStrings.UpgradeCannotBeCalledMultipleTimes, ex.Message); } @@ -243,7 +243,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } } - var ex = await Assert.ThrowsAsync(async () => await upgradeTcs.Task).TimeoutAfter(TestConstants.DefaultTimeout); + var ex = await Assert.ThrowsAsync(async () => await upgradeTcs.Task).DefaultTimeout(); Assert.Equal(CoreStrings.CannotUpgradeNonUpgradableRequest, ex.Message); } @@ -331,7 +331,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests ""); } - await appCompletedTcs.Task.TimeoutAfter(TestConstants.DefaultTimeout); + await appCompletedTcs.Task.DefaultTimeout(); } } } diff --git a/test/Kestrel.Transport.Libuv.Tests/LibuvConnectionTests.cs b/test/Kestrel.Transport.Libuv.Tests/LibuvConnectionTests.cs index dd29e06b11..e44f5465b8 100644 --- a/test/Kestrel.Transport.Libuv.Tests/LibuvConnectionTests.cs +++ b/test/Kestrel.Transport.Libuv.Tests/LibuvConnectionTests.cs @@ -35,7 +35,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests Thread = thread }; var socket = new MockSocket(mockLibuv, Thread.CurrentThread.ManagedThreadId, transportContext.Log); - var connection = new LibuvConnection(socket, listenerContext.TransportContext.Log, thread); + var connection = new LibuvConnection(socket, listenerContext.TransportContext.Log, thread, null, null); listenerContext.TransportContext.ConnectionDispatcher.OnConnection(connection); connectionTask = connection.Start(); @@ -90,7 +90,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests Thread = thread }; var socket = new MockSocket(mockLibuv, Thread.CurrentThread.ManagedThreadId, transportContext.Log); - var connection = new LibuvConnection(socket, listenerContext.TransportContext.Log, thread); + var connection = new LibuvConnection(socket, listenerContext.TransportContext.Log, thread, null, null); listenerContext.TransportContext.ConnectionDispatcher.OnConnection(connection); connectionTask = connection.Start(); @@ -106,7 +106,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests // Now complete the output writer so that the connection closes mockConnectionDispatcher.Output.Writer.Complete(); - await connectionTask.TimeoutAfter(TestConstants.DefaultTimeout); + await connectionTask.DefaultTimeout(); // Assert that we don't try to start reading Assert.Null(mockLibuv.AllocCallback); @@ -159,7 +159,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests Thread = thread }; var socket = new MockSocket(mockLibuv, Thread.CurrentThread.ManagedThreadId, transportContext.Log); - var connection = new LibuvConnection(socket, listenerContext.TransportContext.Log, thread); + var connection = new LibuvConnection(socket, listenerContext.TransportContext.Log, thread, null, null); listenerContext.TransportContext.ConnectionDispatcher.OnConnection(connection); connectionTask = connection.Start(); @@ -191,7 +191,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests // Now complete the output writer and wait for the connection to close mockConnectionDispatcher.Output.Writer.Complete(); - await connectionTask.TimeoutAfter(TestConstants.DefaultTimeout); + await connectionTask.DefaultTimeout(); // Assert that we don't try to start reading Assert.Null(mockLibuv.AllocCallback); @@ -226,7 +226,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests Thread = thread }; var socket = new MockSocket(mockLibuv, Thread.CurrentThread.ManagedThreadId, transportContext.Log); - var connection = new LibuvConnection(socket, listenerContext.TransportContext.Log, thread); + var connection = new LibuvConnection(socket, listenerContext.TransportContext.Log, thread, null, null); listenerContext.TransportContext.ConnectionDispatcher.OnConnection(connection); connectionTask = connection.Start(); diff --git a/test/Kestrel.Transport.Libuv.Tests/LibuvOutputConsumerTests.cs b/test/Kestrel.Transport.Libuv.Tests/LibuvOutputConsumerTests.cs index e269bda59c..89a16caa0d 100644 --- a/test/Kestrel.Transport.Libuv.Tests/LibuvOutputConsumerTests.cs +++ b/test/Kestrel.Transport.Libuv.Tests/LibuvOutputConsumerTests.cs @@ -84,7 +84,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests var writeTask = outputProducer.WriteDataAsync(buffer); // Assert - await writeTask.TimeoutAfter(TestConstants.DefaultTimeout); + await writeTask.DefaultTimeout(); } } @@ -122,7 +122,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests var writeTask = outputProducer.WriteDataAsync(buffer); // Assert - await writeTask.TimeoutAfter(TestConstants.DefaultTimeout); + await writeTask.DefaultTimeout(); // Cleanup outputProducer.Dispose(); @@ -181,7 +181,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests await _libuvThread.PostAsync(cb => cb(0), triggerNextCompleted); // Assert - await writeTask.TimeoutAfter(TestConstants.DefaultTimeout); + await writeTask.DefaultTimeout(); // Cleanup outputProducer.Dispose(); @@ -245,7 +245,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests await _libuvThread.PostAsync(cb => cb(0), triggerNextCompleted); // Finishing the first write should allow the second write to pre-complete. - await writeTask2.TimeoutAfter(TestConstants.DefaultTimeout); + await writeTask2.DefaultTimeout(); // Cleanup outputProducer.Dispose(); diff --git a/test/shared/TaskTimeoutExtensions.cs b/test/shared/TaskTimeoutExtensions.cs new file mode 100644 index 0000000000..8e83a7a70e --- /dev/null +++ b/test/shared/TaskTimeoutExtensions.cs @@ -0,0 +1,20 @@ +// 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 Microsoft.AspNetCore.Testing; + +namespace System.Threading.Tasks +{ + public static class TaskTimeoutExtensions + { + public static Task DefaultTimeout(this Task task) + { + return task.TimeoutAfter(TestConstants.DefaultTimeout); + } + + public static Task DefaultTimeout(this Task task) + { + return task.TimeoutAfter(TestConstants.DefaultTimeout); + } + } +} diff --git a/test/shared/TestConnection.cs b/test/shared/TestConnection.cs index 4f65da6bcf..04e547214d 100644 --- a/test/shared/TestConnection.cs +++ b/test/shared/TestConnection.cs @@ -47,8 +47,6 @@ namespace Microsoft.AspNetCore.Testing _reader = new StreamReader(_stream, Encoding.ASCII); } - public Socket Socket => _socket; - public Stream Stream => _stream; public StreamReader Reader => _reader; @@ -215,9 +213,15 @@ namespace Microsoft.AspNetCore.Testing _socket.Shutdown(how); } + public void Reset() + { + _socket.LingerState = new LingerOption(true, 0); + _socket.Dispose(); + } + public Task WaitForConnectionClose() { - var tcs = new TaskCompletionSource(); + var tcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var eventArgs = new SocketAsyncEventArgs(); eventArgs.SetBuffer(new byte[128], 0, 128); eventArgs.Completed += ReceiveAsyncCompleted;