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

Reconnect doesn't work very well #5

Closed
bobrik opened this issue Dec 14, 2014 · 25 comments
Closed

Reconnect doesn't work very well #5

bobrik opened this issue Dec 14, 2014 · 25 comments

Comments

@bobrik
Copy link

bobrik commented Dec 14, 2014

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

# docker logs -f slack-hubot

> topface-slack-hubot@0.2.0 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.

@bobrik
Copy link
Author

bobrik commented Dec 14, 2014

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

@ccoenen
Copy link

ccoenen commented Dec 29, 2014

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

@ccoenen
Copy link

ccoenen commented Dec 30, 2014

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.

@ccoenen
Copy link

ccoenen commented Dec 30, 2014

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.

@the-lay
Copy link

the-lay commented Dec 30, 2014

+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

@nacyot
Copy link

nacyot commented Jan 8, 2015

👍

@ccoenen
Copy link

ccoenen commented Jan 23, 2015

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

@sdhull
Copy link

sdhull commented Feb 5, 2015

Possibly related to slackapi/hubot-slack#127 ?

@np0x
Copy link

np0x commented Feb 12, 2015

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

@bobrik
Copy link
Author

bobrik commented Mar 13, 2015

This is really frustrating if hubot does deploys for qa 😢

@jak
Copy link

jak commented Mar 24, 2015

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?

@jasford
Copy link

jasford commented May 7, 2015

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.

@ccoenen
Copy link

ccoenen commented May 7, 2015

@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.

@jasford
Copy link

jasford commented May 7, 2015

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...

@ccoenen
Copy link

ccoenen commented May 8, 2015

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

@ambikads
Copy link

ambikads commented May 8, 2015

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

@rubensayshi
Copy link

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 = {};

@bbn
Copy link

bbn commented Jul 10, 2015

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

@rubensayshi
Copy link

same, but that's no fun :P

@Nesurion
Copy link

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

@ulion
Copy link

ulion commented Jul 16, 2015

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

@betzerra
Copy link

+1

@fordnox
Copy link

fordnox commented Jul 18, 2015

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

@vanm
Copy link
Contributor

vanm commented Aug 10, 2015

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.

@ghost
Copy link

ghost commented Feb 13, 2016

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.

This issue was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests