emmett-framework / granian

A Rust HTTP server for Python applications
BSD 3-Clause "New" or "Revised" License
2.86k stars 83 forks source link

ASGI Flow Error #186

Closed cyb3rs3ntry closed 8 months ago

cyb3rs3ntry commented 9 months ago

I am getting this error while migrating from daphne on django. I'm currently running the latest build 1.0.1 and django 5.0

I'm running a chatroom that uses channels and I'm not sure if it is helpful to post my consumer.py here but I'm happy to do so if it'll help with troubleshooting.

[INFO] Starting granian (main PID: 1)
2024-01-24T19:12:16.123299427Z [INFO] Listening at: 0.0.0.0:8000
2024-01-24T19:12:16.125546970Z [INFO] Spawning worker-1 with pid: 7
2024-01-24T19:12:18.379630721Z [WARNING] ASGI Lifespan errored, continuing without Lifespan support
2024-01-24T19:12:18.381089390Z [INFO] Started worker-1
2024-01-24T19:12:18.381103932Z [INFO] Started worker-1 runtime-1
2024-01-24T19:13:29.909855016Z [WARNING] Application callable raised an exception
2024-01-24T19:13:29.918650737Z ERROR:asyncio:Task exception was never retrieved
2024-01-24T19:13:29.918670224Z future: <Task finished name='Task-42' coro=<future_watcher_wrapper.<locals>.future_watcher() done, defined at /usr/local/lib/python3.11/site-packages/granian/_futures.py:2> exception=RuntimeError('ASGI flow error')>
2024-01-24T19:13:29.918675290Z Traceback (most recent call last):
2024-01-24T19:13:29.918678650Z   File "/usr/local/lib/python3.11/site-packages/granian/_futures.py", line 4, in future_watcher
2024-01-24T19:13:29.918681599Z     await inner(watcher.scope, watcher.proto)
2024-01-24T19:13:29.918684749Z   File "/usr/local/lib/python3.11/site-packages/channels/routing.py", line 62, in __call__
2024-01-24T19:13:29.918688013Z     return await application(scope, receive, send)
2024-01-24T19:13:29.918690894Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-01-24T19:13:29.918694051Z   File "/usr/local/lib/python3.11/site-packages/channels/security/websocket.py", line 37, in __call__
2024-01-24T19:13:29.918707745Z     return await self.application(scope, receive, send)
2024-01-24T19:13:29.918711302Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-01-24T19:13:29.918714335Z   File "/usr/local/lib/python3.11/site-packages/channels/sessions.py", line 47, in __call__
2024-01-24T19:13:29.918717059Z     return await self.inner(dict(scope, cookies=cookies), receive, send)
2024-01-24T19:13:29.918719700Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-01-24T19:13:29.918722308Z   File "/usr/local/lib/python3.11/site-packages/channels/sessions.py", line 263, in __call__
2024-01-24T19:13:29.918725540Z     return await self.inner(wrapper.scope, receive, wrapper.send)
2024-01-24T19:13:29.918728632Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-01-24T19:13:29.918731199Z   File "/usr/local/lib/python3.11/site-packages/channels/auth.py", line 185, in __call__
2024-01-24T19:13:29.918734349Z     return await super().__call__(scope, receive, send)
2024-01-24T19:13:29.918736928Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-01-24T19:13:29.918739884Z   File "/usr/local/lib/python3.11/site-packages/channels/middleware.py", line 24, in __call__
2024-01-24T19:13:29.918742625Z     return await self.inner(scope, receive, send)
2024-01-24T19:13:29.918745154Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-01-24T19:13:29.918747701Z   File "/usr/local/lib/python3.11/site-packages/channels/routing.py", line 116, in __call__
2024-01-24T19:13:29.918750409Z     return await application(
2024-01-24T19:13:29.918752920Z            ^^^^^^^^^^^^^^^^^^
2024-01-24T19:13:29.918755415Z   File "/usr/local/lib/python3.11/site-packages/channels/consumer.py", line 94, in app
2024-01-24T19:13:29.918758537Z     return await consumer(scope, receive, send)
2024-01-24T19:13:29.918761138Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-01-24T19:13:29.918764763Z   File "/usr/local/lib/python3.11/site-packages/channels/consumer.py", line 58, in __call__
2024-01-24T19:13:29.918768297Z     await await_many_dispatch(
2024-01-24T19:13:29.918770914Z   File "/usr/local/lib/python3.11/site-packages/channels/utils.py", line 57, in await_many_dispatch
2024-01-24T19:13:29.918773618Z     await task
2024-01-24T19:13:29.918776565Z RuntimeError: ASGI flow error

Funding

Fund with Polar

gi0baro commented 9 months ago

@cyb3rs3ntry ASGIFlowError usually means Granian received an unexpected event from the framework/application. Looking at channels source code it seems the issue is related with closing the connection. I never used channels package, so if you're able to provide some code (even stripped) to replicate the issue that would be nice, as it would make it easier to debug the event flow producing the issue.

cyb3rs3ntry commented 9 months ago

@cyb3rs3ntry ASGIFlowError usually means Granian received an unexpected event from the framework/application. Looking at channels source code it seems the issue is related with closing the connection. I never used channels package, so if you're able to provide some code (even stripped) to replicate the issue that would be nice, as it would make it easier to debug the event flow producing the issue.

I don't mind sharing my code at all - a lot of it is from the channels async docs. Here is my full chat consumer which has the recommended way to disconnect per the docs (I believe)

import json
from dataclasses import dataclass

from channels.db import database_sync_to_async
from channels.generic.websocket import AsyncWebsocketConsumer

from apps.chat.tasks import save_message_to_db

@dataclass
class MessageModel:
    sender: str
    message: str
    avatar: str
    level: int

class ChatConsumer(AsyncWebsocketConsumer):
    async def connect(self):
        self.room_name = self.scope["url_route"]["kwargs"]["room_name"]
        self.room_group_name = "chat_%s" % self.room_name

        # Join room group
        await self.channel_layer.group_add(self.room_group_name, self.channel_name)

        await self.accept()
        # Retrieve last 10 messages from database

        last_messages = []
        messages = await self.get_last_messages()

        if messages:
            for message in messages:
                message = MessageModel(**message)
                last_messages.append(
                    {
                        "sender": message.sender,
                        "message": message.message,
                        "avatar": message.avatar,
                        "level": message.level,
                    }
                )

            # Send last 10 messages to the client
            await self.send_last_messages(last_messages)

    async def disconnect(self, code):
        # Leave room group
        await self.channel_layer.group_discard(self.room_group_name, self.channel_name)

    async def receive(self, text_data):
        text_data_json = json.loads(text_data)
        message = text_data_json["message"]
        sender = text_data_json["username"]
        avatar = text_data_json["avatar"]
        level = text_data_json["level"]

        # Send message to room group
        await self.save_data_item(sender, message, self.room_name)
        await self.channel_layer.group_send(
            self.room_group_name,
            {
                "type": "chat_message",
                "message": message,
                "sender": sender,
                "avatar": avatar,
                "level": level,
            },
        )

    async def chat_message(self, event):
        message = event["message"]
        sender = event["sender"]
        avatar = event["avatar"]
        level = event["level"]

        # Send message to WebSocket
        await self.send(
            text_data=json.dumps(
                {
                    "message": message,
                    "sender": sender,
                    "avatar": avatar,
                    "level": level,
                }
            )
        )

    @database_sync_to_async
    def create_data_item(self, sender_name, content):
        from apps.chat.models import Message
        from apps.users.models import CustomUser

        sender = CustomUser.objects.get(username=sender_name)
        return Message.objects.create(sender=sender, content=content, room="lobby")

    async def save_data_item(self, sender, message, room):
        save_message_to_db.delay(sender, message, room)

    @database_sync_to_async
    def get_last_messages(self):
        from apps.chat.models import Message

        messages = Message.objects.order_by("-created_at")[:10][::-1]
        return [
            {
                "sender": message.sender.username,
                "message": message.content,
                "avatar": message.sender.avatar,
                "level": message.sender.level,
            }
            for message in messages
        ]

    async def send_last_messages(self, messages):
        await self.send(text_data=json.dumps({"last_messages": messages}))
cyb3rs3ntry commented 9 months ago

Unsure if this is exactly related, but I see this message a couple times before I see the ASGI Flow error

2024-01-25 11:22:51.488 | INFO     | apps.payment_gateway.api:get_or_create_deposit:214 - Existing payment found
2024-01-25T11:22:52.872675021Z [WARNING] Application callable raised an exception
2024-01-25T11:22:52.874553539Z ERROR:asyncio:Task exception was never retrieved
2024-01-25T11:22:52.874676040Z future: <Task finished name='Task-391' coro=<future_watcher_wrapper.<locals>.future_watcher() done, defined at /usr/local/lib/python3.11/site-packages/granian/_futures.py:2> exception=RequestAborted()>
2024-01-25T11:22:52.874694077Z Traceback (most recent call last):
2024-01-25T11:22:52.874700130Z   File "/usr/local/lib/python3.11/site-packages/granian/_futures.py", line 4, in future_watcher
2024-01-25T11:22:52.874705713Z     await inner(watcher.scope, watcher.proto)
2024-01-25T11:22:52.874709665Z   File "/usr/local/lib/python3.11/site-packages/channels/routing.py", line 62, in __call__
2024-01-25T11:22:52.874713764Z     return await application(scope, receive, send)
2024-01-25T11:22:52.874717998Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-01-25T11:22:52.874721916Z   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/django/asgi.py", line 80, in sentry_patched_asgi_handler
2024-01-25T11:22:52.874726605Z     return await middleware(scope, receive, send)
2024-01-25T11:22:52.874730892Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-01-25T11:22:52.874734150Z   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/asgi.py", line 146, in _run_asgi3
2024-01-25T11:22:52.874737959Z     return await self._run_app(scope, receive, send, asgi_version=3)
2024-01-25T11:22:52.874740848Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-01-25T11:22:52.874782544Z   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/asgi.py", line 241, in _run_app
2024-01-25T11:22:52.874788527Z     raise exc from None
2024-01-25T11:22:52.874792605Z   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/asgi.py", line 234, in _run_app
2024-01-25T11:22:52.874797373Z     return await self.app(
2024-01-25T11:22:52.874800509Z            ^^^^^^^^^^^^^^^
2024-01-25T11:22:52.874804549Z   File "/usr/local/lib/python3.11/site-packages/django/core/handlers/asgi.py", line 170, in __call__
2024-01-25T11:22:52.874808847Z     await self.handle(scope, receive, send)
2024-01-25T11:22:52.874813321Z   File "/usr/local/lib/python3.11/site-packages/django/core/handlers/asgi.py", line 220, in handle
2024-01-25T11:22:52.874817702Z     await task
2024-01-25T11:22:52.874821640Z   File "/usr/local/lib/python3.11/site-packages/django/core/handlers/asgi.py", line 230, in listen_for_disconnect
2024-01-25T11:22:52.874825274Z     raise RequestAborted()
2024-01-25T11:22:52.874828870Z django.core.exceptions.RequestAborted
cyb3rs3ntry commented 9 months ago

any other information I can do to help here? Should I create a basic app in docker? Also I just noticed it happens every ~65 seconds with no requests on the frontend

gi0baro commented 9 months ago

any other information I can do to help here? Should I create a basic app in docker? Also I just noticed it happens every ~65 seconds with no requests on the frontend

I'm running some tests locally on the websocket protocol implementation, will update you as soon as I have news.

gi0baro commented 9 months ago

@cyb3rs3ntry so, I'm going to merge #193 and release a new patch version.

Unfortunately, I'm not sure this is gonna solve everything regarding channels, as from my local tests there's still some random strange behaviours happening sometimes (futures left pending and never fully awaited, random cancels I don't fully understand where coming from, etc). I'm not sure if this depends on my local setup, or is there something I can't see right now, so I'm gonna keep this opened as further investigations might be needed.

cyb3rs3ntry commented 9 months ago

Sounds good - I'm happy to help however I can. I definitely want to see this project continue to evolve and succeed.

I'll continue to use granian in development and daphne for production while we continue to make improvements to granian. 💪

ameyer117 commented 9 months ago

I am also seeing the ASGI Lifespan errored, continuing without Lifespan support warning with Granian 1.02 & Django 5.0.2. Although, I can say I am not using Channels. Happy to help where I can to troubleshoot this one.

gi0baro commented 9 months ago

I am also seeing the ASGI Lifespan errored, continuing without Lifespan support warning with Granian 1.02 & Django 5.0.2. Although, I can say I am not using Channels. Happy to help where I can to troubleshoot this one.

Lifespan is not related to this issue, that message from Granian is just to let you know Django doesn't support lifespan in ASGI, serving the application still works. See also https://github.com/emmett-framework/granian/issues/153

ameyer117 commented 9 months ago

I am also seeing the ASGI Lifespan errored, continuing without Lifespan support warning with Granian 1.02 & Django 5.0.2. Although, I can say I am not using Channels. Happy to help where I can to troubleshoot this one.

Lifespan is not related to this issue, that message from Granian is just to let you know Django doesn't support lifespan in ASGI, serving the application still works. See also #153

Ooops, sorry I probably should have expected Django to not support Lifespan. Thanks for the quick reply!

gi0baro commented 9 months ago

@cyb3rs3ntry would you be able to test this with 1.1.0 and report what's the status?

gi0baro commented 8 months ago

Closing this for inactivity, feel free to open a new issue once tested with latest Granian version