search

mscdex / ssh2

SSH2 client and server modules written in pure JavaScript for node.js
MIT License
5.51k stars 663 forks source link

can not get ssh2 running against Cisco ASR9k #494

Closed wisotzky closed 7 years ago

wisotzky commented 7 years ago

ssh2 seems to have issues against Cisco ASR9k running IOS XR 6.0.2 using NETCONF (port 830).

There is not much about debug messages from the ssh2 client:

DEBUG: Local ident: 'SSH-2.0-ssh2js0.1.14'
DEBUG: Client: Trying 128.251.72.209 on port 830 ...
DEBUG: Client: Connected

After this I always get an "ssh error" with message "read ECONNRESET" and level "client-socket".

This is how it looks like from the server (Cisco ASR9k):

23:38:11.895 : SSHD_[65723]: Inside init_ttylist FUNC
23:38:11.896 : SSHD_[65723]: init_ttylist: Created/Opened the Semaphore %pid:28512443 SEM Value:1:
23:38:11.896 : SSHD_[65723]: (sshd_shm_lock_init) shm path: /dev/shmem/sshd_lock_28512443
23:38:11.897 : SSHD_[65723]: (sshd_shm_lock_init): shared memory truncated fd:14
23:38:11.897 : SSHD_[65723]: (sshd_shm_lock_init): shared memory mmaped fd:14
23:38:12.049 : SSHD_[65723]: SSH path/dev/ssh_pulse_28512443
23:38:12.049 : SSHD_[65723]: Client sockfd 3
23:38:12.049 : SSHD_[65723]: ssh type 2
23:38:12.049 : SSHD_[65723]: ssh type 2 : NIN : 4
23:38:12.049 : SSHD_[65723]: Port on which service running 830
23:38:12.050 : SSHD_[65723]: Setting IP_TOS value:64
23:38:12.050 : SSHD_[65723]: After setting socket options, sndbuf65536, rcvbuf - 65536
23:38:12.051 : SSHD_[65723]: Connection from 135.224.211.68 port 18664
23:38:12.051 : SSHD_[65723]: Inside sshd_session_sem_create FUNC
23:38:12.051 : SSHD_[65723]: sshd_session_sem_create: Created/Opened the Semaphore %pid:28512443 SEM Value:1:
23:38:12.051 : SSHD_[65723]: main: Inside the Critical Section: session_pid=28512443, channel_id=1
23:38:12.052 : SSHD_[65723]: (addrem_ssh_info_tuple) ADD tty:XXXXX(XXXXX), user:()
23:38:12.052 : SSHD_[65723]: main: Exiting the Critical Section: session_pid=28512443, channel_id=1
23:38:12.052 : SSHD_[65723]: Session id 0
23:38:12.052 : SSHD_[65723]: Exchanging versions
23:38:12.053 : SSHD_[65723]: ssh_version_exchange : client_str = SSH-2.0-ssh2js0.1.14  (len = 20)
23:38:12.053 : SSHD_[65723]: Remote protocol version 2.0, remote software version ssh2js0.1.14
23:38:12.053 : SSHD_[65723]: In Key exchange
mscdex commented 7 years ago

If you set debug: console.log in the connection config object, can you post the resulting output?

wisotzky commented 7 years ago

I have played around with this a bit more... Sometimes I get a little bit further, but ERROR seems always to be the same: "read ECONNRESET"

ncclient.coffee:43 DEBUG: Local ident: 'SSH-2.0-ssh2js0.1.14'
ncclient.coffee:43 DEBUG: Client: Trying 128.251.72.209 on port 830 ...
ncclient.coffee:43 DEBUG: Client: Connected
ncclient.coffee:43 DEBUG: Parser: IN_INIT
ncclient.coffee:43 DEBUG: Parser: IN_GREETING
ncclient.coffee:43 DEBUG: Parser: IN_HEADER
ncclient.coffee:43 DEBUG: Remote ident: 'SSH-2.0-Cisco-2.0'
ncclient.coffee:43 DEBUG: Outgoing: Writing KEXINIT
ncclient.coffee:43 DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
ncclient.coffee:43 DEBUG: Parser: IN_PACKET
ncclient.coffee:43 DEBUG: Parser: pktLen:252,padLen:12,remainLen:248
ncclient.coffee:43 DEBUG: Parser: IN_PACKETDATA
ncclient.coffee:43 DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXINIT
ncclient.coffee:43 DEBUG: Comparing KEXINITs ...
ncclient.coffee:43 DEBUG: (local) KEX algorithms: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1
ncclient.coffee:43 DEBUG: (remote) KEX algorithms: diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
ncclient.coffee:43 DEBUG: KEX algorithm: diffie-hellman-group14-sha1
ncclient.coffee:43 DEBUG: (local) Host key formats: ssh-rsa,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521
ncclient.coffee:43 DEBUG: (remote) Host key formats: ssh-dss,ssh-rsa
ncclient.coffee:43 DEBUG: Host key format: ssh-rsa
ncclient.coffee:43 DEBUG: (local) Client->Server ciphers: 3des-cbc
ncclient.coffee:43 DEBUG: (remote) Client->Server ciphers: aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
ncclient.coffee:43 DEBUG: Client->Server Cipher: 3des-cbc
ncclient.coffee:43 DEBUG: (local) Server->Client ciphers: 3des-cbc
ncclient.coffee:43 DEBUG: (remote) Server->Client ciphers: aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
ncclient.coffee:43 DEBUG: Server->Client Cipher: 3des-cbc
ncclient.coffee:43 DEBUG: (local) Client->Server HMAC algorithms: hmac-sha2-256,hmac-sha2-512,hmac-sha1
ncclient.coffee:43 DEBUG: (remote) Client->Server HMAC algorithms: hmac-sha1
ncclient.coffee:43 DEBUG: Client->Server HMAC algorithm: hmac-sha1
ncclient.coffee:43 DEBUG: (local) Server->Client HMAC algorithms: hmac-sha2-256,hmac-sha2-512,hmac-sha1
ncclient.coffee:43 DEBUG: (remote) Server->Client HMAC algorithms: hmac-sha1
ncclient.coffee:43 DEBUG: Server->Client HMAC algorithm: hmac-sha1
ncclient.coffee:43 DEBUG: (local) Client->Server compression algorithms: none,zlib@openssh.com,zlib
ncclient.coffee:43 DEBUG: (remote) Client->Server compression algorithms: none
ncclient.coffee:43 DEBUG: Client->Server compression algorithm: none
ncclient.coffee:43 DEBUG: (local) Server->Client compression algorithms: none,zlib@openssh.com,zlib
ncclient.coffee:43 DEBUG: (remote) Server->Client compression algorithms: none
ncclient.coffee:43 DEBUG: Server->Client compression algorithm: none
ncclient.coffee:43 DEBUG: Outgoing: Writing KEXDH_INIT
ncclient.coffee:43 DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
ncclient.coffee:43 DEBUG: Parser: IN_PACKET
ncclient.coffee:43 DEBUG: Parser: pktLen:572,padLen:7,remainLen:568
ncclient.coffee:43 DEBUG: Parser: IN_PACKETDATA
ncclient.coffee:43 DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXDH_REPLY
ncclient.coffee:43 DEBUG: Checking host key format
ncclient.coffee:43 DEBUG: Checking signature format
ncclient.coffee:43 DEBUG: Verifying host fingerprint
ncclient.coffee:43 DEBUG: Host accepted by default (no verification)
ncclient.coffee:43 DEBUG: Verifying signature
ncclient.coffee:43 DEBUG: Outgoing: Writing NEWKEYS
ncclient.coffee:43 DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
ncclient.coffee:43 DEBUG: Parser: IN_PACKET
ncclient.coffee:43 DEBUG: Parser: pktLen:12,padLen:10,remainLen:8
ncclient.coffee:43 DEBUG: Parser: IN_PACKETDATA
ncclient.coffee:43 DEBUG: Parser: IN_PACKETDATAAFTER, packet: NEWKEYS
ncclient.coffee:43 DEBUG: Outgoing: Writing SERVICE_REQUEST (ssh-userauth)
ncclient.coffee:43 DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
ncclient.coffee:43 DEBUG: Parser: IN_PACKET
ncclient.coffee:43 DEBUG: Parser: Decrypting
ncclient.coffee:43 DEBUG: Parser: pktLen:28,padLen:10,remainLen:24
ncclient.coffee:43 DEBUG: Parser: IN_PACKETDATA
ncclient.coffee:43 DEBUG: Parser: Decrypting
ncclient.coffee:43 DEBUG: Parser: HMAC size:20
ncclient.coffee:43 DEBUG: Parser: IN_PACKETDATAVERIFY
ncclient.coffee:43 DEBUG: Parser: Verifying MAC
ncclient.coffee:43 DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
ncclient.coffee:43 DEBUG: Parser: IN_PACKETDATAAFTER, packet: SERVICE_ACCEPT
ncclient.coffee:43 DEBUG: Outgoing: Writing USERAUTH_REQUEST (password)
ncclient.coffee:43 DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
ncclient.coffee:203 Error: read ECONNRESET
    at exports._errnoException (util.js:890:11)
    at TCP.onread (net.js:552:26)

In other situations the "read ECONNRESET" happens much more early:

ncclient.coffee:43 DEBUG: Local ident: 'SSH-2.0-ssh2js0.1.14'
ncclient.coffee:43 DEBUG: Client: Trying 128.251.72.209 on port 830 ...
ncclient.coffee:43 DEBUG: Client: Connected
ncclient.coffee:203 Error: read ECONNRESET(…)

Currently I am using the following to connect:

@ssh.connect
  host:     hostname
  port:     port
  username: username
  password: password
  algorithms:
    cipher: ["3des-cbc"]
  debug:    @debugSSH

From the error it seems, I am not even get connected - so my procedure to open the subsystem "netconf" is not even called.

wisotzky commented 7 years ago

Just remark: I don't have issues with other ssh servers using the same code. And also I can run paramiko against this Cisco router w/o the same issue.

mscdex commented 7 years ago

ECONNRESET means the underly TCP connection is being terminated abruptly, I'm not sure there's anything that can be done about that at this level... It's also strange that it's happening at random times.

wisotzky commented 7 years ago

So is there any additional logging, that can be enabled to figure out the root cause for this? I only have seen the issue yet with this Cisco router. Maybe it would be worth a bit to widen the scope with other Cisco Routers and maybe Juniper. Currently I am fine with Nokia routers, Paramiko and OpenDaylight.

Also be aware, that even the issue seems to happen at random times - I have not yet been able to establish a single SSH connection successfully on port 830 with this Cisco router.

mscdex commented 7 years ago

Out of curiosity what node version are you testing with?

wisotzky commented 7 years ago

I have tested this with ATOM 1.6 and now upgraded to ATOM 1.11.2 (latest). When checking process.versions I get the following result:

Object {http_parser: "2.6.2", node: "5.10.0", v8: "4.9.385.28", uv: "1.8.0", zlib: "1.2.8"…}
  ares:"1.10.1-DEV"
  atom-shell:"0.37.8"
  chrome:"49.0.2623.75"
  electron:"0.37.8"
  http_parser:"2.6.2"
  modules:"47"
  node:"5.10.0"
  openssl:"1.0.2g"
  uv:"1.8.0"
  v8:"4.9.385.28"
  zlib:"1.2.8"
mscdex commented 7 years ago

Cisco's SSH implementations have never really been that great based on prior issues I've seen.

A quick google search reveals someone (connecting to a Cisco router running IOS XRv -- same "Cisco-2.0" implementation) that had an issue due to the KEXINIT message size being too large for example, but in the first example you gave it's not even getting to that point. It would be interesting to see a packet capture of the connection when it happens that early in the process. If you can supply that in pcap format, I could take a look to see if there is anything out of the ordinary, besides the RST.

No matter what though, you will want to add an 'error' event handler and optionally try to reconnect.

wisotzky commented 7 years ago

I currently use the error event just to tear down everything - so it becomes the responsible of the user to reconnect. My bigger concern was basically, that I was not able to setup any single session against Cisco. So let me try to do some pcap for those examples I've provided.

wisotzky commented 7 years ago

Hi Brian,

Please find 4 wireshark captures and corresponding log files attached. Examples 1-3 are showing different situations where the communication breaks. In example 4 I am using my ncproxy (running on the local machine) based on paramiko (python). Using the proxy everything is setup and closed down correctly.

Sven

mscdex commented 7 years ago

@wisotzky I don't see the attachments?

wisotzky commented 7 years ago

I've send this via email... Hopefully using the web front-end will fix it. ssh2 issues cisco.zip

mscdex commented 7 years ago

Thank you for the captures and logs.

In case 1 it looks like the server never ACKs the KEXDH_INIT message we send after the KEXINIT messages are exchanged. The TCP stack tries to send it a total of 3 times before giving up, resulting in the RST.

In case 2 it looks like the connection is made but the server never responds to the TCP keepalive packets, so the connection is assumed dead and is closed by the TCP stack.

In case 3 it looks like the server sends its ident, we send our KEXINIT, and then we never hear anything at all from the server (at the TCP level even).

I'm wondering if it has to do with TCP keepalive packets, since that is one of the obvious differences between the first 3 cases and the paramiko packet capture. Can you try commenting out this line and see if that fixes things?

wisotzky commented 7 years ago

Indeed, this is fixing those issues... Really strange. Could you make this option configurable in the connection profile?

mscdex commented 7 years ago

Thanks for the confirmation.

I'll probably just disable it outright since the application-level keepalive settings provide more flexibility anyway.

wisotzky commented 7 years ago

I am appreciating your very fast support! As the information contained in the debug was not really pointing to the actual issue, I was not expecting to get it fixed in a day. Very well done!

Thx wiso