search

microsoft / vscode

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

Failed to connect to the remote extension host server (Error: Connection error: Invalid second message) #135643

Closed bl-snwl closed 2 years ago

bl-snwl commented 3 years ago

Steps to Reproduce:

  1. Attempt to connect to server
  2. Fail with message "Failed to connect to the remote extension host server (Error: Connection error: Invalid second message)"

Does this issue occur when you try this locally?: No Does this issue occur when you try this locally and all extensions are disabled?: No

[15:06:26.311] Log Level: 1
[15:06:26.325] remote-ssh@0.65.1
[15:06:26.326] win32 x64
[15:06:26.326] SSH Resolver called for "ssh-remote+buildsc_local", attempt 1
[15:06:26.327] "remote.SSH.useLocalServer": false
[15:06:26.327] "remote.SSH.showLoginTerminal": false
[15:06:26.327] "remote.SSH.remotePlatform": {"buildsc_local":"linux"}
[15:06:26.327] "remote.SSH.sshPath": undefined
[15:06:26.327] "remote.SSH.sshConfigurationFile": undefined
[15:06:26.327] "remote.SSH.useFlock": true
[15:06:26.328] "remote.SSH.lockfilesInTmp": false
[15:06:26.328] "remote.SSH.localServerDownload": auto
[15:06:26.328] "remote.SSH.remoteServerListenOnSocket": false
[15:06:26.328] "remote.SSH.showLoginTerminal": false
[15:06:26.328] "remote.SSH.defaultExtensions": []
[15:06:26.328] SSH Resolver called for host: buildsc_local
[15:06:26.328] Setting up SSH remote "buildsc_local"
[15:06:26.352] Using commit id "2b9aebd5354a3629c3aba0a5f5df49f43d6689f8" and quality "stable" for server
[15:06:26.358] Install and start server if needed
[15:06:26.385] Checking ssh with "ssh -V"
[15:06:26.534] > OpenSSH_for_Windows_7.7p1, LibreSSL 2.6.5

[15:06:26.543] Running script with connection command: ssh -T -D 58165 "buildsc_local" bash
[15:06:26.548] Terminal shell path: C:\Windows\System32\cmd.exe
[15:06:26.898] "install" terminal received data: "warning: agent returned different signature type ssh-rsa (expected rsa-sha2-512)
]0;C:\Windows\System32\cmd.exe[?25h"
[15:06:26.898] Got some output, clearing connection timeout
[15:06:27.953] "install" terminal received data: "7b629e1a5e5d: running"
[15:06:27.997] "install" terminal received data: "Acquiring lock on /home/username/.vscode-server/bin/2b9aebd5354a3629c3aba0a5f5
df49f43d6689f8/vscode-remote-lock.username.2b9aebd5354a3629c3aba0a5f5df49f43d6
689f8"
[15:06:28.023] "install" terminal received data: "Found existing installation at /home/username/.vscode-server/bin/2b9aebd5354a3
629c3aba0a5f5df49f43d6689f8...
Checking /home/username/.vscode-server/.2b9aebd5354a3629c3aba0a5f5df49f43d6689
f8.log and /home/username/.vscode-server/.2b9aebd5354a3629c3aba0a5f5df49f43d66
89f8.pid for a running server
Looking for server with pid: 8491"
[15:06:28.033] "install" terminal received data: "Starting server with command... /home/username/.vscode-server/bin/2b9aebd5354a
3629c3aba0a5f5df49f43d6689f8/server.sh --start-server --host=127.0.0.1 --enable-
remote-auto-shutdown  --port=0  &> "/home/username/.vscode-server/.2b9aebd5354
a3629c3aba0a5f5df49f43d6689f8.log" < /dev/null
printenv:
    SSH_CONNECTION=10.20.23.60 58166 10.20.23.88 22
    LANG=en_US.UTF-8
    SSH_AUTH_SOCK=/tmp/ssh-yJS8RFRImX/agent.9696   
    XDG_SESSION_ID=42
    USER=username
    PWD=/home/username
    HOME=/home/username
    SSH_CLIENT=10.20.23.60 58166 22
    MAIL=/var/mail/username
    SHELL=/bin/bash
    SHLVL=2
    VSCODE_AGENT_FOLDER=/home/username/.vscode-server
    LOGNAME=username
    XDG_RUNTIME_DIR=/run/user/1000
    PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games
:/usr/local/games:/snap/bin
    _=/usr/bin/printenv
Spawned remote server: 9741"
[15:06:28.052] "install" terminal received data: "
Waiting for server log..."
[15:06:28.058] "install" terminal received data: ""
[15:06:28.103] "install" terminal received data: "Waiting for server log..."
[15:06:28.126] "install" terminal received data: "Waiting for server log..."
[15:06:28.165] "install" terminal received data: "Waiting for server log..."
[15:06:28.217] "install" terminal received data: " 
*
* Reminder: You may only use this software with Visual Studio family products,  [?25h
* as described in the license (https://go.microsoft.com/fwlink/?linkid=2077057) "
[15:06:28.223] "install" terminal received data: "
*

7b629e1a5e5d: start"
[15:06:28.235] "install" terminal received data: "
SSH_AUTH_SOCK==/tmp/ssh-yJS8RFRImX/agent.9696==
DISPLAY====
webUiAccessToken====
listeningOn==44693=="
[15:06:28.240] "install" terminal received data: "
osReleaseId==ubuntu==
arch==x86_64==
tmpDir==/run/user/1000==
platform==linux==
unpackResult====
didLocalDownload==0==
downloadTime====
installTime====
extInstallTime====
serverStartTime==180==
connectionToken==11aa1111-a11a-1a11-11a1-1111a11111a1==
7b629e1a5e5d: end"
[15:06:28.241] Received install output: 
SSH_AUTH_SOCK==/tmp/ssh-yJS8RFRImX/agent.9696==
DISPLAY====
webUiAccessToken====
listeningOn==44693==
osReleaseId==ubuntu==
arch==x86_64==
tmpDir==/run/user/1000==
platform==linux==
unpackResult====
didLocalDownload==0==
downloadTime====
installTime====
extInstallTime====
serverStartTime==180==
connectionToken==11aa1111-a11a-1a11-11a1-1111a11111a1==

[15:06:28.242] Remote server is listening on 44693
[15:06:28.242] Parsed server configuration: {"serverConfiguration":{"remoteListeningOn":{"port":44693},"osReleaseId":"ubuntu","arch":"x86_64","webUiAccessToken":"","sshAuthSock":"/tmp/ssh-yJS8RFRImX/agent.9696","display":"","tmpDir":"/run/user/1000","platform":"linux","connectionToken":"11aa1111-a11a-1a11-11a1-1111a11111a1"},"serverStartTime":180,"installUnpackCode":""}
[15:06:28.245] Starting forwarding server. localPort 58168 -> socksPort 58165 -> remotePort 44693
[15:06:28.247] Forwarding server listening on 58168
[15:06:28.247] Waiting for ssh tunnel to be ready
[15:06:28.248] Tunneled 44693 to local port 58168
[15:06:28.249] Resolved "ssh-remote+buildsc_local" to "127.0.0.1:58168"
[15:06:28.249] Updating $SSH_AUTH_SOCK: ln -f -s "/tmp/ssh-yJS8RFRImX/agent.9696" "/run/user/1000/vscode-ssh-auth-sock-362699774"
[15:06:28.249] Using cwd: vscode-remote://ssh-remote%2Bbuildsc_local/
[15:06:28.249] Remote extension host environment: {"SSH_AUTH_SOCK":"/run/user/1000/vscode-ssh-auth-sock-362699774"}
[15:06:28.250] [Forwarding server 58168] Got connection 0
[15:06:28.263] TELEMETRY: {"eventName":"resolver","properties":{"osReleaseId":"ubuntu","arch":"x86_64","askedPw":"0","askedPassphrase":"0","asked2fa":"0","askedHostKey":"0","remoteInConfigFile":"1","gotUnrecognizedPrompt":"0","dynamicForwarding":"1","localServer":"0","didLocalDownload":"0","installUnpackCode":"0","outcome":"success"},"measures":{"resolveAttempts":1,"retries":1,"timing.totalResolveTime":1936,"timing.preSshTime":221,"timing.establishSshTime":1407,"timing.scriptTime":1694,"timing.serverStartTime":180}}
[15:06:28.265] ------

[15:06:28.287] [Forwarding server 58168] Got connection 1
[15:06:28.602] [Forwarding server 58168] Got connection 2

Then pop-up with message:

Failed to connect to the remote extension host server (Error: Connection error: Invalid second message)
bl-snwl commented 3 years ago

Tested with vscode 1.53.2, same issue.

Tested with vsocde 1.52.1 issue does not occur.

Log from successful connection with vscode 1.52.1

[15:22:55.535] Log Level: 1
[15:22:55.557] remote-ssh@0.64.0
[15:22:55.558] win32 x64
[15:22:55.560] SSH Resolver called for "ssh-remote+buildsc_local", attempt 1
[15:22:55.561] "remote.SSH.useLocalServer": false
[15:22:55.562] "remote.SSH.showLoginTerminal": false
[15:22:55.563] "remote.SSH.remotePlatform": {"buildsc_local":"linux"}
[15:22:55.563] "remote.SSH.sshPath": undefined
[15:22:55.564] "remote.SSH.sshConfigurationFile": undefined
[15:22:55.564] "remote.SSH.useFlock": true
[15:22:55.565] "remote.SSH.lockfilesInTmp": false
[15:22:55.565] "remote.SSH.localServerDownload": auto
[15:22:55.566] "remote.SSH.remoteServerListenOnSocket": false
[15:22:55.567] "remote.SSH.showLoginTerminal": false
[15:22:55.567] "remote.SSH.defaultExtensions": []
[15:22:55.568] SSH Resolver called for host: buildsc_local
[15:22:55.568] Setting up SSH remote "buildsc_local"
[15:22:55.629] Using commit id "ea3859d4ba2f3e577a159bc91e3074c5d85c0523" and quality "stable" for server
[15:22:55.644] Install and start server if needed
[15:22:55.676] Checking ssh with "ssh -V"
[15:22:55.989] > OpenSSH_for_Windows_7.7p1, LibreSSL 2.6.5

[15:22:56.008] Running script with connection command: ssh -T -D 58655 "buildsc_local" bash
[15:22:56.015] Terminal shell path: C:\Windows\System32\cmd.exe
[15:22:57.006] "install" terminal received data: "warning: agent returned different signature type ssh-rsa (expected rsa-sha2-512)
]0;C:\Windows\System32\cmd.exe[?25h"
[15:22:57.007] Got some output, clearing connection timeout
[15:22:57.989] "install" terminal received data: "e2fb0795585c: running"
[15:22:58.077] "install" terminal received data: "Acquiring lock on /home/username/.vscode-server/bin/ea3859d4ba2f3e577a159bc91e
3074c5d85c0523/vscode-remote-lock.username.ea3859d4ba2f3e577a159bc91e3074c5d85
c0523"
[15:22:58.087] "install" terminal received data: "Found existing installation at /home/username/.vscode-server/bin/ea3859d4ba2f3
e577a159bc91e3074c5d85c0523...
Checking /home/username/.vscode-server/.ea3859d4ba2f3e577a159bc91e3074c5d85c05
23.log and /home/username/.vscode-server/.ea3859d4ba2f3e577a159bc91e3074c5d85c
0523.pid for a running server
Looking for server with pid: 2036"
[15:22:58.113] "install" terminal received data: "Starting server with command... /home/username/.vscode-server/bin/ea3859d4ba2f
3e577a159bc91e3074c5d85c0523/server.sh --start-server --host=127.0.0.1 --enable-
remote-auto-shutdown  --port=0  &> "/home/username/.vscode-server/.ea3859d4ba2
f3e577a159bc91e3074c5d85c0523.log" < /dev/null
printenv:
    SSH_CONNECTION=10.20.23.60 58659 10.20.23.88 22
    LANG=en_US.UTF-8
    SSH_AUTH_SOCK=/tmp/ssh-VJisAmbVT3/agent.10918  
    XDG_SESSION_ID=47
    USER=username
    PWD=/home/username
    HOME=/home/username
    SSH_CLIENT=10.20.23.60 58659 22
    MAIL=/var/mail/username
    SHELL=/bin/bash
    SHLVL=2"
[15:22:58.120] "install" terminal received data: "
    VSCODE_AGENT_FOLDER=/home/username/.vscode-server
    LOGNAME=username
    XDG_RUNTIME_DIR=/run/user/1000
    PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games
:/usr/local/games:/snap/bin
    _=/usr/bin/printenv"
[15:22:58.142] "install" terminal received data: "
Spawned remote server: 10966
Waiting for server log..."
[15:22:58.169] "install" terminal received data: ""
[15:22:58.175] "install" terminal received data: "Waiting for server log..."
[15:22:58.214] "install" terminal received data: "Waiting for server log..."
[15:22:58.249] "install" terminal received data: "Waiting for server log..."
[15:22:58.301] "install" terminal received data: " 
*
* Reminder: You may only use this software with Visual Studio family products,  [?25h
* as described in the license (https://go.microsoft.com/fwlink/?linkid=2077057) 
*
"
[15:22:58.314] "install" terminal received data: "
e2fb0795585c: start
sshAuthSock==/tmp/ssh-VJisAmbVT3/agent.10918==
webUiAccessToken====
listeningOn==41567==
osReleaseId==ubuntu==
arch==x86_64=="
[15:22:58.322] "install" terminal received data: "
tmpDir==/run/user/1000==
platform==linux==
unpackResult====
didLocalDownload==0==
downloadTime====
installTime====
extInstallTime====
serverStartTime==173==
connectionToken==1aa11111-a111-1111-aa1a-a1111111111a==
e2fb0795585c: end"
[15:22:58.322] Received install output: 
sshAuthSock==/tmp/ssh-VJisAmbVT3/agent.10918==
webUiAccessToken====
listeningOn==41567==
osReleaseId==ubuntu==
arch==x86_64==
tmpDir==/run/user/1000==
platform==linux==
unpackResult====
didLocalDownload==0==
downloadTime====
installTime====
extInstallTime====
serverStartTime==173==
connectionToken==1aa11111-a111-1111-aa1a-a1111111111a==

[15:22:58.323] Remote server is listening on 41567
[15:22:58.323] Parsed server configuration: {"serverConfiguration":{"remoteListeningOn":{"port":41567},"osReleaseId":"ubuntu","arch":"x86_64","webUiAccessToken":"","sshAuthSock":"/tmp/ssh-VJisAmbVT3/agent.10918","tmpDir":"/run/user/1000","platform":"linux","connectionToken":"1aa11111-a111-1111-aa1a-a1111111111a"},"serverStartTime":173,"installUnpackCode":""}
[15:22:58.326] Starting forwarding server. localPort 58660 -> socksPort 58655 -> remotePort 41567
[15:22:58.328] Forwarding server listening on 58660
[15:22:58.328] Waiting for ssh tunnel to be ready
[15:22:58.331] Tunneled 41567 to local port 58660
[15:22:58.331] Resolved "ssh-remote+buildsc_local" to "127.0.0.1:58660"
[15:22:58.331] Updating $SSH_AUTH_SOCK: ln -f -s "/tmp/ssh-VJisAmbVT3/agent.10918" "/run/user/1000/vscode-ssh-auth-sock-266293593"
[15:22:58.332] Using cwd: vscode-remote://ssh-remote%2Bbuildsc_local/
[15:22:58.332] Remote extension host environment: {"SSH_AUTH_SOCK":"/run/user/1000/vscode-ssh-auth-sock-266293593"}
[15:22:58.333] [Forwarding server 58660] Got connection 0
[15:22:58.336] "install" terminal received data: ""
[15:22:58.362] TELEMETRY: {"eventName":"resolver","properties":{"osReleaseId":"ubuntu","arch":"x86_64","askedPw":"0","askedPassphrase":"0","asked2fa":"0","askedHostKey":"0","remoteInConfigFile":"1","gotUnrecognizedPrompt":"0","dynamicForwarding":"1","localServer":"0","didLocalDownload":"0","installUnpackCode":"0","outcome":"success"},"measures":{"resolveAttempts":1,"retries":1,"timing.totalResolveTime":2801,"timing.preSshTime":454,"timing.establishSshTime":1976,"timing.scriptTime":2308,"timing.serverStartTime":173}}
[15:22:58.365] ------

[15:22:58.385] [Forwarding server 58660] Got connection 1
[15:22:58.386] [Forwarding server 58660] Got connection 2
[15:22:59.606] "Update SSH_AUTH_SOCK" terminal command done
[15:23:00.179] [Forwarding server 58660] Got connection 3
[15:23:00.183] [Forwarding server 58660] Got connection 4
[15:23:28.339] TELEMETRY: {"eventName":"extraInfo","properties":{"remoteCloud":""},"measures":{}}
[15:25:58.326] "install" terminal received data: " "
bl-snwl commented 3 years ago

It appears I am the only person in the world with this issue 💯

I can't even find that message in the code. On Github as a whole it appears only as part of a message in some Swift and Java libraries. Perhaps it comes from some upstream framework.

samliddicott commented 3 years ago

I have this problem too on a new windows 10 machine

benliddicott commented 3 years ago

See also https://github.com/microsoft/vscode-remote-release/issues/5143

roblourens commented 3 years ago

Is this still an issue?

Looks like Invalid second message comes from us

alexdima commented 3 years ago

@bl-snwl In 1.61.0 we have improved logging on the server side to also include the stdout and stderr from the remote extension host processes. Could you please also try with 1.61.0 to see if the log contains more information regarding the connection error?

benliddicott commented 3 years ago

Hi

@bl-snwl In 1.61.0 we have improved logging on the server side to also include the stdout and stderr from the remote extension host processes. Could you please also try with 1.61.0 to see if the log contains more information regarding the connection error?

I have since changed employment and so unfortunately I no longer have access either to that github account, or to the environment/configuration where I experienced the error.

My only suggestion would be to increase the logging and/or pass more detailed error information to the GUI, which it appears you have already done. If I experience the issue again I will let you know.

benliddicott commented 3 years ago

@alexdima you may want to also look at https://github.com/microsoft/vscode-remote-release/issues/5143 which may or may not be related.

alexdima commented 2 years ago

With https://github.com/microsoft/vscode/issues/134429 I was able to reproduce a problem in the way we were passing the remote extension host socket from the server process to the remote extension host process. Long story short, it used to be that if connecting would take longer than 5 seconds (i.e. an older machine or a machine under load), the client side would send a keep alive message. This message could arrive on the server side at a time when the server process already began sending the socket, but at a time before the remote extension host process received it. This would cause for 4-8 bytes to be dropped and permanently missed. These bytes could later lead to a zlib corruption, which in some cases manifested itself with a clear error message (e.g. Zlib error: invalid distance too far back), but sometimes manifested as garbled text replacement (like all es would be replaced by as in a string, etc). This would explain why the message would be parsed (i.e. legal JSON) on the server side, but later found to be invalid (i.e. this error Invalid second message).

https://github.com/microsoft/vscode/issues/134429 was fixed in November, so I expect that this problem is fixed starting with 1.63.