ClientTimesoutWhenHandshakeResponseTakesTooLong test failure

[captainsafia]

Failing Test(s)

• Microsoft.AspNetCore.SignalR.Client.Tests.HubConnectionTests+ConnectionLifecycle.ClientTimesoutWhenHandshakeResponseTakesTooLong

Error Message

System.TimeoutException : The operation has timed out.

Stacktrace

Stack trace
   at Microsoft.AspNetCore.Testing.TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) in /_/src/Shared/TaskExtensions.cs:line 143
   at Microsoft.AspNetCore.SignalR.Client.Tests.HubConnectionTests.ConnectionLifecycle.ClientTimesoutWhenHandshakeResponseTakesTooLong() in /_/src/SignalR/clients/csharp/Client/test/UnitTests/HubConnectionTests.ConnectionLifecycle.cs:line 522
--- End of stack trace from previous location ---

Logs

[0.000s] [TestLifetime] [Information] Starting test ClientTimesoutWhenHandshakeResponseTakesTooLong at 2021-08-25T17:12:43
[0.003s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Starting HubConnection.
[0.003s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Information] Using HubProtocol 'json v1'.
[0.003s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Sending Hub Handshake.
[60.015s] [Microsoft.AspNetCore.SignalR.Client.Tests.HubConnectionTests.ConnectionLifecycle] [Error] Test threw an exception.
System.TimeoutException: The operation has timed out.
   at Microsoft.AspNetCore.Testing.TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) in /_/src/Shared/TaskExtensions.cs:line 143
   at Microsoft.AspNetCore.SignalR.Client.Tests.HubConnectionTests.ConnectionLifecycle.ClientTimesoutWhenHandshakeResponseTakesTooLong() in /_/src/SignalR/clients/csharp/Client/test/UnitTests/HubConnectionTests.ConnectionLifecycle.cs:line 522
   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
[60.016s] [TestLifetime] [Information] Finished test ClientTimesoutWhenHandshakeResponseTakesTooLong in 60.0151014s

Build

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

[BrennanConroy]

Copy the specific test logs in the future please. Linking to the logs doesn't help when they go away after a couple weeks.

Thanks for contacting us.

We're moving this issue to the Next sprint planning milestone for future evaluation / consideration. We would like to keep this around to collect more feedback, which can help us with prioritizing this work. We will re-evaluate this issue, during our next planning meeting(s).
If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues.
To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

[BrennanConroy]

I started to look into this and was about to dig into System.IO.Pipelines.PipeReader.ReadAsync(...) to see if there might be a bug with cancellation tokens and then remembered there actually was a bug with ReadAsync that was fixed recently. dotnet/runtime#59090

I believe this is the issue we hit in this test, because the token had a 1 millisecond timeout it was possible to hit the race where ReadAsync sees the token hasn't canceled yet, then a few lines later assumes the token wasn't canceled and runs some code.

cc @davidfowl Do you agree this is likely what happened?

I'm going to mark the test as 'test-fixed' and we can unquarantine in 30 days (assuming it continues passing of course)

[davidfowl]

That fix solved one of the races, but there's another one I have yet to look into dotnet/runtime#58909. That does sound plausible too.

[BrennanConroy]

but there's another one I have yet to look into dotnet/runtime#58909

Oh no 😢 didn't notice the issue was still open with another repro.

[TanayParikh]

Oh no 😢 didn't notice the issue was still open with another repro.

Should I remove the test-fixed label in that case?

[BrennanConroy]

Should I remove the test-fixed label in that case?

No, the race we're likely hitting has been fixed. There might be another issue in pipelines but from our side this test should be fixed until proven otherwise.