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

Inconsistent return code #150

Open
kaisermann opened this issue Oct 26, 2016 · 8 comments
Open

Inconsistent return code #150

kaisermann opened this issue Oct 26, 2016 · 8 comments
Labels

Comments

@kaisermann
Copy link

kaisermann commented Oct 26, 2016

I'm trying to check if my remote machine has a specific command by using which and checking its return code.

const hasWPCLI = transport.exec('which wp', { failsafe: true });
if(hasWPCLI.code !== 0) {
  ...
}

However, I'm getting some strange results as sometimes it is returned '1' and sometimes '0'.

Returning 0:

✈ Running setup:staging
✈ Connecting to 'x.x.x.x'
✈ Executing remote task on x.x.x.x
x.x.x.x $ which wp
x.x.x.x > which: no wp in (/usr/local/bin:/bin:/usr/bin:/usr/local/bin)
x.x.x.x ● ok

Returning 1:

✈ Running setup:staging
✈ Connecting to 'x.x.x.x'
✈ Executing remote task on x.x.x.x
x.x.x.x $ which wp
x.x.x.x > which: no wp in (/usr/local/bin:/bin:/usr/bin:/usr/local/bin)
x.x.x.x ● failed safely (1)

Both calls were made seconds apart from each other.

Any thoughts on what's happening? Thanks!

@pstadler pstadler added the bug label Dec 23, 2016
@pstadler
Copy link
Owner

This is odd. Is this also happening when the failsafe option is disabled?

@kaisermann
Copy link
Author

Yep. I've made a small example logging a 'which wp2' (will fail) return code.

screenshot at dec 23 11-02-46

@pstadler
Copy link
Owner

pstadler commented Dec 23, 2016

Unfortunately, I'm not able to reproduce this.

Could you please replace lib/transport/ssh.js with the following file containing some more logging and re-run your test case -- that would be incredibly helpful. Please run this a couple of times and post the logs here, as it looks like a race-condition. Thanks in advance.

var util = require('util')
  , extend = require('util-extend')
  , Fiber = require('fibers')
  , Connection = require('ssh2').Client
  , byline = require('byline')
  , Transport = require('./index')
  , errors = require('../errors')
  , fs = require('fs');

function SSH(context) {
  SSH.super_.call(this, context);

  var config = extend({}, context.remote); // clone

  if(config.tryKeyboard !== false) {
    config.tryKeyboard = true;
    config.readyTimeout = config.readyTimeout || 30000;
  }

  if(config.privateKey) {
    config.privateKey = fs.readFileSync(config.privateKey, { encoding: 'utf8' });
  }

  var self = this;

  var fiber = Fiber.current;

  this._connection = new Connection();

  this._connection.on('keyboard-interactive', function next(name, instructions,
                                    instructionsLang, prompts, finish, answers) {
    answers = answers || [];

    var currentPrompt = prompts[answers.length];

    if(answers.length < prompts.length) {
      new Fiber(function() {
        var answer = self.prompt(currentPrompt.prompt, { hidden: !currentPrompt.echo });
        answers.push(answer);

        next(name, instructions, instructionsLang, prompts, finish, answers);
      }).run();
    } else {
      finish(answers);
    }
  });

  this._connection.on('ready', function() {
    fiber.run();
  });

  this._connection.on('error', function(err) {
    return fiber.throwInto(err);
  });

  this._connection.connect(config);

  return Fiber.yield();
}
util.inherits(SSH, Transport);

SSH.prototype._exec = function(command, options) {
  options = options || {};

  var self = this;

  options = extend(extend({}, self._options), options); // clone and extend

  var result = {
    code: 0,
    stdout: null,
    stderr: null
  };

  self._logger.command(command);

  var fiber = Fiber.current;

  self._connection.exec(command, options.exec || {}, function(err, stream) {

    stream.on('data', function(data) {
      result.stdout = (result.stdout || '') + data;
    });

    stream.stderr.on('data', function(data) {
      result.stderr = (result.stderr || '') + data;
    });

    byline(stream, { keepEmptyLines: true }).on('data', function(data) {
      if(!options.silent) {
        self._logger.stdout(data);
      }
    });

    byline(stream.stderr, { keepEmptyLines: true }).on('data', function(data) {
      self._logger[options.failsafe ? 'stdwarn' : 'stderr'](data);
    });

    stream.on('exit', function(code) {
      self._logger.warn('DEBUG: exit-start ' + code);
      result.code = code;
      self._logger.warn('DEBUG: exit-end ' + code);
    });

    stream.on('end', function() {
      self._logger.warn('DEBUG: end-start ' + result.code);
      if(result.code === 0) {
        self._logger.success('ok');
      } else if(options.failsafe) {
        self._logger.warn('failed safely (' + result.code + ')');
      } else {
        self._logger.error('failed (' + result.code + ')');

        var error = new errors.CommandExitedAbnormallyError(
                  'Command exited abnormally on ' + self._context.remote.host);

        return fiber.throwInto(error);
      }

      self._logger.warn('DEBUG: end-end ' + result.code);
      fiber.run(result);
    });
  });

  return Fiber.yield();
};

SSH.prototype.close = function() {
  this._connection.end();
};

module.exports = SSH;

@pstadler
Copy link
Owner

Expected output:

x.x.x.x $ which bar
x.x.x.x > bar not found
x.x.x.x ● DEBUG: exit-start 1
x.x.x.x ● DEBUG: exit-end 1
x.x.x.x >
x.x.x.x ● DEBUG: end-start 1
x.x.x.x ● failed safely (1)
x.x.x.x ● DEBUG: end-end 1
x.x.x.x $ which baz
x.x.x.x > baz not found
x.x.x.x ● DEBUG: exit-start 1
x.x.x.x ● DEBUG: exit-end 1
x.x.x.x >
x.x.x.x ● DEBUG: end-start 1
x.x.x.x ● failed safely (1)
x.x.x.x ● DEBUG: end-end 1

@kaisermann
Copy link
Author

There you go:

Code:

plan.remote(function (transport) {
  ['bar','baz'].forEach(function(str){
    var hasWPCLI = transport.exec('which ' + str, {
      failsafe: true
    });
    console.log(hasWPCLI.code);
  });
});

Output:

~/P/o/deployjs 1 $ fly staging                                                        21s 354ms
✈ Running default:staging
✈ Connecting to 'x.x.x.x'
✈ Executing remote task on x.x.x.x
x.x.x.x $ which bar
x.x.x.x > which: no bar in (/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/bin:/usr/local/git/bin)
x.x.x.x ● DEBUG: end-start 0
x.x.x.x ● ok
x.x.x.x ● DEBUG: end-end 0
0
x.x.x.x $ which baz
x.x.x.x > 
x.x.x.x ● DEBUG: exit-start 1
x.x.x.x ● DEBUG: exit-end 1
x.x.x.x > which: no baz in (/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/bin:/usr/local/git/bin)
x.x.x.x ● DEBUG: exit-start 1
x.x.x.x ● DEBUG: exit-end 1
x.x.x.x ● DEBUG: end-start 1
x.x.x.x ● failed safely (1)
x.x.x.x ● DEBUG: end-end 1
1
✈ Remote task on x.x.x.x finished after 595 ms
✈ Flightplan finished after 18 s

Using another target (multiple executions):

~/P/o/deployjs $ fly staging                                                              14:59
✈ Running default:staging
✈ Connecting to 'a.a.a.a'
✈ Executing remote task on a.a.a.a
a.a.a.a $ which bar
a.a.a.a ● DEBUG: end-start 0
a.a.a.a ● ok
a.a.a.a ● DEBUG: end-end 0
0
a.a.a.a $ which baz
a.a.a.a ● DEBUG: exit-start 1
a.a.a.a ● DEBUG: exit-end 1
a.a.a.a ● DEBUG: end-start 0
a.a.a.a ● ok
a.a.a.a ● DEBUG: end-end 0
0
✈ Remote task on a.a.a.a finished after 5.96 s
✈ Flightplan finished after 27 s
~/P/o/deployjs $ fly staging                                                          27s 911ms
✈ Running default:staging
✈ Connecting to 'a.a.a.a'
✈ Executing remote task on a.a.a.a
a.a.a.a $ which bar
a.a.a.a ● DEBUG: exit-start 1
a.a.a.a ● DEBUG: exit-end 1
a.a.a.a ● DEBUG: end-start 1
a.a.a.a ● failed safely (1)
a.a.a.a ● DEBUG: end-end 1
1
a.a.a.a $ which baz
a.a.a.a ● DEBUG: exit-start 1
a.a.a.a ● DEBUG: exit-end 1
a.a.a.a ● DEBUG: end-start 1
a.a.a.a ● failed safely (1)
a.a.a.a ● DEBUG: end-end 1
1
✈ Remote task on a.a.a.a finished after 987 ms
✈ Flightplan finished after 23 s
~/P/o/deployjs $ fly staging                                                          23s 786ms
✈ Running default:staging
✈ Connecting to 'a.a.a.a'
✈ Executing remote task on a.a.a.a
a.a.a.a $ which bar
a.a.a.a ● DEBUG: exit-start 1
a.a.a.a ● DEBUG: exit-end 1
a.a.a.a ● DEBUG: end-start 1
a.a.a.a ● failed safely (1)
a.a.a.a ● DEBUG: end-end 1
1
a.a.a.a $ which baz
a.a.a.a ● DEBUG: exit-start 1
a.a.a.a ● DEBUG: exit-end 1
a.a.a.a ● DEBUG: end-start 1
a.a.a.a ● failed safely (1)
a.a.a.a ● DEBUG: end-end 1
1
✈ Remote task on a.a.a.a finished after 842 ms
✈ Flightplan finished after 20 s
~/P/o/deployjs $ fly staging                                                                    20s 190ms
✈ Running default:staging
✈ Connecting to 'a.a.a.a'
✈ Executing remote task on a.a.a.a
a.a.a.a $ which bar
a.a.a.a ● DEBUG: exit-start 1
a.a.a.a ● DEBUG: exit-end 1
a.a.a.a ● DEBUG: end-start 1
a.a.a.a ● failed safely (1)
a.a.a.a ● DEBUG: end-end 1
1
a.a.a.a $ which baz
a.a.a.a ● DEBUG: end-start 0
a.a.a.a ● ok
a.a.a.a ● DEBUG: end-end 0
0
✈ Remote task on a.a.a.a finished after 869 ms
✈ Flightplan finished after 19 s
~/P/o/deployjs $                                                                                19s 538ms

@pstadler
Copy link
Owner

pstadler commented Jan 2, 2017

Thank you, this is incredibly helpful. It really seems like there's a race condition where the exit event is not thrown, or simply too late.

@pstadler
Copy link
Owner

pstadler commented Jan 2, 2017

I tried multiple workarounds. Before continuing, it would be great if you could replace lib/transport/ssh.js with the following code and run your tests again, as I'm still unable to reproduce this issue.

var util = require('util')
  , extend = require('util-extend')
  , Fiber = require('fibers')
  , Connection = require('ssh2').Client
  , byline = require('byline')
  , Transport = require('./index')
  , errors = require('../errors')
  , fs = require('fs');

function SSH(context) {
  SSH.super_.call(this, context);

  var config = extend({}, context.remote); // clone

  if(config.tryKeyboard !== false) {
    config.tryKeyboard = true;
    config.readyTimeout = config.readyTimeout || 30000;
  }

  if(config.privateKey) {
    config.privateKey = fs.readFileSync(config.privateKey, { encoding: 'utf8' });
  }

  var self = this;

  var fiber = Fiber.current;

  this._connection = new Connection();

  this._connection.on('keyboard-interactive', function next(name, instructions,
                                    instructionsLang, prompts, finish, answers) {
    answers = answers || [];

    var currentPrompt = prompts[answers.length];

    if(answers.length < prompts.length) {
      new Fiber(function() {
        var answer = self.prompt(currentPrompt.prompt, { hidden: !currentPrompt.echo });
        answers.push(answer);

        next(name, instructions, instructionsLang, prompts, finish, answers);
      }).run();
    } else {
      finish(answers);
    }
  });

  this._connection.on('ready', function() {
    fiber.run();
  });

  this._connection.on('error', function(err) {
    return fiber.throwInto(err);
  });

  this._connection.connect(config);

  return Fiber.yield();
}
util.inherits(SSH, Transport);

SSH.prototype._exec = function(command, options) {
  options = options || {};

  var self = this;

  options = extend(extend({}, self._options), options); // clone and extend

  var result = {
    code: 0,
    stdout: null,
    stderr: null
  };

  self._logger.command(command);

  var fiber = Fiber.current;

  self._connection.exec(command, options.exec || {}, function(err, stream) {

    stream.on('data', function(data) {
      result.stdout = (result.stdout || '') + data;
    });

    stream.stderr.on('data', function(data) {
      result.stderr = (result.stderr || '') + data;
    });

    byline(stream, { keepEmptyLines: true }).on('data', function(data) {
      if(!options.silent) {
        self._logger.stdout(data);
      }
    });

    byline(stream.stderr, { keepEmptyLines: true }).on('data', function(data) {
      self._logger[options.failsafe ? 'stdwarn' : 'stderr'](data);
    });

    stream.on('exit', function(code) {
      result.code = code;
    });

    stream.on('end', function() {
      setImmediate(function() {
        if(result.code === 0) {
          self._logger.success('ok');
        } else if(options.failsafe) {
          self._logger.warn('failed safely (' + result.code + ')');
        } else {
          self._logger.error('failed (' + result.code + ')');

          var error = new errors.CommandExitedAbnormallyError(
            'Command exited abnormally on ' + self._context.remote.host);

          return fiber.throwInto(error);
        }

        fiber.run(result);
      });
    });
  });

  return Fiber.yield();
};

SSH.prototype.close = function() {
  this._connection.end();
};

module.exports = SSH;

@kaisermann
Copy link
Author

kaisermann commented Jan 17, 2017

Sorry for the delay!

My flightplan.js:

var plan = require('flightplan');

plan.target('staging', {
  host: 'pepperoni',
  username: 'user',
  agent: process.env.SSH_AUTH_SOCK
});

plan.remote(function (transport) {
  ['bar','baz'].forEach(function(str){
    var returnCode = transport.exec('which ' + str, {
      failsafe: true
    });
    console.log(returnCode.code);
  });
});

The output (executed multiple times):

~/P/P/flightplan $ fly staging                                                          1m 22s 750ms
✈ Running default:staging
✈ Connecting to 'pepperoni'
✈ Executing remote task on pepperoni
pepperoni $ which bar
pepperoni > which: no bar in (/usr/local/bin:/bin:/usr/bin)
pepperoni > 
pepperoni ● failed safely (1)
1
pepperoni $ which baz
pepperoni > which: no baz in (/usr/local/bin:/bin:/usr/bin)
pepperoni > 
pepperoni ● failed safely (1)
1
✈ Remote task on pepperoni finished after 556 ms
✈ Flightplan finished after 22 s
~/P/P/flightplan $ fly staging                                                             23s 610ms
✈ Running default:staging
✈ Connecting to 'pepperoni'
✈ Executing remote task on pepperoni
pepperoni $ which bar
pepperoni > which: no bar in (/usr/local/bin:/bin:/usr/bin)
pepperoni > 
pepperoni ● failed safely (1)
1
pepperoni $ which baz
pepperoni > which: no baz in (/usr/local/bin:/bin:/usr/bin)
pepperoni > 
pepperoni ● ok
0
✈ Remote task on pepperoni finished after 565 ms
✈ Flightplan finished after 22 s
~/P/P/flightplan $ fly staging                                                             22s 490ms
✈ Running default:staging
✈ Connecting to 'pepperoni'
✈ Executing remote task on pepperoni
pepperoni $ which bar
pepperoni > which: no bar in (/usr/local/bin:/bin:/usr/bin)
pepperoni > 
pepperoni ● failed safely (1)
1
pepperoni $ which baz
pepperoni > which: no baz in (/usr/local/bin:/bin:/usr/bin)
pepperoni > 
pepperoni ● failed safely (1)
1
✈ Remote task on pepperoni finished after 607 ms
✈ Flightplan finished after 22 s
~/P/P/flightplan $ fly staging                                                             26s 536ms
✈ Running default:staging
✈ Connecting to 'pepperoni'
✈ Executing remote task on pepperoni
pepperoni $ which bar
pepperoni > which: no bar in (/usr/local/bin:/bin:/usr/bin)
pepperoni > 
pepperoni ● failed safely (1)
1
pepperoni $ which baz
pepperoni > which: no baz in (/usr/local/bin:/bin:/usr/bin)
pepperoni > 
pepperoni ● ok
0
✈ Remote task on pepperoni finished after 608 ms
✈ Flightplan finished after 22 s

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants