Task was destroyed but it is pending! After "harsh" disconnecting the client

Questions and Help
#1

I have a problem after updating sanic to version 22.12.0.

I use this code to connect clients via ws:

server

...
server.add_websocket_route(serve, '/ws')
...

serve

async def serve(request: Request, ws: Websocket):
    token = request.args.get('jwt', None)
    try:
        payload = jwt.decode(token, JWT_SECRET, algorithms=['HS256'])
    except InvalidTokenError:
        raise UserUnauthorizedException()
    user_id = payload['id']
    await service.register(ws, user_id)
    while True:
        try:
            data = await ws.recv()
            print(f'Received {user_id}: ' + data)
        except asyncio.CancelledError:
            await service.unregister(user_id, ws)
            break
    await ws.close()

service

USERS: typing.Dict[int, typing.Set[Websocket]] = dict()


async def register(ws: Websocket, user_id):
    if user_id not in USERS:
        connections_set = set()
        USERS[user_id] = connections_set
        connections_set.add(ws)
    else:
        USERS[user_id].add(ws)
    logger.info(f'Connect user {user_id}, connections {len(USERS[user_id])}, task {asyncio.current_task().get_name()}')


async def unregister(user_id, ws: Websocket):
    if user_id in USERS:
        USERS[user_id].remove(ws)
        if len(USERS[user_id]) == 0:
            del USERS[user_id]
    logger.info(f'Disconnect user {user_id}, connections {len(USERS[user_id]) if user_id in USERS else 0} {asyncio.current_task().get_name()}')

In some cases, the following entries appear in my logs:

Task was destroyed but it is pending!
task: <Task pending name='Task-10' coro=<WebsocketFrameAssembler.get() done, defined at <workspace_dir>/venv/lib/python3.9/site-packages/sanic/server/websockets/frame.py:91> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fc9c8230e20>()]>>

These entries do not cause the application to crash and in general it works fine, but I would like to eliminate the cause of their appearance.

I think I have identified a pattern - this happens when the client disconnects the “harsh” way. For example, closes the browser tab.

I added await ws.close() at the end of the serve method, hoping it would help, but nothing has changed.

I also added a debug log with the task name asyncio in the hope that it would help me understand something, but, for the following example, tasks 10, 16 and 22 were not logged when client was connecting and disconnecting, so it only confused me.

[2023-02-09 17:11:02] - [73633][Ws][sanic.root][INFO]: connection open
[2023-02-09 17:11:02] - [73633][Ws][sanic.root.ws.service][INFO]: Connect user 1, connections 1, task Task-9
[2023-02-09 17:11:03] - [73633][Ws][sanic.root.ws.service][INFO]: Disconnect user 1, connections 0 Task-9
[2023-02-09 17:11:05] - [73633][Ws][sanic.root][INFO]: connection open
[2023-02-09 17:11:05] - [73633][Ws][sanic.root.ws.service][INFO]: Connect user 1, connections 1, task Task-15
[2023-02-09 17:11:06] - [73633][Ws][sanic.root.ws.service][INFO]: Disconnect user 1, connections 0 Task-15
[2023-02-09 17:11:07] - [73633][Ws][sanic.root][INFO]: connection open
[2023-02-09 17:11:07] - [73633][Ws][sanic.root.ws.service][INFO]: Connect user 1, connections 1, task Task-21
[2023-02-09 17:11:08] - [73633][Ws][sanic.root.ws.service][INFO]: Disconnect user 1, connections 0 Task-21
[2023-02-09 17:11:09] - [73633][Ws][sanic.root][INFO]: connection open
[2023-02-09 17:11:09] - [73633][Ws][sanic.root.ws.service][INFO]: Connect user 1, connections 1, task Task-27
[2023-02-09 17:11:10] - [73633][Ws][sanic.root.ws.service][INFO]: Disconnect user 1, connections 0 Task-27
[2023-02-09 17:11:11] - [73633][Ws][sanic.root][INFO]: connection open
[2023-02-09 17:11:11] - [73633][Ws][sanic.root.ws.service][INFO]: Connect user 1, connections 1, task Task-33
Task was destroyed but it is pending!
task: <Task pending name='Task-10' coro=<WebsocketFrameAssembler.get() done, defined at <workspace_dir>/venv/lib/python3.9/site-packages/sanic/server/websockets/frame.py:91> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fc9c8230e20>()]>>
Task was destroyed but it is pending!
task: <Task pending name='Task-16' coro=<WebsocketFrameAssembler.get() done, defined at <workspace_dir>/venv/lib/python3.9/site-packages/sanic/server/websockets/frame.py:91> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fc9c7daae20>()]>>
Task was destroyed but it is pending!
task: <Task pending name='Task-22' coro=<WebsocketFrameAssembler.get() done, defined at <workspace_dir>/venv/lib/python3.9/site-packages/sanic/server/websockets/frame.py:91> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fc9c7daa130>()]>>

To reproduce the problem locally, I used such a script on node.js interrupting it with Ctrl+C after startup.

const Websocket = require('ws')

const ws = new Websocket('ws://localhost:11000/ws?jwt=...')

ws.on('open', function open() {
  console.log('Open')
})

After a while, this log appeared.

#2

This is a known, ongoing problem with handling websockets on the backend. I’m somewhat surprised it wasn’t present in 22.6.

The problem: closing a websocket does not come with a signal from the client unless that’s self implemented, so like your websocket client sending a message that it is going to close, and then you perform cleanup after capturing that message.

If you simply close the websocket, the only way the server has to detect it is that the communication on the socket is rejected, which throws an exception. If you’re not capturing the exception and performing cleanup there (and even if you do) you may have tasks waiting that won’t(can’t) be returned which then causes the task to be destroyed.

It’s ugly, and it’s problematic, and ultimately it’s kind of a non-issue other than the logging cruft so long as you handle the closed websocket whether it was closed in an expected manner or not.

#3

To add, as always, Sanic’s websocket support is built on websockets, and it’s worth reviewing the documentation here: Getting started - websockets 10.4 documentation

#4
  1. I cannot reproduce this.
  2. I am not sure what the known problem is that @sjsadowski is referring to.
  3. Get rid of the ws.close. You do not need that.

Your endpoint should generally look like this:

@app.websocket("/")
async def handler(request: Request, ws):
    try:
        ...
        await service.register(ws, user_id)
        while True:
                data = await ws.recv()
    finally:
        await service.unregister(user_id, ws)