st2chatops doesn't exit on ERROR, keeps waiting/unresponsive when AUTH/API unresolved #124

arm4b · 2019-04-04T17:24:35Z

Spot during the StackStorm/st2-dockerfiles#19 K8s/Docker work

If ST2 AUTH/API urls can't be DNS resolved, ERROR state is reached, however st2chatops doesn't exit with respective error code. Instead it's being unresponsive/hanging/waiting in a running state.

It should exit instead (or retry with limit). This especially makes Docker env unreliable where we expect the process to exit/stop if something didn't work properly.

Reproducing

cd /opt/stackstorm/chatops
ST2_AUTH_URL=http://non-existent:9100/ ST2_API_URL=http://non-existent:9101/ bin/hubot

Log

$ docker logs 9c1d109416fd
body-parser deprecated undefined extended: provide extended option node_modules/hubot/src/robot.js:445:21
[Thu Apr 04 2019 17:03:57 GMT+0000 (Coordinated Universal Time)] DEBUG Loading adapter slack
[Thu Apr 04 2019 17:03:57 GMT+0000 (Coordinated Universal Time)] INFO hubot-slack adapter v4.5.5
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
[Thu Apr 04 2019 17:03:57 GMT+0000 (Coordinated Universal Time)] DEBUG RtmClient initialized with options: undefined
[Thu Apr 04 2019 17:03:57 GMT+0000 (Coordinated Universal Time)] DEBUG RtmClient#start() with options: {}
[Thu Apr 04 2019 17:03:58 GMT+0000 (Coordinated Universal Time)] DEBUG SlackBot#authenticated() Found self in RTM start data
[Thu Apr 04 2019 17:03:58 GMT+0000 (Coordinated Universal Time)] INFO Logged in as @stanley in workspace arma
[Thu Apr 04 2019 17:03:58 GMT+0000 (Coordinated Universal Time)] INFO Connected to Slack RTM
[Thu Apr 04 2019 17:03:58 GMT+0000 (Coordinated Universal Time)] DEBUG Loading scripts from /opt/stackstorm/chatops/scripts
[Thu Apr 04 2019 17:03:58 GMT+0000 (Coordinated Universal Time)] DEBUG Loading scripts from /opt/stackstorm/chatops/src/scripts
[Thu Apr 04 2019 17:03:58 GMT+0000 (Coordinated Universal Time)] DEBUG Loading external-scripts from npm packages
[Thu Apr 04 2019 17:03:58 GMT+0000 (Coordinated Universal Time)] INFO Requesting a token...
[Thu Apr 04 2019 17:03:58 GMT+0000 (Coordinated Universal Time)] DEBUG Using slack post data handler.
[Thu Apr 04 2019 17:03:58 GMT+0000 (Coordinated Universal Time)] DEBUG Parsing help for /opt/stackstorm/chatops/node_modules/hubot-stackstorm/scripts/stackstorm.js
[Thu Apr 04 2019 17:03:58 GMT+0000 (Coordinated Universal Time)] DEBUG Parsing help for /opt/stackstorm/chatops/node_modules/hubot-help/src/help.coffee
[Thu Apr 04 2019 17:03:58 GMT+0000 (Coordinated Universal Time)] ERROR Failed to authenticate: getaddrinfo ENOTFOUND non-existent non-existent:9100
(node:24) UnhandledPromiseRejectionWarning: Error: getaddrinfo ENOTFOUND non-existent non-existent:9100
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:56:26)

(node:24) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:24) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

The text was updated successfully, but these errors were encountered:

arm4b · 2019-04-12T12:49:05Z

More on this like:

Fri, 12 Apr 2019 12:42:58 GMT body-parser deprecated undefined extended: provide extended option at node_modules/hubot/src/robot.js:445:21
[Fri Apr 12 2019 12:42:58 GMT+0000 (Coordinated Universal Time)] DEBUG Loading adapter slack
[Fri Apr 12 2019 12:42:58 GMT+0000 (Coordinated Universal Time)] INFO hubot-slack adapter v4.5.5
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
[Fri Apr 12 2019 12:42:58 GMT+0000 (Coordinated Universal Time)] DEBUG RtmClient initialized with options: undefined
[Fri Apr 12 2019 12:42:58 GMT+0000 (Coordinated Universal Time)] DEBUG RtmClient#start() with options: {}
error: Response not OK:  invalid_auth
[Fri Apr 12 2019 12:42:59 GMT+0000 (Coordinated Universal Time)] ERROR Can't fetch users
error: Response not OK:  invalid_auth
error: Disconnecting because invalid_auth is not recoverable
error:  message=invalid_auth, stack=Error: invalid_auth
    at handleHttpResponse (/opt/stackstorm/chatops/node_modules/@slack/client/lib/clients/transports/call-transport.js:103:17)
    at handleTransportResponse (/opt/stackstorm/chatops/node_modules/@slack/client/lib/clients/transports/call-transport.js:153:19)
    at apply (/opt/stackstorm/chatops/node_modules/lodash/lodash.js:478:17)
    at wrapper (/opt/stackstorm/chatops/node_modules/lodash/lodash.js:5323:16)
    at Request.handleRequestTranportRes (/opt/stackstorm/chatops/node_modules/@slack/client/lib/clients/transports/request.js:21:5)
    at apply (/opt/stackstorm/chatops/node_modules/lodash/lodash.js:478:17)
    at Request.wrapper [as _callback] (/opt/stackstorm/chatops/node_modules/lodash/lodash.js:5323:16)
    at Request.self.callback (/opt/stackstorm/chatops/node_modules/request/request.js:186:22)
    at Request.emit (events.js:189:13)
    at Request.<anonymous> (/opt/stackstorm/chatops/node_modules/request/request.js:1163:10)
    at Request.emit (events.js:189:13)
    at IncomingMessage.<anonymous> (/opt/stackstorm/chatops/node_modules/request/request.js:1085:12)
    at Object.onceWrapper (events.js:277:13)
    at IncomingMessage.emit (events.js:194:15)
    at endReadableNT (_stream_readable.js:1125:12)
    at process._tickCallback (internal/process/next_tick.js:63:19)

seems it's overall regression in hubot-stackstorm module came during upgrade so the process doesn't exit on failure giving no options to recover.

cc @blag

blag · 2019-04-23T04:44:18Z

The fix for this isn't going to make it into ST2 3.0, but I think it can make it into ST2 3.0.1.

arm4b · 2019-04-23T16:48:14Z

@blag Works for me, thanks for the update.
BTW as ST2 K8s is in beta development, we're using dev version of st2 so far.

jinpingh · 2019-05-20T17:15:46Z

@blag Did more testing for different configurations. It comes down one issue, how do we handle failure for st2chatops and exit with respective error code.

Testcase 1: Setup ST2 credential with invalid ST2_AUTH_URL
export ST2_AUTH_USERNAME="st2admin"
export ST2_AUTH_PASSWORD="Ch@ngeMe"
export ST2_AUTH_URL=http://non-existent:9100/
Result:
Duplicated issue as mentioned above.
Caught exception at https://github.com/StackStorm/hubot-stackstorm/blob/master/scripts/stackstorm.js#L172
Log:
Failed to authenticate: getaddrinfo EAI_AGAIN non-existent non-existent:9100

Tastcase 2: With invalid HUBOT_SLACK_TOKEN
Result: Duplicated issue as mentioned above at second comments.
LOG: error: Response not OK: invalid_auth

Testcase 3: Setup ST2 credentials and correct ST2_AUTH_URL with invalid ST2_API_URL
export ST2_AUTH_USERNAME="st2admin"
export ST2_AUTH_PASSWORD="Ch@ngeMe"
export ST2_AUTH_URL="${ST2_API_URL:-https://${ST2_HOSTNAME}/api}"
export ST2_API_URL=http://non-existent:9101/
Result:
Caught exception at: https://github.com/StackStorm/hubot-stackstorm/blob/master/scripts/stackstorm.js#L239
This case has mentioned in the above issue description, but with different result.
Log:
[Mon May 20 2019 03:24:38 GMT+0000 (Coordinated Universal Time)] INFO Loading commands....
[Mon May 20 2019 03:24:38 GMT+0000 (Coordinated Universal Time)] ERROR Failed to retrieve commands from "http://non-existent:9101/": getaddrinfo EAI_AGAIN non-existent non-existent:9101

Testcae 4: Setup credential with invalid ST2_API_KEY:
Result:
Caught exception at https://github.com/StackStorm/hubot-stackstorm/blob/master/scripts/stackstorm.js#L239
Log:
[Mon May 20 2019 03:26:07 GMT+0000 (Coordinated Universal Time)] ERROR Stream error: Event { type: 'error', status: 401 }
[Mon May 20 2019 03:26:07 GMT+0000 (Coordinated Universal Time)] ERROR Failed to retrieve commands from "https://localhost/api": Unauthorized - ApiKey with key_hash=9b5a52e68c3d25baacd535cc50db1e2a729110ba1b93338f9cbba39cbddc37920789aa4f867792cf544eb1350ea24e44291fb85eaa2b31e64b398e810247a8af not found.

Testcase 5: With an invalid ST2_AUTH_TOKEN
Result': Caught exception at https://github.com/StackStorm/hubot-stackstorm/blob/master/scripts/stackstorm.js#L239 Log`:
[Mon May 20 2019 21:32:03 GMT+0000 (Coordinated Universal Time)] ERROR Stream error: Event { type: 'error', status: 401 }
[Mon May 20 2019 21:32:03 GMT+0000 (Coordinated Universal Time)] ERROR Failed to retrieve commands from "https://localhost/api": Unauthorized
[Mon May 20 2019 21:34:03 GMT+0000 (Coordinated Universal Time)] INFO Loading commands....
[Mon May 20 2019 21:34:03 GMT+0000 (Coordinated Universal Time)] ERROR Failed to retrieve commands from "https://localhost/api": Unauthorized
[Mon May 20 2019 21:36:03 GMT+0000 (Coordinated Universal Time)] INFO Loading commands....
[Mon May 20 2019 21:36:03 GMT+0000 (Coordinated Universal Time)] INFO Loading commands....
[Mon May 20 2019 21:36:03 GMT+0000 (Coordinated Universal Time)] ERROR Failed to retrieve commands from "https://localhost/api": Unauthorized

Testcase 6: Without config HUBOT_SLACK_TOKEN
Result:
Caught exception at ./node_modules/hubot-slack/src/bot.coffee Line 33
Log:
[Mon May 20 2019 03:40:33 GMT+0000 (Coordinated Universal Time)] DEBUG RtmClient initialized with options: undefined
[Mon May 20 2019 03:40:33 GMT+0000 (Coordinated Universal Time)] ERROR No token provided to Hubot

Fixes StackStorm/st2chatops#124 For the case if st2chatops encounters authenticate or unresolved application URL issues with Stackstorm, instead it's being unresponsive/hanging/waiting in a running state, st2chatops will be exit. With EXIT_ON_FAILURES is setup during interval call for loadCommands, it will not be exit from process.

Fixes StackStorm/st2chatops#124 For the case if st2chatops encounters authenticate or unresolved application URL issues with Stackstorm, instead it's being unresponsive/hanging/waiting in a running state, st2chatops will be exit.

arm4b · 2019-06-20T17:10:40Z

More identified corner cases from this issue yet to be resolved.
StackStorm/hubot-stackstorm#172 addresses it partially.

arm4b added the bug label Apr 4, 2019

arm4b added the regression label Apr 12, 2019

arm4b mentioned this issue Apr 12, 2019

Chatops integration StackStorm/stackstorm-k8s#55

Merged

4 tasks

This was referenced May 21, 2019

Log errors and exit on authentication issues on Hubot plugin initialization StackStorm/hubot-stackstorm#168

Closed

Create a new environment variable EXIT_ON_FAILURES. #125

Closed

jinpingh mentioned this issue May 29, 2019

End to end test cases for st2chatops bad ST2 config. StackStorm/st2tests#170

Closed

arm4b mentioned this issue Jun 5, 2019

Exit hubot on unhandled promise rejections and other unrecoverable errors StackStorm/hubot-stackstorm#172

Merged

arm4b closed this as completed in StackStorm/hubot-stackstorm@efb13e1 Jun 20, 2019

arm4b reopened this Jun 20, 2019

blag mentioned this issue Jun 20, 2019

Refactor stackstorm.js a bit StackStorm/hubot-stackstorm#177

Merged

arm4b mentioned this issue Jun 25, 2019

Exit hubot on Unauthorized errors StackStorm/hubot-stackstorm#178

Merged

arm4b closed this as completed in 4b20d4c Jun 26, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

st2chatops doesn't exit on ERROR, keeps waiting/unresponsive when AUTH/API unresolved #124

st2chatops doesn't exit on ERROR, keeps waiting/unresponsive when AUTH/API unresolved #124

arm4b commented Apr 4, 2019 •

edited

Loading

arm4b commented Apr 12, 2019 •

edited

Loading

blag commented Apr 23, 2019

arm4b commented Apr 23, 2019

jinpingh commented May 20, 2019 •

edited

Loading

arm4b commented Jun 20, 2019 •

edited

Loading

st2chatops doesn't exit on ERROR, keeps waiting/unresponsive when AUTH/API unresolved #124

st2chatops doesn't exit on ERROR, keeps waiting/unresponsive when AUTH/API unresolved #124

Comments

arm4b commented Apr 4, 2019 • edited Loading

Reproducing

Log

arm4b commented Apr 12, 2019 • edited Loading

blag commented Apr 23, 2019

arm4b commented Apr 23, 2019

jinpingh commented May 20, 2019 • edited Loading

arm4b commented Jun 20, 2019 • edited Loading

arm4b commented Apr 4, 2019 •

edited

Loading

arm4b commented Apr 12, 2019 •

edited

Loading

jinpingh commented May 20, 2019 •

edited

Loading

arm4b commented Jun 20, 2019 •

edited

Loading