daphne icon indicating copy to clipboard operation
daphne copied to clipboard

Raised ConnectionClosedError with message "Reader at end of file"

Open ghost opened this issue 5 years ago • 8 comments

Hi,

I'm currently seeing a lot of such errors in my Daphne logs in production. I'm not fully sure if this is a generic Channels issue, a Daphne one, or more specific to channels_redis.

Exception inside application: Reader at end of file
  File "/usr/local/lib/python3.7/site-packages/channels/sessions.py", line 183, in __call__
    return await self.inner(receive, self.send)
  File "/usr/local/lib/python3.7/site-packages/channels/middleware.py", line 41, in coroutine_call
    await inner_instance(receive, send)
  File "/usr/local/lib/python3.7/site-packages/channels/consumer.py", line 59, in __call__
    [receive, self.channel_receive], self.dispatch
  File "/usr/local/lib/python3.7/site-packages/channels/utils.py", line 52, in await_many_dispatch
    await dispatch(result)
  File "/usr/local/lib/python3.7/site-packages/asgiref/sync.py", line 150, in __call__
    return await asyncio.wait_for(future, timeout=None)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 388, in wait_for
    return await fut
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.7/site-packages/channels/db.py", line 14, in thread_handler
    return super().thread_handler(loop, *args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/asgiref/sync.py", line 169, in thread_handler
    return func(*args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/channels/consumer.py", line 105, in dispatch
    handler(message)
  File "/usr/local/lib/python3.7/site-packages/channels/generic/websocket.py", line 106, in websocket_disconnect
    self.disconnect(message["code"])
  File "/project/platform/project/websockets/consumers.py", line 122, in disconnect
    async_to_sync(self.channel_layer.group_discard)(self.get_client_group(), self.channel_name)
  File "/usr/local/lib/python3.7/site-packages/asgiref/sync.py", line 79, in __call__
    return call_result.result()
  File "/usr/local/lib/python3.7/concurrent/futures/_base.py", line 432, in result
    return self.__get_result()
  File "/usr/local/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/usr/local/lib/python3.7/site-packages/asgiref/sync.py", line 95, in main_wrap
    result = await self.awaitable(*args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/channels_redis/core.py", line 599, in group_discard
    await connection.zrem(key, channel)
  File "/usr/local/lib/python3.7/site-packages/aioredis/commands/sorted_set.py", line 224, in zrem
    return self.execute(b'ZREM', key, member, *members)
  File "/usr/local/lib/python3.7/site-packages/aioredis/commands/__init__.py", line 51, in execute
    return self._pool_or_conn.execute(command, *args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/aioredis/connection.py", line 319, in execute
    raise ConnectionClosedError(msg)
  Reader at end of file

The code referenced to /project/platform/project/websockets/consumers.py is:

class WSConsumer(JsonWebsocketConsumer):
    http_user_and_session = True

    def connect(self):
        if not self.scope["user"].is_authenticated:
            self.close(code="4000")
        else:
            
            async_to_sync(self.channel_layer.group_add)("user-broadcast", self.channel_name)
            super().connect()

    def disconnect(self, code):
        if self.scope["user"].is_authenticated:
            # NEXT IS LINE 122 as referenced in the error stack
            async_to_sync(self.channel_layer.group_discard)("user-broadcast", self.channel_name)
        
        super().disconnect(code)

    def ws_send(self, event):
        self.send_json(event["body"])

I'm running Daphne from supervisord behind nginx. Both nginx and Daphne are in two different Docker containers running on Kubernetes. Redis is on a separate machine (the connection is over TLS).

Python: 3.7.3 Django: 2.1.8 Daphne: 2.3.0 Channels: 2.2.0 channels_redis: 2.4.0 aioredis: 1.2.0 Redis: 5.0.5 OS: Alpine Linux 3.9 (Docker image)

In channels_redis a similar issue has been reported but discarded: https://github.com/django/channels_redis/issues/158

Any hint on what could be the root cause for this issue?

Thanks for your time.

ghost avatar May 17 '19 09:05 ghost

I am also getting this error as well.

dfitzpatrick avatar Jun 09 '19 22:06 dfitzpatrick

OK, interesting. Any chance either of you can put together a small sample project that recreated the issue (that we can run locally and see what's going on)?

carltongibson avatar Jun 11 '19 06:06 carltongibson

OK, interesting. Any chance either of you can put together a small sample project that recreated the issue (that we can run locally and see what's going on)?

Good question. I'm trying to replicate this issue in my DEV or UAT environments, but with no luck. This stil occurs in PROD, where the noticeable difference is that Redis is provided by the Azure service. In DEV and UAT is provided by the official Docker image.

This error started when I migrate to the new 2.x Channels (from 1.1.x). Also, I'm using teh very same Redis instance with Celery and the internal Django cache, yet in those cases there are no errors.

Anyway, as soon as I have a more reproducible scenario I'll post it! I hope @dfitzpatrick could be more helpful, maybe with a different stack.

ghost avatar Jun 11 '19 07:06 ghost

sometimes same error happend with all sync or async channel_layer.group_add/group_discard/group_send.

yaomengsi avatar Jun 24 '19 04:06 yaomengsi

Hi all! Getting this in my uat environment but not locally. Does anyone have any ideas?

daxaxelrod avatar Oct 23 '19 01:10 daxaxelrod

Hi all, I am also experiencing this issue in uat environment but not locally. Anyone have any ideas?

RealScatman avatar Nov 05 '19 22:11 RealScatman

I'll dig into the stack trace above this weekend :D

daxaxelrod avatar Nov 06 '19 00:11 daxaxelrod

I use Heroku to host my application, and the redis server provisioned via Heroku sets a timeout of 300 seconds (5 minutes.) I set the timeout to 0 yesterday, and have yet to experience the issue again...hope this may help some people. You can also declare the maxmemory config option as well.

RealScatman avatar Nov 07 '19 19:11 RealScatman