search

dotnet / aspnetcore

ASP.NET Core is a cross-platform .NET framework for building modern cloud-based web applications on Windows, Mac, or Linux.
https://asp.net
MIT License
35.32k stars 9.97k forks source link

Flaky test: "AppCanHandleClientAbortingConnectionMidRequest" #27157

Open JunTaoLuo opened 3 years ago

JunTaoLuo commented 3 years ago

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 commented 3 years ago

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
ghost commented 3 years ago

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 commented 3 years ago

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 commented 2 years ago

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

Tratcher commented 2 years ago

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

amcasey commented 10 months ago

@BrennanConroy Is this still severity-major? 😆

amcasey commented 3 weeks ago

Pass rate is 97.22% - looks like this is still happening.

amcasey commented 3 weeks ago

https://dev.azure.com/dnceng-public/public/_build/results?buildId=808495 failed on mac

Microsoft.AspNetCore.Server.Kestrel.Sockets.FunctionalTests.RequestTests.AppCanHandleClientAbortingConnectionMidRequest(listenOptionsName: "PassThrough") [FAIL]
  System.TimeoutException : The operation has timed out.
  Stack Trace:
    /_/src/Shared/TaskExtensions.cs(88,0): at Microsoft.AspNetCore.InternalTesting.TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber)
    /_/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs(1087,0): at Microsoft.AspNetCore.Server.Kestrel.Sockets.FunctionalTests.RequestTests.AppCanHandleClientAbortingConnectionMidRequest(String listenOptionsName)
    /_/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs(1087,0): at Microsoft.AspNetCore.Server.Kestrel.Sockets.FunctionalTests.RequestTests.AppCanHandleClientAbortingConnectionMidRequest(String listenOptionsName)
    --- End of stack trace from previous location ---
  Output:
    | [0.002s] TestLifetime Information: Starting test AppCanHandleClientAbortingConnectionMidRequest-PassThrough at 2024-09-14T06:36:44
    | [0.004s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting starting
    | [0.006s] Microsoft.Hosting.Lifetime Information: Now listening on: http://127.0.0.1:51561
    | [0.006s] Microsoft.AspNetCore.Hosting.Diagnostics Debug: Loaded hosting startup assembly Sockets.FunctionalTests
    | [0.006s] Microsoft.Hosting.Lifetime Information: Application started. Press Ctrl+C to shut down.
    | [0.006s] Microsoft.Hosting.Lifetime Information: Hosting environment: Production
    | [0.007s] Microsoft.Hosting.Lifetime Information: Content root path: /private/tmp/helix/working/AB430988/w/AC06099F/e/
    | [0.007s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting started
    | [0.007s] Microsoft.AspNetCore.Server.Kestrel Debug: TestServer is listening on port 51561
    | [0.010s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HN6KGUCPMA5P" accepted.
    | [0.010s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HN6KGUCPMA5P" started.
    | [0.012s] Microsoft.AspNetCore.Hosting.Diagnostics Information: Request starting HTTP/1.1 POST http:/// - - 8192
    | [0.012s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HN6KGUCPMA5P", Request id "0HN6KGUCPMA5P:00000001": started reading request body.
    | [30.127s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting stopping
    | [30.127s] Microsoft.Hosting.Lifetime Information: Application is shutting down...
    | [60.160s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Some connections failed to close gracefully during server shutdown.
    | [60.163s] Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets Debug: Connection id "0HN6KGUCPMA5P" sending RST 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.163s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HN6KGUCPMA5P" disconnecting.
    | [60.164s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HN6KGUCPMA5P", Request id "0HN6KGUCPMA5P:00000001": The request was aborted by the client.
    | [60.164s] Microsoft.AspNetCore.Hosting.Diagnostics Information: Request finished HTTP/1.1 POST http:/// - 499 - - 60144.3640ms
    | [60.164s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HN6KGUCPMA5P", Request id "0HN6KGUCPMA5P:00000001": done reading request body.
    | [60.165s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HN6KGUCPMA5P" stopped.
    | [60.165s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting stopped
    | [60.167s] Microsoft.AspNetCore.Server.Kestrel.Sockets.FunctionalTests.RequestTests Error: Test threw an exception.
    | System.TimeoutException: The operation has timed out.
    |    at Microsoft.AspNetCore.InternalTesting.TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) in /_/src/Shared/TaskExtensions.cs:line 88
    |    at Microsoft.AspNetCore.Server.Kestrel.Sockets.FunctionalTests.RequestTests.AppCanHandleClientAbortingConnectionMidRequest(String listenOptionsName) in /_/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs:line 1087
    |    at Microsoft.AspNetCore.Server.Kestrel.Sockets.FunctionalTests.RequestTests.AppCanHandleClientAbortingConnectionMidRequest(String listenOptionsName) in /_/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs:line 1087
    |    at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass46_0.<<InvokeTestMethodAsync>b__1>d.MoveNext() in /_/src/xunit.execution/Sdk/Frameworks/Runners/TestInvoker.cs:line 253
    | --- End of stack trace from previous location ---
    |    at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in /_/src/xunit.execution/Sdk/Frameworks/ExecutionTimer.cs:line 48
    |    at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in /_/src/xunit.core/Sdk/ExceptionAggregator.cs:line 90
    | [60.168s] TestLifetime Information: Finished test AppCanHandleClientAbortingConnectionMidRequest-PassThrough in 60.1584067s
amcasey commented 3 weeks ago

https://dev.azure.com/dnceng-public/public/_build/results?buildId=801459 and https://dev.azure.com/dnceng-public/public/_build/results?buildId=787693 also failed only on mac.

amcasey commented 3 weeks ago

It looks like it's always PassThrough and not Loopback that fails.

amcasey commented 3 weeks ago

I'm definitely wondering whether it matters that PassThroughPipeReader and PassThroughPipeWriter are missing a number of overrides, including CompleteAsync.