Channels: Daphne freezes on some ws disconnects

[yspreen]

python 3.8
channels==2.3.1
channels-redis==2.4.1
daphne==2.4.0
Django==2.2.8

Entrypoint is daphne on alpine linux.
Consumer is quite simple:

class Consumer(AsyncWebsocketConsumer):
    async def connect(self):
        self.user = self.scope["user"]
        self.name = self.scope["url_route"]["kwargs"]["name"]
        # this line is changed by different subclasses
        self.group_name = "%s%s" % ("chat-", self.name)

        await self.accept()
        # Join group
        await self.channel_layer.group_add(self.group_name, self.channel_name)

        if not True: # auth check
            await self.send(text_data="not authorized")
            await self.close()

    # Receive message from group
    async def m(self, event):
        message = event["m"]

        # Send message to WebSocket
        await self.send(text_data=json.dumps(message))

This is the error that comes up after a random amount of disconnects:

2019-12-15 15:57:32,107 WARNING  Application instance <Task pending name='Task-21465' coro=<SessionMiddlewareInstance.__call__() running at /usr/local/lib/python3.8/site-packages/channels/sessions.py:178> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /usr/local/lib/python3.8/asyncio/futures.py:357, <TaskWakeupMethWrapper object at 0x7f7ebec32910>()]>> for connection <WebSocketProtocol client=['127.0.0.1', 41380] path=b'/api/ws/chat/ddd8ce11-50d0-456a-b8d8-15a068682d1e/'> took too long to shut down and was killed.
2019-12-15 15:57:33,108 ERROR    Exception in callback AsyncioSelectorReactor.callLater.<locals>.run() at /usr/local/lib/python3.8/site-packages/twisted/internet/asyncioreactor.py:287
handle: <TimerHandle when=1090864.949068441 AsyncioSelectorReactor.callLater.<locals>.run() at /usr/local/lib/python3.8/site-packages/twisted/internet/asyncioreactor.py:287>
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/asyncio/events.py", line 81, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.8/site-packages/twisted/internet/asyncioreactor.py", line 290, in run
    f(*args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/daphne/server.py", line 275, in application_checker
    exception = application_instance.exception()
asyncio.exceptions.CancelledError

Subsequent requests, http and ws, aren't served anymore. Timeout.

Any insight into this at all is greatly appreciated!

[yspreen]

I did set capacity and ASGI_THREADS to 1000 btw, that did not fix it.

[tarikki]

I had a similar issue which was caused by the consumers not being cleaned up properly on closing and it was solved by raising StopConsumer()

def disconnect(self, close_code):
    # Leave room group
    async_to_sync(self.channel_layer.group_discard)(
        self.room_group_name,
        self.channel_name
    )
    raise StopConsumer()

You are using AsyncWebsocketConsumer where I used WebsocketConsumer, so your code might look a bit different if you want to try this.

[yspreen]

That is the code I had before. In an attempt to streamline the consumer I removed it, same issue with both versions:

class Consumer(AsyncWebsocketConsumer):
    …
    async def disconnect(self, close_code):
        # Leave group
        await self.channel_layer.group_discard(self.group_name, self.channel_name)
        raise channels.exceptions.StopConsumer()

I think this code handles server-side disconnect events only. You can call it to manually close a ws. Maybe this is what should be called in the failed auth check above (?)

Since all my tests are with correct auth and I never disconnect from serverside otherwise, this shouldn't make a difference.

Edit: I found this inside AsyncWebsocketConsumer:

class AsyncWebsocketConsumer:
    …
    async def websocket_disconnect(self, message):
        """
        Called when a WebSocket connection is closed. Base level so you don't
        need to call super() all the time.
        """
        try:
            for group in self.groups:
                await self.channel_layer.group_discard(group, self.channel_name)
        except AttributeError:
            raise InvalidChannelLayerError(
                "BACKEND is unconfigured or doesn't support groups"
            )
        await self.disconnect(message["code"])
        raise StopConsumer()

So channel_layer.group_discard and raise StopConsumer are called in the ws disconnect anyway. Making the implementation in self.disconnect redundant.

[yspreen]

Now I get this error over and over. I changed to python3.7 as an attempt to fix the issue:

2019-12-16 14:50:48,687 WARNING  Application instance <Task pending coro=<AsgiHandler.__call__() running at /usr/local/lib/python3.7/site-packages/channels/http.py:192> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /usr/local/lib/python3.7/asyncio/futures.py:348, <TaskWakeupMethWrapper object at 0x7f82bda299d0>()]>> for connection <WebRequest at 0x7f82bd999710 method=POST uri=<uri> clientproto=HTTP/1.0> took too long to shut down and was killed.

It's not even a WS endpoint. Just a regular POST.

[yspreen]

I booted up two instances of the same project, one serving HTTP one serving WS. This has solved the problem for now, but it feels like that is just a workaround.

[javier938a]

Arranqué dos instancias del mismo proyecto, una para HTTP y otra para WS. Esto ha resuelto el problema por ahora, pero parece que eso es solo una solución.
ese mismo problema tengo ahorita y no se como resolverlo...

[yspreen]

@javier938a Would you mind translating to English for the rest of us?

[javier938a]

@ javier938a ¿Le importaría traducir al inglés para el resto de nosotros?
upss! Sorry, how to translate the page, I did not remember that it was in English,
I was saying that I have the same disconnection problem right now and there is no way to solve
this shot me......

Application instance <Task pending name='Task-10' coro=<SessionMiddlewareInstance.__call__() running at /home/javier/python-project/el_chat/env/lib/python3.8/site-packages/channels/sessions.py:183> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /usr/local/lib/python3.8/asyncio/futures.py:360, <TaskWakeupMethWrapper object at 0x7fded83d2c40>()]>> for connection <WebSocketProtocol client=['127.0.0.1', 35092] path=b'/ws/chat/hola/'> took too long to shut down and was killed.
Exception in callback AsyncioSelectorReactor.callLater.<locals>.run() at /home/javier/python-project/el_chat/env/lib/python3.8/site-packages/twisted/internet/asyncioreactor.py:287
handle: <TimerHandle when=11268.495661238 AsyncioSelectorReactor.callLater.<locals>.run() at /home/javier/python-project/el_chat/env/lib/python3.8/site-packages/twisted/internet/asyncioreactor.py:287>
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/asyncio/events.py", line 81, in _run
    self._context.run(self._callback, *self._args)
  File "/home/javier/python-project/el_chat/env/lib/python3.8/site-packages/twisted/internet/asyncioreactor.py", line 290, in run
    f(*args, **kwargs)
  File "/home/javier/python-project/el_chat/env/lib/python3.8/site-packages/daphne/server.py", line 275, in application_checker
    exception = application_instance.exception()
asyncio.exceptions.CancelledError

[yspreen]

The logs' formatting is a bit hard to read. But nonetheless, I don't think there's a real solution for this (yet).

As stated above, this worked for me:

I booted up two instances of the same project, one serving HTTP one serving WS. This has solved the problem for now, but it feels like that is just a workaround.

[javier938a]

The logs' formatting is a bit hard to read. But nonetheless, I don't think there's a real solution for this (yet).

As stated above, this worked for me:

I booted up two instances of the same project, one serving HTTP one serving WS. This has solved the problem for now, but it feels like that is just a workaround.

So I can't implement chat with channels? so what other appi can i use?

[carltongibson]

Were either of you able to reproduce this in a minimal example? The description doesn't really say very much...—difficult to know what the issue is or where to address it. A sample project with reproduce steps would be ideal.

[ShaheedHaque]

I believe I just saw an instance of this, also on a regular HTTP GET request. Interestingly, this endpoint is easily the slowest we have, taking quite a few seconds to respond, and just before the traceback, there was WARNING level log message about the processing taking too long, and being timedout:

2020-08-25 08:15:10,901 [WARNING] daphne.server: Application instance <Task pending name='Task-15823' coro=<AsgiHandler.__call__() running at /usr/local/lib/python3.8/dist-packages/channels/http.py:192> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /usr/lib/python3.8/asyncio/futures.py:360, <TaskWakeupMethWrapper object at 0x7f8d504abfd0>()]>> for connection <WebRequest at 0x7f8d5c547ee0 method=GET uri=/paiyroll/m/ee/11498/mydocuments?employment=2018-07-28&tax_year=2018 clientproto=HTTP/1.1> took too long to shut down and was killed.

I accidentally got rid of the VM involved before I managed to record the traceback, but it was similar to the two above.

It is also worth saying that the test which encountered this has run many times with just this one failure, so a repro will be tricky.

[i6mi6]

Still having this problem with 2.4.2 after trying all of the proposed solutions in the current and other similar issues. Any other ideas?

[Genarito]

I've solved the problem updating my Redis server and dependencies. My final versions are:

• Python: 3.8.5 or 3.8.6 (both tested)
• Redis: 6.0.8
• Dependencies:

channels==2.4.0
channels-redis==3.1.0
daphne==2.5.0
Django==3.1.2
django-filter==2.4.0
djangorestframework==3.12.1

Hope it helps

[adrzystek]

I can confirm @Genarito's words, I had the same issue while on Python 3.8.2 but it was enough to upgrade channels (in my case from 2.3.0 to 2.4.0) and channels-redis (2.4.0 -> 3.1.0) packages.

[jihoon796]

I'm having the same issues even using the dependencies provided by @Genarito. The only difference is that I'm using Django 2.2 though - everything else is the same (Python 3.8.6 & Redis 6.0.8).

[Genarito]

@jihoon796 have you tried updating Django? Probably it's the main problem

[adrzystek]

While I can't advise against upgrading Django package, I'd like to note that I myself have its 2.2 version as well.

My full stack of relevant libraries:

aioredis==1.3.1
asgiref==3.2.10
channels==2.4.0
channels-redis==3.1.0
daphne==2.3.0
Django==2.2.5

python:3.8.2
redis:5.0.8

[jihoon796]

@Genarito I'm not able to update Django due to work considerations, but I did finally get things to work on Django 2.2.

This no longer throws the exception:

asyncio.exceptions.CancelledError

@adrzystek here's the dependency stack that finally worked for me:

aioredis==1.3.1
asgiref==3.2.10
channels==2.3.1
channels-redis==2.4.1
daphne==2.5.0
Django==2.2

python: 3.8.6
redis: 6.0.8 (also tested on 5.0.6)

Thanks for all your help!

[Genarito]

Good to read that!! :D

[jihoon796]

This configuration also worked for me - this uses the latest version of Django 2.2:

aioredis==1.3.1
asgiref==3.2.10
channels==3.0.3
channels-redis==3.2.0
daphne==3.0.1
Django==2.2.17

[yspreen]

I'm no longer working on the project where I first encountered the issues. Hard for me to say if this is closed or not. Might I consider we wait until I work on another channels project and try one instance for both HTTP and WS this time? ;)

[yspreen]

I'll just assume it's fixed and re-open when I encounter it again. Thanks for all the responses