Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

When updating from version 0.8.9 to 1.1.0 connections takes 10 times longer to establish (with ssh2-sftp-client) #1031

Closed
gilles-crealp opened this issue Jul 7, 2021 · 8 comments

Comments

@gilles-crealp
Copy link

gilles-crealp commented Jul 7, 2021

May be related to #927 & #1010. Ticket at ssh2-sftp-client.

Version 0.8.9 of ssh2 (ssh2-sftp-client 6.0.1) takes 3 seconds after DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXDH_GEX_GROUP.

Debug version ssh2-sftp-client 6.0.1 (ssh2 0.8.9, node 14)…
CLIENT[sftp]: Debugging turned on
CLIENT[sftp]: Connect attempt 1
DEBUG: Local ident: 'SSH-2.0-ssh2js0.4.10'
DEBUG: Client: Trying xxx.yyy.zzz on port 22 ...
DEBUG: Client: Connected
DEBUG: Parser: IN_INIT
DEBUG: Parser: IN_GREETING
DEBUG: Parser: IN_HEADER
DEBUG: Remote ident: 'SSH-2.0-OpenSSH_5.3'
DEBUG: Outgoing: Writing KEXINIT
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:836,padLen:10,remainLen:832
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXINIT
DEBUG: Comparing KEXINITs ...
DEBUG: (local) KEX algorithms: curve25519-sha256@libssh.org,curve25519-sha256,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha1
DEBUG: (remote) KEX algorithms: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
DEBUG: KEX algorithm: diffie-hellman-group-exchange-sha256
DEBUG: (local) Host key formats: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-rsa
DEBUG: (remote) Host key formats: ssh-rsa,ssh-dss
DEBUG: Host key format: ssh-rsa
DEBUG: (local) Client->Server ciphers: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm,aes128-gcm@openssh.com,aes256-gcm,aes256-gcm@openssh.com
DEBUG: (remote) Client->Server ciphers: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
DEBUG: Client->Server Cipher: aes128-ctr
DEBUG: (local) Server->Client ciphers: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm,aes128-gcm@openssh.com,aes256-gcm,aes256-gcm@openssh.com
DEBUG: (remote) Server->Client ciphers: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
DEBUG: Server->Client Cipher: aes128-ctr
DEBUG: (local) Client->Server HMAC algorithms: hmac-sha2-256,hmac-sha2-512,hmac-sha1
DEBUG: (remote) Client->Server HMAC algorithms: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
DEBUG: Client->Server HMAC algorithm: hmac-sha2-256
DEBUG: (local) Server->Client HMAC algorithms: hmac-sha2-256,hmac-sha2-512,hmac-sha1
DEBUG: (remote) Server->Client HMAC algorithms: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
DEBUG: Server->Client HMAC algorithm: hmac-sha2-256
DEBUG: (local) Client->Server compression algorithms: none,zlib@openssh.com,zlib
DEBUG: (remote) Client->Server compression algorithms: none,zlib@openssh.com
DEBUG: Client->Server compression algorithm: none
DEBUG: (local) Server->Client compression algorithms: none,zlib@openssh.com,zlib
DEBUG: (remote) Server->Client compression algorithms: none,zlib@openssh.com
DEBUG: Server->Client compression algorithm: none
DEBUG: Outgoing: Writing KEXDH_GEX_REQUEST
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:532,padLen:8,remainLen:528
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXDH_GEX_GROUP
DEBUG: Outgoing: Writing KEXDH_GEX_INIT
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:1084,padLen:10,remainLen:1080
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXDH_GEX_REPLY
DEBUG: Checking host key format
DEBUG: Checking signature format
DEBUG: Verifying host fingerprint
DEBUG: Host accepted by default (no verification)
DEBUG: Verifying signature
DEBUG: Outgoing: Writing NEWKEYS
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:12,padLen:10,remainLen:8
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: NEWKEYS
DEBUG: Outgoing: Writing SERVICE_REQUEST (ssh-userauth)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:28,padLen:10,remainLen:16
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: SERVICE_ACCEPT
DEBUG: Outgoing: Writing USERAUTH_REQUEST (none)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:60,padLen:6,remainLen:48
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: USERAUTH_FAILURE
DEBUG: Client: none auth failed
DEBUG: Outgoing: Writing USERAUTH_REQUEST (password)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:12,padLen:10,remainLen:0
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: USERAUTH_SUCCESS
DEBUG: Outgoing: Writing CHANNEL_OPEN (0, session)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:28,padLen:10,remainLen:16
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_OPEN_CONFIRMATION
DEBUG: Outgoing: Writing CHANNEL_REQUEST (0, subsystem: sftp)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:28,padLen:18,remainLen:16
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_WINDOW_ADJUST (0, 2097152)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:12,padLen:6,remainLen:0
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_SUCCESS (0)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:124,padLen:15,remainLen:112
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_DATA (0)
CLIENT[sftp]: SFTP channel established
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
CLIENT[sftp]: Removing listener from ready
CLIENT[sftp]: Adding listener to close
CLIENT[sftp]: Have connection - calling end()
DEBUG: Outgoing: Writing DISCONNECT (BY_APPLICATION)
CLIENT[sftp]: Handled end event for end
CLIENT[sftp]: handled close event for end
DEBUG: Outgoing: Writing CHANNEL_CLOSE (0)
CLIENT[sftp]: Removing listener from close

Version 1.1.0 of ssh2 (ssh2-sftp-client 7.0.0) takes 30 seconds (have to set readyTimeout) after Received DH GEX Group.

Debug version ssh2-sftp-client 7.0.0 (ssh2 1.1.0, node 14)…
CLIENT[sftp]: Debugging turned on
CLIENT[sftp]: Connect attempt 1
CLIENT[sftp]: sftpConnect: Adding end listener
CLIENT[sftp]: sftpConnect: Adding close listener
CLIENT[sftp]: sftpConnect: Adding error listener
Custom crypto binding not available
Client: Trying xxx.yyy.zzz on port 22 ...
Local ident: 'SSH-2.0-ssh2js1.1.0'
Socket connected
Remote ident: 'SSH-2.0-OpenSSH_5.3'
Outbound: Sending KEXINIT
Inbound: Handshake in progress
Handshake: (local) KEX method: curve25519-sha256@libssh.org,curve25519-sha256,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group15-sha512,diffie-hellman-group16-sha512,diffie-hellman-group17-sha512,diffie-hellman-group18-sha512
Handshake: (remote) KEX method: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
Handshake: KEX algorithm: diffie-hellman-group-exchange-sha256
Handshake: (local) Host key format: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa
Handshake: (remote) Host key format: ssh-rsa,ssh-dss
Handshake: Host key format: ssh-rsa
Handshake: (local) C->S cipher: aes128-gcm,aes128-gcm@openssh.com,aes256-gcm,aes256-gcm@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,chacha20-poly1305@openssh.com
Handshake: (remote) C->S cipher: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
Handshake: C->S Cipher: aes128-ctr
Handshake: (local) S->C cipher: aes128-gcm,aes128-gcm@openssh.com,aes256-gcm,aes256-gcm@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,chacha20-poly1305@openssh.com
Handshake: (remote) S->C cipher: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
Handshake: S->C cipher: aes128-ctr
Handshake: (local) C->S MAC: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
Handshake: (remote) C->S MAC: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
Handshake: C->S MAC: hmac-sha2-256
Handshake: (local) S->C MAC: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
Handshake: (remote) S->C MAC: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
Handshake: S->C MAC: hmac-sha2-256
Handshake: (local) C->S compression: none,zlib@openssh.com,zlib
Handshake: (remote) C->S compression: none,zlib@openssh.com
Handshake: C->S compression: none
Handshake: (local) S->C compression: none,zlib@openssh.com,zlib
Handshake: (remote) S->C compression: none,zlib@openssh.com
Handshake: S->C compression: none
Outbound: Sending KEXDH_GEX_REQUEST
Received DH GEX Group
Outbound: Sending KEXDH_GEX_INIT
Received DH GEX Reply
Received DH Reply
Host accepted by default (no verification)
Host accepted (verified)
Inbound: NEWKEYS
Verifying signature ...
Verified signature
Outbound: Sending NEWKEYS
Handshake completed
Outbound: Sending SERVICE_REQUEST (ssh-userauth)
Inbound: Received SERVICE_ACCEPT (ssh-userauth)
Outbound: Sending USERAUTH_REQUEST (none)
Inbound: Received USERAUTH_FAILURE (publickey,gssapi-keyex,gssapi-with-mic,password)
Client: none auth failed
Outbound: Sending USERAUTH_REQUEST (password)
Inbound: Received USERAUTH_SUCCESS
CLIENT[sftp]: Removing listener from ready
CLIENT[sftp]: sftp: Removing end listener
CLIENT[sftp]: sftp: Removing close listener
CLIENT[sftp]: sftp: Removing error listener
Outbound: Sending CHANNEL_OPEN (r:0, session)
Inbound: CHANNEL_OPEN_CONFIRMATION (r:0, s:0)
Outbound: Sending CHANNEL_REQUEST (r:0, subsystem: sftp)
Inbound: CHANNEL_WINDOW_ADJUST (r:0, 2097152)
Inbound: CHANNEL_SUCCESS (r:0)
Outbound: Sending CHANNEL_DATA (r:0, 9)
Inbound: CHANNEL_DATA (r:0, 99)
SFTP: Inbound: Received VERSION (v3, exts:posix-rename@openssh.com,statvfs@openssh.com,fstatvfs@openssh.com)
CLIENT[sftp]: end: Adding end listener
CLIENT[sftp]: end: Adding close listener
CLIENT[sftp]: end: Adding error listener
CLIENT[sftp]: Adding listener to close
CLIENT[sftp]: Have connection - calling end()
Outbound: Sending DISCONNECT (11)
Socket ended
CLIENT[sftp]: Handled end event for end
Socket closed
CLIENT[sftp]: handled close event for end
CLIENT[sftp]: sftp: Removing end listener
CLIENT[sftp]: sftp: Removing close listener
CLIENT[sftp]: sftp: Removing error listener
CLIENT[sftp]: Removing listener from close
@mscdex
Copy link
Owner

mscdex commented Jul 7, 2021

If you're using different node versions, it could be due to changes made awhile back in node's OpenSSL to improve security with traditional diffie-hellman key exchanges. I believe you shouldn't see this slowdown on servers that can utilize curve25519 key exchanges though.

@gilles-crealp
Copy link
Author

gilles-crealp commented Jul 7, 2021

No, both ssh2 (in fact ssh2-sftp-client) codes are running on the same node version.

I've try both ssh2-sftp-client versions on these environments (without changing node version):

  • Node 14.17.0 on Windows 10
  • Node 14.16.1 on CentOS 7

@mscdex
Copy link
Owner

mscdex commented Jul 7, 2021

I'm not sure why there would be any difference then. The exact same crypto API is being used for doing key exchanges.

@gilles-crealp
Copy link
Author

OK, so I will look further on ssh2-sftp-client side.

@gilles-crealp
Copy link
Author

gilles-crealp commented Jul 8, 2021

It's not a ssh2-sftp-client problem.

For my test I used the following script:

let { Client } = require('ssh2')
let prettyTime = require('pretty-time')

let client = new Client()

let startTime = process.hrtime()

client.on('ready', () => {
  console.log(`Connection time: ${prettyTime(process.hrtime(startTime), 'ms')}`)
  client.sftp((err, sftp) => {
    if (err) console.error(err)
    sftp.stat('.', (err, stats) => {
      if (err) console.error(err)
      console.log(stats)
      client.end()
    })
  })
}).on('close', () => {
  console.log(`Total execution time: ${prettyTime(process.hrtime(startTime), 'ms')}`)
}).connect({
  host: 'xxx.yyy.zzz',
  username: 'user',
  password: 'pass',
  readyTimeout: 100000,
  debug: console.log
})
With ssh2 0.8.9 (node 14.17.0, Windows 10) connection in 3s 74ms and total execution in 3s 148ms.
DEBUG: Local ident: 'SSH-2.0-ssh2js0.4.10'
DEBUG: Client: Trying xxx.yyy.zzz on port 22 ...
DEBUG: Client: Connected
DEBUG: Parser: IN_INIT
DEBUG: Parser: IN_GREETING
DEBUG: Parser: IN_HEADER
DEBUG: Remote ident: 'SSH-2.0-OpenSSH_5.3'
DEBUG: Outgoing: Writing KEXINIT
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:836,padLen:10,remainLen:832
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXINIT
DEBUG: Comparing KEXINITs ...
DEBUG: (local) KEX algorithms: curve25519-sha256@libssh.org,curve25519-sha256,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha1
DEBUG: (remote) KEX algorithms: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
DEBUG: KEX algorithm: diffie-hellman-group-exchange-sha256
DEBUG: (local) Host key formats: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-rsa
DEBUG: (remote) Host key formats: ssh-rsa,ssh-dss
DEBUG: Host key format: ssh-rsa
DEBUG: (local) Client->Server ciphers: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm,aes128-gcm@openssh.com,aes256-gcm,aes256-gcm@openssh.com
DEBUG: (remote) Client->Server ciphers: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
DEBUG: Client->Server Cipher: aes128-ctr
DEBUG: (local) Server->Client ciphers: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm,aes128-gcm@openssh.com,aes256-gcm,aes256-gcm@openssh.com
DEBUG: (remote) Server->Client ciphers: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
DEBUG: Server->Client Cipher: aes128-ctr
DEBUG: (local) Client->Server HMAC algorithms: hmac-sha2-256,hmac-sha2-512,hmac-sha1
DEBUG: (remote) Client->Server HMAC algorithms: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
DEBUG: Client->Server HMAC algorithm: hmac-sha2-256
DEBUG: (local) Server->Client HMAC algorithms: hmac-sha2-256,hmac-sha2-512,hmac-sha1
DEBUG: (remote) Server->Client HMAC algorithms: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
DEBUG: Server->Client HMAC algorithm: hmac-sha2-256
DEBUG: (local) Client->Server compression algorithms: none,zlib@openssh.com,zlib
DEBUG: (remote) Client->Server compression algorithms: none,zlib@openssh.com
DEBUG: Client->Server compression algorithm: none
DEBUG: (local) Server->Client compression algorithms: none,zlib@openssh.com,zlib
DEBUG: (remote) Server->Client compression algorithms: none,zlib@openssh.com
DEBUG: Server->Client compression algorithm: none
DEBUG: Outgoing: Writing KEXDH_GEX_REQUEST
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:532,padLen:8,remainLen:528
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXDH_GEX_GROUP
DEBUG: Outgoing: Writing KEXDH_GEX_INIT
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:1084,padLen:10,remainLen:1080
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXDH_GEX_REPLY
DEBUG: Checking host key format
DEBUG: Checking signature format
DEBUG: Verifying host fingerprint
DEBUG: Host accepted by default (no verification)
DEBUG: Verifying signature
DEBUG: Outgoing: Writing NEWKEYS
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:12,padLen:10,remainLen:8
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: NEWKEYS
DEBUG: Outgoing: Writing SERVICE_REQUEST (ssh-userauth)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:28,padLen:10,remainLen:16
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: SERVICE_ACCEPT
DEBUG: Outgoing: Writing USERAUTH_REQUEST (none)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:60,padLen:6,remainLen:48
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: USERAUTH_FAILURE
DEBUG: Client: none auth failed
DEBUG: Outgoing: Writing USERAUTH_REQUEST (password)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:12,padLen:10,remainLen:0
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: USERAUTH_SUCCESS
Connection time: 3s 74ms
DEBUG: Outgoing: Writing CHANNEL_OPEN (0, session)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:28,padLen:10,remainLen:16
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_OPEN_CONFIRMATION
DEBUG: Outgoing: Writing CHANNEL_REQUEST (0, subsystem: sftp)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:28,padLen:18,remainLen:16
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_WINDOW_ADJUST (0, 2097152)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:12,padLen:6,remainLen:0
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_SUCCESS (0)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:124,padLen:15,remainLen:112
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_DATA (0)
DEBUG[SFTP]: Outgoing: Writing STAT
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:60,padLen:9,remainLen:48
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_DATA (0)
DEBUG[SFTP]: Parser: Response: ATTRS
Stats {
  mode: 16888,
  permissions: 16888,
  uid: 505,
  gid: 505,
  size: 344064,
  atime: 1625722794,
  mtime: 1625722742
}
DEBUG: Outgoing: Writing DISCONNECT (BY_APPLICATION)
Total execution time: 3s 148ms
DEBUG: Outgoing: Writing CHANNEL_CLOSE (0)
With ssh2 1.1.0 (node 14.17.0, Windows 10) connection in 23s 34ms and total execution in 23s 101ms.
Custom crypto binding not available
Client: Trying xxx.yyy.zzz on port 22 ...
Local ident: 'SSH-2.0-ssh2js1.1.0'
Socket connected
Remote ident: 'SSH-2.0-OpenSSH_5.3'
Outbound: Sending KEXINIT
Inbound: Handshake in progress
Handshake: (local) KEX method: curve25519-sha256@libssh.org,curve25519-sha256,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group15-sha512,diffie-hellman-group16-sha512,diffie-hellman-group17-sha512,diffie-hellman-group18-sha512
Handshake: (remote) KEX method: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
Handshake: KEX algorithm: diffie-hellman-group-exchange-sha256
Handshake: (local) Host key format: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa
Handshake: (remote) Host key format: ssh-rsa,ssh-dss
Handshake: Host key format: ssh-rsa
Handshake: (local) C->S cipher: aes128-gcm,aes128-gcm@openssh.com,aes256-gcm,aes256-gcm@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,chacha20-poly1305@openssh.com
Handshake: (remote) C->S cipher: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
Handshake: C->S Cipher: aes128-ctr
Handshake: (local) S->C cipher: aes128-gcm,aes128-gcm@openssh.com,aes256-gcm,aes256-gcm@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,chacha20-poly1305@openssh.com
Handshake: (remote) S->C cipher: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
Handshake: S->C cipher: aes128-ctr
Handshake: (local) C->S MAC: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
Handshake: (remote) C->S MAC: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
Handshake: C->S MAC: hmac-sha2-256
Handshake: (local) S->C MAC: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
Handshake: (remote) S->C MAC: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
Handshake: S->C MAC: hmac-sha2-256
Handshake: (local) C->S compression: none,zlib@openssh.com,zlib
Handshake: (remote) C->S compression: none,zlib@openssh.com
Handshake: C->S compression: none
Handshake: (local) S->C compression: none,zlib@openssh.com,zlib
Handshake: (remote) S->C compression: none,zlib@openssh.com
Handshake: S->C compression: none
Outbound: Sending KEXDH_GEX_REQUEST
Received DH GEX Group
Outbound: Sending KEXDH_GEX_INIT
Received DH GEX Reply
Received DH Reply
Host accepted by default (no verification)
Host accepted (verified)
Inbound: NEWKEYS
Verifying signature ...
Verified signature
Outbound: Sending NEWKEYS
Handshake completed
Outbound: Sending SERVICE_REQUEST (ssh-userauth)
Inbound: Received SERVICE_ACCEPT (ssh-userauth)
Outbound: Sending USERAUTH_REQUEST (none)
Inbound: Received USERAUTH_FAILURE (publickey,gssapi-keyex,gssapi-with-mic,password)
Client: none auth failed
Outbound: Sending USERAUTH_REQUEST (password)
Inbound: Received USERAUTH_SUCCESS
Connection time: 23s 34ms
Outbound: Sending CHANNEL_OPEN (r:0, session)
Inbound: CHANNEL_OPEN_CONFIRMATION (r:0, s:0)
Outbound: Sending CHANNEL_REQUEST (r:0, subsystem: sftp)
Inbound: CHANNEL_WINDOW_ADJUST (r:0, 2097152)
Inbound: CHANNEL_SUCCESS (r:0)
Outbound: Sending CHANNEL_DATA (r:0, 9)
Inbound: CHANNEL_DATA (r:0, 99)
SFTP: Inbound: Received VERSION (v3, exts:posix-rename@openssh.com,statvfs@openssh.com,fstatvfs@openssh.com)
Outbound: Sending CHANNEL_DATA (r:0, 14)
SFTP: Outbound: Buffered STAT
Inbound: CHANNEL_DATA (r:0, 41)
SFTP: Inbound: Received ATTRS (id:0)
Stats {
  mode: 16888,
  uid: 505,
  gid: 505,
  size: 344064,
  atime: 1625722794,
  mtime: 1625722742,
  extended: undefined
}
Outbound: Sending DISCONNECT (11)
Socket ended
Socket closed
Total execution time: 23s 101ms

The waiting time take place after Received DH GEX Group.

@mscdex
Copy link
Owner

mscdex commented Jul 8, 2021

Ok there are a couple of issues at play here:

  1. There were a couple of bugs in the estimation of the preferred prime number size for the Diffie-Hellman exchange where the maximum value was always being used. This is fixed now in 6d8692d.

  2. Prior to ssh2 v1.0.0, the preferred prime number size used in the Diffie-Hellman (group) exchange was always set to 4096 (bits). Starting with ssh2 v1.0.0, (aside from bumping the minimum number of bits from 1024 to 2048 based on RFC recommendations) I changed the preferred number of bits to be dynamic. The logic for determining this value follows that of how OpenSSH determines the same value.

Even after fixing issue 1, issue 2 could still cause larger prime numbers to be requested from the server, depending on the negotiated algorithms. However in some cases it can also cause smaller prime numbers to be requested than in ssh2 pre-v1.0.0.

@mscdex
Copy link
Owner

mscdex commented Jul 8, 2021

Let me know how the master branch fares for you.

@gilles-crealp
Copy link
Author

Excellent job! 🚀

Here is the result with ssh2 6d8692d (node 14.17.0, Windows 10) connection in 1s 538ms and total execution in 1s 594ms.
Custom crypto binding available
Client: Trying xxx.yyy.zzz on port 22 ...
Local ident: 'SSH-2.0-ssh2js1.1.0'
Socket connected
Remote ident: 'SSH-2.0-OpenSSH_5.3'
Outbound: Sending KEXINIT
Inbound: Handshake in progress
Handshake: (local) KEX method: curve25519-sha256@libssh.org,curve25519-sha256,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group15-sha512,diffie-hellman-group16-sha512,diffie-hellman-group17-sha512,diffie-hellman-group18-sha512
Handshake: (remote) KEX method: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
Handshake: KEX algorithm: diffie-hellman-group-exchange-sha256
Handshake: (local) Host key format: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa
Handshake: (remote) Host key format: ssh-rsa,ssh-dss
Handshake: Host key format: ssh-rsa
Handshake: (local) C->S cipher: aes128-gcm,aes128-gcm@openssh.com,aes256-gcm,aes256-gcm@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,chacha20-poly1305@openssh.com
Handshake: (remote) C->S cipher: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
Handshake: C->S Cipher: aes128-ctr
Handshake: (local) S->C cipher: aes128-gcm,aes128-gcm@openssh.com,aes256-gcm,aes256-gcm@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,chacha20-poly1305@openssh.com
Handshake: (remote) S->C cipher: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
Handshake: S->C cipher: aes128-ctr
Handshake: (local) C->S MAC: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
Handshake: (remote) C->S MAC: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
Handshake: C->S MAC: hmac-sha2-256
Handshake: (local) S->C MAC: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
Handshake: (remote) S->C MAC: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
Handshake: S->C MAC: hmac-sha2-256
Handshake: (local) C->S compression: none,zlib@openssh.com,zlib
Handshake: (remote) C->S compression: none,zlib@openssh.com
Handshake: C->S compression: none
Handshake: (local) S->C compression: none,zlib@openssh.com,zlib
Handshake: (remote) S->C compression: none,zlib@openssh.com
Handshake: S->C compression: none
Outbound: Sending KEXDH_GEX_REQUEST
Received DH GEX Group
Outbound: Sending KEXDH_GEX_INIT
Received DH GEX Reply
Received DH Reply
Host accepted by default (no verification)
Host accepted (verified)
Inbound: NEWKEYS
Verifying signature ...
Verified signature
Outbound: Sending NEWKEYS
Handshake completed
Outbound: Sending SERVICE_REQUEST (ssh-userauth)
Inbound: Received SERVICE_ACCEPT (ssh-userauth)
Outbound: Sending USERAUTH_REQUEST (none)
Inbound: Received USERAUTH_FAILURE (publickey,gssapi-keyex,gssapi-with-mic,password)
Client: none auth failed
Outbound: Sending USERAUTH_REQUEST (password)
Inbound: Received USERAUTH_SUCCESS
Connection time: 1s 538ms
Outbound: Sending CHANNEL_OPEN (r:0, session)
Inbound: CHANNEL_OPEN_CONFIRMATION (r:0, s:0)
Outbound: Sending CHANNEL_REQUEST (r:0, subsystem: sftp)
Inbound: CHANNEL_WINDOW_ADJUST (r:0, 2097152)
Inbound: CHANNEL_SUCCESS (r:0)
Outbound: Sending CHANNEL_DATA (r:0, 9)
Inbound: CHANNEL_DATA (r:0, 99)
SFTP: Inbound: Received VERSION (v3, exts:posix-rename@openssh.com,statvfs@openssh.com,fstatvfs@openssh.com)
Outbound: Sending CHANNEL_DATA (r:0, 14)
SFTP: Outbound: Buffered STAT
Inbound: CHANNEL_DATA (r:0, 41)
SFTP: Inbound: Received ATTRS (id:0)
Stats {
  mode: 16888,
  uid: 505,
  gid: 505,
  size: 344064,
  atime: 1625806978,
  mtime: 1625806654,
  extended: undefined
}
Outbound: Sending DISCONNECT (11)
Socket ended
Socket closed
Total execution time: 1s 594ms

Thank you very much!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants