Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

'WebRequest' object has no attribute 'client_addr' under Firefox #244

Closed
lfaucheux opened this issue Jan 7, 2019 · 8 comments
Closed

'WebRequest' object has no attribute 'client_addr' under Firefox #244

lfaucheux opened this issue Jan 7, 2019 · 8 comments
Labels
blocked/user-response

Comments

@lfaucheux
Copy link

lfaucheux commented Jan 7, 2019 •
edited

While instantiating a WebSocket object under Firefox64, i.e.

new WebSocket(`wss://${window.location.host}/path/to/room`);

... and having Daphne set to the highest level of verbosity, I get the following server-side error:

[07/Jan/2019:17:09:51 +0100] [upstream] [903083] STDERR: 2019-01-07 16:09:51,657 INFO     "127.0.0.1" - - [11/Mar/1970:02:49:09 +0000] "GET / HTTP/1.1" 500 27 "https://bored.alwaysdata.net/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:64.0) Gecko/20100101 Firefox/64.0"
[07/Jan/2019:17:09:51 +0100] [upstream] [903083] STDERR: 2019-01-07 16:09:51,657 DEBUG    HTTP response complete for ['127.0.0.1', 42164]
[07/Jan/2019:17:09:51 +0100] [upstream] [903083] STDERR: 2019-01-07 16:09:51,658 DEBUG    poll 622.967 ms took 0.098 ms: 1 events
[07/Jan/2019:17:09:51 +0100] [upstream] [903083] STDERR: 2019-01-07 16:09:51,658 DEBUG    poll 622.617 ms took 0.050 ms: 1 events
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR: 2019-01-07 16:09:53,819 DEBUG    poll 999.816 ms took 536.038 ms: 1 events
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR: 2019-01-07 16:09:53,819 DEBUG    poll 463.229 ms took 0.011 ms: 1 events
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR: 2019-01-07 16:09:53,820 DEBUG    poll 462.904 ms took 0.008 ms: 1 events
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR: 2019-01-07 16:09:53,821 CRITICAL Unhandled Error
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR: Traceback (most recent call last):
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/home/.virtualenvs/boredenv/lib/python3.7/site-packages/twisted/internet/asyncioreactor.py", line 267, in run
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     self._asyncioEventloop.run_forever()
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/usr/alwaysdata/python/3.7.1/lib/python3.7/asyncio/base_events.py", line 528, in run_forever
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     self._run_once()
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/usr/alwaysdata/python/3.7.1/lib/python3.7/asyncio/base_events.py", line 1756, in _run_once
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     handle._run()
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/usr/alwaysdata/python/3.7.1/lib/python3.7/asyncio/events.py", line 88, in _run
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     self._context.run(self._callback, *self._args)
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR: --- <exception caught here> ---
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/home/.virtualenvs/boredenv/lib/python3.7/site-packages/twisted/python/log.py", line 103, in callWithLogger
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     return callWithContext({"system": lp}, func, *args, **kw)
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/home/.virtualenvs/boredenv/lib/python3.7/site-packages/twisted/python/log.py", line 86, in callWithContext
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     return context.call({ILogContext: newCtx}, func, *args, **kw)
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/home/.virtualenvs/boredenv/lib/python3.7/site-packages/twisted/python/context.py", line 122, in callWithContext
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     return self.currentContext().callWithContext(ctx, func, *args, **kw)
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/home/.virtualenvs/boredenv/lib/python3.7/site-packages/twisted/python/context.py", line 85, in callWithContext
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     return func(*args,**kw)
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/home/.virtualenvs/boredenv/lib/python3.7/site-packages/twisted/internet/asyncioreactor.py", line 141, in _readOrWrite
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     self._disconnectSelectable(selectable, why, read)
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/home/.virtualenvs/boredenv/lib/python3.7/site-packages/twisted/internet/posixbase.py", line 255, in _disconnectSelectable
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     selectable.connectionLost(f)
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/home/.virtualenvs/boredenv/lib/python3.7/site-packages/twisted/internet/tcp.py", line 327, in connectionLost
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     protocol.connectionLost(reason)
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/home/.virtualenvs/boredenv/lib/python3.7/site-packages/twisted/web/http.py", line 2339, in connectionLost
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     request.connectionLost(reason)
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:   File "/home/.virtualenvs/boredenv/lib/python3.7/site-packages/daphne/http_protocol.py", line 202, in connectionLost
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR:     logger.debug("HTTP disconnect for %s", self.client_addr)
[07/Jan/2019:17:09:53 +0100] [upstream] [903083] STDERR: builtins.AttributeError: 'WebRequest' object has no attribute 'client_addr'

With Chrome, the WebSocket-Upgrade is perfectly handled, see

[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,440 INFO     "127.0.0.1" - - [11/Mar/1970:02:52:07 +0000] "GET / HTTP/1.1" 200 2540 "https://bored.alwaysdata.net/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.140 Safari/537.36 Edge/17.17134"
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,440 DEBUG    HTTP response complete for ['127.0.0.1', 59340]
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,440 DEBUG    poll 20.169 ms took 0.019 ms: 1 events
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,441 DEBUG    poll 19.849 ms took 0.052 ms: 1 events
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,535 DEBUG    poll 957.750 ms took 74.050 ms: 1 events
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,536 DEBUG    HTTP b'GET' request for ['127.0.0.1', 59340]
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,580 DEBUG    poll 881.080 ms took 42.220 ms: 1 events
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,581 DEBUG    poll 838.234 ms took 0.014 ms: 1 events
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,586 DEBUG    Upgraded connection ['127.0.0.1', 60946] to WebSocket
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,635 DEBUG    poll 783.904 ms took 0.011 ms: 1 events
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,638 DEBUG    poll 780.953 ms took 0.026 ms: 1 events
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,639 DEBUG    WebSocket ['127.0.0.1', 60946] open and established
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,639 DEBUG    WebSocket ['127.0.0.1', 60946] accepted by application
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,651 DEBUG    poll 779.949 ms took 12.212 ms: 1 events
[07/Jan/2019:17:12:50 +0100] [upstream] [903083] STDERR: 2019-01-07 16:12:50,652 DEBUG    HTTP 200 response started for ['127.0.0.1', 59340]
...

Client-side, all this results in a 400 status code.

My OS is Debian GNU/Linux 8.11 (jessie) and pip freeze returns

aioredis==1.2.0
asgiref==2.3.2
asn1crypto==0.24.0
async-timeout==3.0.1
attrs==18.2.0
autobahn==18.12.1
Automat==0.7.0
certifi==2018.11.29
cffi==1.11.5
channels==2.1.6
channels-redis==2.3.2
chardet==3.0.4
constantly==15.1.0
cryptography==2.4.2
Cython==0.29.2
daphne==2.2.4
defusedxml==0.5.0
Django==2.1.4
django-allauth==0.38.0
django-extensions==1.6.7
h2==3.0.1
hiredis==0.3.1
hpack==3.0.0
hyperframe==5.1.0
hyperlink==18.0.0
idna==2.8
incremental==17.5.0
msgpack==0.5.6
oauthlib==2.1.0
Pillow==5.3.0
priority==1.3.0
psycopg2-binary==2.7.6.1
pyasn1==0.4.5
pyasn1-modules==0.2.3
pycparser==2.19
PyHamcrest==1.9.0
pyOpenSSL==18.0.0
pyproj==1.9.5.1
python-dateutil==2.7.5
python3-openid==3.1.0
pytz==2018.7
redis==3.0.1
requests==2.21.0
requests-oauthlib==1.0.0
service-identity==18.1.0
six==1.12.0
Twisted==18.9.0
txaio==18.8.1
urllib3==1.24.1
whitenoise==4.1.2
zope.interface==4.6.0

But I had the same problem with previous versions, regarding the libraries' or Python3's.

ps: Daphne is awesome.
@andrewgodwin
Copy link
Member

Hm. Do you have a way to reliably reproduce this? It doesn't just happen for me when I open a normal WebSocket.

@lfaucheux
Copy link
Author

lfaucheux commented Jan 8, 2019 •
edited

Thank you very much for helping @andrewgodwin.

Sure... mm... This problem occurs in production. In local environment, it works perfectly with FF, but without SSL though....

Actually, do you think that the problem is due to how FF deals with SSL certificates (by opposition to Chrome)? And I do not pass either certificate or key to Daphne, i.e. I make "her" run as follows

/home/.virtualenvs/boredenv/bin/daphne -b 0.0.0.0 -p 8100 --verbosity 3 bored.asgi:application

which causes no issue with Chrome, but may with FF (?)

In the idea of reproducing the error I get: what if you deal with a secured connection under FF without telling Daphne ?

@andrewgodwin
Copy link
Member

It's possible that it's the SSL - I don't have the ability to repro that locally right now easily, though. Any chance you could try connecting to the production instance without SSL temporarily and see if it still happens?

And, I'm guessing from the report, it works fine on the same server from Chrome/Edge/etc?

@lfaucheux
Copy link
Author

Perfectly fine with Chrome, Opera and Edge, (haven't tryed with Safari).

I will make an attempt under FF with no SSL UTC-tomorrow.

@lfaucheux
Copy link
Author

No. It wasn't the problem. I have just tried without SSL and I get exactly the same error message. I am still investigating. I'll be back ASAP.

@lfaucheux
Copy link
Author

lfaucheux commented Jan 17, 2019 •
edited

Digging in http_protocol.py, and by adding what follows at line 97,

for ih,hh in enumerate(self.requestHeaders.getAllRawHeaders()):
    logger.debug(f"Simple Check 0-{ih}: {hh}")

I get the following site-log under Firefox:

    Simple Check 0-0: (b'Host', [b'bored.alwaysdata.net'])
    Simple Check 0-1: (b'User-Agent', [b'Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:64.0) Gecko/20100101 Firefox/64.0'])
    Simple Check 0-2: (b'Accept', [b'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'])
    Simple Check 0-3: (b'Accept-Language', [b'en-US,fr-FR;q=0.8,fr;q=0.5,en;q=0.3'])
    Simple Check 0-4: (b'Accept-Encoding', [b'gzip, deflate, br'])
    Simple Check 0-5: (b'Connection', [b'keep-alive'])
    Simple Check 0-6: (b'Cookie', [b'csrftoken=hDZ9HNvnjwrIVAUvnRGbvIDB7mfGqtlT10ZFIsNnQgVnpZgC91GjDjkhtSFZeHxJ; sessionid=czoeeat08edfshs1dayzg6zskbqkj3tr'])
    Simple Check 0-7: (b'Upgrade-Insecure-Requests', [b'1'])
    Simple Check 0-8: (b'Pragma', [b'no-cache'])
    Simple Check 0-9: (b'Cache-Control', [b'no-cache'])
    Simple Check 0-10: (b'X-Real-Ip', [b'WWW.XXX.YYY.ZZZ'])
    Simple Check 0-11: (b'Via', [b'1.1 alproxy'])
    Simple Check 0-12: (b'X-Forwarded-Proto', [b'https'])
    Simple Check 0-13: (b'X-Ssl', [b'1'])
    Simple Check 0-14: (b'X-Ssl-Client-Verify', [b'NONE'])

The surprising thing is that there is a difference between the request headers that are sent by the Firefox-client and the headers received by Daphne. Some keys are missing. See:

	Host: bored.alwaysdata.net
	User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:64.0) Gecko/20100101 Firefox/64.0
	Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
	Accept-Language: en-US,fr-FR;q=0.8,fr;q=0.5,en;q=0.3
	Accept-Encoding: gzip, deflate, br
	Sec-WebSocket-Version: 13
	Origin: https://bored.alwaysdata.net
	Sec-WebSocket-Extensions: permessage-deflate
	Sec-WebSocket-Key: Pa+nVQepQNTJ95xKHafwmw==
	Connection: keep-alive, Upgrade
	Cookie: csrftoken=hDZ9HNvnjwrIVAUvnRGbvIDB7mfGqtlT10ZFIsNnQgVnpZgC91GjDjkhtSFZeHxJ; sessionid=czoeeat08edfshs1dayzg6zskbqkj3tr
	Pragma: no-cache
	Cache-Control: no-cache
	Upgrade: websocket

FYI, under Chrome, the (successfully) received headers are:

    Simple Check 0-1: (b'Connection', [b'Upgrade'])
    Simple Check 0-2: (b'Pragma', [b'no-cache'])
    Simple Check 0-3: (b'Cache-Control', [b'no-cache'])
    Simple Check 0-4: (b'User-Agent', [b'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3578.98 Safari/537.36'])
    Simple Check 0-5: (b'Upgrade', [b'websocket'])
    Simple Check 0-6: (b'Origin', [b'https://bored.alwaysdata.net'])
    Simple Check 0-7: (b'Sec-Websocket-Version', [b'13'])
    Simple Check 0-8: (b'Accept-Encoding', [b'gzip, deflate, br'])
    Simple Check 0-9: (b'Accept-Language', [b'en-GB,en;q=0.9,en-US;q=0.8,fr;q=0.7'])
    Simple Check 0-10: (b'Cookie', [b'csrftoken=CRGCynUdrfACkd7Dz5RUAQDEKfshQYOJYEZlgdHnZlbCljd2GQnpWJMfqP9JlyIb; sessionid=eyrqbawsr576bfusv0b77hunaqhamril'])
    Simple Check 0-11: (b'Sec-Websocket-Key', [b'OLv0zn2kwnSkEyvcY4dgkQ=='])
    Simple Check 0-12: (b'Sec-Websocket-Extensions', [b'permessage-deflate; client_max_window_bits'])
    Simple Check 0-13: (b'X-Real-Ip', [b'WWW.XXX.YYY.ZZZ'])
    Simple Check 0-14: (b'Via', [b'1.1 alproxy'])
    Simple Check 0-15: (b'X-Forwarded-Proto', [b'https'])
    Simple Check 0-16: (b'X-Ssl', [b'1'])
    Simple Check 0-17: (b'X-Ssl-Client-Verify', [b'NONE'])
    Upgraded connection ['127.0.0.1', 39694] to WebSocket

Does it tell you anything?

@lfaucheux
Copy link
Author

lfaucheux commented Jan 24, 2019 •
edited

So... It looks like the problem is not du to Daphne! I'll be back very soon with a confirmation....

@lfaucheux
Copy link
Author

lfaucheux commented Jan 28, 2019 •
edited

@andrewgodwin Ok. This is not du to Daphne!! I use a share hosting Service and the so-implied proxy was doing weird things.

@marcinocto marcinocto mentioned this issue Jan 28, 2022
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
blocked/user-response
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@andrewgodwin @lfaucheux