500 Error when heavy load on worker

[elineda]

Hello,

I created a server with django 3.1.4 et Channel 3.0.1 for the websocket features. At start with launch it with several worker of uvicorn and nginx.
Everythings work fine until I have more then 10 request per second on my server. I take 10% of code 500 errors. I tested it with artillery.io with a single request on start page on my project (without authentification)
I tested with many asgi worker, uvicorn, gunicorn with uvicorn class, hypercorn, daphne : same problem.

There is two exemple of errors, one with uvicorn and other with daphne

uvicorn[15055]: INFO:     127.0.0.1:44826 - "GET / HTTP/1.1" 200 OK

uvicorn[15055]: ERROR:    ASGI callable returned without starting response.
uvicorn[15055]: INFO:     127.0.0.1:44822 - "GET / HTTP/1.1" 500 Internal Server Error
uvicorn[15055]: INFO:     127.0.0.1:44830 - "GET / HTTP/1.1" 200 OK
uvicorn[15055]: ERROR:    Exception in ASGI application
uvicorn[15055]: Traceback (most recent call last):
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/uvicorn/protocols/http/httptools_impl.py", line 396, in run_asgi
uvicorn[15055]:     result = await app(self.scope, self.receive, self.send)
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/uvicorn/middleware/proxy_headers.py", line 45, in __call__
uvicorn[15055]:     return await self.app(scope, receive, send)
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/channels/routing.py", line 71, in __call__
uvicorn[15055]:     return await application(scope, receive, send)
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/channels/http.py", line 200, in __call__
uvicorn[15055]:     await self.handle(body_stream)
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/asgiref/sync.py", line 304, in __call__
uvicorn[15055]:     ret = await asyncio.wait_for(future, timeout=None)
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/lib/python3.7/asyncio/tasks.py", line 414, in wait_for
uvicorn[15055]:     return await fut
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/lib/python3.7/concurrent/futures/thread.py", line 57, in run
uvicorn[15055]:     result = self.fn(*self.args, **self.kwargs)
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/asgiref/sync.py", line 343, in thread_handler
uvicorn[15055]:     return func(*args, **kwargs)
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/channels/http.py", line 258, in handle
uvicorn[15055]:     self.send(response_message)
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/asgiref/sync.py", line 147, in __call__
uvicorn[15055]:     return call_result.result()
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/lib/python3.7/concurrent/futures/_base.py", line 428, in result
uvicorn[15055]:     return self.__get_result()
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
uvicorn[15055]:     raise self._exception
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/asgiref/sync.py", line 212, in main_wrap
uvicorn[15055]:     result = await self.awaitable(*args, **kwargs)
uvicorn[15055]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/uvicorn/protocols/http/httptools_impl.py", line 540, in send
uvicorn[15055]:     raise RuntimeError(msg % message_type)
uvicorn[15055]: RuntimeError: Unexpected ASGI message 'http.response.start' sent, after response already completed.

daphne[7052]: 2021-02-04 16:30:03,183 ERROR    Exception inside application: HTTP response has not yet been started but got http.response.body
daphne[7052]: Traceback (most recent call last):
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/channels/routing.py", line 71, in __call__
daphne[7052]:     return await application(scope, receive, send)
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/channels/http.py", line 200, in __call__
daphne[7052]:     await self.handle(body_stream)
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/asgiref/sync.py", line 304, in __call__
daphne[7052]:     ret = await asyncio.wait_for(future, timeout=None)
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/lib/python3.7/asyncio/tasks.py", line 414, in wait_for
daphne[7052]:     return await fut
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/lib/python3.7/concurrent/futures/thread.py", line 57, in run
daphne[7052]:     result = self.fn(*self.args, **self.kwargs)
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/asgiref/sync.py", line 343, in thread_handler
daphne[7052]:     return func(*args, **kwargs)
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/channels/http.py", line 258, in handle
daphne[7052]:     self.send(response_message)
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/asgiref/sync.py", line 147, in __call__
daphne[7052]:     return call_result.result()
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/lib/python3.7/concurrent/futures/_base.py", line 428, in result
daphne[7052]:     return self.__get_result()
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
daphne[7052]:     raise self._exception
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/asgiref/sync.py", line 212, in main_wrap
daphne[7052]:     result = await self.awaitable(*args, **kwargs)
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/daphne/server.py", line 233, in handle_reply
daphne[7052]:     protocol.handle_reply(message)
daphne[7052]:   File "/home/rtadmin/.pyenv/versions/3.7.9/envs/maif_conf/lib/python3.7/site-packages/daphne/http_protocol.py", line 262, in handle_reply
daphne[7052]:     % message["type"]
daphne[7052]: ValueError: HTTP response has not yet been started but got http.response.body

I work on other project without channel and I haven't these problems on it on "heavy" load. So I test a workaround.

I split my workers on two type

• The 1st where I use only the webserver part of my project
• The 2nd where I use the websocket part of it.

I use a environnement variable for tell to django to no charge channel on webserver worker

There is the code I put on my asgi.py

[...]
os.environ.setdefault("DJANGO_SETTINGS_MODULE", "configuration.settings")
django_asgi_app = get_asgi_application()
type_server = os.environ['TYPESERVER']

if type_server == 'webserver':
    application = django_asgi_app

else:
    from channels.auth import AuthMiddlewareStack
    from channels.routing import ProtocolTypeRouter, URLRouter
    import maifConf.routing

    application = ProtocolTypeRouter({
      "https": django_asgi_app,
      "websocket": AuthMiddlewareStack(
            URLRouter(
                maifConf.routing.websocket_urlpatterns
            )
        ),
    })

I tell to nginx to use websocket worker for all /ws/ request and all other in webserver ones.

After this fix I no longer use channel for http request and I have no 500 errors like this.

This is clearly a channel error, but I don't know why I have these one with doing a request on a simple page.

there is my requirements

channels==3.0.1
channels-redis==3.2.0
Django==3.1.4
django-crispy-forms==1.10.0
psycopg2==2.8.6
uvicorn[standard]==0.13.3
pyyaml==5.3.1
websockets==8.1
sib-api-v3-sdk==7.1.0

[carltongibson]

Hi. Thanks for the extra detail.

This is essentially #1587 I think.
Issue is that Django requires the thread_sensitive arg to sync_to_async.

...

For now your workaround is correct. Use WSGI for Django, adding the async channels stuff with ASGI at the side.

[elineda]

I use ASGI of django even on webserver worker I just skip channel. It's not a ASGI problème but channel one isn't ?

There is my View of start page

    async def get(self, request, *args, **kwargs):
        login_form = LoginForm
        sign_up_form = SignUpForm
        param_form = ParamForm
        # live = server_settings['LIVE']

        @sync_to_async
        def eventfunction():
            return Evenement.objects.filter(inscription_auto=True).first()
        event = await eventfunction()
        if event and event.date and event.date < timezone.now():
            event_date = True
        else:
            event_date = False
        if request.user.is_authenticated:
            [...]
        else:
            return render(request, 'index.html', {'login_form': login_form, 'sign_up_form': sign_up_form,
                                                  'event_date': event_date, 'event': event,})

[carltongibson]

Can't now reproduce. This was likely resolved by v3.0.3 https://channels.readthedocs.io/en/latest/releases/3.0.3.html

Happy to look at a sample project reproducing the issue.