Flaky test: "AppCanHandleClientAbortingConnectionMidRequest"

[JunTaoLuo]

Build: https://dev.azure.com/dnceng/public/_build/results?buildId=861089&view=results

Error:

System.TimeoutException : The operation at /_/src/Servers/Kestrel/shared/test/TaskTimeoutExtensions.cs:22 timed out after reaching the limit of 30000ms.
   at Microsoft.AspNetCore.Testing.TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) in /_/src/Testing/src/TaskExtensions.cs:line 35
   at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.RequestTests.AppCanHandleClientAbortingConnectionMidRequest(ListenOptions listenOptions) in /_/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs:line 847
   at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.RequestTests.AppCanHandleClientAbortingConnectionMidRequest(ListenOptions listenOptions) in /_/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs:line 847
--- End of stack trace from previous location ---

[Tratcher]

It looks like the server never detected the disconnect.

[0.001s] [TestLifetime] [Information] Starting test AppCanHandleClientAbortingConnectionMidRequest-http_127.0.0.1_0 at 2020-10-21T13:12:11
[0.100s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting starting
[0.101s] [Microsoft.Hosting.Lifetime] [Information] Now listening on: http://127.0.0.1:50597
[0.101s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Debug] Loaded hosting startup assembly Sockets.FunctionalTests
[0.101s] [Microsoft.Hosting.Lifetime] [Information] Application started. Press Ctrl+C to shut down.
[0.101s] [Microsoft.Hosting.Lifetime] [Information] Hosting environment: Production
[0.101s] [Microsoft.Hosting.Lifetime] [Information] Content root path: /private/tmp/helix/working/A779099E/w/A67C0945/e/
[0.101s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting started
[0.102s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] TestServer is listening on port 50597
[0.103s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM3LOBKM5FFI" accepted.
[0.103s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM3LOBKM5FFI" started.
[0.104s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request starting HTTP/1.1 POST http:/// - 8192
[0.105s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM3LOBKM5FFI", Request id "0HM3LOBKM5FFI:00000002": started reading request body.
[30.133s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting stopping
[30.133s] [Microsoft.Hosting.Lifetime] [Information] Application is shutting down...
[60.149s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Some connections failed to close gracefully during server shutdown.
[60.151s] [Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets] [Debug] Connection id "0HM3LOBKM5FFI" sending FIN because: "The connection was aborted because the server is shutting down and request processing didn't complete within the time specified by HostOptions.ShutdownTimeout."
[60.152s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM3LOBKM5FFI" disconnecting.
[60.153s] [Microsoft.AspNetCore.Server.Kestrel] [Error] Connection id "0HM3LOBKM5FFI", Request id "0HM3LOBKM5FFI:00000002": An unhandled exception was thrown by the application.
System.Threading.Tasks.TaskCanceledException: The request was aborted
 ---> Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was aborted because the server is shutting down and request processing didn't complete within the time specified by HostOptions.ShutdownTimeout.
   at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1ContentLengthMessageBody.ReadAsyncInternal(CancellationToken cancellationToken) in /_/src/Servers/Kestrel/Core/src/Internal/Http/Http1ContentLengthMessageBody.cs:line 62
   --- End of inner exception stack trace ---
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1ContentLengthMessageBody.ReadAsyncInternal(CancellationToken cancellationToken) in /_/src/Servers/Kestrel/Core/src/Internal/Http/Http1ContentLengthMessageBody.cs:line 67
   at System.IO.Pipelines.PipeReader.CopyToAsyncCore[TStream](TStream destination, Func`4 writeAsync, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.RequestTests.<>c__DisplayClass21_0.<<AppCanHandleClientAbortingConnectionMidRequest>b__1>d.MoveNext() in /_/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs:line 819
--- End of stack trace from previous location ---
   at Xunit.Assert.RecordExceptionAsync(Func`1 testCode) in C:\Dev\xunit\xunit\src\xunit.assert\Asserts\Record.cs:line 81
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application) in /_/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs:line 662
[60.153s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request finished HTTP/1.1 POST http:/// - 8192 - 0 - - 60047.1630ms
[60.153s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM3LOBKM5FFI", Request id "0HM3LOBKM5FFI:00000002": done reading request body.
[60.153s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM3LOBKM5FFI" stopped.
[60.154s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting stopped
[60.155s] [TestLifetime] [Information] Finished test AppCanHandleClientAbortingConnectionMidRequest-http_127.0.0.1_0 in 60.1520932s

Thanks for contacting us.
We're moving this issue to the Next sprint planning milestone for future evaluation / consideration. We will evaluate the request when we are planning the work for the next milestone. To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

[jkotalik]

This test is only failing on OSX.1100.Amd64. We'd probably need to look into that specific OS build. It looks like the transport layer isn't seeing the connection reset at all:
Compare above to the expected logs:

[0.002s] [TestLifetime] [Information] Starting test AppCanHandleClientAbortingConnectionMidRequest-Loopback at 2021-01-26T18:38:17
[0.006s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting starting
[0.007s] [Microsoft.Hosting.Lifetime] [Information] Now listening on: http://127.0.0.1:60399
[0.007s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Debug] Loaded hosting startup assembly Sockets.FunctionalTests
[0.007s] [Microsoft.Hosting.Lifetime] [Information] Application started. Press Ctrl+C to shut down.
[0.007s] [Microsoft.Hosting.Lifetime] [Information] Hosting environment: Production
[0.007s] [Microsoft.Hosting.Lifetime] [Information] Content root path: /private/tmp/helix/working/C0280A3A/w/B6A409A4/e/
[0.007s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting started
[0.008s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] TestServer is listening on port 60399
[0.008s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM62565VTHSV" accepted.
[0.008s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM62565VTHSV" started.
[0.009s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request starting HTTP/1.1 POST http:/// - 8192
[0.024s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM62565VTHSV", Request id "0HM62565VTHSV:00000002": started reading request body.
[0.040s] [Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets] [Debug] Connection id "0HM62565VTHSV" reset.
[0.053s] [Microsoft.AspNetCore.Server.Kestrel] [Error] Connection id "0HM62565VTHSV", Request id "0HM62565VTHSV:00000002": An unhandled exception was thrown by the application.
Microsoft.AspNetCore.Connections.ConnectionResetException: Connection reset by peer
 ---> System.Net.Sockets.SocketException (54): Connection reset by peer
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketAwaitableEventArgs.<GetResult>g__ThrowSocketException|7_0(SocketError e) in /_/src/Servers/Kestrel/Transport.Sockets/src/Internal/SocketAwaitableEventArgs.cs:line 46
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketAwaitableEventArgs.GetResult() in /_/src/Servers/Kestrel/Transport.Sockets/src/Internal/SocketAwaitableEventArgs.cs:line 39
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection.ProcessReceives() in /_/src/Servers/Kestrel/Transport.Sockets/src/Internal/SocketConnection.cs:line 200
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection.DoReceive() in /_/src/Servers/Kestrel/Transport.Sockets/src/Internal/SocketConnection.cs:line 147
   --- End of inner exception stack trace ---
   at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1ContentLengthMessageBody.ReadAsyncInternal(CancellationToken cancellationToken) in /_/src/Servers/Kestrel/Core/src/Internal/Http/Http1ContentLengthMessageBody.cs:line 62
   at System.IO.Pipelines.PipeReader.CopyToAsyncCore[TStream](TStream destination, Func`4 writeAsync, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.RequestTests.<>c__DisplayClass24_0.<<AppCanHandleClientAbortingConnectionMidRequest>b__1>d.MoveNext() in /_/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs:line 825
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application) in /_/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs:line 663
[0.055s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM62565VTHSV" completed keep alive response.
[0.056s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Information] Request finished HTTP/1.1 POST http:/// - 8192 - 500 0 - 46.8959ms
[0.059s] [Microsoft.AspNetCore.Server.Kestrel] [Error] Connection id "0HM62565VTHSV", Request id "0HM62565VTHSV:00000002": An unhandled exception was thrown by the application.
Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was aborted by the application.
 ---> System.InvalidOperationException: Reading is already in progress.
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1ContentLengthMessageBody.TryReadInternal(ReadResult& readResult) in /_/src/Servers/Kestrel/Core/src/Internal/Http/Http1ContentLengthMessageBody.cs:line 121
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1MessageBody.OnConsumeAsync() in /_/src/Servers/Kestrel/Core/src/Internal/Http/Http1MessageBody.cs:line 53
   --- End of inner exception stack trace ---
[0.060s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM62565VTHSV", Request id "0HM62565VTHSV:00000002": done reading request body.
[0.061s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM62565VTHSV" disconnecting.
[0.062s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM62565VTHSV" stopped.
[0.065s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting stopping
[0.065s] [Microsoft.Hosting.Lifetime] [Information] Application is shutting down...
[0.066s] [Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets] [Debug] Connection id "0HM62565VTHSV" reset.
[0.066s] [Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets] [Debug] Connection id "0HM62565VTHSV" sending FIN because: "Broken pipe"
[0.068s] [Microsoft.Extensions.Hosting.Internal.Host] [Debug] Hosting stopped
[0.082s] [TestLifetime] [Information] Finished test AppCanHandleClientAbortingConnectionMidRequest-Loopback in 0.0798965s

So either the call TestConnection.Reset() on the client isn't causing the connection to reset or for some reason the server isn't seeing it. Any ideas @halter73 @Tratcher?

[adityamandaleeka]

Update: I just looked through recent history, and it looks like this still happens, and only on macOS+libuv.

[Tratcher]

There are equal failures in the quarantine history for Sockets and Libuv.

[amcasey]

@BrennanConroy Is this still severity-major? 😆