If hubot reconnects due to a slow system, it answers messages twice

[alitheg]

I'm running hubot on a raspberry pi, and I've had to turn up the timeout to avoid "last pong too old" problems on startup. The slack adapter has been made to deal with these errors by reconnecting, but I don't think it's correctly closing the old connection properly - every response hubot sends is duplicated unless I hack the timeout value to prevent the error.

[ptierno]

👍 just started noticing this today

[eriklindebratt]

Yep, have the same issue as well.

[eiroh]

same issue

[technicalpickles]

I was debugging some other issues with HUBOT_LOG_LEVEL=debug, and saw:

[Sun Sep 27 2015 01:24:37 GMT-0400 (EDT)] ERROR Last pong is too old: 3598.976
[Sun Sep 27 2015 01:24:37 GMT-0400 (EDT)] INFO Reconnecting in 1000ms
[Sun Sep 27 2015 01:24:38 GMT-0400 (EDT)] INFO Attempting reconnect
[Sun Sep 27 2015 01:24:38 GMT-0400 (EDT)] INFO Connecting...
[Sun Sep 27 2015 01:24:39 GMT-0400 (EDT)] INFO Logged in as examplebot of Hubot, but not yet connected
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] INFO Slack client now connected
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] DEBUG Loading scripts from /examplebot-slack/scripts
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] DEBUG Parsing help for /examplebot-slack/scripts/example.coffee
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] DEBUG Loading scripts from /examplebot-slack/src/scripts
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] DEBUG Loading hubot-scripts from /examplebot-slack/node_modules/hubot-scripts/src/scripts
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] DEBUG Loading external-scripts from npm packages
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] DEBUG Parsing help for /examplebot-slack/node_modules/hubot-help/src/help.coffee
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] DEBUG Parsing help for /examplebot-slack/node_modules/hubot-google-images/src/google-images.coffee
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] DEBUG Parsing help for /examplebot-slack/node_modules/hubot-google-translate/src/google-translate.coffee
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] DEBUG Parsing help for /examplebot-slack/node_modules/hubot-pugme/src/pugme.coffee
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] DEBUG Parsing help for /examplebot-slack/node_modules/hubot-maps/src/maps.coffee
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] DEBUG Parsing help for /examplebot-slack/node_modules/hubot-rules/src/rules.coffee
[Sun Sep 27 2015 01:24:42 GMT-0400 (EDT)] DEBUG Parsing help for /examplebot-slack/node_modules/hubot-shipit/src/shipit.coffee

I'll need to dig more, but something about the reconnect is causing scripts to be loaded a second time, which would explain getting two responses.

[technicalpickles]

I think I tracked it down:

• hubot-slack registers a handler with node-slack on 'open': https://github.com/slackhq/hubot-slack/blob/af37d933671423e5c00966395c9852ee7123bab7/src/slack.coffee#L34
• open emits that the adapter is connected: https://github.com/slackhq/hubot-slack/blob/af37d933671423e5c00966395c9852ee7123bab7/src/slack.coffee#L84-L88
• hubot loads scripts once the adapter is connected: https://github.com/github/hubot/blob/a658cc3e41d01172a6402c515e476590b3faa876/bin/hubot#L135
• when node-slack detects the ping being too old, it reconnects: https://github.com/slackhq/node-slack-client/blob/1ab67fc4bdd650ec186db63ce8d9aaa94d838b9a/src/client.coffee#L111-L116
• node-slack reconnect calls login: https://github.com/slackhq/node-slack-client/blob/1ab67fc4bdd650ec186db63ce8d9aaa94d838b9a/src/client.coffee#L166-L169
• login restarts the stream: https://github.com/slackhq/node-slack-client/blob/1ab67fc4bdd650ec186db63ce8d9aaa94d838b9a/src/client.coffee#L166-L169
• eventually, there's a new 'hello' event, which fires 'open' a second time: https://github.com/slackhq/node-slack-client/blob/1ab67fc4bdd650ec186db63ce8d9aaa94d838b9a/src/client.coffee#L345-L348

And with that, the scripts are loaded a second time. To fix this without requiring an update to hubot upstream, the adapter should only emit 'connected' once.

[EvanLomas]

I have this issue when running hubot on a Gen1 Raspberry Pi

[joekinley]

Any idea when this will be fixed? I have this bug every day, and it gets really annoying

[Krishna-teja]

I am running hubot in azure. Having the same issue. Can we know when this can be fixed?

[technicalpickles]

We just released hubot 2.17.0 with a fix for this: hubotio/hubot#1083