Slack-side disconnects

[Kyrremann]

In the last week my slack bot has started to disconnect from our Slack team. There are no logs of disconnect, or stack traces. I've started running the bot in debug-mode, and the last thing it logged before it disconnected was the following.

2018-06-08 20:44:59 20:44:59 bot.1  | D, [2018-06-08T20:44:59.795621 #34] DEBUG -- Slack::RealTime::Concurrency::Celluloid::Socket#handle_read: �
2018-06-08 20:44:59 20:44:59 bot.1  | D, [2018-06-08T20:44:59.795799 #34] DEBUG -- Slack::RealTime::Concurrency::Celluloid::Socket#write: ��iP¸
2018-06-08 20:46:59 20:46:59 bot.1  | D, [2018-06-08T20:46:59.795748 #34] DEBUG -- Slack::RealTime::Concurrency::Celluloid::Socket#handle_read: �
2018-06-08 20:46:59 20:46:59 bot.1  | D, [2018-06-08T20:46:59.795976 #34] DEBUG -- Slack::RealTime::Concurrency::Celluloid::Socket#write: ����
2018-06-08 20:48:59 20:48:59 bot.1  | D, [2018-06-08T20:48:59.796764 #34] DEBUG -- Slack::RealTime::Concurrency::Celluloid::Socket#handle_read: �
2018-06-08 20:48:59 20:48:59 bot.1  | D, [2018-06-08T20:48:59.796915 #34] DEBUG -- Slack::RealTime::Concurrency::Celluloid::Socket#write: ����o
2018-06-08 20:50:59 20:50:59 bot.1  | D, [2018-06-08T20:50:59.797632 #34] DEBUG -- Slack::RealTime::Concurrency::Celluloid::Socket#handle_read: �
2018-06-08 20:50:59 20:50:59 bot.1  | D, [2018-06-08T20:50:59.797844 #34] DEBUG -- Slack::RealTime::Concurrency::Celluloid::Socket#write: ���
2018-06-08 20:50:59 20:50:59 bot.1  | �#

I'm not sure how to debug this my self, and I have no idea for what is wrong.

My setup is running on Google App Engine, with one process for a Sinatra web and a different process running the slackbot. Neither of the process stops, but the bot is offline in Slack.

The code for the project is available here: https://github.com/navikt/standbot

Any help would be welcoming!

[dblock]

I am seeing the same thing on larger production bots. I am going to guess this is slack-side, but it also looks like we're not seeing/handling the disconnect properly somehow. I would say first lets understand what we expect on a disconnect like this? An exception?

[dblock]

For celluloid we want to emit a :close like here. So I would add debug code around there to find out how this is caused.

[Kyrremann]

Thanks for the reply.
We have a little over 1100 users in our team, but I don't feel the problem started before more of the users started using my app. In the beginning it was only 10 users, but now we are just below 50 users.

One strange thing is that the bot goes down in the evening, when no one is at work.

About what we expect. I guess an exception with a reason would be a good start. I will also reach out to Slack, and hear with them.

[dblock]

I stuck a restart into my bots (eg. dblock/slack-strava@bc29324) and I am seeing about a dozen of these every hour on a bot system with hundreds of connections.

Did you hear back from slack? Either way we definitely don’t have correct handling code here and the client thinks the connection is still open - maybe we can reproduce this or at least attempt to handle this based on that data being recieved? What’s that data is a good question.

[aoberoi]

hey, there! i'm from slack and i'd like to help you folks get this issue resolved. while i do have some expertise in our RTM API and Websockets (i helped build our node implementation), my Ruby is a little rusty. as a first step, i'd like to reproduce this with minimal steps, in my own app/workspace. if anyone has any shortcuts for me, please share. otherwise i'll update here as i find things.

[alexagranov]

@dblock @Kyrremann I can also confirm the strange disconnects but not seeing any issues restarting via latest master code.

We're not running close to hundreds of teams yet and getting to the restart! handler just fine: https://github.com/slack-ruby/slack-ruby-bot-server/blob/master/lib/slack-ruby-bot-server/server.rb#L19

Attaching a log from Prod with names redacted to protect the innocent. The disconnects start happening around 10PM UTC.

[alexagranov]

Oh woops, just realized we're in slack-ruby-client project, not slack-ruby-bot-server. Well, I'll leave my comment in case it's helpful.

[dblock]

Hi @aoberoi and thanks for jumping in!

I think the easiest is to run a full blown bot. Alternatively we can write some code to open hundreds of RTM connections and see what happens. Here's a full bot:

Clone https://github.com/slack-ruby/slack-shellbot.
Create a slack app with Slack and create .env with the following.

SLACK_CLIENT_ID=...
SLACK_CLIENT_SECRET=...

Run bundle install, make sure you have a local MongoDB, then foreman start. This will start a local instance of the bot. Navigate to http://localhost:5000 and you can install the bot with any team. Try DMing ls or help to the test bot and it should respond.

Registration creates a Team object. I think this happens more often with many connections, so I would just add this to app.rb:

team = Team.first
100.times do
   SlackShellbot::Service.instance.start!(team)
end

You should get 100 instances of the bot running.

[dblock]

Here's a recent down log from a bot with 297 teams.

W, [2018-06-13T22:08:38.463423 #212]  WARN -- : DOWN: game=pong, name=, id=T02BTFT45
W, [2018-06-13T22:08:39.509848 #212]  WARN -- : DOWN: game=pong, name=, id=T5ATQ5K6W
W, [2018-06-13T22:08:47.103501 #212]  WARN -- : DOWN: game=pong, name=, id=T04LD63KU
W, [2018-06-13T22:08:47.571911 #212]  WARN -- : DOWN: game=pong, name=, id=T6GF0T8UT
W, [2018-06-13T22:08:54.902196 #212]  WARN -- : DOWN: game=pong, name=, id=TAV9ZRUBY
W, [2018-06-13T22:09:04.200495 #212]  WARN -- : DOWN: game=tic-tac-toe, name=, id=TB1QA85PH
W, [2018-06-13T22:09:06.035861 #212]  WARN -- : DOWN: game=pong, name=, id=T024XAHD7
W, [2018-06-13T22:09:06.789929 #212]  WARN -- : DOWN: game=pong, name=, id=T0JT3RRV2
W, [2018-06-13T22:09:13.165823 #212]  WARN -- : DOWN: game=pong, name=, id=T06N1SCTB
I, [2018-06-13T22:09:38.589368 #212]  INFO -- : RESTART: game=pong, name=, id=T02BTFT45
I, [2018-06-13T22:09:38.589496 #212]  INFO -- : Starting team game=pong, name=, id=T02BTFT45.
...

I left team IDs in there for you @aoberoi in case you have logs to look at on your side. These all went offline in the 5 minutes preceding this log.

Note that we also see successful disconnects/restarts.

I, [2018-06-14T00:10:29.391865 #212]  INFO -- : T02990GNF: socket closed, restarting ...
I, [2018-06-14T00:10:29.586615 #212]  INFO -- : Successfully connected team  (T02990GNF) to https://....slack.com.

[dblock]

If you want to add more logging to the code that handles disconnects, put it here.

[Kyrremann]

@dblock I forgot to contact the Slack team, but since @aoberoi joined the issue, I'll wait.

I havne't had time to work any more on this, but I have now had the bot running since Monday. Also, I'm just running one team.

[andrewhood125]

Any luck with this? Our bot disconnects daily. It's a important piece of our infrastructure we use to coordinate deployments.