Unhandled server-side disconnects

[dblock]

Coming from slack-ruby/slack-ruby-client#208 and celluloid/celluloid-io#187, we're seeing the Slack server drop connections and the client not noticing and being stuck in a run loop.

There's some chance this is a bug here or misunderstanding in the way we use websocket-ruby-driver. Initially I thought this was celluloid-io, but I think this is the driver not handling something correctly.

This currently affects many thousands of users as the slack-ruby-client library is widely used in production and we haven't had much luck even when they looked at it from their side via @aoberoi.

Questions:

• Could someone please take a look at this code to see if there's an obvious bug in the run loop?
• Can someone please share debugging code to translate the opaque binary messages read to add here?
• Any other suggestions?

[ioquatix]

There are two kinds of disconnects - the web socket disconnect event, and the socket read returning nil or throwing an exception (e.g. EPIPE).

Are you detecting the later cases?

https://github.com/slack-ruby/slack-ruby-client/blob/d8b7b267377c4ef97742de2919ee328249e10b49/lib/slack/real_time/concurrency/celluloid.rb#L37-L39

Are you sure that's covering all cases?

Is this returning nil?

https://github.com/slack-ruby/slack-ruby-client/blob/d8b7b267377c4ef97742de2919ee328249e10b49/lib/slack/real_time/concurrency/celluloid.rb#L55

Are you handling that case?

[dblock]

Thanks @ioquatix!

I didn't realize the socket read can return nil meaning something like a disconnect, just to confirm, does that mean it's disconnected and is that a special kind of disconnect (we want to distinguish between client closing and server throwing the client out)? Looks like we're not handling that ...

Help me write the correct code here? What should it look like on nil read?

I would have expected to never need this code (and the driver to emit this in all the right cases):

driver.emit(:close, WebSocket::Driver::CloseEvent.new(1001, 'server closed connection')) unless @closing

Are we doing it wrong?

Will add logging to see if we're getting a nil read too.

[ioquatix]

Ruby sockets are a bit of a mess. A read of length 0 gives nil return. You also need to handle empty string, i.e. read(x > 0) -> nil | "" indicates disconnected. Try printing out the result of that line to see what you get.

[dblock]

I kinda expected the driver to do this for me as it emits other kinds of disconnects. Am I asking for too much?

[ioquatix]

Yes. Do I think it's annoying? EPIPE, EOFError, nil, "". Yes, it's a mess.

Here is an implementation that works:

https://github.com/socketry/async-websocket/blob/f946504fc21a62c3546aa5efa3fd3443dbe6a931/lib/async/websocket/connection.rb#L56-L72

[dblock]

This doesn't look like the problem :(

I added this code to log all messages, handle and show nil or empty buffers.

I never see one.

I, [2018-08-20T16:21:42.177568 #214]  INFO -- : Starting team game=pool, name=Team, id=ID.
I, [2018-08-20T16:21:43.122604 #214]  INFO -- : [69912811601720, :server_open]
I, [2018-08-20T16:21:43.123755 #214]  INFO -- : [69912811601720, :server_message, "{\"type\": \"hello\"}"]
I, [2018-08-20T16:21:43.124090 #214]  INFO -- : [69912811601720, "Successfully connected team Team (ID) to https://....slack.com."]
I, [2018-08-20T16:21:52.980706 #214]  INFO -- : [69912811601720, :server_ping, ""]
I, [2018-08-20T16:22:33.646281 #214]  INFO -- : [69912811601720, :server_message, "{\"type\":\"user_change\", ...}"]
I, [2018-08-20T16:23:21.760776 #214]  INFO -- : [69912811601720, :server_message, "{\"type\":\"user_change\", ...}"]
I, [2018-08-20T16:23:52.985827 #214]  INFO -- : [69912811601720, :server_ping, ""]
I, [2018-08-20T16:23:58.959916 #214]  INFO -- : [69912811601720, :server_message, "{\"type\":\"user_change\", ...}"]
I, [2018-08-20T16:25:52.973440 #214]  INFO -- : [69912811601720, :server_ping, ""]
I, [2018-08-20T16:38:14.770694 #214]  INFO -- : [69912811601720, :server_ping, "", "repeated 7 times"]
I, [2018-08-20T16:39:53.168919 #214]  INFO -- : [69912811601720, :server_ping, ""]
I, [2018-08-20T16:53:00.228227 #214]  INFO -- : [69912811601720, :server_ping, "", "repeated 7 times"]
I, [2018-08-20T19:15:20.998797 #214]  INFO -- : [69912811601720, :server_message, "{\"type\":\"dnd_updated_user\", ..."]
I, [2018-08-20T19:15:53.211556 #214]  INFO -- : [69912811601720, :server_ping, ""]
W, [2018-08-20T19:47:40.985025 #214]  WARN -- : DOWN: game=pool, name=Team, id=ID

That last down is from a ping thread that watches slack status and restarts a bot when slack reports it's down.

I noticed in your implementation you implement next_event and keep a queue to process. This is a bit different from our code that loops over socket.readpartial and asynchronously lets the driver.parse on that returned data which I believe triggers the events. Could we be skipping messages because too slow? Doesn't seem so but I am out of ideas.

[dblock]

I also have a piece of ping code that can identify a socket/driver stuck in this disconnected state. I can examine anything on the object when that happens, ie. an instance of ::WebSocket::Driver or Celluloid::IO::SSLSocket, if something could be helpful?

[ioquatix]

I wonder if there are bugs in Celluloid::IO::SSLSocket. Maybe check the implementation of readpartial.

[ioquatix]

As you know if it's a bug in Celluloid, it's unlikely to ever get fixed.

[dblock]

I am seeing more new problems, now with the DNS resolver ... sigh.

What should I be replacing celluloid-io with?

[ioquatix]

I already shower how to use async with slack: https://gist.github.com/ioquatix/c24f107e2cc7f48e571a37e8e93b0cda

[dblock]

Yes thank you @ioquatix for being helpful.

[ioquatix]

Let me know if I can be of further assistance.