Couldn't upgrade the protocol in some random cases

[dskorykh]

Hello!

I found a confusing issue

As I understand from https://github.com/socketio/engine.io-protocol/blob/master/README.md, when the client sends the PING packet, server should respond with the PONG packet and then the client sends the UPGRADE packet.
BUT! In some random cases (found only on the iOS browsers) NOOP packet which should be sent after PONG is processed before PONG and client hangs by 25s without sending upgrade packet.

I found that this issue appears since v3.2.0 release of python-engineio
If I revert these changes 919d8ea#diff-73af4c5d72e7a60feddc2ce0427079d3R90-R93 to
just self.queue.put(pkt) without packet_backlog, the problem doesn't appear.

I really couldn't figure out what was causing the problem, how putting messages to the packet_backlog instead of the queue could cause a change in the order of processing low-level packets in the client.

It's reproducible with the simple Flask-SocketIO example (async_mode is eventlet with monkey patching)

Debug log from the iOS browser (tested with Safari 13 and Chrome 79.0.3945.73)

[Log] socket.io-client:url parse http://192.168.2.247:2000 +0ms (socket.io.js, line 6)
[Log] socket.io-client new io instance for http://192.168.2.247:2000 +0ms (socket.io.js, line 6)
[Log] socket.io-client:manager readyState closed +0ms (socket.io.js, line 6)
[Log] socket.io-client:manager opening http://192.168.2.247:2000 +0ms (socket.io.js, line 6)
[Log] engine.io-client:socket creating transport "polling" +0ms (socket.io.js, line 6)
[Log] engine.io-client:polling polling +0ms (socket.io.js, line 6)
[Log] engine.io-client:polling-xhr xhr poll +0ms (socket.io.js, line 6)
[Log] engine.io-client:polling-xhr xhr open GET: http://192.168.2.247:2000/socket.io/?EIO=3&transport=polling&t=Mz21lBR +0ms (socket.io.js, line 6)
[Log] engine.io-client:polling-xhr xhr data null +1ms (socket.io.js, line 6)
[Log] engine.io-client:socket setting transport polling +3ms (socket.io.js, line 6)
[Log] socket.io-client:manager connect attempt will timeout after 20,000 +4ms (socket.io.js, line 6)
[Log] socket.io-client:manager readyState opening +1ms (socket.io.js, line 6)
[Log] engine.io-client:polling polling got data ArrayBuffer +62ms (socket.io.js, line 6)
[Log] engine.io-client:socket socket receive: type "open", data "{"pingInterval":25000,"pingTimeout":60000,"upgrades":["websocket"],"sid":"7f37c197ae8049878d3cbfc2bc01b6fc"}" +62ms (socket.io.js, line 6)
[Log] engine.io-client:socket socket open +0ms (socket.io.js, line 6)
[Log] socket.io-client:manager open +62ms (socket.io.js, line 6)
[Log] socket.io-client:manager cleanup +0ms (socket.io.js, line 6)
[Log] socket.io-client:socket transport is open - connecting +0ms (socket.io.js, line 6)
[Log] engine.io-client:socket starting upgrade probes +2ms (socket.io.js, line 6)
[Log] engine.io-client:socket probing transport "websocket" +0ms (socket.io.js, line 6)
[Log] engine.io-client:socket creating transport "websocket" +1ms (socket.io.js, line 6)
[Log] engine.io-client:socket socket receive: type "message", data "0" +1ms (socket.io.js, line 6)
[Log] socket.io-parser decoded 0 as {"type":0,"nsp":"/"} +0ms (socket.io.js, line 6)
[Log] socket.io-client:manager writing packet {"type":2,"data":["my_event",{"data":"I'm connected!"}],"options":{"compress":true},"nsp":"/"} +4ms (socket.io.js, line 6)
[Log] socket.io-parser encoding packet {"type":2,"data":["my_event",{"data":"I'm connected!"}],"options":{"compress":true},"nsp":"/"} +2ms (socket.io.js, line 6)
[Log] socket.io-parser encoded {"type":2,"data":["my_event",{"data":"I'm connected!"}],"options":{"compress":true},"nsp":"/"} as 2["my_event",{"data":"I'm connected!"}] +0ms (socket.io.js, line 6)
[Log] engine.io-client:socket flushing 1 packets in socket +4ms (socket.io.js, line 6)
[Log] engine.io-client:polling-xhr xhr open POST: http://192.168.2.247:2000/socket.io/?EIO=3&transport=polling&t=Mz21lCa&sid=7f37c197ae8049878d3cbfc2bc01b6fc +73ms (socket.io.js, line 6)
[Log] engine.io-client:polling-xhr xhr data 40:42["my_event",{"data":"I'm connected!"}] +0ms (socket.io.js, line 6)
[Log] engine.io-client:polling polling +14ms (socket.io.js, line 6)
[Log] engine.io-client:polling-xhr xhr poll +2ms (socket.io.js, line 6)
[Log] engine.io-client:polling-xhr xhr open GET: http://192.168.2.247:2000/socket.io/?EIO=3&transport=polling&t=Mz21lCd&sid=7f37c197ae8049878d3cbfc2bc01b6fc +1ms (socket.io.js, line 6)
[Log] engine.io-client:polling-xhr xhr data null +0ms (socket.io.js, line 6)
[Log] engine.io-client:socket probe transport "websocket" opened +28ms (socket.io.js, line 6)
[Log] engine.io-client:polling polling got data ArrayBuffer +36ms (socket.io.js, line 6)
[Log] engine.io-client:socket socket receive: type "noop", data "undefined" +13ms (socket.io.js, line 6)
[Log] engine.io-client:polling polling +2ms (socket.io.js, line 6)
[Log] engine.io-client:polling-xhr xhr poll +37ms (socket.io.js, line 6)
[Log] engine.io-client:polling-xhr xhr open GET: http://192.168.2.247:2000/socket.io/?EIO=3&transport=polling&t=Mz21lDD&sid=7f37c197ae8049878d3cbfc2bc01b6fc +0ms (socket.io.js, line 6)
[Log] engine.io-client:polling-xhr xhr data null +1ms (socket.io.js, line 6)
[Log] engine.io-client:socket probe transport "websocket" pong +3ms (socket.io.js, line 6)
[Log] engine.io-client:socket pausing current transport "polling" +0ms (socket.io.js, line 6)
[Log] engine.io-client:polling we are currently polling - waiting to pause +2ms (socket.io.js, line 6)
[Log] socket.io-client:manager writing packet {"type":2,"data":["my_ping"],"options":{"compress":true},"nsp":"/"} +936ms (socket.io.js, line 6)
[Log] socket.io-parser encoding packet {"type":2,"data":["my_ping"],"options":{"compress":true},"nsp":"/"} +936ms (socket.io.js, line 6)
[Log] socket.io-parser encoded {"type":2,"data":["my_ping"],"options":{"compress":true},"nsp":"/"} as 2["my_ping"] +0ms (socket.io.js, line 6)
...... 
[Log] socket.io-parser encoded {"type":2,"data":["my_ping"],"options":{"compress":true},"nsp":"/"} as 2["my_ping"] +1ms (socket.io.js, line 6)
[Log] engine.io-client:socket writing ping packet - expecting pong within 60000ms +25s (socket.io.js, line 6)
[Log] socket.io-client:manager writing packet {"type":2,"data":["my_ping"],"options":{"compress":true},"nsp":"/"} +1s (socket.io.js, line 6)
[Log] socket.io-parser encoding packet {"type":2,"data":["my_ping"],"options":{"compress":true},"nsp":"/"} +1s (socket.io.js, line 6)

[salimaboubacar]

I have exactly the same issue and did the same investigation at the same time.

I really couldn't figure out what was causing the problem, how putting messages to the packet_backlog instead of the queue could cause a change in the order of processing low-level packets in the client.

You can't control the order of the processing of the packets in the client, but in the javascript version of engine.io, the protocol seems to work even if the handling of NOOP and PONG are reversed.

I believe this is the logic that is missing from the original implementation: https://github.com/socketio/engine.io/blob/cb0ac6fddcad12c454651bf0e1a312a154e228a4/lib/transports/polling.js#L112-L117

Immediatly sending noop to the poll request that is sent after the first noop is critical to finish the upgrade (It will trigger the event expected after your log we are currently polling - waiting to pause).

As this causes a business critical issue for me, I am ready to open a PR by tomorrow if you think this is the right way to do this @miguelgrinberg (EDIT: opened here: #161)

[salimaboubacar]

I can see that there is this PR => https://github.com/miguelgrinberg/python-engineio/pull/76/files, but it seems like a dirty way to do it, we should only send the noop in the handle_get_request if we are currently upgrading and we sent the PONG

[miguelgrinberg]

@salimaboubacar given that you were able to reproduce this issue with the JS client, can I ask you to test the master branch of this repo? The fix is similar to your PR, but it goes a bit further and fully replaces the packet backlog, which was introduced a while ago to address this problem but was only partially successful. Thanks!