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.19k stars 9.93k forks source link

Quarantine StreamPool_MultipleStreamsConcurrent_StreamsReturnedToPool #39477

Open TanayParikh opened 2 years ago

TanayParikh commented 2 years ago

Failing Test(s)

Error Message

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

Stacktrace

```text 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](https://github.com/dotnet/aspnetcore/files/7859488/Http2ConnectionTests_StreamPool_MultipleStreamsConcurrent_StreamsReturnedToPool.log)

Build

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

TanayParikh commented 2 years ago

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

BrennanConroy commented 2 years ago

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

Failing Test(s)

Error Message

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

Stacktrace

```text 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.<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.<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 commented 3 weeks ago

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

amcasey commented 3 weeks ago

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

amcasey commented 3 weeks ago

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

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

amcasey commented 3 weeks ago

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.