Not reconnecting when used with FastAPI server

[cetteup]

I am trying to set up a project that a) runs a local FastAPI server in order to provide a web ui/api for settings etc and b) runs a socket.io client listening for events.

I set up both the FastAPI app and the socket.io async client globally.

app = FastAPI(title='<sometitle>')
sio = socketio.AsyncClient(logger=True, engineio_logger=True)

Then run the FastAPI app via uvicorn.

if __name__ == '__main__':
    uvicorn.run(app, host=config.LISTEN_ADDR, port=config.LISTEN_PORT)

And connect to the node.js-based socket io server as one of the startup tasks.

@app.on_event('startup')
async def startup():
    await sio.connect(config.SOCKETIO_SERVER)

Which works fine. The FastAPI server starts up and does it's thing and so does the socketio client. However, if the connection to the server is lost for some reason, the client never reconnects.

Waiting for write loop task to end
INFO:engineio.client:Waiting for write loop task to end
packet queue is empty, aborting
ERROR:engineio.client:packet queue is empty, aborting
Exiting write loop task
INFO:engineio.client:Exiting write loop task
Engine.IO connection dropped
INFO:socketio.client:Engine.IO connection dropped
Exiting read loop task
INFO:engineio.client:Exiting read loop task
Connection failed, new attempt in 0.86 seconds
INFO:socketio.client:Connection failed, new attempt in 0.86 seconds
disconnected from server

That when it stops doing anything. I read through most of the similar issues in here, but unless I misunderstood, the issue should actually be fixed.

If I instead use a more default async client script, it reconnects without any issues.

import asyncio
import socketio
import time
import logging

logging.basicConfig(level=logging.DEBUG)

loop = asyncio.get_event_loop()
sio = socketio.AsyncClient(logger=True)

async def start_server():
    await sio.connect('https://qwerty-server.herokuapp.com')
    while True:
        await asyncio.sleep(5)
        await sio.send(data={'time': time.time()})

if __name__ == '__main__':
    loop.run_until_complete(start_server())

Versions I am using:
python 3.8.7 (Windows 64-bit)
socket.io 3.1.0 (on node.js 14)
fastapi 0.63.0
python-engineio 4.0.0
python-socketio 5.0.4
websockets 8.1
aiohttp 3.7.3

[miguelgrinberg]

Can you provide a small example that shows the problem?

[cetteup]

Sure! I was able to reproduce the issue with this client and server setup.

Using this as the client.

# socketio client + FastAPI server
import socketio
import uvicorn
from fastapi import FastAPI

app = FastAPI()
sio = socketio.AsyncClient(logger=True, engineio_logger=True)


@app.on_event('startup')
async def startup():
    await sio.connect('http://localhost:8080')


@app.on_event('shutdown')
async def shutdown():
    await sio.disconnect()


@app.get('/')
async def root():
    return {'message': 'Hello world'}


@sio.event
async def connect():
    print('connection established')
    await sio.send('Hello server')


@sio.on('redemption')
async def on_message(data):
    print('Channel points redeemed!', data)


@sio.event
async def disconnect():
    print('disconnected from server')


if __name__ == '__main__':
    uvicorn.run(app, host='127.0.0.1', port=8000)

And this as the server.

# socketio server (copied from the example)
from aiohttp import web
import socketio

sio = socketio.AsyncServer()
app = web.Application()
sio.attach(app)

async def index(request):
    """Serve the client-side application."""
    with open('index.html') as f:
        return web.Response(text=f.read(), content_type='text/html')

@sio.event
def connect(sid, environ):
    print("connect ", sid)

@sio.event
async def chat_message(sid, data):
    print("message ", data)
    await sio.emit('reply', room=sid)

@sio.event
def disconnect(sid):
    print('disconnect ', sid)

app.router.add_static('/static', 'static')
app.router.add_get('/', index)

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

Results in:

INFO:     Started server process [121915]
INFO:     Waiting for application startup.
Attempting polling connection to http://localhost:8080/socket.io/?transport=polling&EIO=4
Polling connection accepted with {'sid': 'YKIkYS3COkqahcqJAAAA', 'upgrades': ['websocket'], 'pingTimeout': 5000, 'pingInterval': 25000}
Engine.IO connection established
Sending packet MESSAGE data 0
Attempting WebSocket upgrade to ws://localhost:8080/socket.io/?transport=websocket&EIO=4
WebSocket upgrade was successful
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
Received packet NOOP data 
Received packet MESSAGE data 0{"sid":"ciU5d4hLxojrTuISAAAB"}
Namespace / is connected
Emitting event "message" [/]
Sending packet MESSAGE data 2["message","Hello server"]
connection established
Waiting for write loop task to end
packet queue is empty, aborting
Exiting write loop task
Engine.IO connection dropped
Exiting read loop task
Connection failed, new attempt in 0.65 seconds
disconnected from server

[miguelgrinberg]

@cetteup Okay, I did find something wrong in the asyncio client reconnects. Your examples apps were useful, thanks for spending the time and creating them.

With the fix applied in this repository on master the reconnection works. However, there is another related issue that I'm seeing. When the Socket.IO log in the client shows the line Waiting for write loop task to end I see a long delay of about 20 seconds before the actual reconnect attempts begin. This delay occurs with or without the fix that I have applied. Did you also see that long delay?

[cetteup]

Thank for you for pushing a fix. And yes, I can confirm the long delay.

2021-02-05 08:54:28,055 INFO    : Waiting for write loop task to end
2021-02-05 08:54:44,074 ERROR   : packet queue is empty, aborting
2021-02-05 08:54:44,074 INFO    : Exiting write loop task
2021-02-05 08:54:44,075 INFO    : Engine.IO connection dropped
2021-02-05 08:54:44,075 INFO    : Exiting read loop task
2021-02-05 08:54:44,076 INFO    : Connection failed, new attempt in 0.59 seconds
disconnected from server

[miguelgrinberg]

Thanks, I'll see if I can figure that one out as well.

[cetteup]

Thank's a lot for you work on this!

In the meantime, I just re-installed from the master branch and I can confirm that the reconnect now works as intended.