[wasm] interpreter timeouts when WebSocket closes unexpectedly #84101

Activity

1. lewing

   added

   arch-wasmWebAssembly architectureWebAssembly architecture

   blocking-clean-ciBlocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'

   Known Build ErrorUse this to report build issues in the .NET Helix tabUse this to report build issues in the .NET Helix tab

   on Mar 29, 2023
2. lewing

   added this to the 8.0.0 milestone on Mar 29, 2023
3. ghost added

   area-System.Net

   on Mar 29, 2023
5. lewing

   assigned

   pavelsavara

   on Mar 30, 2023
6. lewing commented on Mar 30, 2023

   

   lewing

   on Mar 30, 2023

   MemberAuthor

   More actions

   These are the WebSocket only failures getting caught up in #83655 which are different from the general aot timeout in compilation
7. lewing commented on Apr 13, 2023

   

   lewing

   on Apr 13, 2023

   MemberAuthor

   More actions

   this might have stopped when I rolled back the chrome installer :|
8. pavelsavara commented on Apr 18, 2023

   

   pavelsavara

   on Apr 18, 2023

   Member

   More actions

   That message WARNING: Web browsers do not support closing the output side of a WebSocket. is correct/expected side effect of specific unit test in that suite. So I think it tell us nothing about the timeout here.
9. pavelsavara commented on Apr 20, 2023

   

   pavelsavara

   on Apr 20, 2023

   Member

   More actions

   This is timeout on NodeJS, which is strange.
   It will run full suite in under a minute and then hang until xharness timeout.

   Log

   [16:15:26] info: Using js engine NodeJS from path /home/helixbot/node-v16.19.0-linux-x64/bin/node
   ...
   [16:16:15] info: Finished:    System.Net.WebSockets.Client.Tests.dll
   [16:16:15] info: 
   [16:16:15] info: === TEST EXECUTION SUMMARY ===
   [16:16:15] info: Total: 258, Errors: 0, Failed: 0, Skipped: 0, Time: 46.2105388s
   [16:16:15] info: 
   [16:16:15] info: Received expected 122093 of /root/helix/work/workitem/uploads/xharness-output/testResults.xml
   [16:16:15] info: Finished writing 122093 bytes of RESULTXML
   [16:16:15] info: Xml file was written to the provided writer.
   [16:16:15] info: Tests run: 258 Passed: 258 Inconclusive: 0 Failed: 0 Ignored: 0 Skipped: 0
   [16:16:15] info: WASM EXIT 0
   [16:45:26] fail: Tests timed out after 1800secs
   [16:45:26] info: Process 76 didn't exit within 00:30:00 and will be killed
   
10. pavelsavara commented on Apr 20, 2023

    

    pavelsavara

    on Apr 20, 2023

    Member

    More actions

    I updated the pattern.
11. pavelsavara commented on Apr 20, 2023

    

    pavelsavara

    on Apr 20, 2023

    Last edited by pavelsavara

    Member

    More actions

    This is browser log

    going fine until [05:34:49] and then nothing at all until timeout.
    Note message at [05:33:11] as well as other messages here are expected part of the test.

    [05:32:57] Starting ChromeDriver 109.0.5414.0
    [05:33:10] info: Starting:    System.Net.WebSockets.Client.Tests.dll
    [05:33:11] warn: WARNING: Web browsers do not support closing the output side of a WebSocket. CloseOutputAsync has closed the socket and discarded any incoming messages.
    [05:34:47] info: http://127.0.0.1:49168/dotnet.js 2 WebSocket connection to 'ws://127.0.0.1:49168/WebSocket/EchoWebSocket.ashx?delay10sec' failed: WebSocket is closed before the connection is established.
    [05:34:47] info: http://127.0.0.1:49168/dotnet.js 2 WebSocket connection to 'wss://127.0.0.1:49169/WebSocket/EchoWebSocket.ashx?delay10sec' failed: WebSocket is closed before the connection is established.
    [05:34:47] info: http://127.0.0.1:49168/dotnet.js 2 WebSocket connection to 'ws://127.0.0.1:49168/WebSocket/EchoWebSocket.ashx?delay10sec' failed: WebSocket is closed before the connection is established.
    [05:34:47] info: http://127.0.0.1:49168/dotnet.js 2 WebSocket connection to 'wss://127.0.0.1:49169/WebSocket/EchoWebSocket.ashx?delay10sec' failed: WebSocket is closed before the connection is established.
    [05:34:47] fail: [out of order message from the browser]: http://127.0.0.1:49168/dotnet.js 2 WebSocket connection to 'ws://127.0.0.1:49168/WebSocket/EchoWebSocket.ashx?subprotocol=CustomProtocol' failed: Error during WebSocket handshake: Response must not include 'Sec-WebSocket-Protocol' header if not present in request: CustomProtocol
    [05:34:47] fail: [out of order message from the browser]: http://127.0.0.1:49168/dotnet.js 2 WebSocket connection to 'wss://127.0.0.1:49169/WebSocket/EchoWebSocket.ashx?subprotocol=CustomProtocol' failed: Error during WebSocket handshake: Response must not include 'Sec-WebSocket-Protocol' header if not present in request: CustomProtocol
    [05:34:47] fail: [out of order message from the browser]: http://127.0.0.1:49168/dotnet.js 2 WebSocket connection to 'ws://127.0.0.1:49294/' failed: Connection closed before receiving a handshake response
    [05:34:49] fail: [out of order message from the browser]: http://127.0.0.1:49168/dotnet.js 2 WebSocket connection to 'ws://0bd7e6fd642a453ebfaf64d54d37f4cc/' failed: Error in connection establishment: net::ERR_NAME_NOT_RESOLVED
    
    ...
    [EXECUTION TIMED OUT]
    Exit Code:-3Executor timed out after 1800 seconds and was killed
    
12. pavelsavara commented on Apr 20, 2023

    

    pavelsavara

    on Apr 20, 2023

    Last edited by pavelsavara

    Member

    More actions

    It seems from the logs that ReceiveAsync_MultipleOutstandingReceiveOperations_Throws is always last test which got executed before it froze.

    Edit: that's not true.

    👍React with 👍1Reacted by Larry Ewing
13. agocke commented on Apr 20, 2023

    

    agocke

    on Apr 20, 2023

    Member

    More actions

    Looks like this is causing EvaluateOnCallFrameTests to fail more than 1/3 of the time
14. pavelsavara commented on Apr 21, 2023

    

    pavelsavara

    on Apr 21, 2023

    Member

    More actions

    Looks like this is causing EvaluateOnCallFrameTests to fail more than 1/3 of the time

    That is different issue likely with different cause. Just my error pattern is also capturing that. We know that debugger tests are fragile.
    I'm only trying to figure out WebSocket on wasm here.
15. pavelsavara commented on Apr 21, 2023

    

    pavelsavara

    on Apr 21, 2023

    Member

    More actions

    Here is another WASM timeout on NodeJS Log

    which means that NodeJS timeout is not related to WebSocket problems.

    [16:16:05] info: Total: 41, Errors: 0, Failed: 0, Skipped: 1, Time: 8.370929s
    [16:16:05] info: 
    [16:16:05] info: Received expected 10748 of /root/helix/work/workitem/uploads/xharness-output/testResults.xml
    [16:16:05] info: Finished writing 10748 bytes of RESULTXML
    [16:16:05] info: Xml file was written to the provided writer.
    [16:16:05] info: Tests run: 41 Passed: 40 Inconclusive: 0 Failed: 0 Ignored: 0 Skipped: 1
    [16:16:05] info: WASM EXIT 0
    [16:45:54] info: Process 73 didn't exit within 00:30:00 and will be killed
                     
    [16:45:54] info: Killing process tree of 73...
                     
    [16:45:54] fail: Tests timed out after 1800secs
    [16:45:54] info: Pids to kill: 73
    
16. agocke commented on Apr 21, 2023

    

    agocke

    on Apr 21, 2023

    Last edited by agocke

    Member

    More actions

    Can we move the wasm debugger tests to runtime-extra-platforms? If we don't think there's a quick fix, this is a really high failure rate to keep running on all PRs.
17. pavelsavara commented on Apr 21, 2023

    

    pavelsavara

    on Apr 21, 2023

    Member

    More actions

    Created #85168 for debugger timeout, hope there is more precise patter for it. I will also create PR to disable the test shortly.

    ❤️React with ❤️1Reacted by Andy Gocke
18. pavelsavara commented on Apr 21, 2023

    

    pavelsavara

    on Apr 21, 2023

    Last edited by pavelsavara

    Member

    More actions

    #85169 for the debugger timeout
19. pavelsavara commented on Apr 25, 2023

    

    pavelsavara

    on Apr 25, 2023

    Member

    More actions

    How do I make this to display the last 100 failures rather than first 100 ?
    (I don't care for week old failures)
20. pavelsavara commented on Apr 25, 2023

    

    pavelsavara

    on Apr 25, 2023

    Member

    More actions

    I'm closing this one and opening replacement #85304 in attempt to get latest timeouts.
21. pavelsavara

    closed this as completedon Apr 25, 2023
22. ghost locked as resolved and limited conversation to collaborators on May 25, 2023