Extension install can be corrupted due to cleanup while extension is installing

[jkeech]

Does this issue occur when all extensions are disabled?: No, related to extension installation

• VS Code Version:
  Version: 1.78.0 (Universal)
  Commit: 252e546
  Date: 2023-05-03T20:11:00.813Z
  Electron: 22.4.8
  Chromium: 108.0.5359.215
  Node.js: 16.17.1
  V8: 10.8.168.25-electron.0
  OS: Darwin arm64 22.4.0
  Sandboxed: No
• OS Version: macOS 13.3.1 connected to a codespace

Steps to Reproduce:

1. Have a large extension setup to sync via Settings Sync. I've been able to reproduce this with Copilot and Copilot Nightly so far.
2. Create a codespace
3. 🐛 The Copilot extension installs, but it's missing some files and fails to activate

2023-05-05 21:30:05.044 [info] ExtensionService#_doActivateExtension GitHub.copilot-nightly, startup: false, activationEvent: 'onStartupFinished'
2023-05-05 21:30:05.049 [error] Activating extension GitHub.copilot-nightly failed due to an error:
2023-05-05 21:30:05.049 [error] Error: Cannot find module '/home/codespace/.vscode-remote/extensions/github.copilot-nightly-1.85.76/dist/extension'
Require stack:
- /vscode/bin/linux-x64/252e5463d60e63238250799aef7375787f68b4ee/out/vs/loader.js
- /vscode/bin/linux-x64/252e5463d60e63238250799aef7375787f68b4ee/out/bootstrap-amd.js
- /vscode/bin/linux-x64/252e5463d60e63238250799aef7375787f68b4ee/out/bootstrap-fork.js
	at Function.Module._resolveFilename (node:internal/modules/cjs/loader:956:15)
	at Function.Module._load (node:internal/modules/cjs/loader:804:27)
	at Function.b._load (/vscode/bin/linux-x64/252e5463d60e63238250799aef7375787f68b4ee/out/vs/workbench/api/node/extensionHostProcess.js:127:29948)
	at Function.h._load (/vscode/bin/linux-x64/252e5463d60e63238250799aef7375787f68b4ee/out/vs/workbench/api/node/extensionHostProcess.js:127:26698)
	at Function.I._load (/vscode/bin/linux-x64/252e5463d60e63238250799aef7375787f68b4ee/out/vs/workbench/api/node/extensionHostProcess.js:91:24489)
	at Module.require (node:internal/modules/cjs/loader:1028:19)
	at require (node:internal/modules/cjs/helpers:102:18)
	at Function.i [as __$__nodeRequire] (/vscode/bin/linux-x64/252e5463d60e63238250799aef7375787f68b4ee/out/vs/loader.js:5:98)
	at v.rb (/vscode/bin/linux-x64/252e5463d60e63238250799aef7375787f68b4ee/out/vs/workbench/api/node/extensionHostProcess.js:127:27962)
	at async Promise.all (index 0)

I've verified that the files on disk are only partially there for the extension. Manually inspecting the VSIX content shows that there are more files that are not present on disk. Note in the screenshot below that there is no extension.js file on disk.

Looking at the extension extraction trace logs, it looks like the issue is that the temporary generated folder which is being used for the Copilot extension extraction is deleted in the middle of the extraction process. This deletes the files that were initially extracted. The folder is then recreated almost immediately as additional files are extracted. The result is that the extension install is corrupted with some of the earlier extracted files missing.

2023-05-05 21:46:54.415 [trace] Started extracting the extension from /home/codespace/.vscode-remote/extensionsCache/github.copilot-nightly-1.85.76 to /home/codespace/.vscode-remote/extensions/.005916ee-49f5-4c1a-86f4-648769425c03
...
2023-05-05 21:46:54.425 [trace] [File Watcher (node.js)] [raw] ["rename"] .005916ee-49f5-4c1a-86f4-648769425c03
...
2023-05-05 21:46:54.538 [trace] [File Watcher (node.js)] [ADDED] /home/codespace/.vscode-remote/extensions/.005916ee-49f5-4c1a-86f4-648769425c03
...
2023-05-05 21:46:54.539 [trace] [File Watcher (node.js)] >> normalized [ADDED] /home/codespace/.vscode-remote/extensions/.005916ee-49f5-4c1a-86f4-648769425c03
...
2023-05-05 21:46:56.053 [trace] ExtensionManagementService#removeGeneratedFolders
...
2023-05-05 21:46:56.058 [trace] Deleting the generated extension folder file:///home/codespace/.vscode-remote/extensions/.005916ee-49f5-4c1a-86f4-648769425c03
...
2023-05-05 21:46:56.281 [trace] [File Watcher (node.js)] [DELETED] /home/codespace/.vscode-remote/extensions/.005916ee-49f5-4c1a-86f4-648769425c03
...
2023-05-05 21:46:56.357 [trace] [File Watcher (node.js)] >> normalized [DELETED] /home/codespace/.vscode-remote/extensions/.005916ee-49f5-4c1a-86f4-648769425c03
...
2023-05-05 21:46:57.227 [trace] [File Watcher (node.js)] [raw] ["rename"] .005916ee-49f5-4c1a-86f4-648769425c03
2023-05-05 21:46:57.329 [trace] [File Watcher (node.js)] [ADDED] /home/codespace/.vscode-remote/extensions/.005916ee-49f5-4c1a-86f4-648769425c03
2023-05-05 21:46:57.404 [trace] [File Watcher (node.js)] >> normalized [ADDED] /home/codespace/.vscode-remote/extensions/.005916ee-49f5-4c1a-86f4-648769425c03
...
2023-05-05 21:47:04.354 [info] Extracted extension to /home/codespace/.vscode-remote/extensions/.005916ee-49f5-4c1a-86f4-648769425c03: github.copilot-nightly
2023-05-05 21:47:04.394 [info] Renamed to /home/codespace/.vscode-remote/extensions/github.copilot-nightly-1.85.76
2023-05-05 21:47:04.407 [trace] [File Watcher (node.js)] [raw] ["rename"] .005916ee-49f5-4c1a-86f4-648769425c03
2023-05-05 21:47:04.410 [trace] [File Watcher (node.js)] [raw] ["rename"] github.copilot-nightly-1.85.76
2023-05-05 21:47:04.430 [info] Extracting extension completed. github.copilot-nightly

This might be related to the cleanup code that was added back in February in #173484. cc @sandy081

[cheshire137]

Have a large extension setup to sync via Settings Sync.

This matches my setup, as someone who has been experiencing this problem with the Copilot extension. I have 63 extensions synced to my Codespace.

My workaround has been to take a zip of the Copilot extension, drag-n-drop it into my Codespace, and unzip it over top of the existing extension: rm -rf ~/.vscode-remote/extensions/github.copilot-1.84.51 && unzip github.copilot-1.84.51.zip -d ~/.vscode-remote/extensions.

[sandy081]

This is caused by https://github.com/microsoft/vscode/pull/176663/files#diff-ea2598061ccd634fa22f0e32765b8ea0e2a659d81ebb758278aaa31a76a43feeR239 that delayed extension clean up to later in time.

Even though it was caused by above change, the fix here is to undo the change that introduced removing generated folders. Because, I was assuming deleting an extension folder is not atomic and therefore causing partial deletes and hence changed deleting to rename to generated folder and delete. Therefore I have a task to clean up generated folders. I learned that the del api from file service is internally doing the same and I can revert this redundant logic to rename and delete generated folders.

[sandy081]

This is a pure timing issue when the extension installation starts before the clean up and the clean up got triggered while extension is being extracted.

@jkeech You said that you can see it consistently? Can you please share with which repo it happens?

[jkeech]

@sandy081 I don't think the repo matters very much, but I was able to reproduce on a small sample repo jkeech/simple-server using a 2-core codespace. I've also heard multiple internal reports of this happening on GitHub's much larger monorepo. In both cases, the Copilot extension which is being installed is brought in by Settings Sync, and it's such a large extension that I think it's more likely to run into this timing issue since it takes a few seconds to extract.

[sandy081]

I tried to repro it with couple of repos and it did not happen to me. I know when it can happen and I have the fix. But I would like to know if there is a consistent way to repro it so that I can verify the fix.

BTW I tried reproing with your sample repo jkeech/simple-server and the bug did not happen to me.

[sandy081]

Pushed a tactical fix for recovery - clean up task (deleting generated folders) only deletes the generated folders tagged with removal of extension.

[sandy081]

To verify:

• Using Insiders build
  • From Desktop, have GitHub Copilot nightly extension installed and synced using settings sync
  • Go to codespaces settings page, if you see settings sync option, enable it otherwise ignore this step
  • From web, Create a codespace on any repo and open it in web.
  • Only if you are not on VS Code Insiders (Check by clicking on gear icon in the bottom left corner)
    • Switch to VS Code Insiders
    • Delete this codespace and create again and open in web.
  • Make sure GitHub Copilot nightly extension is installed and activated
  • Try above step on 2 to 3 or other repos.
  • In Desktop, install and uninstall any extension. RESTART (Not Reload) VS Code Insiders and make sure the extension is deleted in the disk. (Use command Open Extensions Folder)
• Using Stable build
  • In Desktop, install and uninstall any extension. RESTART (Not Reload) VS Code and make sure the extension is deleted in the disk. (Use command Open Extensions Folder)

[rzhao271]

Verification failed on the Stable candidate build

[sandy081]

Can you please share shared process log while reproducing?

[rzhao271]

I confused restarting with reloading. VS Code Stable LGTM. I still need to verify Insiders.

[Jason3S]

@sandy081,

This is an old issue that happens on remote servers as well as locally.

See: #181246