Performance issue 100% CPU with Node 12.8.0 (OpenSSL 1.1.1c) on MacOS

[alexey-temnikov]

Due to the change in OpenSSL Implementation
openssl/openssl@2500c09

The usage of crypto algorithms causing 100% CPU usage in certain scenarios (like building ssh tunnels).

It seems it impacts in MacOS when ssh tunnel is build (reproduce using tunnel-ssh module).

 [Summary]:
   ticks  total  nonlib   name
     16    0.0%    0.0%  JavaScript
  95718   99.9%  100.0%  C++
    143    0.1%    0.1%  GC
     63    0.1%          Shared libraries
      4    0.0%          Unaccounted

   ticks parent  name
  92138   96.2%  T node::crypto::DiffieHellman::New(v8::FunctionCallbackInfo<v8::Value> const&)
  92138  100.0%    t __ZN2v88internal12_GLOBAL__N_125SimpleInstallGetterSetterEPNS0_7IsolateENS0_6HandleINS0_8JSObjectEEENS4_INS0_6StringEEENS0_8Builtins4NameESA_
  92138  100.0%      LazyCompile: ~DiffieHellman internal/crypto/diffiehellman.js:32:23
  92138  100.0%        LazyCompile: ~createDiffieHellman crypto.js:126:29
  92138  100.0%          LazyCompile: ~onKEXDH_GEX_GROUP .../node_modules/ssh2-streams/lib/ssh.js:2567:27
  92138  100.0%            LazyCompile: ~<anonymous> .../node_modules/ssh2-streams/lib/ssh.js:217:21

Also reproduced using latest version "ssh2": "^0.8.5".
#816 nodejs/node#28404

[mscdex]

As indicated in the linked node core issue, there's not much we can do until an async interface is exposed by node core.

[mikecbrant]

I was going to come in an open a potential feature/change request related to this same issue. It may be worth considering upping the default readyTimeout value from 20000 to something more like 60000 and/or add some useful message to the timeout error that can at least help direct someone down the right path in resolving the issue. That can potentially at least mitigate impact of those using this library who may have a hard time investigating handshake timeout issues that can suddenly and intermittently happen related to this.

We were ourselves introduced to this issue when updating AWS Lambda runtime environments. It took us a little digging (including fruitless efforts at networking tracing / debugging) until finally hitting on the above linked Node.Js issue report. We bumped our timeout and things started working again :)

I would agree on the last comment that this is out of control of library maintainers to fix the root issue, but it could be pretty easy to help mitigate the problem.

[mscdex]

Perhaps someone could test with node v13.9.0+ and latest version of ssh2? That should make curve25519 available for performing key exchange, which I think should avoid performance issues (as long as the other side supports it as well of course).

[mikecbrant]

I have had no issue running locally in node 13.9, but probably not apple-to-apples comparison to the Lambda (Node 12) environment where I have just run into this problem. I should also note that since my first comment two days ago, I have seen this happen in other Lambda function where SSH is being used, so perhaps the AWS runtime recently took on this openssl update and this might be something encountered more frequently.

[mscdex]

Right, I'm not expecting anyone to use a non-LTS node branch in production. I was mostly just looking to confirm that using curve25519 would solve the CPU usage issue since most (OpenSSH) servers support curve25519.

node v14 will be out soon, but I'm not sure how quickly Amazon makes newer node LTS branches available on Lambda.

[JeremiFerre]

I have the same issue, using tunnel-ssh library to forward multiple ports of a remote server in order to connect to a database using sequelize. The process runs at 100% of CPU when connecting through SSH, and so it is blocking all other parallel request.

We were using node v12 in dev on MacOS, and even after upgrading to node v14.5 the issue still remains.

[mscdex]

@JeremiFerre can you verify the handshake details (set debug to console.log or some other appropriate logging function in the connection config object) when running under node v14?

[JeremiFerre]

Here are the debug logs when I create the SSH tunnel on node 14 (sorry for all the logs I'm not sure where the handshake is):

DEBUG: Local ident: 'SSH-2.0-ssh2js0.1.20'
DEBUG: Client: Trying mathematify.fr 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_6.7p1 Debian-5+deb8u3'
DEBUG: Outgoing: Writing KEXINIT
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:620,padLen:9,remainLen:616
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXINIT
DEBUG: Comparing KEXINITs ...
DEBUG: (local) KEX algorithms: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1
DEBUG: (remote) KEX algorithms: diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1
DEBUG: KEX algorithm: diffie-hellman-group-exchange-sha256
DEBUG: (local) Host key formats: ssh-rsa,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521
DEBUG: (remote) Host key formats: ssh-rsa,ssh-ed25519
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: aes256-gcm@openssh.com,aes128-gcm@openssh.com,aes256-ctr,aes128-ctr
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: aes256-gcm@openssh.com,aes128-gcm@openssh.com,aes256-ctr,aes128-ctr
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-sha2-512-etm@openssh.com,hmac-sha2-256-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-512,hmac-sha2-256,hmac-ripemd160
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-sha2-512-etm@openssh.com,hmac-sha2-256-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-512,hmac-sha2-256,hmac-ripemd160
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:7,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

[mscdex]

@JeremiFerre you're using a very outdated version of ssh2/ssh2-streams.

However in this particular case it probably won't matter much since the server you're connecting to doesn't advertise curve25519 for key exchange, which is odd since curve25519 support has existed in OpenSSH since OpenSSH 6.5. My guess is the server has it explicitly disabled one way or another.

So in your particular situation there isn't much that can be done by ssh2 to avoid the CPU usage issue.

[JeremiFerre]

Ok I'll check this out, thank you very much for your quick answers.