Page MenuHomePhabricator

RCStream should remember subscriptions after socket.io re-connects
Closed, DeclinedPublic

Description

I am using that new RC feed in some python script, basically just a copy of https://wikitech.wikimedia.org/wiki/RCStream

I randomly get disconnected with this error:

WARNING:socketIO_client:[connection error] connection closed ()
DEBUG:socketIO_client: [disconnect]
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 502 181
WARNING:socketIO_client:[waiting for connection] unexpected status code (502)
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 502 181
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 502 181
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 502 181
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 502 181
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 502 181
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 200 89
DEBUG:socketIO_client:[transports available] websocket xhr-multipart htmlfile jsonp-polling flashsocket xhr-polling
DEBUG:socketIO_client.transports:[transport selected] websocket
DEBUG:socketIO_client.transports:[packet received] 1::
DEBUG:socketIO_client: [connect]
DEBUG:socketIO_client.transports:[packet sent] 2:::
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]
DEBUG:socketIO_client.transports:[packet sent] 2:::
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]
DEBUG:socketIO_client.transports:[packet sent] 2:::

Only solution is restart of script. Why is that and how to fix it?

Event Timeline

Petrb raised the priority of this task from to Needs Triage.
Petrb updated the task description. (Show Details)
Petrb subscribed.
Petrb added a subscriber: hashar.

The reconnection looks succesful, but you're not automatically re-subscribed to the relevant feeds. I *think* socket.io is supposed to take care of this, but I'm not completely sure. @ori, could that be related to the load balancing again?

ok, how do I automatically do that

is there any documentation for that python library?

https://github.com/invisibleroads/socketIO-client

You can probably add an on_reconnect handler. Subscribe is idempotent, so should be safe even if you're not actually supposed to re-subscribe.

Aklapper renamed this task from New RC feed is randomly failing to New RC feed is randomly failing: socket.io not re-subscribed?.Jan 14 2015, 6:05 PM
Aklapper triaged this task as Medium priority.

Now that I take a better look: socketIO-client is doing a full new handshake: instead of reconnecting with the same session, it requests a new session:

DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 200 89

so the server has no way to know you're the same client as before.

As such, you'll need to re-subscribe to the stream.

Now that I take a better look: socketIO-client is doing a full new handshake: instead of reconnecting with the same session, it requests a new session:

fwiw, http://codepen.io/Krinkle/full/laucI/ also does this, and that uses the official (js) client. I think the issue is rather with SocketIO_client not calling on_connect, and as far as I can see, this is only very recent.

Ok I did that, it failed again though during night, but I have no logs, so let's see now

Here we go

WARNING:socketIO_client:[connection error] [Errno 104] Connection reset by peer
DEBUG:socketIO_client: [disconnect]
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 200 89
DEBUG:socketIO_client:[transports available] websocket xhr-multipart htmlfile jsonp-polling flashsocket xhr-polling
DEBUG:socketIO_client.transports:[transport selected] websocket
DEBUG:socketIO_client.transports:[packet received] 1::
DEBUG:socketIO_client: [connect]
DEBUG:socketIO_client.transports:[packet sent] 2:::
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]
DEBUG:socketIO_client: [disconnect]
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 200 89
DEBUG:socketIO_client:[transports available] websocket xhr-multipart htmlfile jsonp-polling flashsocket xhr-polling
DEBUG:socketIO_client.transports:[transport selected] websocket
DEBUG:socketIO_client.transports:[packet received] 1::
DEBUG:socketIO_client: [connect]
DEBUG:socketIO_client.transports:[packet sent] 2:::
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]
WARNING:socketIO_client:[connection error] connection closed ()
DEBUG:socketIO_client: [disconnect]
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 200 89
DEBUG:socketIO_client:[transports available] websocket xhr-multipart htmlfile jsonp-polling flashsocket xhr-polling
DEBUG:socketIO_client.transports:[transport selected] websocket
DEBUG:socketIO_client.transports:[packet received] 1::
DEBUG:socketIO_client: [connect]
DEBUG:socketIO_client.transports:[packet sent] 2:::
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]
DEBUG:socketIO_client: [disconnect]
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 200 89
DEBUG:socketIO_client:[transports available] websocket xhr-multipart htmlfile jsonp-polling flashsocket xhr-polling
DEBUG:socketIO_client.transports:[transport selected] websocket
DEBUG:socketIO_client.transports:[packet received] 1::
DEBUG:socketIO_client: [connect]
DEBUG:socketIO_client.transports:[packet sent] 2:::
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]

New source has:

def on_reconnect(self, *args):
  self.emit('subscribe', '*')
def on_connect(self):
  self.emit('subscribe', '*')

it doesn't seem to work :(

For those of us patrolling for SWMT and on spam patrol the use of the bot and reliability of feeds is important. Support for resolution of the matter would be appreciated/

btw I added some debug prints to both on_connect and on_reconnect, but neither triggered on another disconnect I had now:

WARNING:socketIO_client:[connection error] connection closed ()
DEBUG:socketIO_client: [disconnect]
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 502 181
WARNING:socketIO_client:[waiting for connection] unexpected status code (502)
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 502 181
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 502 181
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 502 181
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 502 181
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): stream.wikimedia.org
DEBUG:requests.packages.urllib3.connectionpool:"GET /socket.io/1/ HTTP/1.1" 200 89
DEBUG:socketIO_client:[transports available] websocket xhr-multipart htmlfile jsonp-polling flashsocket xhr-polling
DEBUG:socketIO_client.transports:[transport selected] websocket
DEBUG:socketIO_client.transports:[packet received] 1::
DEBUG:socketIO_client: [connect]
DEBUG:socketIO_client.transports:[packet sent] 2:::
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]
DEBUG:socketIO_client.transports:[packet sent] 2:::
DEBUG:socketIO_client.transports:[packet received] 2::
DEBUG:socketIO_client: [heartbeat]

That means on_reconnect nor on_connect was called after reconnect, why?

I'm having similar issue of not getting updates after ~1-2 hours of running with live RC pagegenerator.
From log:

WARNING: socketIO_client:[connection error] connection closed () WARNING:socketIO_client:[waiting for connection] unexpected status code (502)

For those of us patrolling for SWMT and on spam patrol the use of the bot and reliability of feeds is important. Support for resolution of the matter would be appreciated/

Which SWMT patrol tool is using this at the moment? Handling of subscription is a very basic thing. I can't imagine a tool being deployed out there currently that is used by users and does not handle this correctly.

My comment was about the utilisation of wmbot in various places, and it is about direct and secondary watches rather than the other bots that work in the CVN space.

Yes, wm-bot uses RCStream right now and it is used by many users. It uses it over XmlRcs which fortunately can now handle this problem using a nasty workaround.

I managed to write a python script in a way that when it gets disconnected it crashes, and gets restarted, which is only solution that works so far and even if it's far from being perfect as it causes small (1 - 6 sec) outages in stream every 2 - 10 hours, it can at least provide stream of changes without failure.

On other hand even if I was able to handle disconnects gracefully this still isn't good because in first place these failures shouldn't happen so often.

What is causing these disconnects? Is it bad connectivity between labs and production? I doubt so because it happens to me even when I am using RCStream python or js script on my local PC. This problem is happening on both JS and python versions of client.

BTW connection to XmlRcs seems to have no issues so I doubt there is actually any problem with connectivity and it's being constantly used by approximately 10 - 20 users who are connected to it

Krinkle renamed this task from New RC feed is randomly failing: socket.io not re-subscribed? to RCStream should remember subscriptions after socket.io re-connects.Dec 16 2015, 11:27 PM

Declining per RCStream being deprecated and scheduled to be shut down on July 7th.

See also T156919.