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

Log errors and exit on authentication issues on Hubot plugin initialization #168

Closed
wants to merge 52 commits into from
Closed
Show file tree
Hide file tree
Changes from 38 commits
Commits
Show all changes
52 commits
Select commit Hold shift + click to select a range
8f7c74e
Exit `st2chatop` from `st2client` failures.
jinpingh May 28, 2019
c2770bb
Call 'process.exit(1)' to exit from process.
jinpingh May 28, 2019
6613a3d
Add callback to handle uncaught hubot exceptions.
jinpingh May 31, 2019
fe44e13
Revert change made for `bind(self)`
jinpingh May 31, 2019
c3b451f
Add big comment to Slack monkey patcher
blag Jun 4, 2019
d44be18
Remove Object.assign() polyfill and require node.js >= 8.3.0
blag Jun 4, 2019
3bf6fe2
Break out the dummy Logger into its own module
blag Jun 4, 2019
51b0262
Accept robot_name parameter and save it
blag Jun 4, 2019
969c084
Rename st2client.js variables to api_client and auth_client
blag Jun 4, 2019
98cf5f2
Coalesce multiple var declarations into one
blag Jun 4, 2019
233915c
Combine and rename hubotErrorCallback and exitProcessWithLog into log…
blag Jun 4, 2019
0cf0e26
Refactor loadCommands to not have an options object parameter
blag Jun 4, 2019
28d2e4c
Ensure that we do not authenticate while the robot is stopping and sh…
blag Jun 4, 2019
76e7179
Use array unpacking because we can
blag Jun 4, 2019
f588845
Refactor stream error handle to properly register a callback
blag Jun 4, 2019
8518e92
Remove error handler now that we have an uncaughtException handler
blag Jun 4, 2019
52a4d0f
Rename 'source' to 'stream'
blag Jun 4, 2019
862a331
Close down the previous stream instead of recreating another one
blag Jun 4, 2019
b112859
Add unit tests for invalid auth environment variables
blag Jun 4, 2019
63abae1
Test for exit code
blag Jun 4, 2019
97f2ef9
Simplify Logger methods
blag Jun 4, 2019
b07c28f
Merge pull request #170 from StackStorm/issue-124/simplify-logger
blag Jun 4, 2019
189b2d0
Merge pull request #169 from StackStorm/issue-124/further-tweaks
blag Jun 4, 2019
2ccc85e
Relax assertions on calls to robot.logger.error
blag Jun 5, 2019
e6c5e01
Ignore the actual error string
blag Jun 6, 2019
df5a0db
Merge pull request #175 from StackStorm/issue-124/fix-bad-auth-test
blag Jun 6, 2019
1765c47
Merge branch 'master' into issue-124/exit_on_failures
blag Jun 6, 2019
7605f3c
The express response object is not a hubot response object, so don't …
blag Jun 6, 2019
0dcba8a
Don't exit on ST2 stream (EventSource) error, simply warn about the i…
blag Jun 6, 2019
f81eca6
Merge branch 'master' into issue-124/exit_on_failures
blag Jun 6, 2019
965ffb1
Try to warn the user if posting a message to the chat provider doesn'…
blag Jun 6, 2019
95a4434
Don't exit if loading commands from StackStorm fails
blag Jun 6, 2019
a5311e9
Move changelog line to in development section
blag Jun 6, 2019
c39ba0f
Tweak stop to completely restore previous behavior, and add a shutdow…
blag Jun 6, 2019
6a39dfb
Stop calling 'process.exit(1)` and change some logs
jinpingh Jun 6, 2019
9ac9aa7
Exit `st2chatops` from invalid ST2 configuration.
jinpingh Jun 7, 2019
9903e19
Checking authentication issue from hubot EventSource.
jinpingh Jun 10, 2019
5c86bfa
Move back authentication error check.
jinpingh Jun 10, 2019
6165f1e
Check `err.stack` before log stack information
jinpingh Jun 11, 2019
6d11ae2
Check more error messages for testcases.
jinpingh Jun 11, 2019
de756aa
Log the error message inside logErrorAndExit
jinpingh Jun 11, 2019
59147a6
Change spy function call for error messages.
jinpingh Jun 11, 2019
47639de
Take out two error messages to pass travis testing
jinpingh Jun 11, 2019
954ec13
Remove dead code
blag Jun 11, 2019
1432afd
Rename promise to something useful
blag Jun 11, 2019
e7e9d93
Since we retry anyway, reduce stream errors to warnings
blag Jun 12, 2019
f346581
Move init code to after function definitions
blag Jun 18, 2019
82b8fe6
Remove logErrorAndExit function
blag Jun 18, 2019
27523a0
Allow stopping the stream even when not shutting down hubot
blag Jun 18, 2019
7ee397f
Refactor to use promises properly
blag Jun 18, 2019
0b75e5b
Register globals for linters
blag Jun 18, 2019
68d3b9d
Add and update tests for new behavior
blag Jun 18, 2019
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions CHANGELOG.rst
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,8 @@ Changelog

in development
--------------
* st2chatops now gracefully exits on authentication failures and uncaught exceptions (improvement)
* code cleanup (improvement)

0.9.3
-----
Expand Down
31 changes: 0 additions & 31 deletions lib/slack-messages.js
Original file line number Diff line number Diff line change
Expand Up @@ -16,37 +16,6 @@

var utils = require('./utils.js');

// Polyfill from:
// https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Object/assign
if (typeof Object.assign !== 'function') {
// Must be writable: true, enumerable: false, configurable: true
Object.defineProperty(Object, "assign", {
value: function assign(target, varArgs) { // .length of function is 2
if (target === null) { // TypeError if undefined or null
throw new TypeError('Cannot convert undefined or null to object');
}

var to = Object(target);

for (var index = 1; index < arguments.length; index++) {
var nextSource = arguments[index];

if (nextSource !== null) { // Skip over if undefined or null
for (var nextKey in nextSource) {
// Avoid bugs when hasOwnProperty is shadowed
if (Object.prototype.hasOwnProperty.call(nextSource, nextKey)) {
to[nextKey] = nextSource[nextKey];
}
}
}
}
return to;
},
writable: true,
configurable: true
});
}

var buildMessagesWithChunkedFieldValue = function (msg) {
var msgs;

Expand Down
12 changes: 12 additions & 0 deletions lib/slack_monkey_patch.js
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,18 @@ function patchSendMessage(robot) {
// formatted and parsed on the server side.
// NOTE / TODO: We can get rid of this nasty patch once our node-slack-client and hubot-slack pull
// requests are merged.
// This code was refactored in https://github.com/StackStorm/hubot-stackstorm/pull/6
// which was opened and merged by Kami on 2015-06-04.
// As of 2019-05-22, these were the PRs I could find for the node-slack-client
// hubot-slack repositories:
// * https://github.com/slackapi/node-slack-sdk/pull/42
// - which was closed during a refactor and converted into an issue:
// https://github.com/slackapi/node-slack-sdk/issues/138
// * https://github.com/slackapi/hubot-slack/pull/544
// - which was opened on 2018-11-14, which seems to be too late to actually
// apply to this code
// So...I'm not entirely sure this monkey patch is still necessary.
// End-to-end testing is required to figure out for sure.
if (robot.adapter && robot.adapter.constructor && robot.adapter.constructor.name === 'SlackBot') {
for (var channel in robot.adapter.client.channels) {
robot.adapter.client.channels[channel].sendMessage = sendMessageRaw.bind(robot.adapter.client.channels[channel]);
Expand Down
2 changes: 2 additions & 0 deletions package.json
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,7 @@
"devDependencies": {
"chai": "^4.2.0",
"chai-as-promised": "^7.1.1",
"chai-string": "^1.5.0",
"eslint": "^5.16.0",
"eslint-plugin-notice": "0.7.8",
"gulp": "^3.9.1",
Expand All @@ -48,6 +49,7 @@
"hubot-help": "0.2.2",
"hubot-mock-adapter": "^1.1.1",
"log": "1.4.0",
"mocked-env": "^1.2.4",
"nock": "^10.0.0",
"nyc": "^13.0.1",
"sinon": "^6.3.5",
Expand Down
141 changes: 84 additions & 57 deletions scripts/stackstorm.js
Original file line number Diff line number Diff line change
Expand Up @@ -99,22 +99,20 @@ var TWOFACTOR_MESSAGE = "This action requires two-factor auth! Waiting for your
module.exports = function(robot) {
slack_monkey_patch.patchSendMessage(robot);

var self = this;

var promise = Promise.resolve();

if (env.ST2_API) {
robot.logger.warning("ST2_API is deprecated and will be removed in a future releases. Instead, please use the ST2_API_URL environment variable.");
}
var url = utils.parseUrl(env.ST2_API_URL);

var opts = {
protocol: url.protocol,
host: url.hostname,
port: url.port,
prefix: url.path,
rejectUnauthorized: false
};
var _stream = null,
self = this,
promise = Promise.resolve(),
url = utils.parseUrl(env.ST2_API_URL),
opts = {
protocol: url.protocol,
host: url.hostname,
port: url.port,
prefix: url.path,
rejectUnauthorized: false
};

if (env.ST2_STREAM_URL) {
var stream_url = utils.parseUrl(env.ST2_STREAM_URL);
Expand All @@ -126,16 +124,30 @@ module.exports = function(robot) {
};
}

var api = st2client(opts);
var api_client = st2client(opts);

if (env.ST2_API_KEY) {
api.setKey({ key: env.ST2_API_KEY });
api_client.setKey({ key: env.ST2_API_KEY });
} else if (env.ST2_AUTH_TOKEN) {
api.setToken({ token: env.ST2_AUTH_TOKEN });
api_client.setToken({ token: env.ST2_AUTH_TOKEN });
}

function logErrorAndExit(err, res) {
if (err) {
robot.logger.error(err.stack);
}
if (res) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I found that second param res is only used in robot.error Hubot handler for uncaught exceptions.

Does it make sense to move entire logErrorAndExit code into robot.error handler itself?
And from the code where we want to exit just throw err as it was before. Looks better in the context of https://stackoverflow.com/a/40321400/4533625 (case 3) discussion.
It will be caught by robot.error then.

By throwing when we want to end an app (which will then call robot.error) I think allows any other bubbled up tasks to actually finish in a more safe way. It'll also stick with the previous code logic primitives.

@blag What do you think?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I considered this and ultimately decided against it. We use logErrorAndExit in one more place than just the Hubot error callback, and I suspect that we will expand the use of it in further commits.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@jinpingh What do you think?

Copy link
Contributor Author

@jinpingh jinpingh Jun 6, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@jinpingh What do you think?

Since we changed how st2chatops should be behaviors if something went wrong from initial design, before I understand the goal for this PR, will not change it.

Copy link
Member

@arm4b arm4b Jun 6, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm actually talking about reverting initial design where we previously throw'ed error as a way to complete hubot execution.
In our case robot.error handler will automatically catch those exceptions as unhandled and then call stop.

Here is the diff:

- robot.error(logErrorAndExit);

- function logErrorAndExit(err, res) {
+ robot.error(function(err, res) {
    if (err) {
      robot.logger.error(err.stack);
    }
    if (res) {
      res.send(JSON.stringify({
        "status": "failed",
        "msg": "An error occurred trying to post the message:\n" + err
      }));
    }

    stop({shutdown: true});
- };
+ });

- logErrorAndExit('Failed to authenticate: ' + err.message);
+ throw 'Failed to authenticate: ' + err.message;

By technical reasons I think that raising robot.error handler which then calls stop() via throw instead of logErrorAndExit function would align better with the existing shutdown mechanics.

Add here cases when users want to re-use hubot-stackstorm module and so adding ability to catch errors and re-define robot.error on their side would make sense.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Add here cases when users want to re-use hubot-stackstorm module and so adding ability to catch errors and re-define robot.error on their side would make sense.

That isn't quite how the new code works.

Calling robot.error simply adds a callback function to the callback chain for the error event. See this code in Hubot for more.

If our users want to change or remove any of the error callbacks, they can still do so, they just have to manipulate robot.errorHandlers themselves. It's not as simple as assigning a function to robot.onerror anymore.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Making the hubot error handler an unnamed lambda function, and then simply re-throw()ing exceptions is fine.

res.send(JSON.stringify({
"status": "failed",
"msg": "An error occurred trying to post the message:\n" + err
}));
}

stop({shutdown: true});
}

function authenticate() {
api.removeListener('expiry', authenticate);
api_client.removeListener('expiry', authenticate);

// API key gets precedence 1
if (env.ST2_API_KEY) {
Expand All @@ -152,7 +164,7 @@ module.exports = function(robot) {

var url = utils.parseUrl(env.ST2_AUTH_URL);

var client = st2client({
var auth_client = st2client({
auth: {
protocol: url.protocol,
host: url.hostname,
Expand All @@ -161,26 +173,28 @@ module.exports = function(robot) {
}
});

return client.authenticate(env.ST2_AUTH_USERNAME, env.ST2_AUTH_PASSWORD)
return auth_client.authenticate(env.ST2_AUTH_USERNAME, env.ST2_AUTH_PASSWORD)
.then(function (token) {
robot.logger.info('Token received. Expiring ' + token.expiry);
api.setToken(token);
client.on('expiry', authenticate);
api_client.setToken(token);
auth_client.on('expiry', authenticate);
})
.catch(function (err) {
robot.logger.error('Failed to authenticate: ' + err.message);

throw err;
// Exit from invalid ST2_AUTH_USERNAME or ST2_AUTH_PASSWORD.
robot.logger.error('Failed to authenticate with st2 username and password: ' + err.message);
logErrorAndExit(err);
});
}

if (env.ST2_API_KEY || env.ST2_AUTH_TOKEN || env.ST2_AUTH_USERNAME || env.ST2_AUTH_PASSWORD) {
// If using username and password then all are required.
if ((env.ST2_AUTH_USERNAME || env.ST2_AUTH_PASSWORD) &&
!(env.ST2_AUTH_USERNAME && env.ST2_AUTH_PASSWORD && env.ST2_AUTH_URL)) {
throw new Error('Env variables ST2_AUTH_USERNAME, ST2_AUTH_PASSWORD and ST2_AUTH_URL should only be used together.');
robot.logger.error('Environment variables ST2_AUTH_USERNAME, ST2_AUTH_PASSWORD and ST2_AUTH_URL should only be used together.');
stop({shutdown: true});
} else {
promise = authenticate();
}
promise = authenticate();
}

// Pending 2-factor auth commands
Expand All @@ -199,9 +213,9 @@ module.exports = function(robot) {
var postDataHandler = postData.getDataPostHandler(robot.adapterName, robot, formatter);

var loadCommands = function() {
robot.logger.info('Loading commands....');
robot.logger.info('Loading commands...');

api.actionAlias.list()
api_client.actionAlias.list()
.then(function (aliases) {
// Remove all the existing commands
command_factory.removeCommands();
Expand Down Expand Up @@ -237,6 +251,9 @@ module.exports = function(robot) {
.catch(function (err) {
var error_msg = 'Failed to retrieve commands from "%s": %s';
robot.logger.error(util.format(error_msg, env.ST2_API_URL, err.message));
if (err.status === 401 && err.message.includes("Unauthorized")) {
Copy link
Member

@arm4b arm4b Jun 10, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What if by refactoring reasons backend returned 401 HTTP code and Authorization Required (not Unauthorized) as a message ?
I think || would be more appropriate as a logical operator here.

Copy link
Contributor

@blag blag Jun 18, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It doesn't make sense to handle an unauthorized error differently than another non-connection error, so I had it always handle it this way. The current code looks like (function loadCommands):

      return (...).then(function () {
        ...
      })
      .catch(function (err) {
        var error_msg = 'Failed to retrieve commands from "%s":\n%s';
        err.stack = util.format(error_msg, env.ST2_API_URL, err.stack);
        robot.logger.error(err.stack);
        throw err;

This allows the loadCommands promise to log the error before it rejects, and then rejects are either ignored (function start):

      // Add an interval which tries to re-load the commands
      commands_load_interval = setInterval(
        // Lambda function that swallows errors so they don't propagate up the stack
        // (errors are still logged within loadCommands itself)
        function () {
          loadCommands().catch(function (err) {});
        },
        (env.ST2_COMMANDS_RELOAD_INTERVAL * 1000));

or the rejection is simply passed up the stack (function start):

      // Initial command loading
      return loadCommands();

and handled elsewhere (init code):

  // Authenticate with StackStorm backend and then call start.
  return authenticated.then(function () {
    return start().then(function () {
      return stop;
    });
  }).catch(function (err) {
    // Since start is only called once when the plugin is loaded, bail
    // loudly and harshly if loadCommands() isn't successful
    stop({shutdown: true});
    throw err;
  });

logErrorAndExit(err);
}
});
};

Expand All @@ -263,7 +280,7 @@ module.exports = function(robot) {
var sendAliasExecutionRequest = function (msg, payload) {
robot.logger.debug('Sending command payload:', JSON.stringify(payload));

api.aliasExecution.create(payload)
api_client.aliasExecution.create(payload)
.then(function (res) { sendAck(msg, res); })
.catch(function (err) {
// Compatibility with older StackStorm versions
Expand Down Expand Up @@ -307,7 +324,7 @@ module.exports = function(robot) {
var twofactor_id = uuid.v4();
robot.logger.debug('Requested an action that requires 2FA. Guid: ' + twofactor_id);
msg.send(TWOFACTOR_MESSAGE);
api.executions.create({
api_client.executions.create({
'action': env.HUBOT_2FA,
'parameters': {
'uuid': twofactor_id,
Expand All @@ -326,7 +343,7 @@ module.exports = function(robot) {
};

robot.respond(/([\s\S]+?)$/i, function(msg) {
var command, result, command_name, format_string, action_alias;
var command, result;

// Normalize the command and remove special handling provided by the chat service.
// e.g. slack replace quote marks with left double quote which would break behavior.
Expand All @@ -339,9 +356,7 @@ module.exports = function(robot) {
return;
}

command_name = result[0];
format_string = result[1];
action_alias = result[2];
var [command_name, format_string, action_alias] = result;

executeCommand(msg, command_name, format_string, command, action_alias);
});
Expand All @@ -357,25 +372,30 @@ module.exports = function(robot) {
}
postDataHandler.postData(data);

res.send('{"status": "completed", "msg": "Message posted successfully"}');
} catch (e) {
robot.logger.error("Unable to decode JSON: " + e);
robot.logger.error(e.stack);
res.send('{"status": "failed", "msg": "An error occurred trying to post the message: ' + e + '"}');
res.send(JSON.stringify({
"status": "completed",
"msg": "Message posted successfully"
}));
} catch (err) {
robot.logger.error('Encountered an error when attempting to post ' +
'message to chat provider, execution results for ' +
'chatops.post_message may not be accurate.');
robot.logger.error(err);
}
});

var commands_load_interval;

function start() {
api.stream.listen().catch(function (err) {
robot.logger.error('Unable to connect to stream:', err);
}).then(function (source) {
source.onerror = function (err) {
// TODO: squeeze a little bit more info out of evensource.js
robot.logger.error('Stream error:', err);
};
source.addEventListener('st2.announcement__chatops', function (e) {
robot.error(logErrorAndExit);

api_client.stream.listen().then(function (stream) {
_stream = stream; // save stream for use in stop()
stream.on('error', function (err) {
robot.logger.error('StackStorm event stream error:', err);
robot.logger.error('Implicitly attempting to reconnect to StackStorm event stream.');
});
stream.addEventListener('st2.announcement__chatops', function (e) {
var data;

robot.logger.debug('Chatops message received:', e.data);
Expand All @@ -390,7 +410,7 @@ module.exports = function(robot) {
});

if (env.HUBOT_2FA) {
source.addEventListener('st2.announcement__2fa', function (e) {
stream.addEventListener('st2.announcement__2fa', function (e) {
var data;

robot.logger.debug('Successfull two-factor auth:', e.data);
Expand All @@ -408,22 +428,29 @@ module.exports = function(robot) {
}
});

// Add an interval which tries to re-load the commands
commands_load_interval = setInterval(loadCommands.bind(self), (env.ST2_COMMANDS_RELOAD_INTERVAL * 1000));

// Initial command loading
loadCommands();

// Add an interval which tries to re-load the commands
commands_load_interval = setInterval(loadCommands.bind(self), (env.ST2_COMMANDS_RELOAD_INTERVAL * 1000));

// Install SIGUSR2 handler which reloads the command
install_sigusr2_handler();
}

function stop() {
function stop(opts) {
var default_opts = {shutdown: false},
opts = Object.assign(default_opts, (opts || {}));
clearInterval(commands_load_interval);
api.stream.listen().then(function (source) {
source.removeAllListeners();
source.close();
});

if (opts.shutdown) {
if (_stream) {
_stream.removeAllListeners();
_stream.close();
}

robot.shutdown();
}
}

function install_sigusr2_handler() {
Expand All @@ -433,7 +460,7 @@ module.exports = function(robot) {
}

// Authenticate with StackStorm backend and then call start.
// On a failure to authenticate log the error but do not quit.
// On a failure to authenticate log the error and quit.
return promise.then(function () {
start();
return stop;
Expand Down
Loading