flightplan
flightplan copied to clipboard
Published
20 hours ago •
pstadler
pstadler
Inconsistent return code
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!
Yep. I've made a small example logging a 'which wp2' (will fail) return code.
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;
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
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
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.
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;
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