[wasm] Failure in System.Net.WebSockets.Client.Tests.SendReceiveTest.SendReceive_Concurrent_Success

[lewing]

Failures 6/27-8/27 (incl. PRs):

Day	Run	OS
7/7	PR #55262	Ubuntu.1804.Amd64.Open
8/16	PR #57464	Ubuntu.1804.Amd64.Open
8/26	3x -- 2x PR #58199 + 1x PR #58158	Ubuntu.1804.Amd64.Open

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-57464-merge-1dac8c21ed9a4cf28a/System.Net.WebSockets.Client.Tests/1/console.df96303b.log?sv=2019-07-07&se=2021-09-05T03%3A12%3A54Z&sr=c&sp=rl&sig=g6Rf5539do7uVURpujLQVt5EWAvjVJ62rSoZmrjIWMs%3D

#57464 Has a failure that looks worth investigating.

[03:26:27] info: Starting:    System.Net.WebSockets.Client.Tests.dll
[03:28:10] fail: [out of order message from the browser]: http://127.0.0.1:34425/dotnet.js 0 WebSocket connection to 'ws://127.0.0.1:34425/WebSocket/EchoWebSocket.ashx?subprotocol=CustomProtocol' failed: Error during WebSocket handshake: Response must not include 'Sec-WebSocket-Protocol' header if not present in request: CustomProtocol
[03:28:10] fail: [out of order message from the browser]: http://127.0.0.1:34425/dotnet.js 0 WebSocket connection to 'wss://127.0.0.1:37691/WebSocket/EchoWebSocket.ashx?subprotocol=CustomProtocol' failed: Error during WebSocket handshake: Response must not include 'Sec-WebSocket-Protocol' header if not present in request: CustomProtocol
[03:28:13] info: http://127.0.0.1:34425/dotnet.js 0 WebSocket connection to 'ws://127.0.0.1:46387/' failed: WebSocket is closed before the connection is established.
[03:28:16] info: http://127.0.0.1:34425/dotnet.js 0 WebSocket connection to 'ws://a9fbe9d2339b4c3b85515f69f44fee45/' failed: WebSocket is closed before the connection is established.
[03:28:20] info: http://127.0.0.1:34425/dotnet.js 0 WebSocket connection to 'ws://127.0.0.1:34425/WebSocket/EchoWebSocket.ashx?delay10sec' failed: WebSocket is closed before the connection is established.
[03:28:21] info: http://127.0.0.1:34425/dotnet.js 0 WebSocket connection to 'wss://127.0.0.1:37691/WebSocket/EchoWebSocket.ashx?delay10sec' failed: WebSocket is closed before the connection is established.
[03:31:12] fail: [FAIL] System.Net.WebSockets.Client.Tests.MemorySendReceiveTest.SendReceive_Concurrent_Success(server: ws://127.0.0.1:34425/WebSocket/EchoWebSocket.ashx)
[03:31:12] info: System.OperationCanceledException : The operation was canceled.
[03:31:12] info:    at System.Threading.Channels.AsyncOperation`1[[System.Net.WebSockets.ReceivePayload, System.Net.WebSockets.Client, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a]].GetResult(Int16 token)
[03:31:12] info:    at System.Net.WebSockets.BrowserWebSocket.ReceiveAsync(ArraySegment`1 buffer, CancellationToken cancellationToken)
[03:31:12] info:    at System.Net.WebSockets.BrowserWebSocket.ReceiveAsync(ArraySegment`1 buffer, CancellationToken cancellationToken)
[03:31:12] info:    at System.Net.WebSockets.WebSocket.ReceiveAsync(Memory`1 buffer, CancellationToken cancellationToken)
[03:31:12] info:    at System.Net.WebSockets.Client.Tests.MemorySendReceiveTest.ReceiveAsync(WebSocket ws, ArraySegment`1 arraySegment, CancellationToken cancellationToken)
[03:31:12] info:    at System.Net.WebSockets.Client.Tests.SendReceiveTest.SendReceive_Concurrent_Success(Uri server)
[03:31:12] info: --- End of stack trace from previous location ---

[ghost]

Tagging subscribers to 'arch-wasm': @lewing
See info in area-owners.md if you want to be subscribed.

Issue Details

---

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-57464-merge-1dac8c21ed9a4cf28a/System.Net.WebSockets.Client.Tests/1/console.df96303b.log?sv=2019-07-07&se=2021-09-05T03%3A12%3A54Z&sr=c&sp=rl&sig=g6Rf5539do7uVURpujLQVt5EWAvjVJ62rSoZmrjIWMs%3D

#57464 Has a failure that looks worth investigating.

[03:26:27] info: Starting:    System.Net.WebSockets.Client.Tests.dll
[03:28:10] fail: [out of order message from the browser]: http://127.0.0.1:34425/dotnet.js 0 WebSocket connection to 'ws://127.0.0.1:34425/WebSocket/EchoWebSocket.ashx?subprotocol=CustomProtocol' failed: Error during WebSocket handshake: Response must not include 'Sec-WebSocket-Protocol' header if not present in request: CustomProtocol
[03:28:10] fail: [out of order message from the browser]: http://127.0.0.1:34425/dotnet.js 0 WebSocket connection to 'wss://127.0.0.1:37691/WebSocket/EchoWebSocket.ashx?subprotocol=CustomProtocol' failed: Error during WebSocket handshake: Response must not include 'Sec-WebSocket-Protocol' header if not present in request: CustomProtocol
[03:28:13] info: http://127.0.0.1:34425/dotnet.js 0 WebSocket connection to 'ws://127.0.0.1:46387/' failed: WebSocket is closed before the connection is established.
[03:28:16] info: http://127.0.0.1:34425/dotnet.js 0 WebSocket connection to 'ws://a9fbe9d2339b4c3b85515f69f44fee45/' failed: WebSocket is closed before the connection is established.
[03:28:20] info: http://127.0.0.1:34425/dotnet.js 0 WebSocket connection to 'ws://127.0.0.1:34425/WebSocket/EchoWebSocket.ashx?delay10sec' failed: WebSocket is closed before the connection is established.
[03:28:21] info: http://127.0.0.1:34425/dotnet.js 0 WebSocket connection to 'wss://127.0.0.1:37691/WebSocket/EchoWebSocket.ashx?delay10sec' failed: WebSocket is closed before the connection is established.
[03:31:12] fail: [FAIL] System.Net.WebSockets.Client.Tests.MemorySendReceiveTest.SendReceive_Concurrent_Success(server: ws://127.0.0.1:34425/WebSocket/EchoWebSocket.ashx)
[03:31:12] info: System.OperationCanceledException : The operation was canceled.
[03:31:12] info:    at System.Threading.Channels.AsyncOperation`1[[System.Net.WebSockets.ReceivePayload, System.Net.WebSockets.Client, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a]].GetResult(Int16 token)
[03:31:12] info:    at System.Net.WebSockets.BrowserWebSocket.ReceiveAsync(ArraySegment`1 buffer, CancellationToken cancellationToken)
[03:31:12] info:    at System.Net.WebSockets.BrowserWebSocket.ReceiveAsync(ArraySegment`1 buffer, CancellationToken cancellationToken)
[03:31:12] info:    at System.Net.WebSockets.WebSocket.ReceiveAsync(Memory`1 buffer, CancellationToken cancellationToken)
[03:31:12] info:    at System.Net.WebSockets.Client.Tests.MemorySendReceiveTest.ReceiveAsync(WebSocket ws, ArraySegment`1 arraySegment, CancellationToken cancellationToken)
[03:31:12] info:    at System.Net.WebSockets.Client.Tests.SendReceiveTest.SendReceive_Concurrent_Success(Uri server)
[03:31:12] info: --- End of stack trace from previous location ---

Author:	lewing
Assignees:	pavelsavara
Labels:	arch-wasm
Milestone:	-

[lewing]

@pavelsavara is this similar to the failure you saw?

[pavelsavara]

This is same as #53957, but happened in different test.

[pavelsavara]

Possibly related failure I was able to reproduce locally.

System.Threading.Tasks.TaskCanceledException : The request was canceled due to the configured HttpClient.Timeout of 100 seconds elapsing.
---- System.TimeoutException : The operation was canceled.
-------- System.Threading.Tasks.TaskCanceledException : The operation was canceled.
------------ System.Runtime.InteropServices.JavaScript.JSException : AbortError: The user aborted a request.
   at System.Net.Http.HttpClient.HandleFailure(Exception e, Boolean telemetryStarted, HttpResponseMessage response, CancellationTokenSource cts, CancellationToken cancellationToken, CancellationTokenSource pendingRequestsCts) in C:\Dev\runtime\src\libraries\System.Net.Http\src\System\Net\Http\HttpClient.cs:line 623
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) in C:\Dev\runtime\src\libraries\System.Net.Http\src\System\Net\Http\HttpClient.cs:line 546
   at System.Net.Http.Functional.Tests.HttpClientHandler_RemoteServerTest.GetAsync_LargeRequestHeader_HeadersAndValuesSent(RemoteServer remoteServer, Uri uri) in C:\Dev\runtime\src\libraries\Common\tests\System\Net\Http\HttpClientHandlerTest.RemoteServer.cs:line 241

And also

System.Net.Http.HttpRequestException : TypeError: Failed to fetch
---- System.Runtime.InteropServices.JavaScript.JSException : TypeError: Failed to fetch
   at System.Net.Http.BrowserHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in C:\Dev\runtime\src\libraries\System.Net.Http\src\System\Net\Http\BrowserHttpHandler\BrowserHttpHandler.cs:line 332
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) in C:\Dev\runtime\src\libraries\System.Net.Http\src\System\Net\Http\HttpClient.cs:line 547
   at System.Net.Http.Functional.Tests.HttpClientHandler_RemoteServerTest.PostAsync_Redirect_LargePayload_Helper(RemoteServer remoteServer, Int32 statusCode, Boolean expectRedirectToPost) in C:\Dev\runtime\src\libraries\Common\tests\System\Net\Http\HttpClientHandlerTest.RemoteServer.cs:line 725
   at System.Net.Http.Functional.Tests.HttpClientHandler_RemoteServerTest.PostAsync_RedirectWith302_LargePayload(RemoteServer remoteServer) in C:\Dev\runtime\src\libraries\Common\tests\System\Net\Http\HttpClientHandlerTest.RemoteServer.cs:line 688

And also

System.Net.WebSockets.Client.Tests.CancelTest.ConnectAsync_Cancel_ThrowsCancellationException(server: ws://127.0.0.1:49261/WebSocket/EchoWebSocket.ashx)

Assert.Throws() Failure
Expected: typeof(System.OperationCanceledException)
Actual:   (No exception was thrown)

[CarnaViire]

The same failure happened again in #57742
https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-57742-merge-16582b1d2f5945a484/System.Net.WebSockets.Client.Tests/1/console.b5cc2d87.log?sv=2019-07-07&se=2021-09-08T18%3A49%3A07Z&sr=c&sp=rl&sig=Mp93%2BDaEhEe5STLOYzLR%2BGDSHW1OM7Aa0efCDBqKVGA%3D

[19:11:16] info: Starting:    System.Net.WebSockets.Client.Tests.dll
[19:11:16] info: http://127.0.0.1:49231/dotnet.js 0 WebSocket connection to 'ws://127.0.0.1:49231/WebSocket/EchoWebSocket.ashx?delay10sec' failed: WebSocket is closed before the connection is established.
[19:11:16] info: http://127.0.0.1:49231/dotnet.js 0 WebSocket connection to 'wss://127.0.0.1:49232/WebSocket/EchoWebSocket.ashx?delay10sec' failed: WebSocket is closed before the connection is established.
[19:11:19] fail: [out of order message from the browser]: http://127.0.0.1:49231/dotnet.js 0 WebSocket connection to 'ws://127.0.0.1:49231/WebSocket/EchoWebSocket.ashx?subprotocol=CustomProtocol' failed: Error during WebSocket handshake: Response must not include 'Sec-WebSocket-Protocol' header if not present in request: CustomProtocol
[19:11:19] fail: [out of order message from the browser]: http://127.0.0.1:49231/dotnet.js 0 WebSocket connection to 'wss://127.0.0.1:49232/WebSocket/EchoWebSocket.ashx?subprotocol=CustomProtocol' failed: Error during WebSocket handshake: Response must not include 'Sec-WebSocket-Protocol' header if not present in request: CustomProtocol
[19:11:19] info: http://127.0.0.1:49231/dotnet.js 0 WebSocket connection to 'ws://127.0.0.1:49292/' failed: WebSocket is closed before the connection is established.
[19:11:19] info: http://127.0.0.1:49231/dotnet.js 0 WebSocket connection to 'ws://7d2f40ecf2cb43789343edcbafdbb0fc/' failed: WebSocket is closed before the connection is established.
[19:15:19] fail: [FAIL] System.Net.WebSockets.Client.Tests.MemorySendReceiveTest.SendReceive_Concurrent_Success(server: ws://127.0.0.1:49231/WebSocket/EchoWebSocket.ashx)
[19:15:19] info: System.OperationCanceledException : The operation was canceled.
[19:15:19] info:    at System.Threading.Channels.AsyncOperation`1[[System.Net.WebSockets.ReceivePayload, System.Net.WebSockets.Client, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a]].GetResult(Int16 token)
[19:15:19] info:    at System.Net.WebSockets.BrowserWebSocket.ReceiveAsync(ArraySegment`1 buffer, CancellationToken cancellationToken)
[19:15:19] info:    at System.Net.WebSockets.BrowserWebSocket.ReceiveAsync(ArraySegment`1 buffer, CancellationToken cancellationToken)
[19:15:19] info:    at System.Net.WebSockets.WebSocket.ReceiveAsync(Memory`1 buffer, CancellationToken cancellationToken)
[19:15:19] info:    at System.Net.WebSockets.Client.Tests.MemorySendReceiveTest.ReceiveAsync(WebSocket ws, ArraySegment`1 arraySegment, CancellationToken cancellationToken)
[19:15:19] info:    at System.Net.WebSockets.Client.Tests.SendReceiveTest.SendReceive_Concurrent_Success(Uri server)
[19:15:19] info: --- End of stack trace from previous location ---

and another one posted by @pavelsavara above

[19:16:14] fail: [FAIL] System.Net.WebSockets.Client.Tests.CancelTest.ConnectAsync_Cancel_ThrowsCancellationException(server: ws://127.0.0.1:49231/WebSocket/EchoWebSocket.ashx)
[19:16:14] info: Assert.Throws() Failure
[19:16:14] info: Expected: typeof(System.OperationCanceledException)
[19:16:14] info: Actual:   (No exception was thrown)
[19:16:14] info:    at System.Net.WebSockets.Client.Tests.CancelTest.ConnectAsync_Cancel_ThrowsCancellationException(Uri server)
[19:16:14] info: --- End of stack trace from previous location ---
[19:16:15] info: http://127.0.0.1:49231/dotnet.js 0 WebSocket connection to 'wss://127.0.0.1:49232/WebSocket/EchoWebSocket.ashx?delay10sec' failed: WebSocket is closed before the connection is established.

@lewing is all of it now tracked by #53957 or should we reopen this one too?

[pavelsavara]

Let's reopen it. It's different test SendReceive_Concurrent_Success but probably the same cause.

[karelz]

Top post updated with more occurrences. Interestingly the one @CarnaViire hit is not in Kusto ... weird.

[ilonatommy]

@pavelsavara, what's the status?