Python-socketio: Strange behaviours when pingInterval > pingTimeout

[KiloFoxtrotPapa]

I've run into several strange behaviours which only happens when pingInterval > pingTimeout.

Problem 1: Server closes websocket prematurely

This setting would not work at all with a python-socketio server, but is unfortunately the current defaults (pingInterval=25000, pingTimeout=5000) for socket.io.

This is what happens when we use the socket.io ping defaults for a python-socketio server:

client.py

import socketio

client = socketio.Client()
client.connect('http://localhost:8080'),
client.wait()

idle_server.py

from aiohttp import web
import socketio

sio = socketio.AsyncServer(async_mode='aiohttp', ping_timeout=5, ping_interval=25)
app = web.Application()
sio.attach(app)

if __name__ == '__main__':
    web.run_app(app, port=8080)

Output

$ python client.py
2019-01-06 13:20:56,837 [INFO] - _connect_polling: Attempting polling connection to http://localhost:8080/socket.io/?transport=polling&EIO=3
2019-01-06 13:20:56,842 [INFO] - _connect_polling: Polling connection accepted with {'sid': 'b59f99b2136648e9ad1507516ecaa8c2', 'upgrades': ['websocket'], 'pingTimeout': 5000, 'pingInterval': 25000}
2019-01-06 13:20:56,842 [INFO] - _handle_eio_connect: Engine.IO connection established
2019-01-06 13:20:56,842 [INFO] - _receive_packet: Received packet MESSAGE data 0
2019-01-06 13:20:56,842 [INFO] - _handle_connect: Namespace / is connected
2019-01-06 13:20:56,842 [INFO] - _connect_websocket: Attempting WebSocket upgrade to ws://localhost:8080/socket.io/?transport=websocket&EIO=3
2019-01-06 13:20:56,845 [INFO] - _connect_websocket: WebSocket upgrade was successful
2019-01-06 13:20:56,845 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 13:20:56,846 [INFO] - _receive_packet: Received packet NOOP data None
2019-01-06 13:20:56,846 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 13:21:01,847 [INFO] - _receive_packet: Received packet NOOP data None
2019-01-06 13:21:01,848 [WARNING] - _read_loop_websocket: WebSocket connection was closed, aborting
2019-01-06 13:21:01,848 [INFO] - _read_loop_websocket: Waiting for write loop task to end
2019-01-06 13:21:01,848 [INFO] - _write_loop: Exiting write loop task
2019-01-06 13:21:01,848 [INFO] - _read_loop_websocket: Waiting for ping loop task to end
2019-01-06 13:21:01,848 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 13:21:01,849 [WARNING] - _ping_loop: PONG response has not been received, aborting
2019-01-06 13:21:01,849 [INFO] - _ping_loop: Exiting ping task
2019-01-06 13:21:01,849 [INFO] - _read_loop_websocket: Exiting read loop task

---------------------------------------------------------------------------

$ python idle_server.py
2019-01-06 13:20:52,614 [INFO] - __init__: Server initialized for aiohttp.
======== Running on http://0.0.0.0:8080 ========
(Press CTRL+C to quit)
2019-01-06 13:20:56,840 [INFO] - send: b59f99b2136648e9ad1507516ecaa8c2: Sending packet OPEN data {'sid': 'b59f99b2136648e9ad1507516ecaa8c2', 'upgrades': ['websocket'], 'pingTimeout': 5000, 'pingInterval': 25000}
2019-01-06 13:20:56,840 [INFO] - send: b59f99b2136648e9ad1507516ecaa8c2: Sending packet MESSAGE data 0
2019-01-06 13:20:56,843 [INFO] - handle_get_request: b59f99b2136648e9ad1507516ecaa8c2: Received request to upgrade to websocket
2019-01-06 13:20:56,845 [INFO] - _websocket_handler: b59f99b2136648e9ad1507516ecaa8c2: Upgrade to websocket successful
2019-01-06 13:20:56,846 [INFO] - receive: b59f99b2136648e9ad1507516ecaa8c2: Received packet PING data None
2019-01-06 13:20:56,846 [INFO] - send: b59f99b2136648e9ad1507516ecaa8c2: Sending packet PONG data None
2019-01-06 13:21:01,846 [INFO] - check_ping_timeout: b59f99b2136648e9ad1507516ecaa8c2: Client is gone, closing socket
2019-01-06 13:21:01,847 [INFO] - check_ping_timeout: b59f99b2136648e9ad1507516ecaa8c2: Client is gone, closing socket

check_ping_timeout closes the socket after ping_timeout is reached. And this would always be the case when pingInterval > pingTimeout.

However with a socket.io server and the same client, it works mostly fine:

server.js

const io = require('socket.io')(8080);

Output

$ DEBUG=engine,socket.io* node server.js
  socket.io:server initializing namespace / +0ms
  socket.io:server creating http server and binding to 8080 +3ms
  socket.io-parser encoding packet {"type":0,"nsp":"/"} +0ms
  socket.io-parser encoded {"type":0,"nsp":"/"} as 0 +1ms
  socket.io:server creating engine.io instance with opts {"path":"/socket.io","initialPacket":["0"]} +8ms
  socket.io:server attaching client serving req handler +14ms
  engine intercepting request for path "/socket.io/" +0ms
  engine handling "GET" http request "/socket.io/?transport=polling&EIO=3&t=1546807480.9925132" +0ms
  engine handshaking client "4DGfO2LFToQVzLSRAAAA" +5ms
  socket.io:server incoming connection with id 4DGfO2LFToQVzLSRAAAA +11s
  socket.io:client connecting to namespace / +0ms
  socket.io:namespace adding socket to nsp / +0ms
  socket.io:socket socket connected - writing packet +0ms
  socket.io:socket joining room 4DGfO2LFToQVzLSRAAAA +1ms
  socket.io:socket packet already sent in initial handshake +0ms
  socket.io:socket joined room 4DGfO2LFToQVzLSRAAAA +0ms
  engine upgrading existing transport +11ms
  socket.io:client client close with reason ping timeout +6m
  socket.io:socket closing socket - reason ping timeout +6m
-----------------------------------------------------------------------
$ python sync_client.py
2019-01-06 12:44:40,992 [INFO] - _connect_polling: Attempting polling connection to http://localhost:8080/socket.io/?transport=polling&EIO=3
2019-01-06 12:44:41,009 [INFO] - _connect_polling: Polling connection accepted with {'sid': '4DGfO2LFToQVzLSRAAAA', 'upgrades': ['websocket'], 'pingInterval': 25000, 'pingTimeout': 5000}
2019-01-06 12:44:41,009 [INFO] - _handle_eio_connect: Engine.IO connection established
2019-01-06 12:44:41,009 [INFO] - _receive_packet: Received packet MESSAGE data 0
2019-01-06 12:44:41,009 [INFO] - _handle_connect: Namespace / is connected
2019-01-06 12:44:41,010 [INFO] - _connect_websocket: Attempting WebSocket upgrade to ws://localhost:8080/socket.io/?transport=websocket&EIO=3
2019-01-06 12:44:41,018 [INFO] - _connect_websocket: WebSocket upgrade was successful
2019-01-06 12:44:41,019 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:44:41,020 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:45:06,019 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:45:06,020 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:45:31,020 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:45:31,020 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:45:56,020 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:45:56,021 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:46:21,021 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:46:21,021 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:46:46,021 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:46:46,022 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:47:11,022 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:47:11,023 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:47:36,022 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:47:36,023 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:48:01,023 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:48:01,024 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:48:26,023 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:48:26,024 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:48:51,024 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:48:51,025 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:49:16,024 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:49:16,025 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:49:41,025 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:49:41,026 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 12:50:06,026 [ERROR] - _write_loop: packet queue is empty, aborting
2019-01-06 12:50:06,026 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 12:50:06,026 [INFO] - _write_loop: Exiting write loop task
2019-01-06 12:50:11,052 [INFO] - _receive_packet: Received packet NOOP data None
2019-01-06 12:50:11,052 [INFO] - _read_loop_websocket: Waiting for write loop task to end
2019-01-06 12:50:11,052 [INFO] - _read_loop_websocket: Waiting for ping loop task to end
2019-01-06 12:50:11,052 [INFO] - _ping_loop: Exiting ping task
2019-01-06 12:50:11,053 [INFO] - _read_loop_websocket: Exiting read loop task

We see that the client and server can ping-pong back and forth for a while until another problem occurs.

Problem 2: Race between _write_loop and _ping_loop

The timeout for the queue is calculated timeout = max(self.ping_interval, self.ping_timeout), so when pingInterval > pingTimeout, the timeout for both _write_loop and _ping_loop would be ping_interval.

So occasionally we get the self.queue.Empty exception and the _write_loop exits. I've "fixed" this with timeout = max(self.ping_interval+100, self.ping_timeout).

Problem 3: Precedence of handling PING and MESSAGE

I'm actually not sure if this is caused by the pingInterval > pingTimeout issue at hand here, I can split this one into a separate issue if you'd prefer.

I ran out of time creating a simple reproducer for this, but I think the logs highlight the condition causing the issue pretty well. This is with a socket.io server and python-socketio client, with pingInterval=25000, pingTimeout=5000

client.log

2019-01-06 09:30:27,685 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 09:30:27,686 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 09:30:52,704 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 09:30:52,706 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 09:31:17,708 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 09:31:17,709 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 09:31:42,712 [INFO] - _receive_packet: Received packet MESSAGE data 2["doThing","2974"]
2019-01-06 09:31:42,713 [INFO] - _handle_event: Received event "doThing" [/]
2019-01-06 09:31:47,847 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 09:31:47,848 [WARNING] - _write_loop: Write loop: WebSocket connection was closed, aborting
2019-01-06 09:31:47,848 [INFO] - _write_loop: Exiting write loop task
2019-01-06 09:31:47,848 [WARNING] - _read_loop_websocket: Read loop: WebSocket connection was closed, aborting
2019-01-06 09:31:47,848 [INFO] - _read_loop_websocket: Waiting for write loop task to end
2019-01-06 09:31:47,848 [INFO] - _read_loop_websocket: Waiting for ping loop task to end
2019-01-06 09:31:47,848 [INFO] - _ping_loop: Exiting ping task
2019-01-06 09:31:47,848 [INFO] - _read_loop_websocket: Exiting read loop task

server.log

2019-01-06 09:26:42 DEBUG <snip>
  socket.io:client writing packet {"type":2,"data":["doThing","2973"],"nsp":"/"} +5m
  socket.io-parser encoding packet {"type":2,"data":["doThing","2973"],"nsp":"/"} +5m
  socket.io-parser encoded {"type":2,"data":["doThing","2973"],"nsp":"/"} as 2["doThing","2973"] +0ms
Run ID #2974 @ 2019-01-06T17:31:36.853Z
2019-01-06 09:31:42 DEBUG <snip>
  socket.io:client writing packet {"type":2,"data":["doThing","2974"],"nsp":"/"} +5m
  socket.io-parser encoding packet {"type":2,"data":["doThing","2974"],"nsp":"/"} +5m
  socket.io-parser encoded {"type":2,"data":["doThing","2974"],"nsp":"/"} as 2["doThing","2974"] +1ms
  socket.io:client client close with reason ping timeout +5s
  socket.io:socket closing socket - reason ping timeout +9h
2019-01-06 09:31:47 DEBUG <snip> io.disconnect callback

Note: the socket.io logs are not timestamped. The timestamps are from other parts of my app.

A MESSAGE comes in right when the client is supposed to send a PING, and a subsequent PING is sent out 5 seconds (pingTimeout) later, and the server thinks that's too late so the connection is closed.

[miguelgrinberg]

Thanks for your detailed reports!

Some comments:

1. I could see how my server would get confused if you used ping interval > ping timeout, I did not intend that case to be supported. I wrote this server a while ago, when the defaults used to be interval=25, timeout=60, and my assumption at the time was that interval should always be less than the timeout. But you are correct, they have reduced the timeout to 5 in recent versions of the JS server, so I need to review my timeout handling in the server to support (and maybe also adopt) that.

2. Makes sense. Here in the client I did try to make it work for the new 5s timeout, but I agree that the write loop needs to wait a bit longer than the ping interval. I will fix that.

3. Not sure if this is the exact same case as yours, but I fixed a potentially related problem in python-engineio master. The problem was that event handlers were awaited in the context of the read loop task, so a handler that took a few seconds would block any incoming packets from the server during that time. My fix puts all event handlers in background tasks so that the read loop is never blocked. Your problem might also be that your handler blocks for those 5 seconds that delayed the sending of the PING packet as well.

[KiloFoxtrotPapa]

Your problem might also be that your handler blocks for those 5 seconds that delayed the sending of the PING packet as well.

That might be it; the handler definitely needs a few seconds. Though, wouldn't that only lock up read loop? Is that also affecting/delaying the ping and write loops?

[KiloFoxtrotPapa]

Problem 3 (More info):

Contrived example like below:

• handler blocks for 5 secs
• server sends MESSAGE every 2 secs
• ping_interval: 9 secs, ping_timeout: 1 sec

async_client.py (logger setup snipped)

import asyncio
import socketio

sio = socketio.AsyncClient()


@sio.on('doThing')
async def on_doThing():
    await asyncio.sleep(5)


async def main():
    await sio.connect('http://localhost:8080')
    await sio.wait()


if __name__ == '__main__':
    asyncio.run(main())

busy_server.js (logger setup snipped)

let sclient = undefined;

const io = require('socket.io')(8080, {
  pingInterval: 9000,
  pingTimeout: 1000,
});
io.on('connect', client => {
  logger.debug('io.connect callback');

  client.on('disconnect', () => {
    sclient = undefined;
    logger.debug('io.disconnect callback')
  });

  client.on('reconnect', rclient => {
    sclient = rclient;
    logger.debug('io.reconnect callback')
  });

 sclient = client;
});

function run(currentTime) {
  if (sclient !== undefined) {
    sclient.emit('doThing');
  }
  else {
    logger.error('no socket.io client');
  }
}

setInterval(run, 2000);

client.log

$ python async_client.py
2019-01-06 17:50:35,999 [INFO] - _connect_polling: Attempting polling connection to http://localhost:8080/socket.io/?transport=polling&EIO=3
2019-01-06 17:50:36,023 [INFO] - _connect_polling: Polling connection accepted with {'sid': 'OAYYfS_lCO3SWP7iAAAA', 'upgrades': ['websocket'], 'pingInterval': 9000, 'pingTimeout': 1000}
2019-01-06 17:50:36,023 [INFO] - _handle_eio_connect: Engine.IO connection established
2019-01-06 17:50:36,024 [INFO] - _receive_packet: Received packet MESSAGE data 0
2019-01-06 17:50:36,024 [INFO] - _handle_connect: Namespace / is connected
2019-01-06 17:50:36,024 [INFO] - _connect_websocket: Attempting WebSocket upgrade to ws://localhost:8080/socket.io/?transport=websocket&EIO=3
2019-01-06 17:50:36,037 [INFO] - _connect_websocket: WebSocket upgrade was successful
2019-01-06 17:50:36,037 [INFO] - _send_packet: Sending packet PING data None
2019-01-06 17:50:36,039 [INFO] - _receive_packet: Received packet PONG data None
2019-01-06 17:50:37,636 [INFO] - _receive_packet: Received packet MESSAGE data 2["doThing"]
2019-01-06 17:50:37,636 [INFO] - _handle_event: Received event "doThing" [/]
2019-01-06 17:50:42,637 [INFO] - _receive_packet: Received packet MESSAGE data 2["doThing"]
2019-01-06 17:50:42,637 [INFO] - _handle_event: Received event "doThing" [/]
2019-01-06 17:50:47,639 [INFO] - _receive_packet: Received packet MESSAGE data 2["doThing"]
2019-01-06 17:50:47,640 [INFO] - _handle_event: Received event "doThing" [/]
2019-01-06 17:50:52,645 [INFO] - _receive_packet: Received packet MESSAGE data 2["doThing"]
2019-01-06 17:50:52,645 [INFO] - _handle_event: Received event "doThing" [/]
2019-01-06 17:50:57,651 [INFO] - _receive_packet: Received packet MESSAGE data 2["doThing"]
2019-01-06 17:50:57,651 [INFO] - _handle_event: Received event "doThing" [/]
2019-01-06 17:51:02,656 [WARNING] - _read_loop_websocket: Read loop: WebSocket connection was closed, aborting
2019-01-06 17:51:02,657 [INFO] - _read_loop_websocket: Waiting for write loop task to end
2019-01-06 17:51:02,657 [INFO] - _write_loop: Exiting write loop task
2019-01-06 17:51:02,657 [INFO] - _read_loop_websocket: Waiting for ping loop task to end
Traceback (most recent call last):
  File "async_client.py", line 32, in <module>
    asyncio.run(main())
  File "/usr/lib64/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/lib64/python3.7/asyncio/base_events.py", line 584, in run_until_complete
    return future.result()
  File "async_client.py", line 28, in main
    await sio.wait()
  File "/home/kfp/git/logs/env/lib/python3.7/site-packages/socketio/asyncio_client.py", line 115, in wait
    await self.eio.wait()
  File "/home/kfp/git/logs/env/lib/python3.7/site-packages/engineio/asyncio_client.py", line 84, in wait
    await self.read_loop_task
  File "/home/kfp/git/logs/env/lib/python3.7/site-packages/engineio/asyncio_client.py", line 443, in _read_loop_websocket
    await self.ping_loop_task
  File "/home/kfp/git/logs/env/lib/python3.7/site-packages/engineio/asyncio_client.py", line 371, in _ping_loop
    self.ping_interval)
  File "/usr/lib64/python3.7/asyncio/tasks.py", line 416, in wait_for
    return fut.result()
  File "/usr/lib64/python3.7/asyncio/locks.py", line 293, in wait
    await fut
RuntimeError: Task <Task pending coro=<Event.wait() running at /usr/lib64/python3.7/asyncio/locks.py:293> cb=[_release_waiter(<Future pendi...b890f2f78>()]>)() at /usr/lib64/python3.7/asyncio/tasks.py:366]> got Future <Future pending> attached to a different loop

server.log

$ DEBUG=engine,socket.io* node busy_server.js
  socket.io:server initializing namespace / +0ms
  socket.io:server creating http server and binding to 8080 +3ms
  socket.io-parser encoding packet {"type":0,"nsp":"/"} +0ms
  socket.io-parser encoded {"type":0,"nsp":"/"} as 0 +0ms
  socket.io:server creating engine.io instance with opts {"pingInterval":9000,"pingTimeout":1000,"path":"/socket.io","initialPacket":["0"]} +8ms
  socket.io:server attaching client serving req handler +14ms
2019-01-06 17:50:35 ERROR [busy_server] no socket.io client
  engine intercepting request for path "/socket.io/" +0ms
  engine handling "GET" http request "/socket.io/?transport=polling&EIO=3&t=1546825835.9999003" +0ms
  engine handshaking client "OAYYfS_lCO3SWP7iAAAA" +5ms
  socket.io:server incoming connection with id OAYYfS_lCO3SWP7iAAAA +2s
  socket.io:client connecting to namespace / +0ms
  socket.io:namespace adding socket to nsp / +0ms
  socket.io:socket socket connected - writing packet +0ms
  socket.io:socket joining room OAYYfS_lCO3SWP7iAAAA +0ms
  socket.io:socket packet already sent in initial handshake +0ms
2019-01-06 17:50:36 DEBUG [busy_server] io.connect callback
  socket.io:socket joined room OAYYfS_lCO3SWP7iAAAA +1ms
  engine upgrading existing transport +13ms
  socket.io:client writing packet {"type":2,"data":["doThing"],"nsp":"/"} +2s
  socket.io-parser encoding packet {"type":2,"data":["doThing"],"nsp":"/"} +4s
  socket.io-parser encoded {"type":2,"data":["doThing"],"nsp":"/"} as 2["doThing"] +0ms
  socket.io:client writing packet {"type":2,"data":["doThing"],"nsp":"/"} +2s
  socket.io-parser encoding packet {"type":2,"data":["doThing"],"nsp":"/"} +2s
  socket.io-parser encoded {"type":2,"data":["doThing"],"nsp":"/"} as 2["doThing"] +0ms
  socket.io:client writing packet {"type":2,"data":["doThing"],"nsp":"/"} +2s
  socket.io-parser encoding packet {"type":2,"data":["doThing"],"nsp":"/"} +2s
  socket.io-parser encoded {"type":2,"data":["doThing"],"nsp":"/"} as 2["doThing"] +0ms
  socket.io:client writing packet {"type":2,"data":["doThing"],"nsp":"/"} +2s
  socket.io-parser encoding packet {"type":2,"data":["doThing"],"nsp":"/"} +2s
  socket.io-parser encoded {"type":2,"data":["doThing"],"nsp":"/"} as 2["doThing"] +0ms
  socket.io:client writing packet {"type":2,"data":["doThing"],"nsp":"/"} +2s
  socket.io-parser encoding packet {"type":2,"data":["doThing"],"nsp":"/"} +2s
  socket.io-parser encoded {"type":2,"data":["doThing"],"nsp":"/"} as 2["doThing"] +0ms
  socket.io:client client close with reason ping timeout +399ms
  socket.io:socket closing socket - reason ping timeout +10s
2019-01-06 17:50:46 DEBUG [busy_server] io.disconnect callback
2019-01-06 17:50:47 ERROR [busy_server] no socket.io client

The obvious solutions would be to speed up the handlers and/or relax the ping_{interval,timeout}s on the server side. Though isn't it a better solution to have the ping and write loops not affected by any lock-ups in the read loop and the handlers?

[miguelgrinberg]

As I mentioned previously, this problem is fixed in python-engineio master. I haven't released it yet. Your example works fine if I use that fix, plus adding a bit of extra time to the ping interval in the ping loop task like you did.

[KiloFoxtrotPapa]

Ah that's what you meant. I looked at the couple released commits and they looked like refactoring changes only. Now it makes sense, thanks!

[miguelgrinberg]

@KiloFoxtrotPapa I think all these issues should be addressed. You need to upgrade both python-socketio and python-engineio to get all the fixes. Thanks!

[moshisushi]

I've had the same problem, I think, but didn't reply until now since a fix was in progress.

I have a python-socketio server and client, and the client always disconnects after 60 seconds with the stacktrace below, which looks very similar to what @KiloFoxtrotPapa reported. I have updated to python-socketio==3.1.1 and python-engineio==3.2.2 but it's still the same. @KiloFoxtrotPapa please let me know whether you have any luck. If it works for you it might just be a configuration issue on my end.

Traceback (most recent call last):
  File "bridge.py", line 74, in <module>
    asyncio.run(start())
  File "/usr/local/Cellar/python/3.7.2/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/local/Cellar/python/3.7.2/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/base_events.py", line 584, in run_until_complete
    return future.result()
  File "bridge.py", line 69, in start
    await sio.wait()
  File "/Users/henry/workspace/portals-reconlive-av/venv/lib/python3.7/site-packages/socketio/asyncio_client.py", line 115, in wait
    await self.eio.wait()
  File "/Users/henry/workspace/portals-reconlive-av/venv/lib/python3.7/site-packages/engineio/asyncio_client.py", line 84, in wait
    await self.read_loop_task
  File "/Users/henry/workspace/portals-reconlive-av/venv/lib/python3.7/site-packages/engineio/asyncio_client.py", line 411, in _read_loop_polling
    await self.ping_loop_task
  File "/Users/henry/workspace/portals-reconlive-av/venv/lib/python3.7/site-packages/engineio/asyncio_client.py", line 374, in _ping_loop
    self.ping_interval)
  File "/usr/local/Cellar/python/3.7.2/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/tasks.py", line 416, in wait_for
    return fut.result()
  File "/usr/local/Cellar/python/3.7.2/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/locks.py", line 293, in wait
    await fut
RuntimeError: Task <Task pending coro=<Event.wait() running at /usr/local/Cellar/python/3.7.2/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/locks.py:293> cb=[_release_waiter(<Future pendi...105ea3cd8>()]>)() at /usr/local/Cellar/python/3.7.2/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/tasks.py:366]> got Future <Future pending> attached to a different loop
Unclosed client session
client_session: <aiohttp.client.ClientSession object at 0x105edb898>
Unclosed connector
connections: ['[(<aiohttp.client_proto.ResponseHandler object at 0x105ec2e28>, 60.434079143)]']
connector: <aiohttp.connector.TCPConnector object at 0x105edb828>

[miguelgrinberg]

@moshisushi do you have multiple loops in your application?

[moshisushi]

@miguelgrinberg I'm just trying with the smallest possible client application at the moment:

import asyncio
import socketio
import requests
import sys

server = "http://127.0.0.1:8080"
sio = socketio.AsyncClient()

@sio.on('connect', namespace='/chat')
async def on_connect():
    print('Connected')
    await sio.emit('joined', {}, namespace='/chat')

@sio.on('disconnect', namespace='/chat')
async def on_disconnect():
    print('Disconnected')

async def start():
    await sio.connect(server, namespaces=['/chat'])
    await sio.wait()


if __name__ == '__main__':
    asyncio.run(start())

I have a browser socket.io client as well which connects fine and stays connected.

I turned on debugging on the server and I don't see the client sending any PINGs after an initial one.

I also see 221abc6945e24bfe8e591ae9cc2925a2: Sending packet OPEN data {'sid': '221abc6945e24bfe8e591ae9cc2925a2', 'upgrades': ['websocket'], 'pingTimeout': 60000, 'pingInterval': 25000}, so this might not be the same issue at all (apologies if that's the case).

[miguelgrinberg]

@moshisushi the problem is that the AsyncClient call creates some asyncio objects. This is before you call asyncio.run(), which creates a new loop. So some of the attributes in the server end up attached to the default loop that was current before asyncio.run() is called.

I'll have to think about how to make this new way of starting asyncio apps work...

[moshisushi]

@miguelgrinberg Thanks, yeah that makes sense, though I'm not sure what the "old" way is (or do you mean something like eventlet?).

If there's an alternative way of running the program I'm happy with that for now.

[miguelgrinberg]

No, see this example. The idea is that you create the loop manually. This was the normal way to start an asyncio app until 3.7 came about. I'll think about how to support asyncio.run() for a future release.

[moshisushi]

@miguelgrinberg Thanks a million! Working perfectly now.