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

[oktonion]

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]

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

[oktonion]

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]

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

[oktonion]

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]

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]

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