Flaky test BidirectionalStream_ServerReadsDataAndCompletes_GracefullyClosed

[amcasey]

Failing Test(s)

• Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests.BidirectionalStream_ServerReadsDataAndCompletes_GracefullyClosed

Error Message

Assert.Contains() Failure
Not found: (filter expression)
In value:  ConcurrentQueue<LogMessage> [LogMessage { EventId = 0, Exception = null, LogLevel = Debug, Message = "Starting HttpEventSourceListener." }, LogMessage { EventId = 0, Exception = null, LogLevel = Information, Message = "Client connecting." }, LogMessage { EventId = 0, Exception = null, LogLevel = Information, Message = "Server accepting stream." }, LogMessage { EventId = AcceptedConnection, Exception = null, LogLevel = Debug, Message = "Connection id "0HMVGD5GA0F75" accepted." }, LogMessage { EventId = 0, Exception = null, LogLevel = Information, Message = "Client sending data." }, ...]

Stacktrace

   at Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests.BidirectionalStream_ServerReadsDataAndCompletes_GracefullyClosed() in /_/src/Servers/Kestrel/Transport.NamedPipes/test/NamedPipeConnectionTests.cs:line 32
   at Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests.BidirectionalStream_ServerReadsDataAndCompletes_GracefullyClosed() in /_/src/Servers/Kestrel/Transport.NamedPipes/test/NamedPipeConnectionTests.cs:line 32

Logs

2023-11-28T23:26:03.2902981Z [xUnit.net 00:00:04.91]         | [0.004s] TestLifetime Information: Starting test BidirectionalStream_ServerReadsDataAndCompletes_GracefullyClosed at 2023-11-28T23:26:02
2023-11-28T23:26:03.2904768Z [xUnit.net 00:00:04.91]         | [0.004s] HttpEventSourceListener Debug: Starting HttpEventSourceListener.
2023-11-28T23:26:03.2906286Z [xUnit.net 00:00:04.91]         | [0.004s] Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests Information: Client connecting.
2023-11-28T23:26:03.2908210Z [xUnit.net 00:00:04.91]         | [0.005s] Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests Information: Server accepting stream.
2023-11-28T23:26:03.2909845Z [xUnit.net 00:00:04.91]         | [0.008s] Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes Debug: Connection id "0HMVGD5GA0F75" accepted.
2023-11-28T23:26:03.2911922Z [xUnit.net 00:00:04.91]         | [0.008s] Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests Information: Client sending data.
2023-11-28T23:26:03.2913522Z [xUnit.net 00:00:04.91]         | [0.008s] Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests Information: Server reading data.
2023-11-28T23:26:03.2914975Z [xUnit.net 00:00:04.91]         | [0.009s] Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes Debug: Connection id "0HMVGD5GA0F75" received end of stream.
2023-11-28T23:26:03.2916419Z [xUnit.net 00:00:04.91]         | [0.009s] Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests Information: Server completing input and output.
2023-11-28T23:26:03.2918366Z [xUnit.net 00:00:04.91]         | [0.010s] Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes Debug: Connection id "0HMVGD5GA0F75" unexpected error.
2023-11-28T23:26:03.2920358Z [xUnit.net 00:00:04.91]         | System.IO.IOException: Pipe is broken.
2023-11-28T23:26:03.2922306Z [xUnit.net 00:00:04.91]         |    at System.IO.Pipes.PipeStream.CheckWriteOperations()
2023-11-28T23:26:03.2924197Z [xUnit.net 00:00:04.91]         |    at System.IO.Pipes.PipeStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
2023-11-28T23:26:03.2925751Z [xUnit.net 00:00:04.91]         |    at Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Internal.NamedPipeConnection.DoSendAsync() in /_/src/Servers/Kestrel/Transport.NamedPipes/src/Internal/NamedPipeConnection.cs:line 168
2023-11-28T23:26:03.2927418Z [xUnit.net 00:00:04.91]         | [0.011s] Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes Debug: Connection id "0HMVGD5GA0F75" disconnecting stream because: "Pipe is broken."
2023-11-28T23:26:03.2929118Z [xUnit.net 00:00:04.91]         | [0.011s] Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests Information: Server disposing connection.
2023-11-28T23:26:03.2931004Z [xUnit.net 00:00:04.91]         | [0.022s] HttpEventSourceListener Debug: Stopping HttpEventSourceListener.
2023-11-28T23:26:03.2932727Z [xUnit.net 00:00:04.91]         | [0.025s] Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests Error: Test threw an exception.
2023-11-28T23:26:03.2934468Z [xUnit.net 00:00:04.91]         | Xunit.Sdk.ContainsException: Assert.Contains() Failure
2023-11-28T23:26:03.2936147Z [xUnit.net 00:00:04.91]         | Not found: (filter expression)
2023-11-28T23:26:03.2937914Z [xUnit.net 00:00:04.91]         | In value:  ConcurrentQueue<LogMessage> [LogMessage { EventId = 0, Exception = null, LogLevel = Debug, Message = "Starting HttpEventSourceListener." }, LogMessage { EventId = 0, Exception = null, LogLevel = Information, Message = "Client connecting." }, LogMessage { EventId = 0, Exception = null, LogLevel = Information, Message = "Server accepting stream." }, LogMessage { EventId = AcceptedConnection, Exception = null, LogLevel = Debug, Message = "Connection id \"0HMVGD5GA0F75\" accepted." }, LogMessage { EventId = 0, Exception = null, LogLevel = Information, Message = "Client sending data." }, ...]
2023-11-28T23:26:03.2939423Z [xUnit.net 00:00:04.91]         |    at Xunit.Assert.Contains[T](IEnumerable`1 collection, Predicate`1 filter) in /_/src/xunit.assert/Asserts/CollectionAsserts.cs:line 264
2023-11-28T23:26:03.2940920Z [xUnit.net 00:00:04.91]         |    at Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests.BidirectionalStream_ServerReadsDataAndCompletes_GracefullyClosed() in /_/src/Servers/Kestrel/Transport.NamedPipes/test/NamedPipeConnectionTests.cs:line 32
2023-11-28T23:26:03.2942469Z [xUnit.net 00:00:04.91]         |    at Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests.BidirectionalStream_ServerReadsDataAndCompletes_GracefullyClosed() in /_/src/Servers/Kestrel/Transport.NamedPipes/test/NamedPipeConnectionTests.cs:line 32
2023-11-28T23:26:03.2944287Z [xUnit.net 00:00:04.91]         |    at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass48_0.<<InvokeTestMethodAsync>b__1>d.MoveNext() in /_/src/xunit.execution/Sdk/Frameworks/Runners/TestInvoker.cs:line 264
2023-11-28T23:26:03.2945968Z [xUnit.net 00:00:04.91]         | --- End of stack trace from previous location ---
2023-11-28T23:26:03.2947651Z [xUnit.net 00:00:04.91]         |    at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in /_/src/xunit.execution/Sdk/Frameworks/ExecutionTimer.cs:line 48
2023-11-28T23:26:03.2949414Z [xUnit.net 00:00:04.91]         |    at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in /_/src/xunit.core/Sdk/ExceptionAggregator.cs:line 90
2023-11-28T23:26:03.2951096Z [xUnit.net 00:00:04.91]         | [0.027s] TestLifetime Information: Finished test BidirectionalStream_ServerReadsDataAndCompletes_GracefullyClosed in 0.0233879s
2023-11-28T23:26:03.2953811Z   Failed Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests.BidirectionalStream_ServerReadsDataAndCompletes_GracefullyClosed [19 ms]
2023-11-28T23:26:03.2955145Z   Error Message:
2023-11-28T23:26:03.2956456Z    Assert.Contains() Failure
2023-11-28T23:26:03.2956552Z Not found: (filter expression)
2023-11-28T23:26:03.2956721Z In value:  ConcurrentQueue<LogMessage> [LogMessage { EventId = 0, Exception = null, LogLevel = Debug, Message = "Starting HttpEventSourceListener." }, LogMessage { EventId = 0, Exception = null, LogLevel = Information, Message = "Client connecting." }, LogMessage { EventId = 0, Exception = null, LogLevel = Information, Message = "Server accepting stream." }, LogMessage { EventId = AcceptedConnection, Exception = null, LogLevel = Debug, Message = "Connection id \"0HMVGD5GA0F75\" accepted." }, LogMessage { EventId = 0, Exception = null, LogLevel = Information, Message = "Client sending data." }, ...]
2023-11-28T23:26:03.2957712Z   Stack Trace:
2023-11-28T23:26:03.2958592Z      at Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests.BidirectionalStream_ServerReadsDataAndCompletes_GracefullyClosed() in /_/src/Servers/Kestrel/Transport.NamedPipes/test/NamedPipeConnectionTests.cs:line 32
2023-11-28T23:26:03.2958863Z    at Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.Tests.NamedPipeConnectionTests.BidirectionalStream_ServerReadsDataAndCompletes_GracefullyClosed() in /_/src/Servers/Kestrel/Transport.NamedPipes/test/NamedPipeConnectionTests.cs:line 32
2023-11-28T23:26:03.2958940Z --- End of stack trace from previous location ---

Build

https://dev.azure.com/dnceng-public/public/_build/results?buildId=483019

[amcasey]

Note that the linked build is for a PR that removes the test from the helix retry list and repeats the flaky test 100 times.

[amcasey]

If we decide that flakiness is acceptable, unquarantine the test, add a comment explaining what makes it flaky, and ensure it's in the helix retry list.