Django, Channels, Uvicorn: "Unexpected ASGI message"

[SHxKM]

Hey all, Running channels 3.0.4, Django 3.2.

Just switched production from Daphne to guincorn with uvicorn workers (as advised here) on Heroku. So basically up until I had this in my Procfile:

web: daphne myapp.asgi:application --port $PORT --bind 0.0.0.0 -v2

web: gunicorn -k uvicorn.workers.UvicornWorker myapp.asgi:application --bind 0.0.0.0:$PORT

So far it's nice to squeeze a bit more from the server, however on the sockets layer I'm getting these exceptions whenever a websocket is closed. I'm assuming this is because both uvicorn and channels are attempting to close the websocket or something? Here are the logs and the consumer's source code follows:

Logs

2023-04-25T20:01:18.275834+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 254, in run_asgi
2023-04-25T20:01:18.275835+00:00 app[web.1]:     result = await self.app(self.scope, self.asgi_receive, self.asgi_send)
2023-04-25T20:01:18.275835+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/uvicorn/middleware/proxy_headers.py", line 78, in __call__
2023-04-25T20:01:18.275835+00:00 app[web.1]:     return await self.app(scope, receive, send)
2023-04-25T20:01:18.275836+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/routing.py", line 71, in __call__
2023-04-25T20:01:18.275836+00:00 app[web.1]:     return await application(scope, receive, send)
2023-04-25T20:01:18.275837+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/sessions.py", line 47, in __call__
2023-04-25T20:01:18.275837+00:00 app[web.1]:     return await self.inner(dict(scope, cookies=cookies), receive, send)
2023-04-25T20:01:18.275838+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/sessions.py", line 263, in __call__
2023-04-25T20:01:18.275838+00:00 app[web.1]:     return await self.inner(wrapper.scope, receive, wrapper.send)
2023-04-25T20:01:18.275838+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/auth.py", line 185, in __call__
2023-04-25T20:01:18.275839+00:00 app[web.1]:     return await super().__call__(scope, receive, send)
2023-04-25T20:01:18.275839+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/middleware.py", line 26, in __call__
2023-04-25T20:01:18.275839+00:00 app[web.1]:     return await self.inner(scope, receive, send)
2023-04-25T20:01:18.275839+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/routing.py", line 150, in __call__
2023-04-25T20:01:18.275840+00:00 app[web.1]:     return await application(
2023-04-25T20:01:18.275841+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/consumer.py", line 94, in app
2023-04-25T20:01:18.275841+00:00 app[web.1]:     return await consumer(scope, receive, send)
2023-04-25T20:01:18.275841+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/consumer.py", line 58, in __call__
2023-04-25T20:01:18.275841+00:00 app[web.1]:     await await_many_dispatch(
2023-04-25T20:01:18.275842+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/utils.py", line 51, in await_many_dispatch
2023-04-25T20:01:18.275842+00:00 app[web.1]:     await dispatch(result)
2023-04-25T20:01:18.275842+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/asgiref/sync.py", line 414, in __call__
2023-04-25T20:01:18.275842+00:00 app[web.1]:     ret = await asyncio.wait_for(future, timeout=None)
2023-04-25T20:01:18.275843+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/asyncio/tasks.py", line 442, in wait_for
2023-04-25T20:01:18.275843+00:00 app[web.1]:     return await fut
2023-04-25T20:01:18.275843+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/concurrent/futures/thread.py", line 58, in run
2023-04-25T20:01:18.275844+00:00 app[web.1]:     result = self.fn(*self.args, **self.kwargs)
2023-04-25T20:01:18.275844+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/db.py", line 13, in thread_handler
2023-04-25T20:01:18.275844+00:00 app[web.1]:     return super().thread_handler(loop, *args, **kwargs)
2023-04-25T20:01:18.275844+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/asgiref/sync.py", line 455, in thread_handler
2023-04-25T20:01:18.275844+00:00 app[web.1]:     return func(*args, **kwargs)
2023-04-25T20:01:18.275845+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/consumer.py", line 125, in dispatch
2023-04-25T20:01:18.275845+00:00 app[web.1]:     handler(message)
2023-04-25T20:01:18.275845+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/generic/websocket.py", line 105, in websocket_disconnect
2023-04-25T20:01:18.275845+00:00 app[web.1]:     self.disconnect(message["code"])
2023-04-25T20:01:18.275846+00:00 app[web.1]:   File "/app/core/consumers.py", line 25, in disconnect
2023-04-25T20:01:18.275846+00:00 app[web.1]:     self.close(code=close_code)
2023-04-25T20:01:18.275846+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/generic/websocket.py", line 87, in close
2023-04-25T20:01:18.275846+00:00 app[web.1]:     super().send({"type": "websocket.close", "code": code})
2023-04-25T20:01:18.275846+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/consumer.py", line 133, in send
2023-04-25T20:01:18.275846+00:00 app[web.1]:     self.base_send(message)
2023-04-25T20:01:18.275847+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/asgiref/sync.py", line 204, in __call__
2023-04-25T20:01:18.275847+00:00 app[web.1]:     return call_result.result()
2023-04-25T20:01:18.275847+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/concurrent/futures/_base.py", line 439, in result
2023-04-25T20:01:18.275847+00:00 app[web.1]:     return self.__get_result()
2023-04-25T20:01:18.275848+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/concurrent/futures/_base.py", line 391, in __get_result
2023-04-25T20:01:18.275848+00:00 app[web.1]:     raise self._exception
2023-04-25T20:01:18.275848+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/asgiref/sync.py", line 270, in main_wrap
2023-04-25T20:01:18.275848+00:00 app[web.1]:     result = await self.awaitable(*args, **kwargs)
2023-04-25T20:01:18.275849+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/channels/sessions.py", line 226, in send
2023-04-25T20:01:18.275849+00:00 app[web.1]:     return await self.real_send(message)
2023-04-25T20:01:18.275853+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.9/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 345, in asgi_send
2023-04-25T20:01:18.275854+00:00 app[web.1]:     raise RuntimeError(msg % message_type)
2023-04-25T20:01:18.275854+00:00 app[web.1]: RuntimeError: Unexpected ASGI message 'websocket.close', after sending 'websocket.close'.

Consumer (relevant code)

class DashboardStatsConsumer(JsonWebsocketConsumer):
    def connect(self):
        logger.info(f"{self.scope['user']} is connected via websocket")
        user_id = self.scope["user"].id
        if user_id:
            async_to_sync(self.channel_layer.group_add)(str(user_id), self.channel_name)
        self.accept()

    def disconnect(self, close_code):
        user_id = self.scope["user"].id
        if user_id:
            async_to_sync(self.channel_layer.group_discard)(str(user_id), self.channel_name)
        self.close(code=close_code)

I left the DashboardStatsConsumer untouched in the migration, should I not call self.close() when using uvicorn? if that's the culprit, how come it's been quiet with Daphne?

Or am I missing something entirely different here?

[carltongibson]

What happens if you put logging in close()? Is it being called twice? (The trace is coming from the session middleware... 🤔)

(A.k.a Can you reduce it or dig some more? — There could be anything going on from what you've put, so investigation needed.)

[SHxKM]

Thanks for the guidance @carltongibson.

What happens if you put logging in close()? Is it being called twice? (The trace is coming from the session middleware... 🤔)

Do you mean in disconnect()? close() is a base method which I'm not overriding..

[carltongibson]

I don't mean specifically in disconnect... — I mean find out what's happening. The error says websocket.close was sent twice... — so what's causing that? (A bit of print() logging should show something, one would hope.)

[SHxKM]

Hmmm, wonder if I can just get rid of this by note calling self.close() on disconnect(). Seems like too much magic, but it seems like uvicorn is closing the websocket connection before Channels' disconnect() is getting called. I can confirm disconnect() is only running once.

I can see these logs from aioredis when I don't called self.close() in disconnect(), don't know if they're related:

[2023-04-26 17:12:51 +0300] [90056] [INFO] connection closed
2023-04-26 17:12:51,888 core.consumers INFO     DashboardStatsConsumer disconnect is being called for 1
2023-04-26 17:12:51,890 aioredis     DEBUG    Cancelling waiter (<Future cancelled>, [None, None])
2023-04-26 17:12:51,892 aioredis     DEBUG    Waiter future is already done <Future cancelled>
2023-04-26 17:12:51,893 aioredis     DEBUG    Closed 1 connection(s)

[SHxKM]

So I think I found the root cause, I think.

The websockets library (utilized by asyncio, utilized by uvicorn) closes the websocket here:

https://github.com/python-websockets/websockets/blob/fe629dede6eb083013e0d2373d5c3120c0078db3/src/websockets/legacy/server.py#L257-L265

...and only then Channels disconnect() method is being called. By the time disconnect() is called, the websocket is already closed, so when we call self.close() - we get the exception.

So now the question is (@carltongibson if you can chime in that'd be great):

Is this expected? is it problematic can I safely remove self.close() from disconnect()?
How do we deal with this if at all? it seems a bit limiting that disconnect() is no longer responsible for closing the websocket, and can only respond after the websocket has been closed.

[carltongibson]

OK, so I'd have to dig in to say 100% — good hunting BTW — but from the Channels perspective what matters is that the consumer is stopped, that is, in websocket_disconnect the StopConsumer is raised.

As long as that happens, I don't see that it matter who is responsible for sending the close message out to the client.

🤔

Let me know how you get on. I feel like there's a bit more to say about this, at least in docs if nothing else (but I haven't got a lot of bandwidth to investigate it fully myself right now.)