search

SchoofsKelvin / vscode-sshfs

Extension for Visual Studio Code: File system provider using SSH
GNU General Public License v3.0
549 stars 36 forks source link

Error while connecting to SSH FS qnx6: Timed out while waiting for handshake #159

Open oktonion opened 5 years ago

oktonion commented 5 years ago

I have Windows 10 as Host and QNX6 OS in VirtualBox with ssh server.

When I try to connect with 'ssh.exe' ("C:\Windows\System32\OpenSSH\ssh.exe") all things work fine. SSH FS extension gives me

"Error while connecting to SSH FS qnx6: Timed out while waiting for handshake"

error.

My config is:

"sshfs.configs": [
    {
        "host": "10.0.2.15",
        "name": "qnx6",
        "privateKeyPath": "c:\\ssh_host_rsa_key",
        "username": "root"
    }

This also does not work for plain password config, however openssh client works fine.

Full log:

[INFO] Loading configurations... [DEBUG] Added configuration qnx6 from 1 [INFO] Found 1 configurations [INFO] [qnx6] Calculating actual config [DEBUG] [qnx6] Read private key from c:\ssh_host_rsa_key [DEBUG] [qnx6] Final configuration: { "host": "10.0.2.15", "name": "qnx6", "privateKeyPath": "c:\ssh_host_rsa_key", "username": "root", "_location": 1, "_locations": [ 1 ], "_calculated": true, "privateKey": "Buffer(1675)" } [INFO] [qnx6] Creating socket [DEBUG] [qnx6] Connecting to 10.0.2.15:22 [INFO] [qnx6] Creating SSH session over the opened socket [ERROR] [qnx6] Timed out while waiting for handshake [ERROR] Error while connecting to SSH FS qnx6: Timed out while waiting for handshake [ERROR] Timed out while waiting for handshake Error: Timed out while waiting for handshake at Timeout._onTimeout (*****.vscode\extensions\kelvin.vscode-sshfs-1.16.2\dist\4.extension.js:1:57322) at ontimeout (timers.js:427:11) at tryOnTimeout (timers.js:289:5) at listOnTimeout (timers.js:252:5) at Timer.processTimers (timers.js:212:10)

Any help is really appreciated.

SchoofsKelvin commented 5 years ago

After how much seconds does the timeout happen? Does connecting using ssh.exe also take so long?

oktonion commented 5 years ago

With OpenSSH client I'm getting "Enter your password" promt in ~8 sec.

With SSH FS extension I'm getting this error in ~20 sec.

SchoofsKelvin commented 5 years ago

That seems like a long time for a "localhost" VirtualBox. Can you access the ssh logs in QNX6?

oktonion commented 5 years ago

After a short but brutal fight with sshd server output there are logs:

Starting ssh server. > 2019-07-04 01:19:30 debug1: Config token is protocol > 2019-07-04 01:19:30 debug1: Config token is logingracetime > 2019-07-04 01:19:30 debug1: Config token is subsystem > 2019-07-04 01:19:30 debug1: HPN Buffer Size: 32768 > 2019-07-04 01:19:30 debug1: sshd version OpenSSH_5.2 QNX_Secure_Shell-20090621 > 2019-07-04 01:19:30 debug1: read PEM private key done: type RSA > 2019-07-04 01:19:30 debug1: private host key: #0 type 1 RSA > 2019-07-04 01:19:30 debug1: read PEM private key done: type DSA > 2019-07-04 01:19:30 debug1: private host key: #1 type 2 DSA > 2019-07-04 01:19:30 debug1: rexec_argv[0]='/usr/sbin/sshd' > 2019-07-04 01:19:30 debug1: rexec_argv[1]='-d' > 2019-07-04 01:19:30 debug1: Bind to port 22 on 0.0.0.0. > 2019-07-04 01:19:30 debug1: Server TCP RWIN socket size: 32768 > 2019-07-04 01:19:30 debug1: HPN Buffer Size: 32768 > 2019-07-04 01:19:30 Server listening on 0.0.0.0 port 22.
Server is started and there is SSH FS incoming connection. > 2019-07-04 01:19:45 debug1: fd 4 clearing O_NONBLOCK > 2019-07-04 01:19:45 debug1: Server will not fork when running in debugging mode. > 2019-07-04 01:19:45 debug1: rexec start in 4 out 4 newsock 4 pipe -1 sock 7 > 2019-07-04 01:19:45 debug1: inetd sockets after dupping: 3, 3 > 2019-07-04 01:19:45 Connection from 10.0.2.1 port 56571 > 2019-07-04 01:19:45 debug1: HPN Disabled: 0, HPN Buffer Size: 32768 > 2019-07-04 01:19:45 debug1: Client protocol version 2.0; client software version ssh2js0.4.2 > 2019-07-04 01:19:45 SSH: Server;Ltype: Version;Remote: 10.0.2.1-56571;Protocol: 2.0;Client: ssh2js0.4.2 > 2019-07-04 01:19:45 debug1: no match: ssh2js0.4.2 > 2019-07-04 01:19:45 debug1: Enabling compatibility mode for protocol 2.0 > 2019-07-04 01:19:45 debug1: Local version string SSH-2.0-OpenSSH_5.2 QNX_Secure_Shell-20090621-hpn13v6 > 2019-07-04 01:19:45 debug1: permanently_set_uid: 15/6 > 2019-07-04 01:19:45 debug1: MYFLAG IS 1 > 2019-07-04 01:19:45 debug1: list_hostkey_types: ssh-rsa,ssh-dss > 2019-07-04 01:19:45 debug1: SSH2_MSG_KEXINIT sent > 2019-07-04 01:19:45 debug1: SSH2_MSG_KEXINIT received > 2019-07-04 01:19:45 debug1: AUTH STATE IS 0 > 2019-07-04 01:19:45 debug1: REQUESTED ENC.NAME is 'aes128-ctr' > 2019-07-04 01:19:45 debug1: kex: client->server aes128-ctr hmac-sha1 none > 2019-07-04 01:19:45 SSH: Server;Ltype: Kex;Remote: 10.0.2.1-56571;Enc: aes128-ctr;MAC: hmac-sha1;Comp: none > 2019-07-04 01:19:45 debug1: REQUESTED ENC.NAME is 'aes128-ctr' > 2019-07-04 01:19:45 debug1: kex: server->client aes128-ctr hmac-sha1 none > 2019-07-04 01:19:45 debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received > 2019-07-04 01:19:45 debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent > 2019-07-04 01:19:45 debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT > 2019-07-04 01:19:46 debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent > 2019-07-04 01:19:46 debug1: SSH2_MSG_NEWKEYS sent > 2019-07-04 01:19:46 debug1: expecting SSH2_MSG_NEWKEYS > 2019-07-04 01:19:46 debug1: SSH2_MSG_NEWKEYS received > 2019-07-04 01:19:46 debug1: KEX done > 2019-07-04 01:19:46 debug1: userauth-request for user root service ssh-connection method none > 2019-07-04 01:19:46 SSH: Server;Ltype: Authname;Remote: 10.0.2.1-56571;Name: root > 2019-07-04 01:19:46 debug1: attempt 0 failures 0 > 2019-07-04 01:20:08 debug1: Config token is protocol > 2019-07-04 01:20:08 debug1: Config token is logingracetime > 2019-07-04 01:20:08 debug1: Config token is subsystem > 2019-07-04 01:20:08 Failed none for root from 10.0.2.1 port 56571 ssh2 > 2019-07-04 01:20:08 Connection closed by 10.0.2.1 > 2019-07-04 01:20:08 debug1: do_cleanup > 2019-07-04 01:20:08 debug1: do_cleanup
Starting ssh server again (because reasons). > 2019-07-04 01:28:00 debug1: Config token is protocol > 2019-07-04 01:28:00 debug1: Config token is logingracetime > 2019-07-04 01:28:00 debug1: Config token is subsystem > 2019-07-04 01:28:00 debug1: HPN Buffer Size: 32768 > 2019-07-04 01:28:00 debug1: sshd version OpenSSH_5.2 QNX_Secure_Shell-20090621 > 2019-07-04 01:28:00 debug1: read PEM private key done: type RSA > 2019-07-04 01:28:00 debug1: private host key: #0 type 1 RSA > 2019-07-04 01:28:00 debug1: read PEM private key done: type DSA > 2019-07-04 01:28:00 debug1: private host key: #1 type 2 DSA > 2019-07-04 01:28:00 debug1: rexec_argv[0]='/usr/sbin/sshd' > 2019-07-04 01:28:00 debug1: rexec_argv[1]='-d' > 2019-07-04 01:28:00 debug1: Bind to port 22 on 0.0.0.0. > 2019-07-04 01:28:00 debug1: Server TCP RWIN socket size: 32768 > 2019-07-04 01:28:00 debug1: HPN Buffer Size: 32768 > 2019-07-04 01:28:00 Server listening on 0.0.0.0 port 22.
Server is started and there is OpenSSH incoming connection. > 2019-07-04 01:28:10 debug1: fd 4 clearing O_NONBLOCK > 2019-07-04 01:28:10 debug1: Server will not fork when running in debugging mode. > 2019-07-04 01:28:10 debug1: rexec start in 4 out 4 newsock 4 pipe -1 sock 7 > 2019-07-04 01:28:10 debug1: inetd sockets after dupping: 3, 3 > 2019-07-04 01:28:10 Connection from 10.0.2.1 port 56664 > 2019-07-04 01:28:10 debug1: HPN Disabled: 0, HPN Buffer Size: 32768 > 2019-07-04 01:28:10 debug1: Client protocol version 2.0; client software version OpenSSH_for_Windows_7.7 > 2019-07-04 01:28:10 SSH: Server;Ltype: Version;Remote: 10.0.2.1-56664;Protocol: 2.0;Client: OpenSSH_for_Windows_7.7 > 2019-07-04 01:28:10 debug1: match: OpenSSH_for_Windows_7.7 pat OpenSSH* > 2019-07-04 01:28:10 debug1: Remote is NON-HPN aware > 2019-07-04 01:28:10 debug1: Enabling compatibility mode for protocol 2.0 > 2019-07-04 01:28:10 debug1: Local version string SSH-2.0-OpenSSH_5.2 QNX_Secure_Shell-20090621-hpn13v6 > 2019-07-04 01:28:10 debug1: permanently_set_uid: 15/6 > 2019-07-04 01:28:10 debug1: MYFLAG IS 1 > 2019-07-04 01:28:10 debug1: list_hostkey_types: ssh-rsa,ssh-dss > 2019-07-04 01:28:10 debug1: SSH2_MSG_KEXINIT sent > 2019-07-04 01:28:10 debug1: SSH2_MSG_KEXINIT received > 2019-07-04 01:28:10 debug1: AUTH STATE IS 0 > 2019-07-04 01:28:10 debug1: REQUESTED ENC.NAME is 'aes128-ctr' > 2019-07-04 01:28:10 debug1: kex: client->server aes128-ctr hmac-sha1 none > 2019-07-04 01:28:10 SSH: Server;Ltype: Kex;Remote: 10.0.2.1-56664;Enc: aes128-ctr;MAC: hmac-sha1;Comp: none > 2019-07-04 01:28:10 debug1: REQUESTED ENC.NAME is 'aes128-ctr' > 2019-07-04 01:28:10 debug1: kex: server->client aes128-ctr hmac-sha1 none > 2019-07-04 01:28:10 debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received > 2019-07-04 01:28:10 debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent > 2019-07-04 01:28:10 debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT > 2019-07-04 01:28:10 debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent > 2019-07-04 01:28:10 debug1: SSH2_MSG_NEWKEYS sent > 2019-07-04 01:28:10 debug1: expecting SSH2_MSG_NEWKEYS > 2019-07-04 01:28:10 debug1: SSH2_MSG_NEWKEYS received > 2019-07-04 01:28:10 debug1: KEX done > 2019-07-04 01:28:10 debug1: userauth-request for user root service ssh-connection method none > 2019-07-04 01:28:10 SSH: Server;Ltype: Authname;Remote: 10.0.2.1-56664;Name: root > 2019-07-04 01:28:10 debug1: attempt 0 failures 0 > 2019-07-04 01:28:32 debug1: Config token is protocol > 2019-07-04 01:28:32 debug1: Config token is logingracetime > 2019-07-04 01:28:32 debug1: Config token is subsystem > 2019-07-04 01:28:32 Failed none for root from 10.0.2.1 port 56664 ssh2 > 2019-07-04 01:28:32 debug1: userauth-request for user root service ssh-connection method keyboard-interactive > 2019-07-04 01:28:32 debug1: attempt 1 failures 0 > 2019-07-04 01:28:32 debug1: keyboard-interactive devs > 2019-07-04 01:28:32 debug1: auth2_challenge: user=root devs= > 2019-07-04 01:28:32 debug1: kbdint_alloc: devices '' > 2019-07-04 01:28:38 debug1: userauth-request for user root service ssh-connection method password > 2019-07-04 01:28:38 debug1: attempt 2 failures 1 > 2019-07-04 01:28:38 Failed password for root from 10.0.2.1 port 56664 ssh2 > 2019-07-04 01:28:39 debug1: userauth-request for user root service ssh-connection method password > 2019-07-04 01:28:39 debug1: attempt 3 failures 2 > 2019-07-04 01:28:39 Failed password for root from 10.0.2.1 port 56664 ssh2 > 2019-07-04 01:28:39 debug1: userauth-request for user root service ssh-connection method password > 2019-07-04 01:28:39 debug1: attempt 4 failures 3 > 2019-07-04 01:28:39 Failed password for root from 10.0.2.1 port 56664 ssh2 > 2019-07-04 01:28:39 Read from socket failed: Connection reset by peer > 2019-07-04 01:28:39 debug1: do_cleanup > 2019-07-04 01:28:39 debug1: do_cleanup >

That's it.

SchoofsKelvin commented 5 years ago

Looking at the logs, it seems like the private key did get sent, but not accepted. With QNX being proprietary, I can't create a quick test machine to see what's wrong. I'm wondering whether QNX does something special when it comes to SSH, and why OpenSSH works fine while the extension doesn't. I'll take a look at the underlying ssh2 library I use, maybe there's an issue that can give me a good lead.

oktonion commented 5 years ago

Note that I used manual password fill from CMD to authorize.