Insiders failed to launch for test run using vscode-test ("Could not delete obsolete instance handle" - sock file missing?)

[DanTup]

I don't have repro steps for this (nor do I know how common it is), but it seems like this came up in #81652 but the issue was closed by the bot and it doesn't seem like it was addressed.

I'm running tests on GitHub Actions - this one using macOS. I use vscode-test to run the tests like this:

const res = await vstest.runTests({
	extensionDevelopmentPath: cwd,
	extensionTestsEnv: { ...testEnv, ...env },
	extensionTestsPath: path.join(cwd, "out", "src", "test", testFolder),
	launchArgs: [
		path.isAbsolute(workspaceFolder)
			? workspaceFolder
			: path.join(cwd, "src", "test", "test_projects", workspaceFolder),
		"--user-data-dir",
		path.join(cwd, ".dart_code_test_data_dir"),
	],
	version: process.env.CODE_VERSION,
});

This is called multiple times with different testFolder and workspaceFolder params. One test run was fine, but then I got this error (which then repeated for every subsequent invocation in the same way):

2019-12-05T09:17:37.8141490Z �[0m  test environment�[0m
2019-12-05T09:17:37.8146740Z 
2019-12-05T09:17:37.8147990Z   �[32m  ✓�[0m�[90m has opened the correct folder�[0m
2019-12-05T09:17:37.8150710Z 
2019-12-05T09:17:37.8151900Z �[92m �[0m�[32m 3 passing�[0m�[90m (6s)�[0m
2019-12-05T09:17:37.8152370Z 
2019-12-05T09:17:37.8158840Z Test run is complete! Calling VS Code callback with (null, 0)
2019-12-05T09:17:37.8173710Z 
2019-12-05T09:17:40.8880150Z Exit code:   0
2019-12-05T09:17:40.8880790Z Done
2019-12-05T09:17:40.8881040Z 
2019-12-05T09:17:40.8881520Z ############################################################
2019-12-05T09:17:40.8881740Z 
2019-12-05T09:17:40.8881870Z 
2019-12-05T09:17:40.8882050Z 
2019-12-05T09:17:40.8882550Z Running not_activated/dart_create tests folder in workspace empty
2019-12-05T09:17:40.8884650Z Attempting to download VS Code attempt #1
2019-12-05T09:17:41.1385550Z Found .vscode-test/vscode-1.40.2. Skipping download.
2019-12-05T09:17:41.1386330Z Running tests with pre-downloaded VS Code
2019-12-05T09:17:41.6285570Z Found .vscode-test/vscode-insiders matching latest Insiders release. Skipping download.
2019-12-05T09:17:42.0750980Z �[93m[main 2019-12-05T09:17:42.070Z]�[0m Could not delete obsolete instance handle Error: ENOENT: no such file or directory, unlink '/Users/runner/runners/2.162.0/work/Dart-Code/Dart-Code/.dart_code_test_data_dir/1.41.0-insider-main.sock'
2019-12-05T09:17:42.0751790Z     at Object.unlinkSync (original-fs.js:976:3)
2019-12-05T09:17:42.0752680Z     at Object.doStartup (/Users/runner/runners/2.162.0/work/Dart-Code/Dart-Code/.vscode-test/vscode-insiders/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:551:165)
2019-12-05T09:17:42.0752980Z     at processTicksAndRejections (internal/process/task_queues.js:89:5) {
2019-12-05T09:17:42.0753490Z   errno: -2,
2019-12-05T09:17:42.0754000Z   syscall: 'unlink',
2019-12-05T09:17:42.0754680Z   code: 'ENOENT',
2019-12-05T09:17:42.0755420Z   path: '/Users/runner/runners/2.162.0/work/Dart-Code/Dart-Code/.dart_code_test_data_dir/1.41.0-insider-main.sock'
2019-12-05T09:17:42.0755680Z }
2019-12-05T09:17:42.0755760Z 
2019-12-05T09:17:42.0757390Z �[91m[main 2019-12-05T09:17:42.075Z]�[0m Error: ENOENT: no such file or directory, unlink '/Users/runner/runners/2.162.0/work/Dart-Code/Dart-Code/.dart_code_test_data_dir/1.41.0-insider-main.sock'
2019-12-05T09:17:42.0758040Z     at Object.unlinkSync (original-fs.js:976:3)
2019-12-05T09:17:42.0758900Z     at Object.doStartup (/Users/runner/runners/2.162.0/work/Dart-Code/Dart-Code/.vscode-test/vscode-insiders/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:551:165)
2019-12-05T09:17:42.0759230Z     at processTicksAndRejections (internal/process/task_queues.js:89:5)
2019-12-05T09:17:42.0759320Z 
2019-12-05T09:17:42.0884930Z Exit code:   1
2019-12-05T09:17:42.0886770Z Done
2019-12-05T09:17:42.0886940Z 
2019-12-05T09:17:42.0894300Z Failed
2019-12-05T09:17:42.0894790Z ############################################################
2019-12-05T09:17:42.0918950Z 

Is this something VS Code can recover better from? It's particularly bad on GitHub Actions where it's not possible to re-run individual steps (so I have to re-run a whole 1-hour run to retry this) - though I appreciate that's hardly VS Code's fault :-)

[DanTup]

Actually, I'm seeing this reliably. Most of my bots only run one set of tests, but the one that runs multiple is seeing this on Insiders on macOS all the time.

Anything I can do to get more info that might help understand what's happening?

[octref]

@dbaeumer I see some old issues where you know more about the socket files created. Do you have any pointers why this might happen?

[dbaeumer]

@octref for communication between various processes we use socket files under Linux / MacOS. The one mentioned here is for the main process. May be @bpasero knows about it.

I was on issues for the extension host and LSP server.

The problem looks like someone tries to delete a non existing socket file (ENOENT). May be we are simply missing code to handle this correctly

[bpasero]

I can answer if I know the source process and the target process. We have different IPC mechanisms in place depending on that.

[octref]

@DonJayamanne Did the problem in #81652 go away or did you find a solution?

[DonJayamanne]

Unfortunately this didn't go away for me.

[octref]

I don't think this is specific to vscode-test, but launching VS Code in general. @joaomoreno you are assigned for the other issue as well, do you have any insights?

[bpasero]

@DonJayamanne @DanTup would be good if you can try to reproduce this running out of sources, then we can possibly add some logging code

[DanTup]

I'm not sure how to make this run from source on GH Actions, but here's a repo that repros the issue on GH Actions:

https://github.com/DanTup/vscode-sock-issue-86382
https://github.com/DanTup/vscode-sock-issue-86382/runs/372401580#step:7:44
https://github.com/DanTup/vscode-sock-issue-86382/blob/1b26fc751d575aa81103da1d5b79eacd84f7a862/src/test/test_all.ts#L33

[joaomoreno]

This comes from

vscode/src/vs/code/electron-main/main.ts

Line 245 in 3d5b61c

logService.warn('Could not delete obsolete instance handle', error);

Which means that Code (1) wasn't able to connect to an existing socket file and (2) wasn't able to delete the socket file. So it can't proceed. Deleting the socket file is the recover action. If that fails we can't do anything else.

Do these tests run concurrently? If so, you must prevent that and run them serially, or run them all with separate user data dirs.

[DanTup]

@joaomoreno they do not run currently. I included a link to the code that runs the tests:

https://github.com/DanTup/vscode-sock-issue-86382/blob/1b26fc751d575aa81103da1d5b79eacd84f7a862/src/test/test_all.ts#L33

runTests is a function defined just above those lines, which just calls runTests of vscode-test and awaits it.

[joaomoreno]

Does it work if you sleep between runTests?

[DanTup]

It doesn't appear to. I added:

await new Promise((resolve) => setTimeout(resolve, 5000));

And still have the same failure:

https://github.com/DanTup/vscode-sock-issue-86382/runs/393328115#step:7:54

[joaomoreno]

Can you check whether that directory exists at the time the error occurs?

/Users/runner/runners/2.163.1/work/vscode-sock-issue-86382/vscode-sock-issue-86382/.test_data_dir

[DanTup]

That's the folder passed to VS Code's --user-data-dir flag so it will be created by the first test run (as far as I know, VS Code does not delete it).

If you fork the repo, it should all be set up to run using GitHub Actions when you commit, so it may be easier for you to debug there directly.

[joaomoreno]

Unfortunately I cannot afford to spend a day investigating an obscure user CI issue, surely you can understand. I'm more than happy to give you a general direction on where to look.

In any case, I would still write some code that checks for that folder's existence once runTests throws.

[vscodebot]

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!

[connor4312]

Rob mentioned he's running into this when running from js-debug, see the linked issue for details. I postulated it might be related to our forceful killTree function that causes some bad/missing teardown behavior in VS Code.

[roblourens]

For me this is easy to repro. I can investigate more if someone can point me towards where these socket files are created and if you know why their path lengths might be limited. Seems like the path length is limited to 103 characters.

mkdir -p /tmp/aaaaaaaa/bbbbbbbbbbbbb/cccccccccccccccc/dddddddddddddddd/eeeeeeeeeeeeeee/fffffffffffffffff/gggggggggggggggggg/hhhhhhhhhhhhhhhhh/iiiiiiiiiiiiiii
code-insiders --user-data-dir /tmp/aaaaaaaa/bbbbbbbbbbbbb/cccccccccccccccc/dddddddddddddddd/eeeeeeeeeeeeeee/fffffffffffffffff/gggggggggggggggggg/hhhhhhhhhhhhhhhhh/iiiiiiiiiiiiiii # works
# same command again with --verbose, produces the error

ls -l /tmp/aaaaaaaa/bbbbbbbbbbbbb/cccccccccccccccc/dddddddddddddddd/eeeeeeeeeeeeeee/fffffffffffffffff/ggggggg

srwxr-xr-x  1 roblou  wheel  0 Mar  2 20:40 /tmp/aaaaaaaa/bbbbbbbbbbbbb/cccccccccccccccc/dddddddddddddddd/eeeeeeeeeeeeeee/fffffffffffffffff/ggggggg

[roblourens]

103 is exactly right: https://nodejs.org/api/net.html#net_identifying_paths_for_ipc_connections

[roblourens]

Here is my suggested fix #91931

[joaomoreno]

Added comment to the PR: #91931 (review)

Given that this is one instance and it's even a CI and not an actual use case, please just use a shorter user data dir. Is that possible?

[roblourens]

Will do this instead

How about I check the length and log a warning if it's too long but leave the logic alone