Quarantine AcceptNewStreamsDuringClosingConnection

[wtgodbe]

Failing Test(s)

• Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests.AcceptNewStreamsDuringClosingConnection

Error Message

System.TimeoutException : The operation has timed out.

Stacktrace

   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

[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.<<InvokeTestMethodAsync>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]

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

[amcasey]

This appears to be the call that was timing out:

aspnetcore/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs

Line 5226 in ffd5a38

await WaitForConnectionStopAsync(expectedLastStreamId: 3, ignoreNonGoAwayFrames: false);

[amcasey]

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]

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

[amcasey]

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