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

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

Closed
rferro opened this issue Jul 12, 2013 · 15 comments
Closed

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

rferro opened this issue Jul 12, 2013 · 15 comments

Comments

@rferro
Copy link

rferro commented Jul 12, 2013

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
Copy link
Owner

mscdex commented Jul 13, 2013

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

@rferro rferro closed this as completed Jul 13, 2013
@rferro rferro reopened this Jul 13, 2013
@rferro
Copy link
Author

rferro commented Jul 13, 2013

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
Copy link
Author

rferro commented Jul 13, 2013

sorry, I closed this issue by mistake.

@mscdex
Copy link
Owner

mscdex commented Jul 14, 2013

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

@rferro
Copy link
Author

rferro commented Jul 14, 2013

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
Copy link
Owner

mscdex commented Jul 14, 2013

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.

@mscdex mscdex closed this as completed Jul 14, 2013
@rferro
Copy link
Author

rferro commented Jul 15, 2013

Tks

@atd
Copy link

atd commented Jul 29, 2015

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
Copy link
Owner

mscdex commented Aug 1, 2015

@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
Copy link

atd commented Aug 1, 2015

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
Copy link

atd commented Aug 3, 2015

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
Copy link
Owner

mscdex commented Aug 4, 2015

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

atd added a commit to Grasia/teem that referenced this issue Aug 4, 2015
Testing the solution to mscdex/ssh2#60
@atd
Copy link

atd commented Aug 4, 2015

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
Copy link
Owner

mscdex commented Aug 4, 2015

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

@atd
Copy link

atd commented Aug 4, 2015

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)

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

3 participants