exit event not always delivered in case of exec failure about ssh2

[mscdex]

What is the command you're executing? What SSH server and version is this on?

[ykumar6]

bump, seeing the same issue, but for another command.

[ykumar6]

self.ssh.exec(ctl_cmd + ' start', function (err, stream) {});

these are the debug messages. The stream event's exit is never fired

DEBUG: Connection: Sent CHANNELèOPEN
DEBUG: Parser: STATEèPACKETBEFORE (expecting 16)
DEBUG: Parser: STATEèPACKET
DEBUG: Parser: remainLen === 0
DEBUG: Parser: STATEèPACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATEèPACKETDATAVERIFY
DEBUG: Parser: STATEèPACKETDATAAFTER, packet: CHANNELèCLOSE
DEBUG: Parser: STATEèPACKETBEFORE (expecting 16)
DEBUG: Parser: STATEèPACKET
DEBUG: Parser: remainLen === 16
DEBUG: Parser: STATEèPACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATEèPACKETDATAVERIFY
DEBUG: Parser: STATEèPACKETDATAAFTER, packet: CHANNELèOPENèCONFIRMATION
DEBUG: Channel: Sent CHANNELèREQUEST (exec)
DEBUG: Parser: STATEèPACKETBEFORE (expecting 16)
DEBUG: Parser: STATEèPACKET
DEBUG: Parser: remainLen === 16
DEBUG: Parser: STATEèPACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATEèPACKETDATAVERIFY
DEBUG: Parser: STATEèPACKETDATAAFTER, packet: CHANNELèWINDOWèADJUST
DEBUG: Parser: STATEèPACKETBEFORE (expecting 16)
DEBUG: Parser: STATEèPACKET
DEBUG: Parser: remainLen === 0
DEBUG: Parser: STATEèPACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATEèPACKETDATAVERIFY
DEBUG: Parser: STATEèPACKETDATAAFTER, packet: CHANNELèSUCCESS
DEBUG: Parser: STATEèPACKETBEFORE (expecting 16)
DEBUG: Parser: STATEèPACKET
DEBUG: Parser: remainLen === 80
DEBUG: Parser: STATEèPACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATEèPACKETDATAVERIFY
DEBUG: Parser: STATEèPACKETDATAAFTER, packet: CHANNELèDATA
DEBUG: Parser: STATEèPACKETBEFORE (expecting 16)
DEBUG: Connection: Sent ping
DEBUG: Connection: Sent ping
DEBUG: Connection: Sent ping
DEBUG: Connection: Sent ping
DEBUG: Connection: Sent ping
DEBUG: Connection: Sent ping
DEBUG: Connection: Sent ping

[mscdex]

@ykumar6 what is an example ctl_cmd here that produces this problem? Also, what SSH server and version are you using?

[mscdex]

One additional thing I'd like to ask both of you is can you verify that the process is not still alive by ssh'ing in with a putty/openssh/etc client and checking the process list?

[mscdex]

Also @snowfix, can you provide debug output too in addition to the requested extra information? Just set debug: console.log or similar in the object passed to the connect() method.

[asnowfix]

@mscdex I am testing against dropbear. I have a consistent behaviour using a dropbear running on Ubuntu 12.04 (dropbear 2011.54-1ubuntu0.12.04.2) & dropbear on the HP webOS 3.0.5 emulator (dropbear - 0.49-r4), so I think a specific dropbear version is not the issue.

UPDATE: the above is not correct: the failure happens only with dropbear - 0.49-r4 on the HP webOS 3.0.5 emulator.

I will previde DEBUG output & test for remote dangling processes. Note that Adding a timer (I tested up to 2000ms) after 'close' waiting for the exit event does not help: exit is simply not sent.

[asnowfix]

Here is a failure DEBUG log:

DEBUG: Parser: STATE_GREETING
DEBUG: Parser: STATE_HEADER
DEBUG: Parser: STATE_PACKETBEFORE (expecting 8)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 360
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: KEXINIT
DEBUG: Parser: STATE_PACKETBEFORE (expecting 8)
DEBUG: Connection: Sent KEXINIT
DEBUG: Connection: Sent KEXDH_INIT
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 440
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: KEXDH_REPLY
DEBUG: Connection: Sent NEWKEYS
DEBUG: Parser: STATE_PACKETBEFORE (expecting 8)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 8
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: NEWKEYS
DEBUG: Connection: Sent SERVICE_REQUEST
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 16
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: SERVICE_ACCEPT
DEBUG: Connection: Sent USERAUTH_REQUEST (publickey -- check)
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 288
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: USERAUTH_PK_OK
DEBUG: Connection: Sent USERAUTH_REQUEST (publickey)
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 0
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: USERAUTH_SUCCESS
DEBUG: Connection: Sent CHANNEL_OPEN
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 16
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_OPEN_CONFIRMATION
DEBUG: Channel: Sent CHANNEL_REQUEST (exec)
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 0
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_SUCCESS
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 16
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_EXTENDED_DATA
sh: DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 64
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_EXTENDED_DATA
can't create /dev/null/mocha10561: nonexistent directoryDEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 16
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_EXTENDED_DATA

DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 0
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_EOF
DEBUG: Channel: Sent CLOSE
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 0
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_CLOSE
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Connection: Sent DISCONNECT

[asnowfix]

Here is a success DEBUG log:

DEBUG: Parser: STATE_GREETING
DEBUG: Parser: STATE_HEADER
DEBUG: Parser: STATE_PACKETBEFORE (expecting 8)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 360
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: KEXINIT
DEBUG: Parser: STATE_PACKETBEFORE (expecting 8)
DEBUG: Connection: Sent KEXINIT
DEBUG: Connection: Sent KEXDH_INIT
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 448
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: KEXDH_REPLY
DEBUG: Connection: Sent NEWKEYS
DEBUG: Parser: STATE_PACKETBEFORE (expecting 8)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 8
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: NEWKEYS
DEBUG: Connection: Sent SERVICE_REQUEST
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 16
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: SERVICE_ACCEPT
DEBUG: Connection: Sent USERAUTH_REQUEST (publickey -- check)
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 288
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: USERAUTH_PK_OK
DEBUG: Connection: Sent USERAUTH_REQUEST (publickey)
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 0
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: USERAUTH_SUCCESS
DEBUG: Connection: Sent CHANNEL_OPEN
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 16
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_OPEN_CONFIRMATION
DEBUG: Channel: Sent CHANNEL_REQUEST (exec)
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 0
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_SUCCESS
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 80
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_EXTENDED_DATA
sh: can't create /dev/null/mocha11130: nonexistent directory
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 0
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_EOF
DEBUG: Channel: Sent CLOSE
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 32
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_REQUEST
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 0
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_CLOSE
DEBUG: Parser: STATE_PACKETBEFORE (expecting 16)
DEBUG: Connection: Sent DISCONNECT

[asnowfix]

The command I was running in my first test was somewhat a cat XXX | node ssh2 cat > /tmp/foo. In order to understand wether the issue is related to streams (I have a couple of pipe() here), I rather use ls /dev/null/toto now. I observe the same problem.

I have run this comment more than 500 times & never observed a dangling process on the other end.

[asnowfix]

Seems like the flow of message does not send CHANNEL_REQUEST (the one that carries the exit code...) when the test fails. Seems like I need to test against an OpenSSH server now...

[asnowfix]

The problem does not happen with the OpenSSH version that comes with Ubuntu 12.04 LTS. I also checked that it does not happen either with the Dropbear version that comes with this Ubuntu 12.04 LTS. An old dropbear is what caused my pain. Unless @ykumar6 still has issues, you can close this issue.

[mscdex]

I can verify that dropbear 0.51 fixed this bug after seeing this and trying it for myself.

[ykumar6]

I have a CentOS server running OpenSSH. I am seeing the exact same issue, CHANNEL_REQUEST isn't triggered, hence no exit message gets sent to the stream,

[ykumar6]

[root@b1 ~]# ssh -v
OpenSSH_5.3p1, OpenSSL 1.0.0-fips 29 Mar 2010

[root@b1 ~]# cat /etc/release
CentOS release 6.3 (Final)
CentOS release 6.3 (Final)
CentOS release 6.3 (Final)
cpe:/o:centos:linux:6:GA

[asnowfix]

Please fix me if I am wrong, but there is no way mscdex/ssh2 can auto-trigger this event when the server does not issue it. Or maybe I a missing something?

[mscdex]

@ykumar6 are you sure the process you're executing isn't still running on the server? It seems that way since the server isn't even sending EOF or CLOSE at all. I tried various commands on a CentOS 6.3 VM and I could not duplicate the problem.

If it's not still running on the server, what is the exact command you're executing so I can try it on my end?

[mscdex]

I've actually been bit by something recently that may be related to this.

In my case, if the command took a considerable amount of time to complete (in my case ~1 hour) the connection was somehow quietly severed at some point in time. The server didn't notice this until it tried to send the exit status and saw it wasn't able to write or read from the channel/connection any longer. On the ssh module client side, there was no indication of disconnection at all. I tried enabling TCP keepalive, but that did not help. Setting a pingInterval in the connect() object did fix things for me, as I was then able to receive the exit code/signal properly and EOF/close.

If this same fix helps you @ykumar6, let me know. I am thinking about setting a default ping interval to prevent unpleasant surprises like this.

[mscdex]

@snowfix Do you still encounter this with the current master branch?

[asnowfix]

@mscdex I haven't tried to update since I identified that the error was due to an old version of dropbear. That sounded like a limitation ssh2 could not do anything against. Did you push some work-around on the master branch?

[mscdex]

Oh sorry, I misread the conversation last night. I did push an update so that there is a default keepalive, which should help for long-running commands not emitting 'exit' when finished.

[mscdex]

@ykumar6 Do you still encounter this problem with the current master branch? How long does your command take to execute on the server?