Node-slack-sdk: Reconnect doesn't work very well

Created on 14 Dec 2014  Â·  25Comments  Â·  Source: slackapi/node-slack-sdk

I have hubot with slack adapter and it fails to reconnect after connection loss.

# docker logs -f slack-hubot

> [email protected] start /app
> coffee ./node_modules/.bin/hubot --adapter slack

Sat, 13 Dec 2014 13:41:55 GMT connect deprecated multipart: use parser (multiparty, busboy, formidable) npm module instead at node_modules/hubot/node_modules/express/node_modules/connect/lib/middleware/bodyParser.js:56:20
Sat, 13 Dec 2014 13:41:55 GMT connect deprecated limit: Restrict request size at location of read at node_modules/hubot/node_modules/express/node_modules/connect/lib/middleware/multipart.js:86:15
[Sat Dec 13 2014 13:41:55 GMT+0000 (UTC)] DEBUG Loading adapter slack
[Sat Dec 13 2014 13:41:55 GMT+0000 (UTC)] INFO Connecting...
[Sat Dec 13 2014 13:41:57 GMT+0000 (UTC)] INFO Logged in as hubot of topface, but not yet connected
[Sat Dec 13 2014 13:41:58 GMT+0000 (UTC)] INFO Slack client now connected
[Sat Dec 13 2014 13:41:58 GMT+0000 (UTC)] DEBUG Loading scripts from /app/scripts
[Sat Dec 13 2014 13:41:58 GMT+0000 (UTC)] DEBUG Parsing help for /app/scripts/deploy.coffee
[Sat Dec 13 2014 13:41:58 GMT+0000 (UTC)] DEBUG Loading scripts from /app/src/scripts
[Sat Dec 13 2014 13:41:58 GMT+0000 (UTC)] DEBUG Loading hubot-scripts from /app/node_modules/hubot-scripts/src/scripts
[Sat Dec 13 2014 13:41:58 GMT+0000 (UTC)] DEBUG Parsing help for /app/node_modules/hubot-scripts/src/scripts/applause.coffee
[Sat Dec 13 2014 13:41:58 GMT+0000 (UTC)] DEBUG Loading external-scripts from npm packages
[Sat Dec 13 2014 13:41:58 GMT+0000 (UTC)] DEBUG Parsing help for /app/node_modules/hubot-help/src/help.coffee
[Sat Dec 13 2014 13:41:58 GMT+0000 (UTC)] DEBUG Parsing help for /app/node_modules/hubot-google-images/src/google-images.coffee
[Sat Dec 13 2014 13:42:02 GMT+0000 (UTC)] DEBUG Received message: '<censored>' in channel: stage-deploy, from: bobrik
[Sat Dec 13 2014 13:47:50 GMT+0000 (UTC)] DEBUG Received message: '<censored>' in channel: stage-deploy, from: ivanpochtar
[Sat Dec 13 2014 13:47:50 GMT+0000 (UTC)] DEBUG Message '<censored>' matched regex //^\s*[@]?hubot[:,]?\s*(?:deploy me (.*)$)/i/
[Sat Dec 13 2014 13:47:50 GMT+0000 (UTC)] DEBUG Sending to stage-deploy: <censored>
[Sat Dec 13 2014 13:52:06 GMT+0000 (UTC)] DEBUG Sending to stage-deploy: <censored>
[Sat Dec 13 2014 13:53:42 GMT+0000 (UTC)] DEBUG Received message: '<censored>' in channel: stage-deploy, from: ivanpochtar
[Sat Dec 13 2014 15:14:46 GMT+0000 (UTC)] DEBUG Received message: '<censored>' in channel: tf-mobile-random, from: topolog
[Sat Dec 13 2014 15:14:56 GMT+0000 (UTC)] DEBUG Received message: '<censored>' in channel: tf-mobile-random, from: topolog
[Sat Dec 13 2014 17:59:35 GMT+0000 (UTC)] DEBUG Received message: '<censored>' in channel: general, from: tony
[Sat Dec 13 2014 22:38:26 GMT+0000 (UTC)] DEBUG Received message: '<https://vk.com/public3861590?w=wall-3861590_1319>' in channel: random, from: amberovsky
[Sat Dec 13 2014 22:53:33 GMT+0000 (UTC)] ERROR Last pong is too old: 14.895
[Sat Dec 13 2014 22:53:33 GMT+0000 (UTC)] INFO Reconnecting in 1000ms
[Sat Dec 13 2014 22:53:33 GMT+0000 (UTC)] INFO Slack client closed
[Sat Dec 13 2014 22:53:34 GMT+0000 (UTC)] INFO Attempting reconnect
[Sat Dec 13 2014 22:53:34 GMT+0000 (UTC)] INFO Connecting...

and then nothing happens.

Most helpful comment

Ok, first off, I apologize for how long it's taken us to resolve these issues.

I just pushed the 2.0.0 release for this library, which is a ground up refactor with the aim of building a lib that both Slack and our external contributors can easily work with and improve.

It also includes substantially improved reconnection logic and handling, for both routine disconnects as well team_migration events and similar. I'll also be making sure to expedite fixes for any issues with reconnection logic in particular, as I know that's been a pain for folks in the past.

So, I'd suggest that the best way to resolve these issues is to upgrade to the latest version. If you have any problems in doing that, please create a new issue and I'll try and help you in there.

All 25 comments

Logging in _apiCall could really help to figure out if Connecting... is actually happening.

I have the same problem. Can i help debug it?

[Sun Dec 28 2014 00:02:13 GMT+0100 (CET)] INFO Data for hubot brain retrieved from Redis
[Sun Dec 28 2014 01:26:22 GMT+0100 (CET)] ERROR Last pong is too old: 12.156
[Sun Dec 28 2014 01:26:22 GMT+0100 (CET)] INFO Reconnecting in 1000ms
[Sun Dec 28 2014 01:26:22 GMT+0100 (CET)] INFO Slack client closed
[Sun Dec 28 2014 01:26:23 GMT+0100 (CET)] INFO Attempting reconnect
[Sun Dec 28 2014 01:26:23 GMT+0100 (CET)] INFO Connecting...
[Sun Dec 28 2014 23:04:18 GMT+0100 (CET)] INFO Connecting...
[Sun Dec 28 2014 23:04:19 GMT+0100 (CET)] INFO Logged in as [redacted], but not yet connected
[Sun Dec 28 2014 23:04:20 GMT+0100 (CET)] INFO Slack client now connected
[Sun Dec 28 2014 23:04:21 GMT+0100 (CET)] INFO Data for hubot brain retrieved from Redis
[Mon Dec 29 2014 02:32:36 GMT+0100 (CET)] ERROR Last pong is too old: 15.235
[Mon Dec 29 2014 02:32:37 GMT+0100 (CET)] INFO Reconnecting in 1000ms
[Mon Dec 29 2014 02:32:37 GMT+0100 (CET)] INFO Slack client closed

I put a few console.logs into ....slack-client/src/client.coffee:500 - i guess, this is what you referred to, right? clickable link to that location

If this turns something up, i'll get back to you.

[edit] my log now looks like this:

[Tue Dec 30 2014 00:53:40 GMT+0100 (CET)] INFO Connecting...
_apiCall with  rtm.start { agent: 'node-slack' }
_apiCall req ended regularly:  200
[Tue Dec 30 2014 00:53:41 GMT+0100 (CET)] INFO Logged in as [redacted], but not yet connected
(...)
[Tue Dec 30 2014 00:53:42 GMT+0100 (CET)] INFO Data for hubot brain retrieved from Redis
_apiCall with  channels.mark { channel: '[redacted]', ts: '1419897438.000015' }
_apiCall req ended regularly:  200

This does not really help. It appears that the reconnect does in fact work, but my bot does not respond anymore:

[Tue Dec 30 2014 00:53:42 GMT+0100 (CET)] INFO Data for hubot brain retrieved from Redis
_apiCall with  channels.mark { channel: '[redacted]', ts: '1419897438.000015' }
_apiCall req ended regularly:  200
[Tue Dec 30 2014 05:19:23 GMT+0100 (CET)] ERROR Last pong is too old: 13.558
[Tue Dec 30 2014 05:19:23 GMT+0100 (CET)] INFO Reconnecting in 1000ms
[Tue Dec 30 2014 05:19:24 GMT+0100 (CET)] INFO Slack client closed
[Tue Dec 30 2014 05:19:24 GMT+0100 (CET)] INFO Attempting reconnect
[Tue Dec 30 2014 05:19:24 GMT+0100 (CET)] INFO Connecting...
_apiCall with  rtm.start { agent: 'node-slack' }
_apiCall req ended regularly:  200
_apiCall with  channels.mark { channel: '[redacted]', ts: '1419926161.000017' }
_apiCall req ended regularly:  200

Interesting is, that the INFO Logged in as... is never printed. In the "regular" restart, it comes right after rtm.start. In the reconnect case, it does not print at all, it directly continues with the channels.mark. I'm not sure if this is important or not. If you could give me any pointers where to poke in next, i'd gladly go deeper.

Funny detail: The connection works alright: if i send messages, i can see a lot of channels.mark messages - so the bot _does_ receive something. It just does not react anymore.

+1, has stumbled upon the same issue.
Last logs:

[Fri Dec 26 2014 23:28:46 GMT+0000 (UTC)] INFO Slack client now connected
[Sun Dec 28 2014 03:17:38 GMT+0000 (UTC)] ERROR Last pong is too old: 14.915
[Sun Dec 28 2014 03:17:38 GMT+0000 (UTC)] INFO Reconnecting in 1000ms
[Sun Dec 28 2014 03:17:39 GMT+0000 (UTC)] INFO Attempting reconnect
[Sun Dec 28 2014 03:17:39 GMT+0000 (UTC)] INFO Connecting...
[Sun Dec 28 2014 03:17:47 GMT+0000 (UTC)] INFO Logged in as REDACTED of REDACTED, but not yet connected
[Sun Dec 28 2014 03:17:47 GMT+0000 (UTC)] INFO Slack client closed

:+1:

I'll try to catch the attention of @grantmd, maybe he has an idea how we can continue to debug this.

running on a raspberrypi it takes a while to get through the startup routine. Long enough that the 10,000ms time at startup is causing the hubot to die.

[Thu Feb 12 2015 03:55:16 GMT+0000 (UTC)] INFO Connecting...
[Thu Feb 12 2015 03:55:18 GMT+0000 (UTC)] INFO Logged in as hubot of **********, but not yet connected
[Thu Feb 12 2015 03:55:19 GMT+0000 (UTC)] INFO Slack client now connected
[Thu Feb 12 2015 03:55:43 GMT+0000 (UTC)] INFO Data for hubot brain retrieved from Redis
[Thu Feb 12 2015 03:55:49 GMT+0000 (UTC)] INFO Using default redis on localhost:6379
[Thu Feb 12 2015 03:55:50 GMT+0000 (UTC)] ERROR Last pong is too old: 11.059
[Thu Feb 12 2015 03:55:50 GMT+0000 (UTC)] INFO Reconnecting in 1000ms
[Thu Feb 12 2015 03:55:50 GMT+0000 (UTC)] INFO Slack client closed

updating the line 135 of _client.js_ to:

        if ((_this._lastPong != null) && Date.now() - _this._lastPong > 30000) {

allows my raspberrypi to startup hubot without any drama and stay running(output captured at debug log level)

[Thu Feb 12 2015 04:27:31 GMT+0000 (UTC)] DEBUG Loading adapter slack
[Thu Feb 12 2015 04:27:36 GMT+0000 (UTC)] INFO Connecting...
[Thu Feb 12 2015 04:27:37 GMT+0000 (UTC)] INFO Logged in as hubot of **************, but not yet connected
[Thu Feb 12 2015 04:27:38 GMT+0000 (UTC)] INFO Slack client now connected
[Thu Feb 12 2015 04:27:38 GMT+0000 (UTC)] DEBUG Loading scripts from /myhubot/scripts
[Thu Feb 12 2015 04:27:38 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/scripts/example.coffee
[Thu Feb 12 2015 04:27:38 GMT+0000 (UTC)] DEBUG Loading scripts from /myhubot/src/scripts
[Thu Feb 12 2015 04:27:38 GMT+0000 (UTC)] DEBUG Loading hubot-scripts from /myhubot/node_modules/hubot-scripts/src/scripts
[Thu Feb 12 2015 04:27:38 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/ambush.coffee
[Thu Feb 12 2015 04:27:40 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/asana.coffee
[Thu Feb 12 2015 04:27:40 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/ascii.coffee
[Thu Feb 12 2015 04:27:41 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/base64.coffee
[Thu Feb 12 2015 04:27:41 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/dealwithit.coffee
[Thu Feb 12 2015 04:27:41 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/demolition-man.coffee
[Thu Feb 12 2015 04:27:44 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/devexcuse.coffee
[Thu Feb 12 2015 04:27:44 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/geocodeme.coffee
[Thu Feb 12 2015 04:27:45 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/insult.coffee
[Thu Feb 12 2015 04:27:45 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/isup.coffee
[Thu Feb 12 2015 04:27:45 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/lmgtfy.coffee
[Thu Feb 12 2015 04:27:45 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/mindkiller.coffee
[Thu Feb 12 2015 04:27:46 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/news.coffee
[Thu Feb 12 2015 04:27:47 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/pomodoro.coffee
[Thu Feb 12 2015 04:27:47 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/quote.coffee
[Thu Feb 12 2015 04:27:49 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/redis-brain.coffee
[Thu Feb 12 2015 04:27:50 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/reload.coffee
[Thu Feb 12 2015 04:27:51 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/remind.coffee
[Thu Feb 12 2015 04:27:54 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/sonos.coffee
[Thu Feb 12 2015 04:27:54 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/spotify.coffee
[Thu Feb 12 2015 04:27:54 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/stock.coffee
[Thu Feb 12 2015 04:27:55 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/update.coffee
[Thu Feb 12 2015 04:27:56 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/uptime.coffee
[Thu Feb 12 2015 04:27:56 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/url.coffee
[Thu Feb 12 2015 04:27:59 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-scripts/src/scripts/wikipedia.coffee
[Thu Feb 12 2015 04:27:59 GMT+0000 (UTC)] DEBUG Successfully connected to Redis
[Thu Feb 12 2015 04:27:59 GMT+0000 (UTC)] DEBUG Loading external-scripts from npm packages
[Thu Feb 12 2015 04:28:02 GMT+0000 (UTC)] INFO Data for hubot brain retrieved from Redis
[Thu Feb 12 2015 04:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-diagnostics/src/diagnostics.coffee
[Thu Feb 12 2015 04:28:03 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-help/src/help.coffee
[Thu Feb 12 2015 04:28:04 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-heroku-keepalive/src/heroku-keepalive.coffee
[Thu Feb 12 2015 04:28:05 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-google-images/src/google-images.coffee
[Thu Feb 12 2015 04:28:06 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-google-translate/src/google-translate.coffee
[Thu Feb 12 2015 04:28:06 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-pugme/src/pugme.coffee
[Thu Feb 12 2015 04:28:08 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-maps/src/maps.coffee
[Thu Feb 12 2015 04:28:09 GMT+0000 (UTC)] INFO Using default redis on localhost:6379
[Thu Feb 12 2015 04:28:09 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-redis-brain/src/redis-brain.coffee
[Thu Feb 12 2015 04:28:10 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-rules/src/rules.coffee
[Thu Feb 12 2015 04:28:10 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-shipit/src/shipit.coffee
[Thu Feb 12 2015 04:28:10 GMT+0000 (UTC)] DEBUG Parsing help for /myhubot/node_modules/hubot-youtube/src/youtube.coffee
[Thu Feb 12 2015 04:28:10 GMT+0000 (UTC)] DEBUG Successfully connected to Redis
[Thu Feb 12 2015 04:28:10 GMT+0000 (UTC)] INFO Data for hubot brain retrieved from Redis

This is really frustrating if hubot does deploys for qa :cry:

I also ran into this issue when running hubot on a raspi - increasing the pong timeout allowed enough time for the startup. Would allowing a parameter to override the pong timeout be a suitable interim solution?

I'm having this same issue. My bot stays connected for hours, sometimes days, then disconnects. It does not seem to be throwing any errors. I'm running on a t1.micro instance on AWS – so I should have a little more power than a raspi.

I'm creating a new Slack client with new SlackClient(config.token, true, true) as part of a bigger Node app that does a few other things. My app does not die and continues to perform it's other duties, but the Slack client disconnects, cutting us off from interacting with the app via Slack. A restart always fixes the issue, forcing a reconnect.

@jasford: i'm using it in a hubot installation, where i recently upgraded the intermediary layer (hubot-slack). For me, the problem is now much less of a hassle. Maybe that helps you find a workaround for you, too.

I'm not using hubot-slack – just this node-slack-client directly. I just upgraded to the latest release though and will see if that helps. It will take a few days to know for sure...

Yes, i realize that. I just meant, maybe you can copy their change over to your code.

I am trying to send messages to all the chat windows from a chat room and slack disconnects with this error message
[Fri May 08 2015 15:08:27 GMT+0000 (UTC)] ERROR Last pong is too old: 21.788
[Fri May 08 2015 15:08:27 GMT+0000 (UTC)] INFO Reconnecting in 1000ms
[Fri May 08 2015 15:08:28 GMT+0000 (UTC)] INFO Slack client closed

having same issue with node-slack-client :(

Most of the time it just goes [Fri Jun 19 2015 11:55:28 GMT+0000 (UTC)] ERROR Last pong is too old: 11.226
Sometimes a Fri, 19 Jun 2015 11:55:28 GMT tipbot:user ERROR { [Error: socket hang up] code: 'ECONNRESET' } just before that.

it reconnects fine, the open event is emitted again and it receives messages, but connected: false when debugging

it seems to me the close from the ws should be handled to reconnect too?

also maybe the client state needs to be reset after a reconnect? something like;

    this.channels = {};
    this.dms = {};
    this.groups = {};
    this.users = {};
    this.bots = {};

same problem here. i have resorted to restarting the bot frequently.

same, but that's no fun :P

Having the same issue. Hope this get's fixed soon. Restarting the bot every other day isn't really a solution.

when the pong timeout, it call reconnect, but which should not do that if autoConnect is false.

+1

Same issue here:

[Fri Jul 17 2015 23:48:32 GMT-0400 (EDT)] ERROR Last pong is too old: 14.756
[Fri Jul 17 2015 23:48:32 GMT-0400 (EDT)] INFO Reconnecting in 1000ms
[Fri Jul 17 2015 23:48:32 GMT-0400 (EDT)] INFO Slack client closed

I'd appreciate it if people tested #66 and posted their thoughts. Adopting that branch would require you to abandon any explicit reconnect calls in Slack close events you may have set, as it shifts the reconnect responsibility into this Client.

If you want to test this + some websocket upgrades and fixes, I've been using https://github.com/vanm/node-slack-client/tree/ws-and-team-migration-fixes in production.

Ok, first off, I apologize for how long it's taken us to resolve these issues.

I just pushed the 2.0.0 release for this library, which is a ground up refactor with the aim of building a lib that both Slack and our external contributors can easily work with and improve.

It also includes substantially improved reconnection logic and handling, for both routine disconnects as well team_migration events and similar. I'll also be making sure to expedite fixes for any issues with reconnection logic in particular, as I know that's been a pain for folks in the past.

So, I'd suggest that the best way to resolve these issues is to upgrade to the latest version. If you have any problems in doing that, please create a new issue and I'll try and help you in there.

Was this page helpful?
0 / 5 - 0 ratings

Related issues

CoreyCole picture CoreyCole  Â·  12Comments

aoberoi picture aoberoi  Â·  11Comments

hckhanh picture hckhanh  Â·  21Comments

kurisubrooks picture kurisubrooks  Â·  36Comments

aoberoi picture aoberoi  Â·  16Comments