Flask-socketio: socketio hangs after 250 concurrent connections

[andmekaevur]

I have an application utilizing socket.io. At one point it started hanging under a slightly increased load. Only websocket traffic going on is the PING-PONG, http requests get timed out. I haven't reached this problem when disabling websocket and forcing polling. However, then a part of my app that has quite heavy websocket traffic, get super slow and kind of freezes for half a minute or a minute. This could be related to the original problem.

I managed to replicate the bug by simply opening aroudn 250 connections from my browser.

Client side code. The following equates to making 500 connections during 250 seconds. The freeze happens at around 250 connections.

for (var i = 0; i<500; i++) {
    (function (index) {
        setTimeout(function () {
            console.log(index)
            var client_socket = io.connect('URL/client', {'path': '/test_socket.io'});
            client_socket.on('connect', function(data) {
                console.log('client connected')
            });
        }, index * 500);
    })(i);
}

Server side code:

@socketio.on('connect', namespace='/client')
def client_connect():
    sid = request.sid
    connected_client_sids.add(sid)
    log.info('connected clients count {}'.format(len(connected_client_sids)))
    emit('helpdesk status', helpdesk_status())

Server side logs

INFO 2017-09-11 15:46:04,857 client_connect views.py connected clients count 254
INFO 2017-09-11 15:46:04,857 emit         server.py emitting event "helpdesk status" to eb29a1d7e31f4de3b9d4120e496e6f5c [/client]
INFO 2017-09-11 15:46:04,857 send         socket.py eb29a1d7e31f4de3b9d4120e496e6f5c: Sending packet MESSAGE data 2/client,["helpdesk status",[{"category":"billing","segment":"private","langu
age":"et"}]]
INFO 2017-09-11 15:46:04,857 send         socket.py eb29a1d7e31f4de3b9d4120e496e6f5c: Sending packet MESSAGE data 0/client
INFO 2017-09-11 15:46:04,867 send         socket.py c60470765bfc4adb95a57389da09de34: Sending packet NOOP data None
INFO 2017-09-11 15:46:04,880 handle_get_request socket.py ce855ceca9814045bfc2b840be13baf9: Received request to upgrade to websocket
INFO 2017-09-11 15:46:04,881 _websocket_handler socket.py d3cc9b7dfa5548c18a6c8b836f05a3aa: Upgrade to websocket successful
INFO 2017-09-11 15:46:04,902 send         socket.py ff00fbf2859b4cc5b105b65dc4452e8d: Sending packet OPEN data {'sid': 'ff00fbf2859b4cc5b105b65dc4452e8d', 'pingInterval': 25000, 'pingTimeout'
: 60000, 'upgrades': ['websocket']}
INFO 2017-09-11 15:46:04,903 send         socket.py ff00fbf2859b4cc5b105b65dc4452e8d: Sending packet MESSAGE data 0
INFO 2017-09-11 15:46:04,914 receive      socket.py 8d01079b60964c779c962f51885b3134: Received packet PING data None
INFO 2017-09-11 15:46:04,914 send         socket.py 8d01079b60964c779c962f51885b3134: Sending packet PONG data None
INFO 2017-09-11 15:46:04,917 _websocket_handler socket.py c60470765bfc4adb95a57389da09de34: Upgrade to websocket successful
INFO 2017-09-11 15:46:04,920 send         socket.py ce855ceca9814045bfc2b840be13baf9: Sending packet NOOP data None
INFO 2017-09-11 15:46:04,936 handle_get_request socket.py eb29a1d7e31f4de3b9d4120e496e6f5c: Received request to upgrade to websocket
INFO 2017-09-11 15:46:04,947 receive      socket.py ff00fbf2859b4cc5b105b65dc4452e8d: Received packet MESSAGE data 0/client,
INFO 2017-09-11 15:46:04,947 client_connect views.py connected clients count 255
INFO 2017-09-11 15:46:04,947 emit         server.py emitting event "helpdesk status" to ff00fbf2859b4cc5b105b65dc4452e8d [/client]
INFO 2017-09-11 15:46:04,947 send         socket.py ff00fbf2859b4cc5b105b65dc4452e8d: Sending packet MESSAGE data 2/client,["helpdesk status",[{"category":"billing","segment":"private","langu
age":"et"}]]
INFO 2017-09-11 15:46:04,948 send         socket.py ff00fbf2859b4cc5b105b65dc4452e8d: Sending packet MESSAGE data 0/client
INFO 2017-09-11 15:46:04,948 _websocket_handler socket.py ce855ceca9814045bfc2b840be13baf9: Upgrade to websocket successful
INFO 2017-09-11 15:46:04,955 send         socket.py eb29a1d7e31f4de3b9d4120e496e6f5c: Sending packet NOOP data None
INFO 2017-09-11 15:46:04,992 _websocket_handler socket.py eb29a1d7e31f4de3b9d4120e496e6f5c: Upgrade to websocket successful
INFO 2017-09-11 15:46:05,008 send         socket.py 32bd5a9001e147759f72e2690945892b: Sending packet OPEN data {'sid': '32bd5a9001e147759f72e2690945892b', 'pingInterval': 25000, 'pingTimeout'
: 60000, 'upgrades': ['websocket']}
INFO 2017-09-11 15:46:05,008 send         socket.py 32bd5a9001e147759f72e2690945892b: Sending packet MESSAGE data 0
INFO 2017-09-11 15:46:05,036 receive      socket.py 32bd5a9001e147759f72e2690945892b: Received packet MESSAGE data 0/client,
INFO 2017-09-11 15:46:05,037 client_connect views.py connected clients count 256
INFO 2017-09-11 15:46:05,037 emit         server.py emitting event "helpdesk status" to 32bd5a9001e147759f72e2690945892b [/client]
INFO 2017-09-11 15:46:05,037 send         socket.py 32bd5a9001e147759f72e2690945892b: Sending packet MESSAGE data 2/client,["helpdesk status",[{"category":"billing","segment":"private","langu
age":"et"}]]
INFO 2017-09-11 15:46:05,037 send         socket.py 32bd5a9001e147759f72e2690945892b: Sending packet MESSAGE data 0/client
INFO 2017-09-11 15:46:05,052 receive      socket.py cdacf614f7114eaeba0e4eddc2fc9ca7: Received packet PING data None
INFO 2017-09-11 15:46:05,052 send         socket.py cdacf614f7114eaeba0e4eddc2fc9ca7: Sending packet PONG data None
INFO 2017-09-11 15:46:05,211 send         socket.py 112fa78735644b1ab5a93a06cda38b35: Sending packet OPEN data {'sid': '112fa78735644b1ab5a93a06cda38b35', 'pingInterval': 25000, 'pingTimeout'
: 60000, 'upgrades': ['websocket']}
INFO 2017-09-11 15:46:05,211 send         socket.py 112fa78735644b1ab5a93a06cda38b35: Sending packet MESSAGE data 0
INFO 2017-09-11 15:46:05,238 receive      socket.py 112fa78735644b1ab5a93a06cda38b35: Received packet MESSAGE data 0/client,
INFO 2017-09-11 15:46:05,239 client_connect views.py connected clients count 257
INFO 2017-09-11 15:46:05,239 emit         server.py emitting event "helpdesk status" to 112fa78735644b1ab5a93a06cda38b35 [/client]
INFO 2017-09-11 15:46:05,239 send         socket.py 112fa78735644b1ab5a93a06cda38b35: Sending packet MESSAGE data 2/client,["helpdesk status",[{"category":"billing","segment":"private","langu
age":"et"}]]
INFO 2017-09-11 15:46:05,239 send         socket.py 112fa78735644b1ab5a93a06cda38b35: Sending packet MESSAGE data 0/client
INFO 2017-09-11 15:46:05,249 receive      socket.py 3cc020e944f941afa97db91b4d921c88: Received packet PING data None
INFO 2017-09-11 15:46:05,250 send         socket.py 3cc020e944f941afa97db91b4d921c88: Sending packet PONG data None
INFO 2017-09-11 15:46:05,382 receive      socket.py 3756ecb991434d4bbf94a4515a7afb45: Received packet PING data None
INFO 2017-09-11 15:46:05,382 send         socket.py 3756ecb991434d4bbf94a4515a7afb45: Sending packet PONG data None
INFO 2017-09-11 15:46:05,383 receive      socket.py 22bf1e6e5fc54db087944b03caeabd1a: Received packet PING data None
INFO 2017-09-11 15:46:05,383 send         socket.py 22bf1e6e5fc54db087944b03caeabd1a: Sending packet PONG data None
INFO 2017-09-11 15:46:05,386 receive      socket.py 006cff65347d467c880e2049e9ffb541: Received packet PING data None
INFO 2017-09-11 15:46:05,386 send         socket.py 006cff65347d467c880e2049e9ffb541: Sending packet PONG data None
INFO 2017-09-11 15:46:05,425 send         socket.py 240c096dbfb74453ac792806c2f45289: Sending packet OPEN data {'sid': '240c096dbfb74453ac792806c2f45289', 'pingInterval': 25000, 'pingTimeout'
: 60000, 'upgrades': ['websocket']}
INFO 2017-09-11 15:46:05,425 send         socket.py 240c096dbfb74453ac792806c2f45289: Sending packet MESSAGE data 0
INFO 2017-09-11 15:46:05,452 receive      socket.py 240c096dbfb74453ac792806c2f45289: Received packet MESSAGE data 0/client,
INFO 2017-09-11 15:46:05,453 client_connect views.py connected clients count 258
INFO 2017-09-11 15:46:05,453 emit         server.py emitting event "helpdesk status" to 240c096dbfb74453ac792806c2f45289 [/client]
INFO 2017-09-11 15:46:05,453 send         socket.py 240c096dbfb74453ac792806c2f45289: Sending packet MESSAGE data 2/client,["helpdesk status",[{"category":"billing","segment":"private","langu
age":"et"}]]
INFO 2017-09-11 15:46:05,453 send         socket.py 240c096dbfb74453ac792806c2f45289: Sending packet MESSAGE data 0/client
INFO 2017-09-11 15:46:05,473 receive      socket.py a7fbdfbf105249ec8c69c1fcf0770335: Received packet PING data None
INFO 2017-09-11 15:46:05,473 send         socket.py a7fbdfbf105249ec8c69c1fcf0770335: Sending packet PONG data None
INFO 2017-09-11 15:46:05,483 receive      socket.py 9c66a3f3548247409f2e076932890587: Received packet PING data None
INFO 2017-09-11 15:46:05,483 send         socket.py 9c66a3f3548247409f2e076932890587: Sending packet PONG data None
INFO 2017-09-11 15:46:05,591 receive      socket.py 5b8982018b0240dba541047cfa60ba7b: Received packet PING data None
INFO 2017-09-11 15:46:05,591 send         socket.py 5b8982018b0240dba541047cfa60ba7b: Sending packet PONG data None
INFO 2017-09-11 15:46:05,609 send         socket.py 2a0f96f1c28f42ef95477674f307d91a: Sending packet OPEN data {'sid': '2a0f96f1c28f42ef95477674f307d91a', 'pingInterval': 25000, 'pingTimeout'
: 60000, 'upgrades': ['websocket']}
INFO 2017-09-11 15:46:05,609 send         socket.py 2a0f96f1c28f42ef95477674f307d91a: Sending packet MESSAGE data 0
INFO 2017-09-11 15:46:05,646 receive      socket.py 2a0f96f1c28f42ef95477674f307d91a: Received packet MESSAGE data 0/client,
INFO 2017-09-11 15:46:05,647 client_connect views.py connected clients count 259
INFO 2017-09-11 15:46:05,647 emit         server.py emitting event "helpdesk status" to 2a0f96f1c28f42ef95477674f307d91a [/client]
INFO 2017-09-11 15:46:05,647 send         socket.py 2a0f96f1c28f42ef95477674f307d91a: Sending packet MESSAGE data 2/client,["helpdesk status",[{"category":"billing","segment":"private","langu
age":"et"}]]
INFO 2017-09-11 15:46:05,647 send         socket.py 2a0f96f1c28f42ef95477674f307d91a: Sending packet MESSAGE data 0/client
INFO 2017-09-11 15:46:05,648 receive      socket.py 95f70f0437884fb795d976d1161a8cf6: Received packet PING data None
INFO 2017-09-11 15:46:05,648 send         socket.py 95f70f0437884fb795d976d1161a8cf6: Sending packet PONG data None
INFO 2017-09-11 15:46:05,657 receive      socket.py 9f39495052a04b2da3cd945d468884d2: Received packet PING data None
INFO 2017-09-11 15:46:05,658 send         socket.py 9f39495052a04b2da3cd945d468884d2: Sending packet PONG data None
INFO 2017-09-11 15:46:05,806 send         socket.py 8e9d92dbec804abd85df9e48059bce14: Sending packet OPEN data {'sid': '8e9d92dbec804abd85df9e48059bce14', 'pingInterval': 25000, 'pingTimeout'
: 60000, 'upgrades': ['websocket']}
INFO 2017-09-11 15:46:05,806 send         socket.py 8e9d92dbec804abd85df9e48059bce14: Sending packet MESSAGE data 0
INFO 2017-09-11 15:46:05,851 receive      socket.py cc5fbab5c7aa4832a7835cccdcf6a964: Received packet PING data None
INFO 2017-09-11 15:46:05,851 send         socket.py cc5fbab5c7aa4832a7835cccdcf6a964: Sending packet PONG data None
INFO 2017-09-11 15:46:05,851 receive      socket.py 737be393783f496e8d79d77712f03c2e: Received packet PING data None
INFO 2017-09-11 15:46:05,851 send         socket.py 737be393783f496e8d79d77712f03c2e: Sending packet PONG data None
INFO 2017-09-11 15:46:05,852 receive      socket.py 8e9d92dbec804abd85df9e48059bce14: Received packet MESSAGE data 0/client,
INFO 2017-09-11 15:46:05,852 client_connect views.py connected clients count 260
INFO 2017-09-11 15:46:05,853 emit         server.py emitting event "helpdesk status" to 8e9d92dbec804abd85df9e48059bce14 [/client]
INFO 2017-09-11 15:46:05,853 send         socket.py 8e9d92dbec804abd85df9e48059bce14: Sending packet MESSAGE data 2/client,["helpdesk status",[{"category":"billing","segment":"private","langu
age":"et"}]]
INFO 2017-09-11 15:46:05,853 send         socket.py 8e9d92dbec804abd85df9e48059bce14: Sending packet MESSAGE data 0/client
INFO 2017-09-11 15:46:06,054 receive      socket.py b9157310770e4863b163901fde6f9bd8: Received packet PING data None
INFO 2017-09-11 15:46:06,054 send         socket.py b9157310770e4863b163901fde6f9bd8: Sending packet PONG data None
INFO 2017-09-11 15:46:06,081 receive      socket.py a4cc2f8f967b4d0499cf53e110b2f3da: Received packet PING data None
INFO 2017-09-11 15:46:06,081 send         socket.py a4cc2f8f967b4d0499cf53e110b2f3da: Sending packet PONG data None
INFO 2017-09-11 15:46:06,197 receive      socket.py d124dd5c8bfb4d3f92873948e4f8cf76: Received packet PING data None
INFO 2017-09-11 15:46:06,197 send         socket.py d124dd5c8bfb4d3f92873948e4f8cf76: Sending packet PONG data None
INFO 2017-09-11 15:46:06,231 receive      socket.py 8120d76ea2144d6bb5e83ca2749696ae: Received packet PING data None
INFO 2017-09-11 15:46:06,231 send         socket.py 8120d76ea2144d6bb5e83ca2749696ae: Sending packet PONG data None
INFO 2017-09-11 15:46:06,251 receive      socket.py 2cc492a3f93e49438204de0a2efa2afd: Received packet PING data None
INFO 2017-09-11 15:46:06,251 send         socket.py 2cc492a3f93e49438204de0a2efa2afd: Sending packet PONG data None
INFO 2017-09-11 15:46:06,432 receive      socket.py f244d00a387544e1a7554c0700294b67: Received packet PING data None
INFO 2017-09-11 15:46:06,432 send         socket.py f244d00a387544e1a7554c0700294b67: Sending packet PONG data None
INFO 2017-09-11 15:46:06,437 receive      socket.py 2c476c7d45e144e083741f15d20ece3a: Received packet PING data None
INFO 2017-09-11 15:46:06,437 send         socket.py 2c476c7d45e144e083741f15d20ece3a: Sending packet PONG data None
INFO 2017-09-11 15:46:06,639 receive      socket.py 2ef3829ed415498a84347f9b2d82fca3: Received packet PING data None
INFO 2017-09-11 15:46:06,639 send         socket.py 2ef3829ed415498a84347f9b2d82fca3: Sending packet PONG data None
INFO 2017-09-11 15:46:06,643 receive      socket.py 62bbbc9f78d74d94b2935ee81a72c8bf: Received packet PING data None
INFO 2017-09-11 15:46:06,643 send         socket.py 62bbbc9f78d74d94b2935ee81a72c8bf: Sending packet PONG data None
INFO 2017-09-11 15:46:06,836 receive      socket.py 23ca0a4d125347a891f30301168726dd: Received packet PING data None
INFO 2017-09-11 15:46:06,836 send         socket.py 23ca0a4d125347a891f30301168726dd: Sending packet PONG data None
INFO 2017-09-11 15:46:06,849 receive      socket.py 93d3e4fda2aa465fa71744e7545c3cbb: Received packet PING data None
INFO 2017-09-11 15:46:06,850 send         socket.py 93d3e4fda2aa465fa71744e7545c3cbb: Sending packet PONG data None
INFO 2017-09-11 15:46:07,042 receive      socket.py 44463b65b3b5445d9b707053250e4c33: Received packet PING data None
INFO 2017-09-11 15:46:07,042 send         socket.py 44463b65b3b5445d9b707053250e4c33: Sending packet PONG data None
INFO 2017-09-11 15:46:07,199 receive      socket.py 80f8e65bdc6746c0b25872b5514c204f: Received packet PING data None
INFO 2017-09-11 15:46:07,200 send         socket.py 80f8e65bdc6746c0b25872b5514c204f: Sending packet PONG data None
INFO 2017-09-11 15:46:07,239 receive      socket.py da8c45032ba4466d97923ee551503c58: Received packet PING data None
INFO 2017-09-11 15:46:07,239 send         socket.py da8c45032ba4466d97923ee551503c58: Sending packet PONG data None
INFO 2017-09-11 15:46:07,395 receive      socket.py 39f5cdaf62c9475793428baa5af628c7: Received packet PING data None
INFO 2017-09-11 15:46:07,395 send         socket.py 39f5cdaf62c9475793428baa5af628c7: Sending packet PONG data None
INFO 2017-09-11 15:46:07,432 receive      socket.py ae7b696155e243edbb4b2fe5d5afd141: Received packet PING data None
INFO 2017-09-11 15:46:07,433 send         socket.py ae7b696155e243edbb4b2fe5d5afd141: Sending packet PONG data None
INFO 2017-09-11 15:46:07,464 receive      socket.py a0346ff8152644c4bf5521d75aff5ca6: Received packet PING data None
INFO 2017-09-11 15:46:07,465 send         socket.py a0346ff8152644c4bf5521d75aff5ca6: Sending packet PONG data None
INFO 2017-09-11 15:46:07,649 receive      socket.py b2fe383335a843afb9f0546785a1ed73: Received packet PING data None
INFO 2017-09-11 15:46:07,650 send         socket.py b2fe383335a843afb9f0546785a1ed73: Sending packet PONG data None
INFO 2017-09-11 15:46:07,663 receive      socket.py c110c9bf03e34d8f86f2894b2b3a537b: Received packet PING data None
INFO 2017-09-11 15:46:07,663 send         socket.py c110c9bf03e34d8f86f2894b2b3a537b: Sending packet PONG data None
INFO 2017-09-11 15:46:07,853 receive      socket.py b9c738e6de344b4eb034701c64979f3a: Received packet PING data None
INFO 2017-09-11 15:46:07,853 send         socket.py b9c738e6de344b4eb034701c64979f3a: Sending packet PONG data None
INFO 2017-09-11 15:46:07,871 receive      socket.py 1818cd0a1a064a45aceffa72741faad7: Received packet PING data None
INFO 2017-09-11 15:46:07,871 send         socket.py 1818cd0a1a064a45aceffa72741faad7: Sending packet PONG data None
INFO 2017-09-11 15:46:08,037 receive      socket.py 5703faaa64a542bb9b53dde876f4c754: Received packet PING data None
INFO 2017-09-11 15:46:08,037 send         socket.py 5703faaa64a542bb9b53dde876f4c754: Sending packet PONG data None
INFO 2017-09-11 15:46:08,056 receive      socket.py f13d8750f7f64863b8c1f6fca71bae0d: Received packet PING data None
INFO 2017-09-11 15:46:08,056 send         socket.py f13d8750f7f64863b8c1f6fca71bae0d: Sending packet PONG data None
INFO 2017-09-11 15:46:08,246 receive      socket.py 1e0a56d30ad0419ba583a034698b4953: Received packet PING data None
INFO 2017-09-11 15:46:08,246 send         socket.py 1e0a56d30ad0419ba583a034698b4953: Sending packet PONG data None
INFO 2017-09-11 15:46:08,284 receive      socket.py cabda4e2305241d3ad6e37b6fb84a1a0: Received packet PING data None
INFO 2017-09-11 15:46:08,285 send         socket.py cabda4e2305241d3ad6e37b6fb84a1a0: Sending packet PONG data None
INFO 2017-09-11 15:46:08,447 receive      socket.py 70d7e866289849f4a2e5e10842a3f53a: Received packet PING data None

Client logs:

socket.io-client:url parse https://URL/client +0ms
socket.io-client new io instance for https://URL/client +2ms
socket.io-client:manager readyState closed +1ms
socket.io-client:manager opening https://URL/client +1ms
engine.io-client:socket creating transport "polling" +1ms
engine.io-client:polling polling +2ms
engine.io-client:polling-xhr xhr poll +1ms
engine.io-client:polling-xhr xhr open GET: https://URL/test_socket.io/?EIO=3&transport=polling&t=Lvm89kF +4ms
engine.io-client:polling-xhr xhr data null +1ms
engine.io-client:socket setting transport polling +2ms
socket.io-client:manager connect attempt will timeout after 20000 +1ms
socket.io-client:manager readyState opening +2ms
socket.io-client:manager connect attempt timed out after 20000 +20s
engine.io-client:socket socket close with reason: "forced close" +1ms
engine.io-client:polling transport not open - deferring close +1ms
engine.io-client:socket socket closing - telling transport to close +0ms
socket.io-client:manager connect_error +1ms
socket.io-client:manager cleanup +0ms
socket.io-client:manager will wait 1298ms before reconnect attempt +1ms
socket.io-client:manager attempting reconnect +1s
socket.io-client:manager readyState closed +1ms
socket.io-client:manager opening https://URL/client +0ms
engine.io-client:socket creating transport "polling" +0ms
engine.io-client:polling polling +1ms
engine.io-client:polling-xhr xhr poll +0ms
engine.io-client:polling-xhr xhr open GET: https://URL/test_socket.io/?EIO=3&transport=polling&t=Lvm8ExG +1ms
engine.io-client:polling-xhr xhr data null +1ms
engine.io-client:socket setting transport polling +1ms
socket.io-client:manager connect attempt will timeout after 20000 +2ms
socket.io-client:manager connect attempt timed out after 20000 +21s
engine.io-client:socket socket close with reason: "forced close" +1ms
engine.io-client:polling transport not open - deferring close +0ms
engine.io-client:socket socket closing - telling transport to close +0ms
socket.io-client:manager connect_error +0ms
socket.io-client:manager cleanup +1ms
socket.io-client:manager reconnect attempt error +0ms
socket.io-client:manager will wait 1185ms before reconnect attempt +0ms
socket.io-client:manager attempting reconnect +2s
socket.io-client:manager readyState closed +1ms
socket.io-client:manager opening https://URL/client +0ms
engine.io-client:socket creating transport "polling" +0ms
engine.io-client:polling polling +1ms
engine.io-client:polling-xhr xhr poll +0ms
engine.io-client:polling-xhr xhr open GET: https://URL/test_socket.io/?EIO=3&transport=polling&t=Lvm8KVO +0ms
engine.io-client:polling-xhr xhr data null +1ms
engine.io-client:socket setting transport polling +1ms
socket.io-client:manager connect attempt will timeout after 20000 +0ms
socket.io-client:manager connect attempt timed out after 20000 +20s
engine.io-client:socket socket close with reason: "forced close" +1ms
engine.io-client:polling transport not open - deferring close +0ms
engine.io-client:socket socket closing - telling transport to close +0ms
socket.io-client:manager connect_error +0ms
socket.io-client:manager cleanup +0ms
socket.io-client:manager reconnect attempt error +1ms
socket.io-client:manager will wait 4274ms before reconnect attempt +0ms
socket.io-client:manager attempting reconnect +4s
socket.io-client:manager readyState closed +1ms
socket.io-client:manager opening https://URL/client +0ms
engine.io-client:socket creating transport "polling" +1ms
engine.io-client:polling polling +1ms
engine.io-client:polling-xhr xhr poll +0ms
engine.io-client:polling-xhr xhr open GET: https://URL/test_socket.io/?EIO=3&transport=polling&t=Lvm8QQx +1ms
engine.io-client:polling-xhr xhr data null +0ms
engine.io-client:socket setting transport polling +1ms
socket.io-client:manager connect attempt will timeout after 20000 +1ms

I have the test and production application on the same server at the moment.

Production had 70 websocket connections, test crashed at 255 connections.
Closed the production app, so it was 0 websocket connections from live, test crashed at 260.
This is indicative of it being an app problem?

The open file limit should not be the problem here:

$ prlimit -p 5212
RESOURCE   DESCRIPTION                             SOFT      HARD UNITS
NOFILE     max number of open files                1024     65536

After the freezing: 

$ lsof -p *ID* | wc -l
474
$ lsof | wc -l
29772

The versions and libraries associated with the project:

eventlet==0.21.0
SQLAlchemy==1.1.13
Flask_Migrate==2.0.4
estnltk==1.4.1.1
pandas==0.19.2
Flask_SQLAlchemy==2.2
alembic==0.9.2
nltk==3.2.2
requests==2.13.0
Flask_Script==2.0.5
Flask_SocketIO==2.8.6
regex==2017.6.23
fuzzywuzzy==0.15.1
Flask==0.12

Monkey patching.

When I run the project, the first line of code is

from project import app, socketio

the first two lines in project module:

import eventlet
eventlet.monkey_patch()

So it should apply, as it should be the first command thing that is run.

[andmekaevur]

Going as basic as possible, the following code and on localhost, I get the same result. I find it hard to believe socket.io supports only 250 concurrent connections. Is there something I'm missing here? Perhaps this kind of debugging does not simulate the real world, and the production behaviour is due to something else?

The following code can be used to replicate the problem at least on my computer.

main.py

from flask import Flask, render_template
from flask_socketio import SocketIO
from flask_socketio import send, emit
from logging.config import fileConfig
import logging

fileConfig('logging.conf')

log = logging.getLogger(__name__)

app = Flask(__name__)
app.config['SECRET_KEY'] = 'secret!'
socketio = SocketIO(app, allow_upgrades=True, engineio_logger=log, logger=log)

@socketio.on('connect')
def test_connect():
    emit('response', {'data': 'Connected'})

if __name__ == '__main__':
    socketio.run(app, debug=True)

test.html

<!DOCTYPE html>
<html>
<head>
    <title>test socket</title>
</head>
<body>

<script type="text/javascript" src="https://cdnjs.cloudflare.com/ajax/libs/socket.io/2.0.3/socket.io.slim.js"></script>
<script type="text/javascript" charset="utf-8">
    clients = []
    for (var i = 0; i<500; i++) {
        (function (index) {
            setTimeout(function () {
                console.log(index)
                var client_socket = io.connect('http://localhost:5000');
                client_socket.on('connect', function(data) {
                    console.log('client connected')
                });
                clients.push(client_socket)
            }, index * 300);
        })(i);
    }
</script>
</body>
</html>

logging.conf

[loggers]
keys=root

[handlers]
keys=stream_handler,file_handler

[formatters]
keys=formatter

[logger_root]
level=DEBUG
handlers=stream_handler,file_handler

[handler_stream_handler]
class=StreamHandler
level=DEBUG
formatter=formatter
args=(sys.stdout,)

[handler_file_handler]
class=handlers.TimedRotatingFileHandler
level=INFO
formatter=formatter
args=('bot-api.log', 'D', 7)

[formatter_formatter]
format=%(levelname)s %(asctime)s %(funcName)-12s %(filename)-8s %(message)s

Environment:

$ pipdeptree -p Flask-SocketIO
Flask-SocketIO==2.8.6
  - Flask [required: >=0.9, installed: 0.10.1]
    - itsdangerous [required: >=0.21, installed: 0.24]
    - Jinja2 [required: >=2.4, installed: 2.8]
      - MarkupSafe [required: Any, installed: 1.0]
    - Werkzeug [required: >=0.7, installed: 0.10.4]
  - python-engineio [required: >=1.0.0, installed: 1.5.4]
    - six [required: >=1.9.0, installed: 1.10.0]
  - python-socketio [required: >=1.5.0, installed: 1.7.5]
    - python-engineio [required: >=1.2.1, installed: 1.5.4]
      - six [required: >=1.9.0, installed: 1.10.0]
    - six [required: >=1.9.0, installed: 1.10.0]

[andmekaevur]

Update: the 250 comes from chrome limitation. Cannot do load testing using the browser (or must increase the limit).

Currently stuck at the point, that pure websocket connections go as far as needed, but polling connections get stuck at 1024. So I can get pure websocket connections using the Tornado framework, but socketio requires long polled connections before websocket and fails to go over 1024.

[miguelgrinberg]

You can do the following to bypass the long-polling connection:

var socket = io.connect(location.origin + '/chat', {transports: ['websocket']});

[andmekaevur]

I'm using Artillery for load testing.
I have a simple Tornado application, enabling a ws:// connection, and a simple flask-socketio application, enabling a socketio connection.

The Tornado app allows for as many websocket connections, as set by ulimit (4096), but the flask-socketio app hangs at 1024. Using either transports method.

Maybe this helps:

flask-socketio

from flask import Flask, render_template
from flask_socketio import SocketIO
from flask_socketio import send, emit
from logging.config import fileConfig
import logging

fileConfig('logging.conf')

log = logging.getLogger(__name__)

app = Flask(__name__)
app.config['SECRET_KEY'] = 'secret!'
# socketio = SocketIO(app, allow_upgrades=True, engineio_logger=log, logger=log)
socketio = SocketIO(app, allow_upgrades=True)

connected_clients_count = 0

@socketio.on('connect')
def test_connect():
    global connected_clients_count
    connected_clients_count += 1
    print(connected_clients_count)
    # emit('response', {'data': 'Connected'})

@app.route('/')
def render_load_test():
    return render_template('test-socketio.html')

import resource
if __name__ == '__main__':
    print(resource.getrlimit(resource.RLIMIT_NOFILE))
    socketio.run(app, debug=True)

Tornado

from tornado import websocket, web, ioloop, options
import json

options.define("debug", default=True, help="run in debug mode")

cl = []

class IndexHandler(web.RequestHandler):
    def get(self):
        self.render("tornado-test.html")

class SocketHandler(websocket.WebSocketHandler):
    def check_origin(self, origin):
        return True

    def open(self):
        if self not in cl:
            cl.append(self)
            print(len(cl))

    def on_close(self):
        if self in cl:
            cl.remove(self)

    def on_message(self, message):
        print("got message", message)

class ApiHandler(web.RequestHandler):

    @web.asynchronous
    def get(self, *args):
        self.finish()
        id = self.get_argument("id")
        value = self.get_argument("value")
        data = {"id": id, "value" : value}
        data = json.dumps(data)
        for c in cl:
            c.write_message(data)

    @web.asynchronous
    def post(self):
        pass

app = web.Application([
    (r'/', IndexHandler),
    (r'/ws', SocketHandler),
    (r'/api', ApiHandler),
    (r'/(rest_api_example.png)', web.StaticFileHandler, {'path': './'}),
], debug=True)

if __name__ == '__main__':
    print(1234)
    app.listen(8888)
    ioloop.IOLoop.instance().start()

Artillery YAML files
tornado

config:
  target: "ws://localhost:8888/ws"
  phases:
    - duration: 100
      arrivalRate: 2000
  ws:
    # Ignore SSL certificate errors
    # - useful in *development* with self-signed certs
    rejectUnauthorized: false
scenarios:
  - engine: "ws"
    flow:
    flow:
      - loop:
        - send: "hello"
        - think: 1
      - count: 50

socketio

config:
  target: "http://localhost:5000"
  phases:
    - duration: 100
      arrivalRate: 100
  socketio:
    transports: ["websocket"]
scenarios:
  - engine: "socketio"
    flow:
      - loop:
        - emit:
            channel: "echo"
            data: "hello"
        - think: 1
      - count: 50

[miguelgrinberg]

Are you using eventlet by any chance? See the max_size config option for the WSGI server: http://eventlet.net/doc/modules/wsgi.html#eventlet.wsgi.server. You can pass this or other server options in the socketio.run() call, anything this function does not recognize it passes down to the server.

[andmekaevur]

Great! It worked! Will have to verify this in the production environment as well though, but looking good atm. Many thanks Miguel!

[andmekaevur]

The above script now freezes at 3000 connections. Searching for the new limit. @miguelgrinberg do you know what a reasonable limit for socketio connections should be?

[miguelgrinberg]

The server is single-threaded and single-process, so it really depends on how much work each connection requires. A few thousand should be doable for a lightweight server.

[andmekaevur]

Both Tornado on flask-socketio freeze at 3000 connections point. These are empty connections doing very little work (one emit per 50 sec). This seems like another limit set by the system somewhere, any ideas?

[andmekaevur]

Well this is interesting, they freeze at 3000 only at a certain connections/sec. At 100 connections /sec it does, at 500 it does not. Will try with a slower one.

[andmekaevur]

10 connections/sec does not either.

[andmekaevur]

Arrived at 20k connections, that should be suitable. Another story is if they have the production load as well, but that wont be related with the current issue. Thanks again!

[xarg]

@andmekaevur can you share your production setup please and how you arrived at 20k? Thanks a lot!

[andmekaevur]

The main things were that I increased the system file limits (i'm on ubuntu) and the max_size config option for the WSGI server Miguel talks about above. Googling around I found some network connectivity parameters people had to tweak as well, but on ubuntu 14 and 16 the deafults were sufficient. @xarg

[xarg]

Thanks @andmekaevur