Quarantine StreamPool_MultipleStreamsConcurrent_StreamsReturnedToPool

[TanayParikh]

Failing Test(s)

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

Error Message

Assert.Equal() Failure
Expected: 2
Actual:   1

Stacktrace

  at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests.StreamPool_MultipleStreamsConcurrent_StreamsReturnedToPool() in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs:line 407
--- End of stack trace from previous location ---

Logs

Http2ConnectionTests_StreamPool_MultipleStreamsConcurrent_StreamsReturnedToPool.log

Build

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

[TanayParikh]

I believe we'd like to keep these issues open to ensure the QuarantinedTest attribute is removed after 30 days.

[BrennanConroy]

Test is failing again, same failure, logs look the exact same as before when it was failing.

Failing Test(s)

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

Error Message

Assert.Equal() Failure
Expected: 2
Actual:   1

Stacktrace

   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
   at Xunit.Assert.Equal[T](T expected, T actual) in C:\Dev\xunit\xunit\src\xunit.assert\Asserts\EqualityAsserts.cs:line 24
   at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests.StreamPool_MultipleStreamsConcurrent_StreamsReturnedToPool() in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs:line 473
   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
--- 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 48
   at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 90

Logs

[0.002s] [TestLifetime] [Information] Starting test StreamPool_MultipleStreamsConcurrent_StreamsReturnedToPool at 2022-05-18T12:49:56
[0.017s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending SETTINGS frame for stream ID 0 with length 18 and flags NONE.
[0.018s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
[0.018s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" received SETTINGS frame for stream ID 0 with length 0 and flags NONE.
[0.018s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending SETTINGS frame for stream ID 0 with length 0 and flags ACK.
[0.032s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" received HEADERS frame for stream ID 1 with length 310 and flags END_HEADERS.
[0.033s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "TestConnectionId", Request id "TestConnectionId:00000001": started reading request body.
[0.033s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" received HEADERS frame for stream ID 3 with length 9 and flags END_HEADERS.
[0.034s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "TestConnectionId", Request id "TestConnectionId:00000003": started reading request body.
[0.034s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" received DATA frame for stream ID 1 with length 5 and flags END_STREAM.
[0.034s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "TestConnectionId", Request id "TestConnectionId:00000001": done reading request body.
[0.035s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending HEADERS frame for stream ID 1 with length 32 and flags END_HEADERS.
[0.035s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending DATA frame for stream ID 1 with length 5 and flags NONE.
[0.036s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending DATA frame for stream ID 1 with length 0 and flags END_STREAM.
[0.037s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" received DATA frame for stream ID 3 with length 5 and flags END_STREAM.
[0.037s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "TestConnectionId", Request id "TestConnectionId:00000003": done reading request body.
[0.038s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending HEADERS frame for stream ID 3 with length 2 and flags END_HEADERS.
[0.038s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending DATA frame for stream ID 3 with length 5 and flags NONE.
[0.038s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending DATA frame for stream ID 3 with length 0 and flags END_STREAM.
[0.075s] [Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests] [Error] Test threw an exception.
Xunit.Sdk.EqualException: Assert.Equal() Failure
Expected: 2
Actual:   1
   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
   at Xunit.Assert.Equal[T](T expected, T actual) in C:\Dev\xunit\xunit\src\xunit.assert\Asserts\EqualityAsserts.cs:line 24
   at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests.StreamPool_MultipleStreamsConcurrent_StreamsReturnedToPool() in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs:line 473
   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
--- 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 48
   at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 90
[0.080s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Debug] Connection id "TestConnectionId" is closed. The last processed stream ID was 3.
[0.080s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending GOAWAY frame for stream ID 0 with length 8 and flags 0x0.
[0.080s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Debug] The connection queue processing loop for TestConnectionId completed.
[0.087s] [TestLifetime] [Information] Finished test StreamPool_MultipleStreamsConcurrent_StreamsReturnedToPool in 0.0846351s

Build

https://dev.azure.com/dnceng/public/_build/results?buildId=1777007&view=ms.vss-test-web.build-test-results-tab&runId=47676046&resultId=119821&paneView=debug

[amcasey]

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

[amcasey]

All of the line numbers have moved, but it looks like the failing assert was probably about the stream pool count.

[amcasey]

A stream won't go back into the pool unless it has finished closing gracefully. There's no obvious error in the log, but maybe it was still in the process of shutting down when the assert was evaluated?

[amcasey]

Sleeping for three seconds before returning the stream to the pool doesn't break the test, so that's probably not the race.

[amcasey]

Putting a delay before the stream's status is set does break the test, so there's a race there.

Edit: This isn't totally fair since the test uses simulated time, but it certainly seems to indicate that it's not waiting on the stream to complete before checking the pool count.