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.43k stars 10.02k forks source link

Quarantine AcceptNewStreamsDuringClosingConnection #41172

Closed wtgodbe closed 1 month ago

wtgodbe commented 2 years ago

Failing Test(s)

Error Message

System.TimeoutException : The operation has timed out.

Stacktrace

```text at Microsoft.AspNetCore.Testing.TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) in /_/src/Shared/TaskExtensions.cs:line 106 at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2TestBase.ReceiveFrameAsync(UInt32 maxFrameSize) in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2TestBase.cs:line 1172 at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2TestBase.WaitForConnectionErrorAsyncDoNotCloseTransport[TException](Boolean ignoreNonGoAwayFrames, Int32 expectedLastStreamId, Http2ErrorCode expectedErrorCode, String[] expectedErrorMessage) in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2TestBase.cs:line 1240 at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2TestBase.WaitForConnectionErrorAsync[TException](Boolean ignoreNonGoAwayFrames, Int32 expectedLastStreamId, Http2ErrorCode expectedErrorCode, String[] expectedErrorMessage) in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2TestBase.cs:line 1213 at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests.AcceptNewStreamsDuringClosingConnection() in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs:line 4768 --- End of stack trace from previous location --- ```

Logs

```text [0.001s] [TestLifetime] [Information] Starting test AcceptNewStreamsDuringClosingConnection at 2022-04-13T13:02:05 [0.010s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending SETTINGS frame for stream ID 0 with length 18 and flags NONE. [0.010s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0. [0.010s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" received SETTINGS frame for stream ID 0 with length 0 and flags NONE. [0.010s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending SETTINGS frame for stream ID 0 with length 0 and flags ACK. [0.012s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" received HEADERS frame for stream ID 1 with length 310 and flags END_HEADERS. [0.012s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "TestConnectionId", Request id "TestConnectionId:00000001": started reading request body. [0.012s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Debug] Connection id "TestConnectionId" is closing. [0.012s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending GOAWAY frame for stream ID 0 with length 8 and flags 0x0. [0.012s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" received HEADERS frame for stream ID 3 with length 9 and flags END_HEADERS. [0.012s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "TestConnectionId", Request id "TestConnectionId:00000003": started reading request body. [0.013s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" received DATA frame for stream ID 1 with length 5 and flags END_STREAM. [0.013s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "TestConnectionId", Request id "TestConnectionId:00000001": done reading request body. [0.034s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending HEADERS frame for stream ID 1 with length 32 and flags END_HEADERS. [0.034s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending DATA frame for stream ID 1 with length 5 and flags NONE. [0.056s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending DATA frame for stream ID 1 with length 0 and flags END_STREAM. [0.076s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" received DATA frame for stream ID 3 with length 5 and flags END_STREAM. [0.076s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "TestConnectionId", Request id "TestConnectionId:00000003": done reading request body. [0.088s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending HEADERS frame for stream ID 3 with length 2 and flags END_HEADERS. [0.088s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending DATA frame for stream ID 3 with length 5 and flags NONE. [0.099s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending DATA frame for stream ID 3 with length 0 and flags END_STREAM. [30.102s] [Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests] [Error] Test threw an exception. System.TimeoutException: The operation has timed out. at Microsoft.AspNetCore.Testing.TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) in /_/src/Shared/TaskExtensions.cs:line 106 at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2TestBase.ReceiveFrameAsync(UInt32 maxFrameSize) in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2TestBase.cs:line 1172 at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2TestBase.WaitForConnectionErrorAsyncDoNotCloseTransport[TException](Boolean ignoreNonGoAwayFrames, Int32 expectedLastStreamId, Http2ErrorCode expectedErrorCode, String[] expectedErrorMessage) in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2TestBase.cs:line 1240 at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2TestBase.WaitForConnectionErrorAsync[TException](Boolean ignoreNonGoAwayFrames, Int32 expectedLastStreamId, Http2ErrorCode expectedErrorCode, String[] expectedErrorMessage) in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2TestBase.cs:line 1213 at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests.AcceptNewStreamsDuringClosingConnection() in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs:line 4768 at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass48_1.<b__1>d.MoveNext() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\Runners\TestInvoker.cs:line 273 --- End of stack trace from previous location --- at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\ExecutionTimer.cs:line 54 at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 96 [30.103s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Debug] Connection id "TestConnectionId" is closed. The last processed stream ID was 3. [30.103s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending GOAWAY frame for stream ID 0 with length 8 and flags 0x0. [30.107s] [TestLifetime] [Information] Finished test AcceptNewStreamsDuringClosingConnection in 30.106574s ```

Build

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

amcasey commented 1 month ago

This test hasn't failed in the last 30 days.

amcasey commented 1 month ago

This appears to be the call that was timing out: https://github.com/dotnet/aspnetcore/blob/ffd5a38ecc618cac8c424a78ea8f452779120276/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs#L5226

amcasey commented 1 month ago

Curiously, the log above shows that, after the 30 second timeout, the server did actually send the desired GOAWAY.

It's hard to believe it could have fired immediately after the timeout by coincidence. Maybe there's some reason it was blocked until the timeout completed?

amcasey commented 1 month ago

In at least a few runs, Http2FrameWriter.WriteGoAwayAsync and WaitForConnectionErrorAsyncDoNotCloseTransport appear to be called on the same thread.

amcasey commented 1 month ago

As in #40626, I think the fact that the test is using an inline scheduler probably makes the original race impossible.