Extension host test wait now 6 seconds to exit

[dbaeumer]

I see this now when running my extension host tests:

[main 2022-07-08T14:39:50.017Z] UtilityProcess<1>: Waiting for extension host with pid 31365 to exit.

[main 2022-07-08T14:39:56.017Z] UtilityProcess<1>: Extension host with pid 31365 did not exit within 6000ms, will kill it now.

[main 2022-07-08T14:39:56.025Z] UtilityProcess<1>: received exit event with code 0.

[main 2022-07-08T14:39:56.025Z] Extension host with pid 31365 exited with code: 0, signal: .

Exit code:   0
Done

Is there something I need to do in my tests. This didn't happen before.

[bpasero]

Is this on Windows? Does not seem to happen in our CI with integration tests:

https://monacotools.visualstudio.com/DefaultCollection/Monaco/_build/results?buildId=178104&view=logs&j=672276a2-8d3a-5fab-615d-090c51352f92&t=316b23c8-21ca-5aab-3515-3225235af7bb&l=655

Maybe related to a specific test?

[deepak1556]

@dbaeumer can you provide some steps to repro the issue, thanks!

[dbaeumer]

Repository: https://github.com/microsoft/vscode-languageserver-node.git

• npm run install
• npm run symlink
• npm run compile
• npm run test

[deepak1556]

Unable to repro the issue on my machine

OS: Windows_NT x64 10.0.22000

  166 passing (5s)

[main 2022-07-18T15:07:09.588Z] UtilityProcess<1>: Waiting for extension host with pid 17316 to exit.

[main 2022-07-18T15:07:09.758Z] UtilityProcess<1>: received exit event with code 0.

[main 2022-07-18T15:07:09.758Z] Extension host with pid 17316 exited with code: 0, signal: .

Exit code:   0
Done

[deepak1556]

@dbaeumer can you try again, latest insiders contain some fix for the utility process so it might be fixed with it. Also, fwiw I couldn't repro the issue with older insiders version as well.

[dbaeumer]

Tested it today and it still shows up.

What I forgot to mention is that I see this using WSL2 under Windows.

[dbaeumer]

@deepak1556 if you want we can have a look together on my machine.

[VSCodeTriageBot]

This issue has been closed automatically because it needs more information and has not had recent activity. See also our issue reporting guidelines.

Happy Coding!

[deepak1556]

I will first try your repro under WSL and if I cannot repro, we can debug on your machine.

[bpasero]

Interestingly, scanning some smoke test logs, I often come across this message from the main.log:

Extension host with pid 47478 did not exit within 6000ms, will kill it now.

Full log:

[2022-08-15 15:11:17.068] [main] [info] update#ctor - updates are disabled by the environment
[2022-08-15 15:11:21.108] [main] [info] UtilityProcess<1>: Creating new...
[2022-08-15 15:11:21.114] [main] [info] UtilityProcess<1>: received spawn event.
[2022-08-15 15:11:22.609] [main] [info] Keytar is disabled. Using in-memory credential store instead.
[2022-08-15 15:11:28.759] [main] [info] UtilityProcess<1>: received exit event with code 0.
[2022-08-15 15:11:28.759] [main] [info] Extension host with pid 46674 exited with code: 0, signal: .
[2022-08-15 15:11:32.231] [main] [info] update#ctor - updates are disabled by the environment
[2022-08-15 15:11:35.893] [main] [info] UtilityProcess<1>: Creating new...
[2022-08-15 15:11:35.903] [main] [info] UtilityProcess<1>: received spawn event.
[2022-08-15 15:11:38.198] [main] [info] Keytar is disabled. Using in-memory credential store instead.
[2022-08-15 15:11:39.103] [main] [info] UtilityProcess<1>: Waiting for extension host with pid 47478 to exit.
[2022-08-15 15:11:45.701] [main] [info] UtilityProcess<1>: Extension host with pid 47478 did not exit within 6000ms, will kill it now.
[2022-08-15 15:11:45.711] [main] [info] UtilityProcess<1>: received exit event with code 0.
[2022-08-15 15:11:45.711] [main] [info] Extension host with pid 47478 exited with code: 0, signal: .

I wonder how we can figure out what the condition is that triggers it and maybe add more logging?

[bpasero]

I can reproduce locally that on Linux running smoke tests shows the 6000ms warning and I can also see how the window closes only after.

Steps to reproduce:

• be on Linux (e.g. Ubuntu 20)
• download a new insiders build zip
• you can open test/smoke/src/areas/workbench/data-loss.test.ts and make the first describe a describe.only to get results only from this suite
• run yarn smoketest --build <path to insiders>, e.g. yarn smoketest --build /home/parallels/Downloads/code-insider-arm64-1660800067/VSCode-linux-arm64/
• wait until finished

You can then cd into .build/logs$ cd smoke-tests-electron and open that folder in VSCode. When you open smoke-test-runner.log and search for 6000ms you should see a few entries.

I cannot reproduce this on macOS, so I suspect a Linux only issue. Interestingly when I test on Linux against stable I can see one instance of test hanging on shutdown as well, somewhat 6 seconds, but I see no log message. So maybe we only log this message when utility process is enabled and we actually had this issue already previously?

[dbaeumer]

Any progress on this. Still seeing this when running my tests.

[deepak1556]

Addressed in #164882.

Verified #154515 (comment) and #154515 (comment) in respective setups.