search

mscdex / ssh2

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

exec stream: 'exit' event triggered before 'data' events #60

Closed rferro closed 11 years ago

rferro commented 11 years ago

That happens sometimes, 'exit' event is triggered before 'data' events. This is the correct flow? If yes, how do I handle this because I created a function with a callback to return the output of the ssh command and i trigger this callback in the event 'exit', and sometimes it is empty because the data comes later.

mscdex commented 11 years ago

Can you provide a simple example that reproduces this? Also what node version are you using?

rferro commented 11 years ago

I'm using node v0.10.12.

See this example:

var ssh2 = require('ssh2');

var conn = new ssh2();

function exec(conn, cmd, callback) {
  conn.exec(cmd, function(err, stream) {
    if (err) throw err;

    var out = "";

    stream.on('data', function(data, extended) {
      console.log('> DATA', cmd);
      out += data.toString();
    });

    stream.on('exit', function(code, signal) {
      console.log('> EXIT', cmd);
      callback(null, out.split("\n"));
    });
  });
};

conn.on('ready', function() {
  exec(conn, 'echo 1; seq 3', function(err, out) {
    console.log('> 1 OUT', out);

    exec(conn, 'echo 2; seq 3', function(err, out) {
      console.log('> 2 OUT', out);
      conn.end();
    });
  });
});

conn.connect({
  host: 'host',
  port: 22,
  username: 'user',
  privateKey: require('fs').readFileSync('key.pem')
});

Most of the time the output is:

> DATA echo 1; seq 3
> DATA echo 1; seq 3
> EXIT echo 1; seq 3
> 1 OUT [ '1', '1', '2', '3', '' ]
> DATA echo 2; seq 3
> DATA echo 2; seq 3
> EXIT echo 2; seq 3
> 2 OUT [ '2', '1', '2', '3', '' ]

But sometimes the output is:

> DATA echo 1; seq 3
> DATA echo 1; seq 3
> EXIT echo 1; seq 3
> 1 OUT [ '1', '1', '2', '3', '' ]
> DATA echo 2; seq 3
> EXIT echo 2; seq 3
> 2 OUT [ '2', '' ]
> DATA echo 2; seq 3

The second 'data' event of command "echo 2; seq 3" was triggered after the event 'exit'.

rferro commented 11 years ago

sorry, I closed this issue by mistake.

mscdex commented 11 years ago

Can you set debug: console.log in the settings passed to connect() and post the output here?

rferro commented 11 years ago 
DEBUG: Parser: STATE_INIT
DEBUG: Parser: STATE_GREETING
DEBUG: Parser: STATE_HEADER
DEBUG: Connection: Server ident: 'SSH-2.0-OpenSSH_4.7p1 Debian-8ubuntu3'
DEBUG: Parser: STATE_PACKETBEFORE (expecting 8)
DEBUG: Connection: Sent KEXINIT
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 776
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: KEXINIT
DEBUG: Connection: Comparing KEXInits...
DEBUG: Connection: Sent KEXDH_INIT
DEBUG: Parser: STATE_PACKETBEFORE (expecting 8)
DEBUG: Parser: STATE_PACKET
DEBUG: Parser: remainLen === 824
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 === 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 === 16
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_DATA
> DATA echo 1; seq 3
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
> EXIT echo 1; seq 3
> 1 OUT [ '1', '' ]
DEBUG: Connection: Sent CHANNEL_OPEN
DEBUG: Channel: Sent 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_DATA
> DATA echo 1; seq 3
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: 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 === 16
DEBUG: Parser: STATE_PACKETDATA
DEBUG: Parser: hmacSize === 16
DEBUG: Parser: STATE_PACKETDATAVERIFY
DEBUG: Parser: STATE_PACKETDATAAFTER, packet: CHANNEL_DATA
> DATA echo 2; seq 3
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_DATA
> DATA echo 2; seq 3
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
> EXIT echo 2; seq 3
> 2 OUT [ '2', '1', '2', '3', '' ]
DEBUG: Connection: Sent DISCONNECT
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_EOF
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)
mscdex commented 11 years ago

You should really use the 'close' event on the stream instead of 'exit' if you're buffering data like this. Like node's child_process.spawn(), when 'exit' is emitted, the stdout/stderr "streams" can still be open.

rferro commented 11 years ago

Tks

atd commented 9 years ago

I am having same problem. Using node v0.10.29 and close event.

If I run it invoking gulp from shell, everything goes fine. But jenkins fails with

....
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
data: 

undefined:0

^
SyntaxError: Unexpected end of input
    at Object.parse (native)
    at Channel.<anonymous> (/var/lib/jenkins/jobs/Pear2Pear/workspace/gulpfile.js:499:32)
    at Channel.emit (events.js:95:17)
    at SSH2Stream.<anonymous> (/var/lib/jenkins/jobs/Pear2Pear/workspace/node_modules/ssh2/lib/Channel.js:124:14)
    at SSH2Stream.g (events.js:180:16)
    at SSH2Stream.emit (events.js:92:17)
    at parsePacket (/var/lib/jenkins/jobs/Pear2Pear/workspace/node_modules/ssh2/node_modules/ssh2-streams/lib/ssh.js:3437:10)
    at SSH2Stream._transform (/var/lib/jenkins/jobs/Pear2Pear/workspace/node_modules/ssh2/node_modules/ssh2-streams/lib/ssh.js:555:13)
    at SSH2Stream.Transform._read [as __read] (_stream_transform.js:179:10)
    at SSH2Stream._read (/var/lib/jenkins/jobs/Pear2Pear/workspace/node_modules/ssh2/node_modules/ssh2-streams/lib/ssh.js:213:15)

Code:

  connection.on('ready', function() {
    connection.exec('docker inspect ' + config.deploy.swellrt.name, function(err, stream) {
      if (err) { throw err ; }

      var data = '';

      stream.
        on('data', function(d) {
          data += d;
          console.log(data);
        }).
        on('close', function() {
          console.log('data: ' + data);

          var container = JSON.parse(data)[0];

          if (container) {
            if (container.Config.Image === taggedImage) {
              // Right image is deployed
              console.log('swellrt already running');
              done();
              connection.end();
            } else {
              console.log('updating swellrt');
              stop(container.Id, function() {
                start();
              });
            }
          } else {
            console.log('swellrt not running');
            start();
          }
        }).
        stderr.on('data', function(data) { console.log('STDERR: ' + data); });
    });
  }).connect(config.deploy.swellrt.ssh);

Debug output:

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'
DEBUG: Outgoing: Writing KEXINIT
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:940,padLen:8,remainLen:936
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXINIT
DEBUG: Comparing KEXINITs ...
DEBUG: (local) KEX algorithms: diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
DEBUG: (remote) KEX algorithms: curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1
DEBUG: KEX algorithm: diffie-hellman-group14-sha1
DEBUG: (local) Host key formats: ssh-rsa,ssh-dss
DEBUG: (remote) Host key formats: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256
DEBUG: Host key format: ssh-rsa
DEBUG: (local) Client->Server ciphers: aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,blowfish-cbc,3des-cbc,arcfour256,arcfour128,cast128-cbc,arcfour
DEBUG: (remote) Client->Server ciphers: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com
DEBUG: Client->Server Cipher: aes256-ctr
DEBUG: (local) Server->Client ciphers: aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,blowfish-cbc,3des-cbc,arcfour256,arcfour128,cast128-cbc,arcfour
DEBUG: (remote) Server->Client ciphers: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com
DEBUG: Server->Client Cipher: aes256-ctr
DEBUG: (local) Client->Server HMAC algorithms: hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,hmac-sha1-96,hmac-md5-96
DEBUG: (remote) Client->Server HMAC algorithms: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
DEBUG: Client->Server HMAC algorithm: hmac-sha1
DEBUG: (local) Server->Client HMAC algorithms: hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,hmac-sha1-96,hmac-md5-96
DEBUG: (remote) Server->Client HMAC algorithms: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
DEBUG: Server->Client HMAC algorithm: hmac-sha1
DEBUG: (local) Client->Server compression algorithms: none
DEBUG: (remote) Client->Server compression algorithms: none,zlib@openssh.com
DEBUG: Client->Server compression algorithm: none
DEBUG: (local) Server->Client compression algorithms: none
DEBUG: (remote) Server->Client compression algorithms: none,zlib@openssh.com
DEBUG: Server->Client compression algorithm: none
DEBUG: Outgoing: Writing KEXDH_INIT
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:828,padLen:7,remainLen:824
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXDH_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:20
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 (publickey -- check)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:300,padLen:4,remainLen:288
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:20
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: USERAUTH_PK_OK
DEBUG: Outgoing: Writing USERAUTH_REQUEST (publickey)
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:20
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:20
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, exec)
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:20
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:20
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: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:4732,padLen:11,remainLen:4720
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:20
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_DATA (0)
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:20
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_EOF (0)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:18,remainLen:32
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:20
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_REQUEST (0, exit-status)
DEBUG: Outgoing: Writing CHANNEL_CLOSE (0)
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:20
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
data:
mscdex commented 9 years ago

@atd Can you use console.dir(data); instead? I'm not sure if that undefined:0 is part of data or if it's part of the exception message. Also, you might try logging the data from the stream.stderr stream to see if docker is spitting anything out on stderr.

atd commented 9 years ago

Thank you @mscdex

I though I was logging stream.stderr (see code in previous comment). If not, could you please provide me with more specific code?

I changed the code a little bit for logging the data along with the events:

      stream.
        on('data', function(d) {
          data += d;
          console.dir('on data: ' + data);
        }).
        on('close', function() {
          console.log('on close: ' + data);

          var container = JSON.parse(data)[0];
         [....]

There is no sign of the data event in the output:

[...]
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:18,remainLen:32
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:20
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_REQUEST (0, exit-status)
DEBUG: Outgoing: Writing CHANNEL_CLOSE (0)
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:20
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
'on close: '

undefined:0

^
SyntaxError: Unexpected end of input
    at Object.parse (native)
    at Channel.<anonymous> (/var/lib/jenkins/jobs/Pear2Pear/workspace/gulpfile.js:500:32)
    at Channel.emit (events.js:95:17)
    at SSH2Stream.<anonymous> (/var/lib/jenkins/jobs/Pear2Pear/workspace/node_modules/ssh2/lib/Channel.js:124:14)
    at SSH2Stream.g (events.js:180:16)
    at SSH2Stream.emit (events.js:92:17)
    at parsePacket (/var/lib/jenkins/jobs/Pear2Pear/workspace/node_modules/ssh2/node_modules/ssh2-streams/lib/ssh.js:3437:10)
    at SSH2Stream._transform (/var/lib/jenkins/jobs/Pear2Pear/workspace/node_modules/ssh2/node_modules/ssh2-streams/lib/ssh.js:555:13)
    at SSH2Stream.Transform._read [as __read] (_stream_transform.js:179:10)
    at SSH2Stream._read (/var/lib/jenkins/jobs/Pear2Pear/workspace/node_modules/ssh2/node_modules/ssh2-streams/lib/ssh.js:213:15)
atd commented 9 years ago

Waiting 5s inside the close callback solves the issue

      stream.
        on('data', function(d) {
          data += d;
          console.dir('on data: ' + data);
        }).
        on('close', function() {
          setTimeout(function() {
            console.log('on close: ' + data);

            var container = JSON.parse(data)[0];

           [....]

         }, 5000);
mscdex commented 9 years ago

Can you try the master branch (removing your 5s timeout too) and let me know if that works for you?

atd commented 9 years ago

Sorry @mscdex but it still fails. Two tries, the first one passed but the job remained alive (I think the output was not closed). The second one failed with the usual behaviour

mscdex commented 9 years ago

@atd Can you provide debug output with the master branch? I want to verify that it's not closing the channel early still.

atd commented 9 years ago

Here it is

[...]
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: HMAC size:20
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_EOF (0)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:18,remainLen:32
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:20
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_REQUEST (0, exit-status)
DEBUG: Outgoing: Writing CHANNEL_CLOSE (0)
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:20
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
'on close: '

undefined:0

^
SyntaxError: Unexpected end of input
    at Object.parse (native)
    at Channel.<anonymous> (/var/lib/jenkins/jobs/Pear2Pear/workspace/gulpfile.js:500:32)
    at Channel.emit (events.js:95:17)
    at SSH2Stream.<anonymous> (/var/lib/jenkins/jobs/Pear2Pear/workspace/node_modules/ssh2/lib/Channel.js:124:14)
    at SSH2Stream.g (events.js:180:16)
    at SSH2Stream.emit (events.js:92:17)
    at parsePacket (/var/lib/jenkins/jobs/Pear2Pear/workspace/node_modules/ssh2/node_modules/ssh2-streams/lib/ssh.js:3437:10)
    at SSH2Stream._transform (/var/lib/jenkins/jobs/Pear2Pear/workspace/node_modules/ssh2/node_modules/ssh2-streams/lib/ssh.js:555:13)
    at SSH2Stream.Transform._read [as __read] (_stream_transform.js:179:10)
    at SSH2Stream._read (/var/lib/jenkins/jobs/Pear2Pear/workspace/node_modules/ssh2/node_modules/ssh2-streams/lib/ssh.js:213:15)