channels: 503 in the middle of long requests

If you’re submitting a bug report, please include:

Your OS and runtime environment, and browser if applicable
The versions of Channels, Daphne, Django, Twisted, and your ASGI backend (asgi_ipc or asgi_redis normally)
What you expected to happen vs. what actually happened
How you’re running Channels (runserver? daphne/runworker? Nginx/Apache in front?)
Console logs and full tracebacks of any errors

OS: Mac OS Sierra Browser: Google Chrome Channels: 1.1.6 daphne: 1.3.0 Twisted: 17.5.0 Django: 1.11.5 ASGI Backend: asgi_redis

Running channels from just runserver, heres my redis config:

REDIS_HOST = os.environ['REDIS_HOST'] if 'REDIS_HOST' in os.environ else 'localhost'
REDIS_PORT = os.environ['REDIS_PORT'] if 'REDIS_PORT' in os.environ else 6379

CHANNEL_LAYERS = {
    "default": {
        "BACKEND": "asgi_redis.RedisChannelLayer",
        "CONFIG": {
            "hosts": [(REDIS_HOST, REDIS_PORT)],
        },
        "ROUTING": "helloDeploy.routing.channel_routing",
    },
}

so on long requests, django returns a 503 to the frontend in the middle of the request. If I set a breakpoint somewhere, then leave the breakpoint running, then a 503 is returned. I’m fairly sure that this is caused by channels somehow as this has never happened before. Anybody have any insight here?

About this issue

Original URL
State: closed
Created 7 years ago
Comments: 28 (14 by maintainers)

Most upvoted comments

So Django has its own http_timeout arg. Will setting this also set it for Daphne? If not, how would I set it for Daphne as I’m using the python manage.py runserver command?

EDIT: Nevermind, I see this here

  --http_timeout HTTP_TIMEOUT
                        Specify the daphne http_timeout interval in seconds
                        (default: 60)

So for anyone who comes across this, just run

python manage.py runserver --http_timeout=TIMEOUT

lightninglu10 on Sep 20, 2017

Aha, yes, that’s it. I didn’t twig that this was a websocket working perfectly for 60 seconds and then getting a 503 sent to it. Fixing it.

andrewgodwin on Feb 4, 2018

This should be fixed by https://github.com/django/daphne/commit/105e1d5436f007acfadfd669c2b4550ae8faf32d. I’ll do a daphne release momentarily.

andrewgodwin on Feb 4, 2018

I have the same problem with this simple echo consumer:

class Websocket(WebsocketConsumer):
    def receive(self, text_data, **kwargs):
        self.send(text_data=text_data)


application = ProtocolTypeRouter({
    "websocket": URLRouter([
        url("", Websocket)
    ])
})

and this in a browser:

    socket = new WebSocket("ws://localhost:8000");
    setInterval(function() {
        socket.send('test');
    }, 5000)

Started with “runserver -v 2”, the output is:

[2018/02/03 09:35:22] WebSocket HANDSHAKING / [127.0.0.1:49160]
2018-02-03 09:35:22,735 - DEBUG - http_protocol - Upgraded connection ['127.0.0.1', 49160] to WebSocket
2018-02-03 09:35:22,737 - DEBUG - ws_protocol - WebSocket ['127.0.0.1', 49160] open and established
[2018/02/03 09:35:22] WebSocket CONNECT / [127.0.0.1:49160]
2018-02-03 09:35:22,737 - DEBUG - ws_protocol - WebSocket ['127.0.0.1', 49160] accepted by application
2018-02-03 09:35:27,727 - DEBUG - ws_protocol - WebSocket incoming frame on ['127.0.0.1', 49160]
2018-02-03 09:35:27,729 - DEBUG - ws_protocol - Sent WebSocket packet to client for ['127.0.0.1', 49160]
[...]
2018-02-03 09:36:23,906 - DEBUG - http_protocol - HTTP 503 response started for ['127.0.0.1', 49160]
2018-02-03 09:36:23,907 - DEBUG - http_protocol - HTTP close for ['127.0.0.1', 49160]
2018-02-03 09:36:23,908 - DEBUG - http_protocol - HTTP response complete for ['127.0.0.1', 49160]
[2018/02/03 09:36:23] HTTP GET / 503 [61.18, 127.0.0.1:49160]
2018-02-03 09:36:23,911 - DEBUG - ws_protocol - WebSocket closed for ['127.0.0.1', 49160]
[2018/02/03 09:36:23] WebSocket DISCONNECT / [127.0.0.1:49160]

Somehow the “http_protocol” seems to thinks its still responsible for the connection and closes it after a timeout, i think here: https://github.com/django/daphne/blob/3b2fb6f78e7bbee887663cb64e81e735b09134ee/daphne/http_protocol.py#L236-L242

The Invalid frame header is simply because daphne responds with http while the browser expects websocket. Wireshark capture:

GET / HTTP/1.1
Host: localhost:8000
Connection: Upgrade
Upgrade: websocket
Sec-WebSocket-Version: 13
[...]
Sec-WebSocket-Key: w9uYZo2HGLIP6VIHxGP4iw==
Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits

HTTP/1.1 101 Switching Protocols
Server: Daphne
Upgrade: WebSocket
Connection: Upgrade
Sec-WebSocket-Accept: BJXShcEXxA9e2M539fPCO80ZYp8=

....U.r.&...test..[B../'.a..test....\g.}/...test....$.|.W...test............test..V..@"..4..test...c.,..wX..test.....<...H..test.....A.q.5..test.......r....test...s....e...test...2..zWe...testHTTP/1.1 503 Service Unavailable
Transfer-Encoding: chunked
Content-Type: text/html; charset=utf-8

1d4
 <html> <head> <title>503 Service Unavailable</title> <style>  body { font-family: sans-serif; margin: 0; padding: 0; }  h1 { padding: 0.6em 0 0.2em 20px; color: #896868; margin: 0; }  p { padding: 0 0 0.3em 20px; margin: 0; }  footer { padding: 1em 0 0.3em 20px; color: #999; font-size: 80%; font-style: italic; } </style> </head> <body> <h1>503 Service Unavailable</h1> <p>Application failed to respond within time limit.</p> <footer>Daphne</footer> </body> </html> 
0

..1$.R2..7Sw.1ZA.raV.&^G.>.a. ^V....

Maybe because what is stated in this comment line here looks like its never actually done? I see no code to remove the “reply channel association” after this comment https://github.com/django/daphne/blob/3b2fb6f78e7bbee887663cb64e81e735b09134ee/daphne/http_protocol.py#L119

UweM on Feb 4, 2018

Is there a backwards-compatible fix for 1.X here? I am seeing the same error there. (NB: obviously we’d love to upgrade, but we utterly failed at accounting for performance when trying it previously)

jobelenus on Jun 20, 2018

Tested and confirmed. No time out errors (503) with your latest commit.

tsiaGeorge on Feb 4, 2018