Flaky test SignalR.StackExchangeRedis.Tests.RedisEndToEndTests.CanSendAndReceiveUserMessagesUserNameWithPatternIsTreatedAsLiteral

[eerhardt]

Failing Test(s)

• Microsoft.AspNetCore.SignalR.StackExchangeRedis.Tests.RedisEndToEndTests.CanSendAndReceiveUserMessagesUserNameWithPatternIsTreatedAsLiteral(transportType: LongPolling, protocolName: "json")

Error Message

2024-01-24T22:41:21.1022920Z  | [30.025s] Microsoft.AspNetCore.SignalR.StackExchangeRedis.Tests.RedisEndToEndTests Error: Test threw an exception.
2024-01-24T22:41:21.1022953Z  | System.TimeoutException: The operation has timed out.
2024-01-24T22:41:21.1022984Z  |    at Microsoft.AspNetCore.InternalTesting.TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) in /_/src/Shared/TaskExtensions.cs:line 88
2024-01-24T22:41:21.1023014Z  |    at Microsoft.AspNetCore.SignalR.StackExchangeRedis.Tests.RedisEndToEndTests.CanSendAndReceiveUserMessagesUserNameWithPatternIsTreatedAsLiteral(HttpTransportType transportType, String protocolName) in /_/src/SignalR/server/StackExchangeRedis/test/RedisEndToEnd.cs:line 203
2024-01-24T22:41:21.1023065Z  |    at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass48_0.<<InvokeTestMethodAsync>b__1>d.MoveNext() in /_/src/xunit.execution/Sdk/Frameworks/Runners/TestInvoker.cs:line 264
2024-01-24T22:41:21.1023095Z  | --- End of stack trace from previous location ---
2024-01-24T22:41:21.1023290Z  |    at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in /_/src/xunit.execution/Sdk/Frameworks/ExecutionTimer.cs:line 48
2024-01-24T22:41:21.1023332Z  |    at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in /_/src/xunit.core/Sdk/ExceptionAggregator.cs:line 90

Logs

[0.004s] [TestLifetime] [Information] Starting test CanSendAndReceiveUserMessagesUserNameWithPatternIsTreatedAsLiteral-LongPolling-json at 2024-01-24T22:40:50
[0.005s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Registering handler for client method 'Echo'.
[0.005s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Registering handler for client method 'Echo'.
[0.005s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Starting HubConnection.
[0.005s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Starting HttpConnection.
[0.005s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Establishing connection with server at 'http://127.0.0.1:34291/echo'.
[0.006s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Established connection 'oAS76lqCe9uDPjEGXvIJew' with the server.
[0.006s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Skipping transport WebSockets because it was disabled by the client.
[0.007s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Skipping transport ServerSentEvents because it was disabled by the client.
[0.007s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Starting transport 'LongPolling' with Url: http://127.0.0.1:34291/echo.
[0.007s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Information] Starting transport. Transfer mode: Text.
[0.007s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Starting receive loop.
[0.008s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Starting the send loop.
[0.008s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Transport 'LongPolling' started.
[0.008s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Information] HttpConnection Started.
[0.008s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Information] Using HubProtocol 'json v1'.
[0.008s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Sending Hub Handshake.
[0.008s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Sending 32 bytes to the server using url: http://127.0.0.1:34291/echo?id=0f_Eu8cMZISKhepDiIYQNw.
[0.009s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Message(s) sent successfully.
[0.010s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Received messages from the server.
[0.010s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Handshake with server complete.
[0.010s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Receive loop starting.
[0.010s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Information] HubConnection started.
[0.011s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Starting HubConnection.
[0.011s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Starting HttpConnection.
[0.011s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Establishing connection with server at 'http://127.0.0.1:40429/echo'.
[0.013s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Established connection 'LuyWGlgPK025txAjCLSS0g' with the server.
[0.013s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Skipping transport WebSockets because it was disabled by the client.
[0.013s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Skipping transport ServerSentEvents because it was disabled by the client.
[0.013s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Starting transport 'LongPolling' with Url: http://127.0.0.1:40429/echo.
[0.013s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Information] Starting transport. Transfer mode: Text.
[0.014s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Starting receive loop.
[0.014s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Starting the send loop.
[0.014s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Debug] Transport 'LongPolling' started.
[0.014s] [Microsoft.AspNetCore.Http.Connections.Client.HttpConnection] [Information] HttpConnection Started.
[0.014s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Information] Using HubProtocol 'json v1'.
[0.014s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Sending Hub Handshake.
[0.014s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Sending 32 bytes to the server using url: http://127.0.0.1:40429/echo?id=rrKj3yvck6hzRkoNIMQF9w.
[0.016s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Received messages from the server.
[0.017s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Handshake with server complete.
[0.016s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Message(s) sent successfully.
[0.017s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Receive loop starting.
[0.017s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Information] HubConnection started.
[0.017s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Registering Invocation ID '1' for tracking.
[0.017s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Sending InvocationMessage message '1'.
[0.017s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Sending InvocationMessage message '1' completed.
[0.017s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Sending 88 bytes to the server using url: http://127.0.0.1:40429/echo?id=rrKj3yvck6hzRkoNIMQF9w.
[0.019s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Message(s) sent successfully.
[0.020s] [Microsoft.AspNetCore.Http.Connections.Client.Internal.LongPollingTransport] [Debug] Received messages from the server.
[0.020s] [Microsoft.AspNetCore.SignalR.Client.HubConnection] [Debug] Processing 44 byte message from server.
[30.026s] [Microsoft.AspNetCore.SignalR.StackExchangeRedis.Tests.RedisEndToEndTests] [Error] Test threw an exception.
System.TimeoutException: The operation has timed out.
   at Microsoft.AspNetCore.InternalTesting.TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) in /_/src/Shared/TaskExtensions.cs:line 88
   at Microsoft.AspNetCore.SignalR.StackExchangeRedis.Tests.RedisEndToEndTests.CanSendAndReceiveUserMessagesUserNameWithPatternIsTreatedAsLiteral(HttpTransportType transportType, String protocolName) in /_/src/SignalR/server/StackExchangeRedis/test/RedisEndToEnd.cs:line 203
   at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass48_0.<<InvokeTestMethodAsync>b__1>d.MoveNext() in /_/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 /_/src/xunit.execution/Sdk/Frameworks/ExecutionTimer.cs:line 48
   at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in /_/src/xunit.core/Sdk/ExceptionAggregator.cs:line 90
[30.026s] [TestLifetime] [Information] Finished test CanSendAndReceiveUserMessagesUserNameWithPatternIsTreatedAsLiteral-LongPolling-json in 30.0236305s

Build

https://dev.azure.com/dnceng-public/public/_build/results?buildId=539561&view=logs&jobId=3f6d4e0f-1b71-56b5-361e-d95b6e6da15a

[amcasey]

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