microsoft / vscode

Visual Studio Code
https://code.visualstudio.com
MIT License
163.39k stars 28.94k forks source link

Scoop: does not start anymore (blank window) (related to symlinks of installations) #126533

Closed lediur closed 3 years ago

lediur commented 3 years ago

Edit with workaround: This was due to VS Code being launched via a path with a symlink in it. Launching the executable without a symlink in the path works fine. This should be fixed in more recent Insider builds. See discussion starting at https://github.com/microsoft/vscode/issues/126533#issuecomment-863079344 for cause and resolution.


Does this issue occur when all extensions are disabled?: Yes

Steps to Reproduce:

  1. Open VS Code
  2. Window appears, but seemingly stops loading forever. It only displays the placeholder monaco-parts-splash elements and no other controls. No resize handles, but I can grab the window by the title bar area and resize it with Aero Snap (either dragging or keyboard shortcuts). Window immediately responds to Alt-F4. Process is idle (0-0.2% CPU usage, ~18MB RAM). See screenshot:

image

A few things I've tried with no resolution:

Some more context:

Sometimes the next two lines are also included:

[2021-06-16 14:18:28.022] [main] [info] update#setState checking for updates
[2021-06-16 14:18:28.199] [main] [info] update#setState idle

Keywords for search:

bpasero commented 3 years ago

@lediur sorry to hear that, as a first step can you make sure to backup the entire %appdata%\Code - Insiders folder so that anything we try out here does not result in loss of information to diagnose this issue further?

The Code Cache folder is no longer being used for caching, it will now be inside %appdata%\Code - Insiders\CachedData. This folder will contain a folder per version (commit) of VSCode, so there must be a 3e0c442a8ee9fdc037d627d70fe291f72af04cfd folder in there. Within you should find a chrome folder, which is the location of the code cache.

Here are things to try:

[1]

, "enable-browser-code-loading": false
bpasero commented 3 years ago

I would still like to see if we can find an exception though, so with the old user data contents that do not work, try to run like this: code-insiders --verbose --open-devtools

This should open the developer tools and on the "Console" tab maybe something is printed?

image

lediur commented 3 years ago

Hey @bpasero thanks for the reply. Since I opened the ticket, I did try deleting all of the folders that started with “Cache” in case it was causing things to get stuck in a weird state. The folder you mentioned was one of the folders I deleted. Unfortunately, there was no change in behavior after removing those folders.

I also tried looking into the dev tools console earlier, but saw absolutely no logging output at all (no errors, no tracing, nothing).

I’ll try the “enable-browser-code-loading” flag and let you know what happens.

lediur commented 3 years ago

Okay, I added the flag as you suggested, and the editor loaded up properly as normal. To confirm, I removed the flag and restarted, and it freezes at the blank placeholder screen again.

bpasero commented 3 years ago

@lediur can you then do the code-insiders --verbose --open-devtools launch again without the enable-browser-code-loading?

lediur commented 3 years ago

Yep, sure thing. Here's the log from the terminal:

> code-insiders --verbose --open-devtools

[main 2021-06-17T06:59:45.926Z] Starting VS Code
[main 2021-06-17T06:59:45.928Z] from: c:\Users\dliu\scoop\apps\vscode-insiders\nightly-20210616\resources\app
[main 2021-06-17T06:59:45.928Z] args: {
  _: [],
  diff: false,
  add: false,
  goto: false,
  'new-window': false,
  'reuse-window': false,
  wait: false,
  help: false,
  'list-extensions': false,
  'show-versions': false,
  version: false,
  verbose: true,
  status: false,
  'prof-startup': false,
  'prof-v8-extensions': false,
  'disable-extensions': false,
  'disable-gpu': false,
  telemetry: false,
  debugRenderer: false,
  logExtensionHostCommunication: false,
  'skip-release-notes': false,
  'skip-welcome': false,
  'disable-telemetry': false,
  'disable-updates': false,
  'disable-keytar': false,
  'disable-workspace-trust': false,
  'disable-crash-reporter': false,
  'crash-reporter-id': 'ac0b41a1-e1bf-4d5e-b907-5ba3e31632f8',
  'skip-add-to-recently-opened': false,
  'unity-launch': false,
  'open-url': false,
  'file-write': false,
  'file-chmod': false,
  'driver-verbose': false,
  force: false,
  'do-not-sync': false,
  trace: false,
  'force-user-env': false,
  'force-disable-user-env': false,
  'open-devtools': true,
  __sandbox: false,
  'no-proxy-server': false,
  nolazy: false,
  'force-renderer-accessibility': false,
  'ignore-certificate-errors': false,
  'allow-insecure-localhost': false,
  logsPath: 'C:\\Users\\dliu\\AppData\\Roaming\\Code - Insiders\\logs\\20210616T235945'
}
[main 2021-06-17T06:59:45.930Z] Resolving machine identifier...
[main 2021-06-17T06:59:45.930Z] Resolved machine identifier: c9ec33d18138ccc2c3c9cfd4f41d6ef2f126138cdd5c397cc267c12cc36ce240
[main 2021-06-17T06:59:45.931Z] Main->SharedProcess#connect
[main 2021-06-17T06:59:45.950Z] StorageMainService: creating global storage
[main 2021-06-17T06:59:45.951Z] lifecycle (main): phase changed (value: 2)
[main 2021-06-17T06:59:45.952Z] windowsManager#open
[main 2021-06-17T06:59:45.952Z] windowsManager#open pathsToOpen [
  {
    workspace: { id: '34396725fd6acd65b70c27fa15c9d72f', uri: [g] },
    exists: true
  }
]
[main 2021-06-17T06:59:45.954Z] IPC Object URL: Registered new channel vscode:9c0ca6b6-35bf-4772-844d-865f4103f307.
[main 2021-06-17T06:59:45.955Z] window#validateWindowState: validating window state on 2 display(s) { mode: 1, x: 1094, y: 0, width: 1284, height: 1400 }
[main 2021-06-17T06:59:45.955Z] window#validateWindowState: multi-monitor working area { x: 0, y: 0, width: 2560, height: 1400 }
[main 2021-06-17T06:59:45.955Z] window#ctor: using window state { mode: 1, x: 1094, y: 0, width: 1284, height: 1400 }
[main 2021-06-17T06:59:45.956Z] window: using vscode-file:// protocol and V8 cache options: bypassHeatCheck
[main 2021-06-17T06:59:46.028Z] StorageMainService: creating workspace storage (34396725fd6acd65b70c27fa15c9d72f)
[main 2021-06-17T06:59:46.028Z] windowsManager#open used window count 1 (workspacesToOpen: 0, foldersToOpen: 1, emptyToRestore: 0, emptyToOpen: 0)
[main 2021-06-17T06:59:46.110Z] lifecycle (main): phase changed (value: 3)
[main 2021-06-17T06:59:46.119Z] update#setState idle
[main 2021-06-17T06:59:46.120Z] resolveShellEnv(): skipped (Windows)
[main 2021-06-17T06:59:46.483Z] [File Watcher (node.js)] [CHANGED] c:\Users\dliu\AppData\Roaming\Code - Insiders\User\globalStorage
[main 2021-06-17T06:59:46.485Z] [File Watcher (node.js)] [CHANGED] c:\Users\dliu\AppData\Roaming\Code - Insiders\User\globalStorage
[main 2021-06-17T06:59:46.627Z] resolveShellEnv(): skipped (Windows)
[main 2021-06-17T06:59:46.694Z] [File Watcher (node.js)] >> normalized [CHANGED] c:\Users\dliu\AppData\Roaming\Code - Insiders\User\globalStorage
[24288:0616/235946.950:VERBOSE1:CONSOLE(1)] "Main._createAppUI: 43.784912109375 ms", source: devtools://devtools/bundled/main/main.js (1)
[24288:0616/235946.971:VERBOSE1:CONSOLE(1)] "Main._showAppUI: 19.7060546875 ms", source: devtools://devtools/bundled/main/main.js (1)
[24288:0616/235947.102:VERBOSE1:CONSOLE(1)] "Main._initializeTarget: 11.714111328125 ms", source: devtools://devtools/bundled/main/main.js (1)
[main 2021-06-17T06:59:47.117Z] [File Watcher (node.js)] [CHANGED] c:\Users\dliu\AppData\Roaming\Code - Insiders\User\globalStorage
[24288:0616/235947.246:VERBOSE1:CONSOLE(1)] "Main._lateInitialization: 0.370849609375 ms", source: devtools://devtools/bundled/main/main.js (1)
[main 2021-06-17T06:59:47.327Z] [File Watcher (node.js)] >> normalized [CHANGED] c:\Users\dliu\AppData\Roaming\Code - Insiders\User\globalStorage

As before, there's no output in the devtools console. After a few minutes, I get a warning about not being able to load the sourcemap. Probably ancillary?:

image

bpasero commented 3 years ago

@lediur can you try this:

image

lediur commented 3 years ago

If I toggle the "Pause on exceptions" button to "on" and reload, I don't get anything. If I also check "pause on caught exceptions" I get some stuff. Do you want info on those?

bpasero commented 3 years ago

Yeah if possible.

bpasero commented 3 years ago

The thing that puzzles me a bit is that you can reproduce when CachedData is deleted, but in that case no code cache is generated and thus I do not think this is exactly the same issue as https://github.com/microsoft/vscode/issues/114459

To clarify, you can even reproduce when you do code-insiders --user-data-dir <some empty folder>?

lediur commented 3 years ago

Here's one:

Error: Cannot find module 'graceful-fs' Require stack: - electron/js2c/renderer_init

image

lediur commented 3 years ago

To clarify, you can even reproduce when you do code-insiders --user-data-dir <some empty folder>?

I haven't tried this yet. I can try that now.

lediur commented 3 years ago

Okay, just tried this:

image

Now the window is totally blank, and doesn't respond to dragging anymore. Still can aero snap it around so it's responsive.

bpasero commented 3 years ago

@lediur uh oh, that looks more like the issue we had...

Back to your normal user data dir and devtools, I recorded something to try out to see specifically where the error could happen by setting two breakpoints and only enabling break on error after the first one is hit, can you try? In your case I would expect the first breakpoint to get hit but not the second one. The first one will stop where that splashscreen is rendered (the shapes in the window before the workbench loads) and the second one is for successfully loading the workbench:

recording

lediur commented 3 years ago

Okay, just tried it. I set the two breakpoints at :6 and :17 and reloaded. I think I've hit the second breakpoint according to the call stack:

image

bpasero commented 3 years ago

uh oh, that looks more like the issue we had...

Actually I take that back. The reason that no placeholder UI shows is just a consequence of starting with a fresh user data dir where we did not cache the placeholder yet, that is why the window is empty.

bpasero commented 3 years ago

@lediur yeah, do you hit the one above too or does that end up in an error when you break on error + caught exceptions?

lediur commented 3 years ago

It hits the error that I screenshotted above before it gets to the breakpoint on line 6 (the return statement).

image

So:

bpasero commented 3 years ago

@lediur ok very confusing for me why this would be hit. To rule out corrupt installation issues can you try to reproduce from:

These are zip archives that need no installation. If they work, we can try the setup ones next.

lediur commented 3 years ago

Okay let me give those a shot.

lediur commented 3 years ago

Okay both builds seem to launch fine.

bpasero commented 3 years ago

@lediur ok next step to reinstall your main VSCode, not sure if you use system wide install or user install?

Just to confirm: you are NOT running with that argv.json change I had asked you initially right?

lediur commented 3 years ago

Yeah, I removed the argv flag you mentioned earlier.

I used the scoop package manager to install vscode (via scoop install vscode-insiders) which I believe uses the portable version. https://github.com/lukesampson/scoop-extras/blob/master/bucket/vscode-insiders.json indicates it downloads the archive at https://update.code.visualstudio.com/latest/win32-x64-archive/insider.

Do you still want me to go through the setup process with the installer? I could also try uninstalling and reinstalling via scoop, or unpacking the install from that archive link over my installation.

It's getting pretty late here so I'll have to take off soon.

bpasero commented 3 years ago

@lediur oh yeah, I am not entirely sure what scoop does. Let's keep the version on disk as it is for now to figure out more, there is one additional idea we had when I brought this up with team today:

Does this show the same symptoms?

PS: thanks a ton for being so responsive ❤️

lediur commented 3 years ago

Okay this is super bizarre but I just used rclone check to compare the two folders (my broken installation, at ~/scoop/apps/vscode-insiders/current, and the working download of yesterday's build). rclone found them to be identical (apparently using a hash check as well 😵)

lediur commented 3 years ago

Running code-insiders --no-cached-data with the argv "enable-browser-code-loading": false in place was able to successfully launch the editor.

bpasero commented 3 years ago

Ok thanks maybe I need to try out scoop myself to see if I can reproduce.

lediur commented 3 years ago

I can try installing fresh from scoop in a Windows Sandbox instance and see if it repros there?

lediur commented 3 years ago

I'll try doing that. Happy to be of help tracking this issue down - it's the least I can do :P

bpasero commented 3 years ago

Oh yeah that would be awesome!

lediur commented 3 years ago

Yep, I was able to repro with a fresh scoop install on a "fresh" Windows Sandbox image.

Windows PowerShell
Copyright (C) Microsoft Corporation. All rights reserved.
                                                                                                                        Install the latest PowerShell for new features and improvements! https://aka.ms/PSWindows                                                                                                                                                       PS C:\Users\WDAGUtilityAccount> Set-ExecutionPolicy RemoteSigned -scope CurrentUser                                     
Execution Policy Change
The execution policy helps protect you from scripts that you do not trust. Changing the execution policy might expose
you to the security risks described in the about_Execution_Policies help topic at
https:/go.microsoft.com/fwlink/?LinkID=135170. Do you want to change the execution policy?
[Y] Yes  [A] Yes to All  [N] No  [L] No to All  [S] Suspend  [?] Help (default is "N"): y
PS C:\Users\WDAGUtilityAccount> iwr -useb get.scoop.sh | iex
>>
Initializing...
Downloading scoop...
Extracting...
Creating shim...
Downloading main bucket...
Extracting...
Adding ~\scoop\shims to your path.
'lastupdate' has been set to '2021-06-17T02:10:08.4943169-07:00'
Scoop was installed successfully!
Type 'scoop help' for instructions.
PS C:\Users\WDAGUtilityAccount> scoop bucket add extras
Git is required for buckets. Run 'scoop install git' and try again.
PS C:\Users\WDAGUtilityAccount> scoop install git
Installing '7zip' (19.00) [64bit]
7z1900-x64.msi (1.7 MB) [=====================================================================================] 100%
Checking hash of 7z1900-x64.msi ... ok.
Extracting 7z1900-x64.msi ... done.
Linking ~\scoop\apps\7zip\current => ~\scoop\apps\7zip\19.00
Creating shim for '7z'.
Creating shortcut for 7-Zip (7zFM.exe)
'7zip' (19.00) was installed successfully!
Installing 'git' (2.32.0.windows.1) [64bit]
PortableGit-2.32.0-64-bit.7z.exe (44.4 MB) [==================================================================] 100%
Checking hash of PortableGit-2.32.0-64-bit.7z.exe ... ok.
Extracting dl.7z ... done.
Linking ~\scoop\apps\git\current => ~\scoop\apps\git\2.32.0.windows.1
Creating shim for 'git'.
Creating shim for 'gitk'.
Creating shim for 'git-gui'.
Creating shim for 'tig'.
Creating shim for 'git-bash'.
Creating shortcut for Git Bash (git-bash.exe)
Creating shortcut for Git GUI (git-gui.exe)
'git' (2.32.0.windows.1) was installed successfully!
PS C:\Users\WDAGUtilityAccount> scoop bucket add extras
Checking repo... ok
The extras bucket was added successfully.
PS C:\Users\WDAGUtilityAccount> scoop install vscode-insider
Couldn't find manifest for 'vscode-insider'.
PS C:\Users\WDAGUtilityAccount> scoop install vscode-insiders
WARN  This is a nightly version. Downloaded files won't be verified.
Installing 'vscode-insiders' (nightly-20210617) [64bit]
dl.7z (105.5 MB) [============================================================================================] 100%
vscode-install-context.reg (652 B) [==========================================================================] 100%
vscode-uninstall-context.reg (488 B) [========================================================================] 100%
Extracting dl.7z ... done.
Linking ~\scoop\apps\vscode-insiders\current => ~\scoop\apps\vscode-insiders\nightly-20210617
Creating shim for 'code-insiders'.
Creating shortcut for Visual Studio Code - Insiders (Code - Insiders.exe)
Running post-install script...
'vscode-insiders' (nightly-20210617) was installed successfully!
Notes
-----
Add Visual Studio Code as a context menu option by running:
"C:\Users\WDAGUtilityAccount\scoop\apps\vscode-insiders\current\vscode-install-context.reg"
PS C:\Users\WDAGUtilityAccount>

image

However, if I download the zip from the link in the manifest and unzip it directly, it works:

image

If I navigate to the scoop "installation" folder for vscode and launch the executable (avoiding the scoop shim), it does not work.


Oh. I think I might have found the issue.

Scoop maintains versions in separate folders and uses a symlink called "current" to point to the folder containing the most recent version:

image

If I open current/Code - Insiders.exe, it hangs with the issue.

If I open the original folder nightly-20210617/Code - Insiders.exe, it launches properly.

lediur commented 3 years ago

Can confirm that launching the non-symlinked folder nightly-20210616/Code - Insiders.exe works on my machine, with and without the argv flag.

😪

bpasero commented 3 years ago

@lediur great findings! I will try to reproduce as well.

In the debugger when you see that exception raised about "gracefulfs" not being found, if you press play to continue, are there more exception breakpoints hit after, or is that the only one? I wonder if that one is expected in node.js but another one is not.

lediur commented 3 years ago

It throws another graceful-fs exception after the first one. Seems like it's in the same place so maybe being called twice?

exception 1: image

exception 2: image

Okay I'm going to try and get some sleep now, but I'll check back in in the morning if I can help further debug. Thanks so much for your time and help working through this!

bpasero commented 3 years ago

Yeah looks like it, thanks a ton, now that I should be able to reproduce I can investigate further. I hope this is addressable by us in some way...

bpasero commented 3 years ago

This is very easy to reproduce:

=> 🐛 nothing loads, reload from devtools with break on error ends up in the exception that gracefulfs cannot be found

I get a feeling that this may be ASAR related.

bpasero commented 3 years ago

Here is something interesting, when running with our loader loading node.js modules, the paths include the node_modules.asar thing:

image

But when running with vscode-file and the node.js standard loader the paths are only this:

image

And here we go, when I do run without symlink I see the asar file is back on the paths!

image

bpasero commented 3 years ago

Further looking into it, it falls apart here:

https://github.com/microsoft/vscode/blob/30f0d188c71400fbb9a1e2b00b4f20ebe1256d6d/src/bootstrap.js#L47-L47

appRoot is actually the resolved symlink (nightly-20210617)

And then here:

https://github.com/microsoft/vscode/blob/30f0d188c71400fbb9a1e2b00b4f20ebe1256d6d/src/bootstrap.js#L73-L73

This check is never true because for node.js the paths are the symlink'ed form (current).

The property appRoot is coming all the way from here:

https://github.com/microsoft/vscode/blob/30f0d188c71400fbb9a1e2b00b4f20ebe1256d6d/src/bootstrap.js#L73-L73

Which seems to be using require.toUrl which I think is a method our loader defines. But I fail to understand where the loader gets its root path from.

bpasero commented 3 years ago

I wonder if a pragmatic fix could be to just always add the node_modules.asar file to the lookup paths and then remove this change again once the filesystem has moved off the renderer because then gracefulfs wouldn't be needed anymore.

@alexdima thoughts?

lediur commented 3 years ago

Nice debugging. Out of curiosity and to narrow things down I downloaded the Linux archive version and set up a similar symlink structure on WSL, and that launched fine, so seems like it's Windows specific. I have very little knowledge of the internals of the editor startup process but thought this might help save a bit of time.

alexdima commented 3 years ago

@lediur @bpasero Thank you for figguring this out! Very impressive analysis! I'm working on a fix.

lediur commented 3 years ago

/verified

NatoBoram commented 3 years ago

It works in 1.58.0-insider 🎉