503 in the middle of long requests #746

lightninglu10 · 2017-09-20T23:09:19Z

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?

andrewgodwin · 2017-09-20T23:12:58Z

503 just means your server didn't return a response in time - the Daphne HTTP timeout is 60 seconds by default, I think, as nearly all sites should respond faster than that. You can increase it with command line options if you really want.

lightninglu10 · 2017-09-20T23:15:24Z

Oh, is there any documentation on here for this? The default django timeout is 300s https://docs.djangoproject.com/en/1.11/ref/settings/ and so Daphne isn't using this?

How do I set the one for Daphne?

andrewgodwin · 2017-09-20T23:17:31Z

There's no specific documentation but daphne --help will tell you what it is (--http-timeout). Django does not have a HTTP timeout setting as far as I know - the only timeouts it has are for caches and email.

lightninglu10 · 2017-09-20T23:20:07Z

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

andrewgodwin · 2017-09-20T23:21:49Z

Oh, you mean the runserver argument. We should honour that but we don't right now, you'll have to run daphne separately if you want to set it.

lightninglu10 · 2017-09-20T23:23:06Z

See above comment, the help method of python manage.py runserver --help outputs that, it sets the daphne interval right?

andrewgodwin · 2017-09-20T23:36:08Z

Oh maybe it does. I forget.

bastbnl · 2018-02-03T23:37:23Z

Do I need to do additional steps for channels 2? Each websocket connection ran through channels 2 is terminated with a 503 error after ~60 seconds. I use accept() (or close())

andrewgodwin · 2018-02-04T00:24:03Z

A 503 error code is not something emitted by Channels - what are you running it behind? Are you sure it can pass WebSocket connections correctly? Have you tried connecting to Daphne directly and seeing what happens?

bastbnl · 2018-02-04T09:25:13Z

I start channels using the Django development server using manage.py runserver 0:8000. I used to run like this for development on channels 1 - which worked properly. I can see the websocket network requests from Chrome and I can see the websocket request being accepted by channels:

...
[2018/02/04 09:05:24] WebSocket DISCONNECT /async/signals/ [84.xx.xxx.xxx:50556]
[2018/02/04 09:05:27] WebSocket HANDSHAKING /async/signals/ [84.xx.xxx.xxx:50573]
---> sending accepting
[2018/02/04 09:05:27] WebSocket CONNECT /async/signals/ [84.xx.xxx.xxx:50573]
[2018/02/04 09:06:28] HTTP GET /async/signals/ 503 [60.96, 84.xx.xxx.xxx:50573]
...

Chrome 63.0.3239.132 then reports WebSocket connection to 'ws://dev.brwnppr.com:8000/async/signals/' failed: Invalid frame header in the console.

The websocket at the server:

class UserSignalConsumer(WebsocketConsumer):
    def connect(self):
        # ...'url_route': {'kwargs': {}, 'args': ()}, 'type': 'websocket'}
        requesting_user = self.scope['user']
        if requesting_user.is_anonymous:
            self.close()
        else:
            .... 
            self.accept()

I'm using Python 3.5.3 with:

...
Django==2.0.2
daphne==2.0.1
channels==2.0.0
channels-redis==2.0.1
aioredis==1.0.0
asgiref==2.1.1
...

No errors when starting runserver:

Performing system checks...

System check identified no issues (0 silenced).
February 04, 2018 - 09:19:02
Django version 2.0.2, using settings 'brownpapersession.settings'
Starting ASGI/Channels development server at http://0:8000/
Quit the server with CONTROL-C.
2018-02-04 09:19:02,794 - INFO - server - HTTP/2 support not enabled (install the http2 and tls Twisted extras)
2018-02-04 09:19:02,795 - INFO - server - Listening on endpoint tcp:port=8000:interface=0

bastbnl · 2018-02-04T09:42:43Z

Same behavior from edge btw. And Chrome 64.0.3282.140.

No difference when I start python manage.py runworker websocket

Also does not work when I start it using daphne: daphne -p 8000 -b 0.0.0.0 brownpapersession.asgi:application including a different runworker. Timeout is set to 2 minutes though

Using a different protocol in the URL scheme (ws vs http) does not make a difference. You can tell it's a development server due to the missing s

dvl · 2018-02-04T16:04:26Z

I'm facing the same issue on Firefox

❯ daphne dconexoes.asgi:application
2018-02-04 02:39:05,534 INFO     Starting server at tcp:port=8000:interface=127.0.0.1
2018-02-04 02:39:05,535 INFO     HTTP/2 support not enabled (install the http2 and tls Twisted extras)
2018-02-04 02:39:05,535 INFO     Listening on endpoint tcp:port=8000:interface=127.0.0.1
127.0.0.1:55047 - - [04/Feb/2018:02:39:08] "WSCONNECTING /lances/" - -
127.0.0.1:55047 - - [04/Feb/2018:02:39:08] "WSCONNECT /lances/" - -
127.0.0.1:55047 - - [04/Feb/2018:02:41:09] "GET /lances/" 503 468
127.0.0.1:55047 - - [04/Feb/2018:02:41:09] "WSDISCONNECT /lances/" - -
127.0.0.1:55067 - - [04/Feb/2018:02:41:11] "WSCONNECTING /lances/" - -
127.0.0.1:55067 - - [04/Feb/2018:02:41:11] "WSCONNECT /lances/" - -
127.0.0.1:55067 - - [04/Feb/2018:02:43:13] "GET /lances/" 503 468
127.0.0.1:55067 - - [04/Feb/2018:02:43:13] "WSDISCONNECT /lances/" - -

andrewgodwin · 2018-02-04T19:22:58Z

Invalid frame header is the only thing here that's a giveaway to what it might be so far, but I'm finding this really hard to replicate. However, enough people have the issue now that it's definitely not a deployment issue, so reopening this.

Can I get people who have failing code to paste me what the consumer they're trying to connect to looks like?

UweM · 2018-02-04T19:53:10Z

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

andrewgodwin · 2018-02-04T20:01:25Z

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.

tsiaGeorge · 2018-02-04T20:06:22Z

I tried various ways and I have the http time out issue as well.

The simplest example is to use the Websocket consumer directly in routing.py

from channels.generic.websocket import WebsocketConsumer
from channels.routing import ProtocolTypeRouter, URLRouter
from django.urls import path

application = ProtocolTypeRouter({
    "websocket":
        URLRouter([
            path('test/', WebsocketConsumer)
        ])
})

andrewgodwin · 2018-02-04T20:14:07Z

This should be fixed by django/daphne@105e1d5. I'll do a daphne release momentarily.

tsiaGeorge · 2018-02-04T20:27:07Z

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

andrewgodwin · 2018-02-04T20:28:12Z

Released in daphne 2.0.2. Sorry for the oversight everyone!

ianjw11 · 2018-03-27T04:06:36Z

I'm still getting this on channels 2.0.2 and Daphne 2.1.0. My websocket connections are being closed after HTTP timeout seconds with invalid frame header.

em1208 · 2018-05-24T09:32:35Z

@ianjw11 I encountered the same issue and it was solved by setting --http-timeout in daphne.

jobelenus · 2018-06-20T21:43:38Z

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)

andrewgodwin · 2018-06-21T02:33:50Z

Afraid not, the 1.x and 2.x codebases are different enough that it'd be too much work for the small team we have to fix. Plus, Daphne 1.x has way more code paths that can make 503 errors because of the fact it doesn't run applications internally, so it might not even be the same root cause. Sorry.

stanchak · 2018-10-12T23:17:43Z

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)

Did you ever find a work around w/ 1.x?

jobelenus · 2018-10-12T23:19:50Z

No. I need to check on the state of the middleware bug that’s preventing us from upgrading

…

On Fri, Oct 12, 2018 at 7:17 PM Christopher Stanchak < ***@***.***> wrote: 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) Did you ever find a work around w/ 1.x? — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#746 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAEPpeaONzzlppEfwLQjMofluqbFX5W_ks5ukSMegaJpZM4Pel-q> .

SohanTirpude · 2020-08-03T08:02:08Z

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

using --http_timeout argument while running runserver gives me an error error: unrecongnised arguments. Is it because I am using django version 3.0.3?

wynshiter · 2023-03-02T17:17:21Z

face the similar problem
#1981

carltongibson · 2023-03-02T17:34:27Z

@wynshiter please stop cross-posting your issue on other threads.

andrewgodwin closed this as completed Sep 20, 2017

andrewgodwin reopened this Feb 4, 2018

andrewgodwin added bug blocked/user-response exp/intermediate labels Feb 4, 2018

This was referenced Feb 4, 2018

Bug issue with upgrading http to websocket django/daphne#158

Closed

http timeout after successful websocket connection django/daphne#159

Closed

andrewgodwin closed this as completed Feb 4, 2018

django temporarily blocked wynshiter Mar 2, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

503 in the middle of long requests #746

503 in the middle of long requests #746

lightninglu10 commented Sep 20, 2017 •

edited

andrewgodwin commented Sep 20, 2017

lightninglu10 commented Sep 20, 2017

andrewgodwin commented Sep 20, 2017

lightninglu10 commented Sep 20, 2017 •

edited

andrewgodwin commented Sep 20, 2017

lightninglu10 commented Sep 20, 2017

andrewgodwin commented Sep 20, 2017

bastbnl commented Feb 3, 2018 •

edited

andrewgodwin commented Feb 4, 2018

bastbnl commented Feb 4, 2018 •

edited

bastbnl commented Feb 4, 2018 •

edited

dvl commented Feb 4, 2018

andrewgodwin commented Feb 4, 2018

UweM commented Feb 4, 2018

andrewgodwin commented Feb 4, 2018

tsiaGeorge commented Feb 4, 2018

andrewgodwin commented Feb 4, 2018

tsiaGeorge commented Feb 4, 2018 •

edited

andrewgodwin commented Feb 4, 2018

ianjw11 commented Mar 27, 2018

em1208 commented May 24, 2018

jobelenus commented Jun 20, 2018

andrewgodwin commented Jun 21, 2018

stanchak commented Oct 12, 2018

jobelenus commented Oct 12, 2018 via email

SohanTirpude commented Aug 3, 2020

wynshiter commented Mar 2, 2023

carltongibson commented Mar 2, 2023

503 in the middle of long requests #746

503 in the middle of long requests #746

Comments

lightninglu10 commented Sep 20, 2017 • edited

andrewgodwin commented Sep 20, 2017

lightninglu10 commented Sep 20, 2017

andrewgodwin commented Sep 20, 2017

lightninglu10 commented Sep 20, 2017 • edited

andrewgodwin commented Sep 20, 2017

lightninglu10 commented Sep 20, 2017

andrewgodwin commented Sep 20, 2017

bastbnl commented Feb 3, 2018 • edited

andrewgodwin commented Feb 4, 2018

bastbnl commented Feb 4, 2018 • edited

bastbnl commented Feb 4, 2018 • edited

dvl commented Feb 4, 2018

andrewgodwin commented Feb 4, 2018

UweM commented Feb 4, 2018

andrewgodwin commented Feb 4, 2018

tsiaGeorge commented Feb 4, 2018

andrewgodwin commented Feb 4, 2018

tsiaGeorge commented Feb 4, 2018 • edited

andrewgodwin commented Feb 4, 2018

ianjw11 commented Mar 27, 2018

em1208 commented May 24, 2018

jobelenus commented Jun 20, 2018

andrewgodwin commented Jun 21, 2018

stanchak commented Oct 12, 2018

jobelenus commented Oct 12, 2018 via email

SohanTirpude commented Aug 3, 2020

wynshiter commented Mar 2, 2023

carltongibson commented Mar 2, 2023

lightninglu10 commented Sep 20, 2017 •

edited

lightninglu10 commented Sep 20, 2017 •

edited

bastbnl commented Feb 3, 2018 •

edited

bastbnl commented Feb 4, 2018 •

edited

bastbnl commented Feb 4, 2018 •

edited

tsiaGeorge commented Feb 4, 2018 •

edited