Quarantine Http2WebSocketTests.HEADERS_Received_SecondRequest_Accepted

[sebastienros]

Failing Test(s)

Http2WebSocketTests.HEADERS_Received_SecondRequest_Accepted

Error Message

2022-06-09T01:05:05.4974061Z [xUnit.net 00:00:11.40]     Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2WebSocketTests.HEADERS_Received_SecondRequest_Accepted [FAIL]
2022-06-09T01:05:05.4976124Z [xUnit.net 00:00:11.40]       Assert.Equal() Failure
2022-06-09T01:05:05.4978120Z [xUnit.net 00:00:11.40]       Expected: 1
2022-06-09T01:05:05.4985406Z [xUnit.net 00:00:11.40]       Actual:   0
2022-06-09T01:05:05.4992247Z [xUnit.net 00:00:11.40]       Stack Trace:
2022-06-09T01:05:05.5001830Z [xUnit.net 00:00:11.40]         /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2WebSocketTests.cs(240,0): at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2WebSocketTests.HEADERS_Received_SecondRequest_Accepted()
2022-06-09T01:05:05.5002058Z [xUnit.net 00:00:11.40]         --- End of stack trace from previous location ---
2022-06-09T01:05:05.5057676Z [xUnit.net 00:00:11.40]       Output:
2022-06-09T01:05:05.5057799Z [xUnit.net 00:00:11.40]         | [0.000s] TestLifetime Information: Starting test HEADERS_Received_SecondRequest_Accepted at 2022-06-09T01:05:04
2022-06-09T01:05:05.5057815Z [xUnit.net 00:00:11.40]         | [0.121s] Microsoft.AspNetCore.Server.Kestrel.Http2 Trace: Connection id "TestConnectionId" sending SETTINGS frame for stream ID 0 with length 24 and flags NONE.
2022-06-09T01:05:05.5057828Z [xUnit.net 00:00:11.40]         | [0.121s] Microsoft.AspNetCore.Server.Kestrel.Http2 Trace: Connection id "TestConnectionId" sending WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
2022-06-09T01:05:05.5057841Z [xUnit.net 00:00:11.40]         | [0.121s] Microsoft.AspNetCore.Server.Kestrel.Http2 Trace: Connection id "TestConnectionId" received SETTINGS frame for stream ID 0 with length 6 and flags NONE.
2022-06-09T01:05:05.5057854Z [xUnit.net 00:00:11.40]         | [0.121s] Microsoft.AspNetCore.Server.Kestrel.Http2 Trace: Connection id "TestConnectionId" sending SETTINGS frame for stream ID 0 with length 0 and flags ACK.
2022-06-09T01:05:05.5060460Z [xUnit.net 00:00:11.40]         | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Http2 Trace: Connection id "TestConnectionId" received HEADERS frame for stream ID 1 with length 230 and flags END_HEADERS.
2022-06-09T01:05:05.5060546Z [xUnit.net 00:00:11.40]         | [0.188s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "TestConnectionId", Request id "TestConnectionId:00000001": started reading request body.
2022-06-09T01:05:05.5060563Z [xUnit.net 00:00:11.40]         | [0.189s] Microsoft.AspNetCore.Server.Kestrel.Http2 Trace: Connection id "TestConnectionId" received DATA frame for stream ID 1 with length 0 and flags END_STREAM.
2022-06-09T01:05:05.5060576Z [xUnit.net 00:00:11.40]         | [0.189s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "TestConnectionId", Request id "TestConnectionId:00000001": done reading request body.
2022-06-09T01:05:05.5060591Z [xUnit.net 00:00:11.40]         | [0.190s] Microsoft.AspNetCore.Server.Kestrel.Http2 Trace: Connection id "TestConnectionId" sending HEADERS frame for stream ID 1 with length 32 and flags END_HEADERS.
2022-06-09T01:05:05.5060946Z [xUnit.net 00:00:11.40]         | [0.190s] Microsoft.AspNetCore.Server.Kestrel.Http2 Trace: Connection id "TestConnectionId" sending DATA frame for stream ID 1 with length 1 and flags NONE.
2022-06-09T01:05:05.5060973Z [xUnit.net 00:00:11.40]         | [0.190s] Microsoft.AspNetCore.Server.Kestrel.Http2 Trace: Connection id "TestConnectionId" sending DATA frame for stream ID 1 with length 0 and flags END_STREAM.
2022-06-09T01:05:05.5060988Z [xUnit.net 00:00:11.40]         | [0.562s] Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2WebSocketTests Error: Test threw an exception.
2022-06-09T01:05:05.5061003Z [xUnit.net 00:00:11.40]         | Xunit.Sdk.EqualException: Assert.Equal() Failure
2022-06-09T01:05:05.5061016Z [xUnit.net 00:00:11.40]         | Expected: 1
2022-06-09T01:05:05.5061030Z [xUnit.net 00:00:11.41]         | Actual:   0
2022-06-09T01:05:05.5061042Z [xUnit.net 00:00:11.41]         |    at Xunit.Assert.Equal[T](T expected, T actual, IEqualityComparer`1 comparer) in C:\Dev\xunit\xunit\src\xunit.assert\Asserts\EqualityAsserts.cs:line 40
2022-06-09T01:05:05.5064051Z [xUnit.net 00:00:11.41]         |    at Xunit.Assert.Equal[T](T expected, T actual) in C:\Dev\xunit\xunit\src\xunit.assert\Asserts\EqualityAsserts.cs:line 24
2022-06-09T01:05:05.5069517Z [xUnit.net 00:00:11.41]         |    at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2WebSocketTests.HEADERS_Received_SecondRequest_Accepted() in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2WebSocketTests.cs:line 240
2022-06-09T01:05:05.5075078Z [xUnit.net 00:00:11.41]         |    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 264
2022-06-09T01:05:05.5080417Z [xUnit.net 00:00:11.41]         | --- End of stack trace from previous location ---
2022-06-09T01:05:05.5085825Z [xUnit.net 00:00:11.41]         |    at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\ExecutionTimer.cs:line 48
2022-06-09T01:05:05.5091445Z [xUnit.net 00:00:11.41]         |    at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 96
2022-06-09T01:05:05.5097426Z [xUnit.net 00:00:11.41]         | [0.564s] Microsoft.AspNetCore.Server.Kestrel.Http2 Debug: Connection id "TestConnectionId" is closed. The last processed stream ID was 1.
2022-06-09T01:05:05.5103719Z [xUnit.net 00:00:11.41]         | [0.564s] Microsoft.AspNetCore.Server.Kestrel.Http2 Trace: Connection id "TestConnectionId" sending GOAWAY frame for stream ID 0 with length 8 and flags 0x0.
2022-06-09T01:05:05.5111120Z [xUnit.net 00:00:11.41]         | [0.564s] Microsoft.AspNetCore.Server.Kestrel.Http2 Debug: The connection queue processing loop for TestConnectionId completed.
2022-06-09T01:05:05.5117429Z [xUnit.net 00:00:11.41]         | [0.603s] TestLifetime Information: Finished test HEADERS_Received_SecondRequest_Accepted in 0.6028587s

Build

(https://dev.azure.com/dnceng/public/_build/results?buildId=1814696&view=ms.vss-test-web.build-test-results-tab&runId=48213948&resultId=120459&paneView=debug)

[BrennanConroy]

cc @Tratcher

[adityamandaleeka]

Looks like the broken assumption here is that asserting right after calling TriggerTick() will always show that the stream has been returned to the pool. In this case, it looks like that hasn't happened. I'm not sure why yet, but admittedly I haven't found where the logic is that returns the stream after some amount of time.

@Tratcher is there a race here between when the stream gets returned and when we assert? FWIW I added a similar test in #47660, which I can't get to fail this way. I was able to reproduce this failure on this test though (took just 35 iterations in Release).