vscode-remote-release
vscode-remote-release copied to clipboard
microsoft
DevContainer stuck on startup with latest container extension
- VSCode Version: 1.86
- Local OS Version: Windows 11
- Remote OS Version: Ubuntu 22.04
- Remote Extension/Connection Type: DevContainer on remote SSH server
- Logs:
2024-02-06 10:00:50.608 [info] Extension host with pid 17324 started
2024-02-06 10:00:50.609 [info] Skipping acquiring lock for c:\Users\nrs338u\AppData\Roaming\Code - Insiders\User\workspaceStorage\36748a8053f8b34fa2252c7bb44f7bfe.
2024-02-06 10:00:50.609 [info] $getCanonicalURI invoked for authority (dev-container)
2024-02-06 10:00:50.621 [info] ExtensionService#_doActivateExtension ms-vscode-remote.remote-containers, startup: false, activationEvent: 'onResolveRemoteAuthority:dev-container'
2024-02-06 10:00:51.348 [info] [resolveAuthority(dev-container,1)][0ms] activating remote resolvers ssh-remote+myserver1.mydomain.net -> dev-container+7b22686f737450617468223a222f686f6d652f6769616467752f736f757263652f4749412e53656c6653657276696365222c226c6f63616c446f636b6572223a66616c73652c22636f6e66696746696c65223a7b22246d6964223a312c2270617468223a222f686f6d652f6769616467752f736f757263652f4749412e53656c66536572766963652f2e646576636f6e7461696e65722f494d41432f646576636f6e7461696e65722e6a736f6e222c22736368656d65223a227673636f64652d66696c65486f7374227d7d
2024-02-06 10:00:51.349 [info] [resolveAuthority(dev-container,1)][1ms] activating resolver for ssh-remote+myserver1.mydomain.net...
2024-02-06 10:00:51.349 [info] [resolveAuthority(dev-container,1)][1ms] activating resolver for dev-container+7b22686f737450617468223a222f686f6d652f6769616467752f736f757263652f4749412e53656c6653657276696365222c226c6f63616c446f636b6572223a66616c73652c22636f6e66696746696c65223a7b22246d6964223a312c2270617468223a222f686f6d652f6769616467752f736f757263652f4749412e53656c66536572766963652f2e646576636f6e7461696e65722f494d41432f646576636f6e7461696e65722e6a736f6e222c22736368656d65223a227673636f64652d66696c65486f7374227d7d...
2024-02-06 10:00:51.358 [info] ExtensionService#_doActivateExtension ms-vscode-remote.remote-ssh, startup: false, activationEvent: 'onResolveRemoteAuthority:ssh-remote'
2024-02-06 10:00:51.408 [info] [resolveAuthority(dev-container,1)][60ms] invoking resolveExecServer() for ssh-remote+myserver1.mydomain.net
2024-02-06 10:00:52.414 [info] [resolveAuthority(dev-container,1)][1066ms] waiting...
2024-02-06 10:00:53.427 [info] [resolveAuthority(dev-container,1)][2079ms] waiting...
2024-02-06 10:00:54.432 [info] [resolveAuthority(dev-container,1)][3084ms] waiting...
2024-02-06 10:00:55.442 [info] [resolveAuthority(dev-container,1)][4094ms] waiting...
2024-02-06 10:00:56.443 [info] [resolveAuthority(dev-container,1)][5095ms] waiting...
2024-02-06 10:00:57.444 [info] [resolveAuthority(dev-container,1)][6096ms] waiting...
2024-02-06 10:00:58.449 [info] [resolveAuthority(dev-container,1)][7101ms] waiting...
2024-02-06 10:00:59.449 [info] [resolveAuthority(dev-container,1)][8101ms] waiting...
2024-02-06 10:01:00.465 [info] [resolveAuthority(dev-container,1)][9117ms] waiting...
2024-02-06 10:01:01.472 [info] [resolveAuthority(dev-container,1)][10124ms] waiting...
2024-02-06 10:01:02.482 [info] [resolveAuthority(dev-container,1)][11134ms] waiting...
2024-02-06 10:01:03.489 [info] [resolveAuthority(dev-container,1)][12141ms] waiting...
2024-02-06 10:01:04.504 [info] [resolveAuthority(dev-container,1)][13156ms] waiting...
2024-02-06 10:01:05.517 [info] [resolveAuthority(dev-container,1)][14169ms] waiting...
2024-02-06 10:01:06.531 [info] [resolveAuthority(dev-container,1)][15183ms] waiting...
2024-02-06 10:01:07.535 [info] [resolveAuthority(dev-container,1)][16187ms] waiting...
2024-02-06 10:01:08.539 [info] [resolveAuthority(dev-container,1)][17191ms] waiting...
2024-02-06 10:01:09.542 [info] [resolveAuthority(dev-container,1)][18194ms] waiting...
2024-02-06 10:01:10.555 [info] [resolveAuthority(dev-container,1)][19207ms] waiting...
2024-02-06 10:01:11.559 [info] [resolveAuthority(dev-container,1)][20211ms] waiting...
2024-02-06 10:01:12.561 [info] [resolveAuthority(dev-container,1)][21213ms] waiting...
2024-02-06 10:01:13.572 [info] [resolveAuthority(dev-container,1)][22224ms] waiting...
Steps to Reproduce:
- Connect to remote ssh and open a project folder
- Run "Reopen in container" (same issue with rebuilding without cache)
- the opening process is stuck in the following mode forever:
i couldn't find proper logs (any hints would be welcome). The logs above show that something is blocking/waiting but not sure how I can what is blocking.
the issue doesn't happen with container extension 0.327. Downgrading from newer versions fixes the issue.
Does this issue occur when you try this locally?: It's a DevContainer only issue
I think the latest version had a fix for #9185 but it looks like it didn't fix the issue it just made it impossible to start a container at all. Can't hang on reconnecting if you can't connect in the first place I guess
the problem still persist with the latest vscode update to 1.86.1. It doesn't seem to be related to the glibc issue. also the pre-release version has the same issue. the last working version is 0.327.
@connor4312 you mentioned that the waiting issue on reconnecting is fixed in the latest version. i never had that issue on reconning but somehow i have it now on the initial connect. Any idea what this can be?
Is there a log in the Remote-SSH output channel in this scenario? Can someone share it?
@roblourens i can see the following in the SSH output now. somehow it looks like it's stuck when starting the ssh-client:
[13:09:51.641] Log Level: 2
[13:09:51.670] Opening exec server for ssh-remote+myserver1.mydomain.net
[13:09:51.678] VS Code version: 1.86.2
[13:09:51.679] Remote-SSH version: [email protected]
[13:09:51.679] win32 x64
[13:09:51.703] Initizing new exec server for ssh-remote+myserver1.mydomain.net
[13:09:51.775] Using commit id "903b1e9d8990623e3d7da1df3d33db3e42d80eda" and quality "stable" for server
[13:09:51.787] Install and start server if needed
[13:09:51.809] Checking ssh with "C:\Program Files\OpenSSH\ssh.exe -V"
[13:09:52.220] > OpenSSH_for_Windows_9.5p1, LibreSSL 3.8.2
one strange thing i noticed is that sometimes i can get it to work for one session when i change the devcontainer extension version. basically switching to another version (e.g. pre-release). close vscode and connect directly to the devcontainer on ssh opens the devcontainer. closing vscode and trying the same again usually leads to the same issue and vscode is just waiting at the same point as in the log above.
That's all? This is just running ssh.exe -V, as described, and it should print the version number and terminate immediately. Are you able to run that command manually in a terminal?
if you look at the logs it returns the version after calling ssh -V but doesn't start with the next command. basically it just waits there forever. so I'm not sure what happens in your code after checking the version. but the version check works perfectly fine even manually running it. also no issue with ssh -V like a stuck process after printing the version to the console. so it must be the next step.
the next thing which should appear in the log is something like the following. but that doesn't show up so I'm not sure what happens between version output and triggering this step/log.
Running script with connection command: "C:\Program Files\OpenSSH\ssh.exe" -T -D 56611 "myserver1.mydomain.net" bash
Well we've had multiple issues with this in the past eg https://github.com/microsoft/vscode-remote-release/issues/3731#issuecomment-700976874
but I think it's not the same since you did get output. But I don't think that anything very interesting happens between this and the next line that should log. Could you try with "remote.SSH.useLocalServer": true,?
the useLocalServer: true didn't make a change as far as the connection logs go. still stuck at the same point. but with useLocalServer i get a the following warning which is a bit strange as the remote ssh server is a linux ubuntu ssh server:
Failed to find a non-Windows SSH installed. Password prompts may not be displayed properly! Disable remote.SSH.useLocalServer if needed.
now i also tried all the pre-prelease versions of the dev container extension. the remote SSH extension was always at version 0.108 in all the tests. even though the logs might let you think it's all about the ssh extension, the changed behavior is due to the dev container extension.
the versions i tested:
Remote SSH: 0.108.0 (never changed it in the tests)
Dev Container
327 - prod - works
328 - pre - works
329 - pre - works
330 - pre - works
331 - pre - works
332 - pre - doesn't work
333 - pre - doesn't work
334 - pre - doesn't work
335 - pre - doesn't work
336 - pre - doesn't work
337 - pre - doesn't work
338 - pre - doesn't work
so it really is down to a change in the devcontainer between the version 331 and 332. i guess that should narrow it down quite a bit.
332 introduced a bug that is fixed in 0.346.0-pre-release, could you give that a try? It seemed to mainly affect legacy connections where Dev Containers would run ssh itself, but I guess there is a chance this also affects connection through Remote-SSH. (The bug is that it would ask for Remote-SSH's ExecServer before the Dev Container resolver finished, not sure if that's a problem.)
@chrmarti unfortunately still the same issue with 346. I'm pretty sure it has something to do with timing. When I test multiple times in a row it works from time to time it works once. But the next try is then back to the broken state again.
Please also append the Dev Containers log from when this happens. (F1 > Dev Containers: Show Container Log)
@chrmarti unfortunately there's no dev container log item in the menu at this time. also in the log-folder i can't see anything for the dev container extension. the ssh extension log has the same thing as shown in the screenshot below.
Could you try enabling the Exec Server for Remote-SSH in the user settings and check if you can still connect to the SSH server with Remote-SSH:
@chrmarti i just tried the remote ssh extension for about 20 times (starting just a remote ssh session with vscode and not opening a devcontainer). i did like 10 times with exec server enabled and 10 times with exec server disabled. all the tests were with version 109. in this tests vscode never got stuck after showing the ssh client version (stderr> OpenSSH_9.5p1, OpenSSL 3.1.4 24 Oct 2023).
after the SSH tests i tried with the latest devcontainer release-version (348) and the exec server enabled and the connection started to hang again after showing the ssh client version.
this deadlock situation still happens with the march update (1.88) though looks more like 50% chance that it works (before it was like 90% that it would fail).
+1, rollback devcontainer to version 327 can fix this problem. I guess that related to windows openssh version?
My environment is windows 10 22H2 19045.4046
ssh client version is OpenSSH_for_Windows_8.1p1, LibreSSL 3.0.2
I already changed from the windows SSH client to the one bundled with git. but same issue. currently I'm using OpenSSH_9.5p1, OpenSSL 3.1.4 24 Oct 2023. still v331 and older works. everthing after v331 started to have this problem more or less often.
The fix for https://github.com/microsoft/vscode-remote-release/issues/9504 did not cover all cases. Working on an improved fix.
Could give Dev Containers 0.359.0-pre-release a try and let us know if that works?
@chrmarti 0.359.0-pre-release looks promising so far! likely fixed the issue here completely.
@OneCyrus Great, thanks for your patience! I'll close this issue, please open new issues for any remaining problems including new logs.
Greetings!
Thank you very much for the project!
Just to clarify, is the issue with long waits may still happen in the following VSCode version?:
Version: 1.88.1
Commit: e170252f762678dec6ca2cc69aba1570769a5d39
Date: 2024-04-10T17:34:12.840Z
Electron: 28.2.8
ElectronBuildId: 27744544
Chromium: 120.0.6099.291
Node.js: 18.18.2
V8: 12.0.267.19-electron.0
OS: Linux x64 5.19.0-35-generic
Currently, when opening a dev-container, 'am getting almost infinite log messages similar to:
...
log.ts:419 INFO Started local extension host with pid 92156.
log.ts:419 INFO Invoking resolveAuthority(dev-container)...
log.ts:419 INFO [LocalProcess0][resolveAuthority(dev-container,1)][0ms] obtaining proxy...
log.ts:419 INFO [LocalProcess0][resolveAuthority(dev-container,1)][0ms] invoking...
log.ts:419 INFO [LocalProcess0][resolveAuthority(dev-container,1)][1000ms] waiting...
log.ts:419 INFO [LocalProcess0][resolveAuthority(dev-container,1)][2000ms] waiting...
log.ts:419 INFO [LocalProcess0][resolveAuthority(dev-container,1)][3000ms] waiting...
...
log.ts:419 INFO [LocalProcess0][resolveAuthority(dev-container,1)][291001ms] waiting...
log.ts:419 INFO [LocalProcess0][resolveAuthority(dev-container,1)][292001ms] waiting...
log.ts:419 INFO [LocalProcess0][resolveAuthority(dev-container,1)][293001ms] waiting...
log.ts:419 INFO [LocalProcess0][resolveAuthority(dev-container,1)][294001ms] waiting...
...
...and then, at some point, the corresponding dev-container gets created with required services and logs:
...
log.ts:419 INFO [LocalProcess0][resolveAuthority(dev-container,1)][299000ms] waiting...
log.ts:419 INFO [LocalProcess0][resolveAuthority(dev-container,1)][299301ms] returned WebSocket(127.0.0.1:44911)
log.ts:419 INFO resolveAuthority(dev-container) returned 'WebSocket(127.0.0.1:44911)' after 299302 ms
log.ts:419 INFO Creating a socket (renderer-Management-e4bbe77d-0323-4dd2-8e00-33c445d14030)...
log.ts:419 INFO Creating a socket (renderer-ExtensionHost-8f0b22de-5ca9-40ab-a100-cf2f2a3d0861)...
log.ts:419 INFO Creating a socket (renderer-Management-e4bbe77d-0323-4dd2-8e00-33c445d14030) was successful after 187 ms.
log.ts:419 INFO Creating a socket (renderer-ExtensionHost-8f0b22de-5ca9-40ab-a100-cf2f2a3d0861) was successful after 325 ms.
console.ts:137 [Extension Host] Congratulations, the extension is working!
...
There was no such issue previously, and it has been happening since today - not sure why though. If I do create the containers manually via docker compose up, those get created in a few seconds - the machine resources should not be the case (4x3.6GHz cores, 32 GB RAM with 60% free during the issue observation).
Interesting that it seems related to files, too.
When I ran "Reopen in Container" and nothing happened, I opened a terminal after a minute of waiting in parallel and removed directory node_modules in the project directory. With the directory removed VSCode, finally, showed "Opening Remote..." message in the bottom left almost instantly, and the time of "INFO [LocalProcess0][resolveAuthority(dev-container,1)][...ms] waiting..." reduced from usual ~294001ms to 144709ms.
So, since the above sudden event, I tend to remove all local fairly old Nuxt project files, including Yarn files with the Node modules and .cache directories before opening the project in dev-container, but... am still curious whether that is expected in the version mentioned above? I believe no such issue existed before.
I see there are logs in VSCode "Terminal" during the "waiting" issue:
[41 ms] Dev Containers 0.354.0 in VS Code 1.88.1 (e170252f762678dec6ca2cc69aba1570769a5d39).
[40 ms] Start: Resolving Remote
[49 ms] Initializing configuration support...
[50 ms] Internal initialization of dev container support package...
[74 ms] Setting up container for folder or workspace: /home/user/projects/git/test-testpay
[78 ms] Start: Check Docker is running
[78 ms] Start: Run: docker version
[93 ms] Client: Docker Engine - Community
Version: 26.0.2
API version: 1.45
Go version: go1.21.9
Git commit: 3c863ff
Built: Thu Apr 18 16:27:07 2024
OS/Arch: linux/amd64
Context: default
[93 ms] Server: Docker Engine - Community
Engine:
Version: 26.0.2
API version: 1.45 (minimum version 1.24)
Go version: go1.21.9
Git commit: 7cef0d9
Built: Thu Apr 18 16:27:07 2024
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: 1.6.31
GitCommit: e377cd56a71523140ca6ae87e30244719194a521
runc:
Version: 1.1.12
GitCommit: v1.1.12-0-g51d5e94
docker-init:
Version: 0.19.0
GitCommit: de40ad0
[96 ms] Start: Run: docker volume ls -q
[109 ms] Start: Run: docker inspect --type container 3f90c77b39a7a8e99c5c281938b9ab38db91e222084263af69f9db3a515d8335
[121 ms] Start: Run: docker ps -q -a --filter label=vsch.local.folder=/home/user/projects/git/test-testpay --filter label=vsch.quality=stable
[134 ms] Start: Run: docker ps -q -a --filter label=devcontainer.local_folder=/home/user/projects/git/test-testpay --filter label=devcontainer.config_file=/home/user/projects/git/test-testpay/.devcontainer/devcontainer.json
[147 ms] Start: Run: docker ps -q -a --filter label=devcontainer.local_folder=/home/user/projects/git/test-testpay
[160 ms] Start: Run: docker ps -q -a --filter label=devcontainer.local_folder=/home/user/projects/git/test-testpay
[171 ms] Running Dev Containers CLI: read-configuration --workspace-folder /home/user/projects/git/test-testpay --id-label devcontainer.local_folder=/home/user/projects/git/test-testpay --id-label devcontainer.config_file=/home/user/projects/git/test-testpay/.devcontainer/devcontainer.json --log-level debug --log-format json --config /home/user/projects/git/test-testpay/.devcontainer/devcontainer.json --mount-workspace-git-root
[172 ms] Start: Run: /usr/share/code/code /home/user/.vscode/extensions/ms-vscode-remote.remote-containers-0.354.0/dist/spec-node/devContainersSpecCLI.js read-configuration --workspace-folder /home/user/projects/git/test-testpay --id-label devcontainer.local_folder=/home/user/projects/git/test-testpay --id-label devcontainer.config_file=/home/user/projects/git/test-testpay/.devcontainer/devcontainer.json --log-level debug --log-format json --config /home/user/projects/git/test-testpay/.devcontainer/devcontainer.json --mount-workspace-git-root
[392 ms] @devcontainers/cli 0.58.0. Node.js v18.18.2. linux 5.19.0-35-generic x64.
[392 ms] Start: Run: docker ps -q -a --filter label=devcontainer.local_folder=/home/user/projects/git/test-testpay --filter label=devcontainer.config_file=/home/user/projects/git/test-testpay/.devcontainer/devcontainer.json
In other words, with the above in VSCode "Terminal", VSCode's "DevTools Console" outputs "INFO [LocalProcess0][resolveAuthority(dev-container,1)][...ms]" each second in parallel.
Sometimes, it shows the following in "Terminal" and hangs similarly (with "INFO [LocalProcess0][resolveAuthority]..." message repeating each second), too:
...
[592 ms] @devcontainers/cli 0.58.0. Node.js v18.18.2. linux 5.19.0-35-generic x64.
[592 ms] Start: Run: docker buildx version
[639 ms] github.com/docker/buildx v0.14.0 171fcbe
[639 ms]
[639 ms] Start: Resolving Remote
[645 ms] Loading 137 extra certificates from /etc/ssl/certs/ca-certificates.crt.
@artshade Please give the latest pre-release version of the Dev Containers extension a try (currently 0.361.0-pre-release).
@artshade Please give the latest pre-release version of the Dev Containers extension a try (currently 0.361.0-pre-release).
Thank you very much for the response! :sparkles:
I've installed v0.361.0 (pre-release), restarted VS Code (v1.88.1, commit e170252f762678dec6ca2cc69aba1570769a5d39), and tried in actual dev. environment - no such issue is being observed anymore right now :rocket:
Sincere gratitude!