"Session ID unknown" after handshake on high server load [Socket.io 1.0.6]

[Rundfunk]

I am running a multi-node server (16 workers running Socket.io 1.0.6; accessed via Nginx, configured as a reverse proxy supporting sticky sessions) for ~ 5k users. While the load of the server is low (23 on a 20 core server / 2k users), everyone is able to connect instantly. When the load of the server gets higher (56 / 5k users), new users are not able to connect and receive data instantly. In this case, it takes 2~4 handshakes for the users to connect succesfully.

This is what happens (high load):

• User opens the website; receives HTML and JS
• User's browser attempts to initialize a socket.io connection to the server (io.connect(...))
• A handshake request is sent to the server, the server responds with a SID and other information ({"sid":"f-re6ABU3Si4pmyWADCx","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000})
• The client initiates a polling-request, including this SID: GET .../socket.io/?EIO=2&transport=polling&t=1408648886249-1&sid=f-re6ABU3Si4pmyWADCx
• Instead of sending data, the server responds with 400 Bad Request: {"code":1,"message":"Session ID unknown"}
• The client performs a new handshake (GET .../socket.io/?EIO=2&transport=polling&t=1408648888050-3, notice the previously received SID is omitted)
• The server responds with new connection data, including a new SID: ({"sid":"DdRxn2gv6vrtZOBiAEAS","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000})
• The client performs a new polling request, including the new SID: GET .../socket.io/?EIO=2&transport=polling&t=1408648888097-4&sid=DdRxn2gv6vrtZOBiAEAS
• The server responds with the data that is emitted in the worker source code.

Depending on the load of the server, it may happen 1~3 times that the server responds with "Session ID unknown" and the client needs to perform a new handshake before data is actually received.

[danielcha]

I have the same problem... Any solution?

[MTK-mcs]

same problem
#1503

[rauchg]

How's the stickiness configured?

[runningskull]

@Rundfunk @danielcha @guille I'm seeing the same thing. Intermittent 502's on a high load multi-node server. My sticky session configuration is very similar to what's in balancerbattle

Still investigating - will update this ticket if I find anything helpful.

[rauchg]

Keep us posted. Please try it with 1.2.1 as we've pushed some important fixes

[runningskull]

Killer - thanks for the quick response. I'll let you know.

[leroix]

upgrading to v1.2.1 didn't fix

[rauchg]

Do you guys have any further debugging information? Could it be a problem in the stickiness logic?
The only way for {"code":1,"message":"Session ID unknown"} to be returned is if the SID is simply not in the in-memory datastructure.

[runningskull]

Nothing of note yet - We're still investigating. Can't replicate in test environments, so debugging is tricky. I'll post here when/if we get something good.

[rauchg]

Btw, in your example this is interesting:

GET .../socket.io/?EIO=2&transport=polling&t=1408648888050-3

Notice the -3, that means 3 requests are being started in the same exact ms?

[rauchg]

(since we have counters at the end of Date.now for higher precision)

[runningskull]

We finally figured this out. The root cause in our case:

• When receiving a 5xx error, nginx proxy by default will take the errant upstream out of rotation for 10 seconds
• when upstream-A is unavailable, ip_hash will route all of A's requests instead to upstream-B
• unfortunately, when upstream-B gets the new requests, it spits out 5xx errors (correctly) because the SID is not found in this.clients
• that makes them get taken out of rotation as well, and their requests get routed to upstream-C
• recurse...

We solved it by changing the nginx max_fails to something more reasonable (and upping the open file-descriptor limit for our app's user, which was a secondary failure point, exacerbated by the constant reconnects)

[rauchg]

wow this is extremely useful feedback for others. Thanks a lot @runningskull.
What was the cause of the original 5xx error?

[runningskull]

I think the very original 5xx error that triggered the chain was just some code that responded 500 as a run-of-the-mill error instead of a more useful error code.

We'll probably do some more research soon into into something like using hash instead of ip_hash, or other measures to increase robustness. If we discover anything generally useful about production setup, I'll be sure to report back. socket.io is great - happy to help in w/e tiny way I can ;)

EDIT: worth mentioning that we had set proxy_next_upstream to do the behavior above on 5xx errors. By default nginx only does this on connection/header errors. However, it seems fairly common (best practice?) to proxy_next_upstream on 5xx errors. We've had similar issues in the past with PaaS vendors doing the same thing.