django-social-auth gives 502 error with Google Ope

Question

I've been fighting with a bug for the past few weeks that's been driving me nuts. Please help!

Here's the symptom:

If the user is not logged in to GMail, he can login to my site (using GMail openID) without problems. This will oviously prompt the user to authenticate in GMail first.

However if the user is already authenticated in GMail, he sees a 502 error page, generated by nginx.

This only happens to a few users (I'm not one of them), and one of them was kind enough to report and even made a video to demonstrate:

http://rvzt.net/Temp/google-freedomsponsors.webm

Weird isn't it?

I have added a few debug lines to django-social-auth in production to try to understand what's going on (here, just do ctrl+f + 'logger' to find my changes)

With this setup, health login attempts will flood my (django) log file with stuff like

2013-09-06 11:19:26,659 [DEBUG] social_auth.backends: auth_complete ARGS=(), KWARGS={...} 2013-09-06 11:19:26,666 [DEBUG] social_auth.backends: response and status <openid.consumer.consumer.SuccessResponse id='https://id.mixi.jp/10452407' signed=[u'openid.mode', u'openid.claimed_id', u'openid.identity', u'openid.op_endpoint', u'openid.return_to', u'openid.response_nonce', u'openid.assoc_handle', u'openid.ax.type.nickname', u'openid.ns.ax', u'openid.ax.mode', u'openid.ax.value.nickname']> / success 2013-09-06 11:19:26,675 [DEBUG] social_auth.views: got user: 5ca95b48317944cd87b7d5af4b6e77 2013-09-06 11:19:26,683 [DEBUG] social_auth.views: return redirect to: /

However this particular user failed login attempts produce no output in django's log file. So, it doesn't even touch the view method.

There are a few logs on nginx though.

Here's what a bad login attempt looks like (in /var/log/nginx/access.log):

``` 130.225.243.86 - - [03/Sep/2013:13:23:39 +0000] "GET /complete/google/?janrain_nonce=2013-09-03T13%3A23%XXXXXXXXXXX&openid.ns=http%3A%2F%2Fspecs.openid.net%2Fauth%2F2.0&openid.mode=id_res&openid.op_endpoint=https%3A%2F%2Fwww.google.com%2Faccounts%2Fo8%2Fud&openid.response_nonce=2013-09-03T13%3A23%3A38Zh5WrngwxTu2ByQ&openid.return_to=http%3A%2F%2Ffreedomsponsors.org%2Fcomplete%2Fgoogle%2F%3Fjanrain_nonce%3D2013-09-03T13%253A23%253XXXXXXXXXX&openid.assoc_handle=1.AMlYXXXXXXXXXXXr5MKoxu-k-3cnkXXXXXXXXXXXXXXXXXXXXXXgdEpo3HOg&openid.signed=op_endpoint%2Cclaimed_id%2Cidentity%2Creturn_to%2Cresponse_nonce%2Cassoc_handle%2Cns.ext1%2Cext1.mode%2Cext1.type.old_email%2Cext1.value.old_email%2Cext1.type.first_name%2Cext1.value.first_name%2Cext1.type.last_name%2Cext1.value.last_name%2Cext1.type.email%2Cext1.value.email&openid.sig=3n46MUyn8wIIWpvYIJXj%2BeZqC7o%3D&openid.identity=https%3A%2F%2Fwww.google.com%2Faccounts%2Fo8%2Fid%3Fid%3DAItOawmGmlrjd-OuXXXXXXXXXXXXXXXtIXGpMJQ&openid.claimed_id=https%3A%2F%2Fwww.google.com%2Faccounts%2Fo8%2Fid%3Fid%3DAItOawmGmlrjd-OuXXXXXXXXXXXXXXXXIXGpMJQ&openid.ns.ext1=http%3A%2F%2Fopenid.net%2Fsrv%2Fax%2F1.0&openid.ext1.mode=fetch_response&openid.ext1.type.old_email=http%3A%2F%2Fschema.openid.net%2Fcontact%2Femail&openid.ext1.value.old_email=xxxxxxxxx.junior%40gmail.com&openid.ext1.type.first_name=http%3A%2F%2Faxschema.org%2FnamePerson%2Ffirst&openid.ext1.value.first_name=Bastian&openid.ext1.type.last_name=http%3A%2F%2Faxschema.org%2FnamePerson%2Flast&openid.ext1.value.last_name=Hougaard&openid.ext1.type.email=http%3A%2F%2Faxschema.org%2Fcontact%2Femail&openid.ext1.value.email=xxxxxxxxx.junior%40gmail.com HTTP/1.1" 502 575 "http://freedomsponsors.org/login/google/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/29.0.1547.62 Safari/537.36"

```

This is always accompanied with an entry in /var/log/nginx/errors.log like:

2013/09/06 10:46:06 [error] 667#0: *116533 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 130.225.198.129, server: freedomsponsors.org, request: "GET //complete/google/?janrain_nonce=2013-09-03T13%3A23%XXXXXXXXXXX&openid.ns=http%3A%2F%2Fspecs.openid.net%2Fauth%2F2.0&openid.mode=id_res&openid.op_endpoint=https%3A%2F%2Fwww.google.com%2Faccounts%2Fo8%2Fud&openid.response_nonce=2013-09-03T13%3A23%3A38Zh5WrngwxTu2ByQ&openid.return_to=http%3A%2F%2Ffreedomsponsors.org%2Fcomplete%2Fgoogle%2F%3Fjanrain_nonce%3D2013-09-03T13%253A23%253XXXXXXXXXX&openid.assoc_handle=1.AMlYXXXXXXXXXXXr5MKoxu-_k_-3cnkXXXXXXXXXXXXXXXXXXXXXXgdEpo3HOg&openid.signed=op_endpoint%2Cclaimed_id%2Cidentity%2Creturn_to%2Cresponse_nonce%2Cassoc_handle%2Cns.ext1%2Cext1.mode%2Cext1.type.old_email%2Cext1.value.old_email%2Cext1.type.first_name%2Cext1.value.first_name%2Cext1.type.last_name%2Cext1.value.last_name%2Cext1.type.email%2Cext1.value.email&openid.sig=3n46MUyn8wIIWpvYIJXj%2BeZqC7o%3D&openid.identity=https%3A%2F%2Fwww.google.com%2Faccounts%2Fo8%2Fid%3Fid%3DAItOawmGmlrjd-OuXXXXXXXXXXXXXXXtIXGpMJQ&openid.claimed_id=https%3A%2F%2Fwww.google.com%2Faccounts%2Fo8%2Fid%3Fid%3DAItOawmGmlrjd-OuXXXXXXXXXXXXXXXXIXGpMJQ&openid.ns.ext1=http%3A%2F%2Fopenid.net%2Fsrv%2Fax%2F1.0&openid.ext1.mode=fetch_response&openid.ext1.type.old_email=http%3A%2F%2Fschema.openid.net%2Fcontact%2Femail&openid.ext1.value.old_email=xxxxxxxxx.junior%40gmail.com&openid.ext1.type.first_name=http%3A%2F%2Faxschema.org%2FnamePerson%2Ffirst&openid.ext1.value.first_name=Bastian&openid.ext1.type.last_name=http%3A%2F%2Faxschema.org%2FnamePerson%2Flast&openid.ext1.value.last_name=Hougaard&openid.ext1.type.email=http%3A%2F%2Faxschema.org%2Fcontact%2Femail&openid.ext1.value.email=xxxxxxxxx.junior%40gmail.com HTTP/1.1", upstream: "uwsgi://unix:///tmp/frespo.sock:", host: "freedomsponsors.org", referrer: "http://freedomsponsors.org/login/google/"

A good login attempt looks just the same (in access.log), but instead of ending with

502 575 "http://freedomsponsors.org/login/google/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/29.0.1547.62 Safari/537.36"

It ends with

302 5 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/29.0.1547.62 Safari/537.36"

and of course, it doesn't generate any entries in error.log.

My production environment is a standard nginx + uswgi with file sockets, pretty much like this tutorial says --> https://uwsgi.readthedocs.org/en/latest/tutorials/Django_and_nginx.html

I appretiate any help you can give!

Answer 1

VICTORY!!!

After researching a little I found out that uwsgi has a --daemonize option that will direct uwsgi logs to a file.

After enabling that, I started to see an error like `invalid request block size: 4167 (max 4096)...skip

So I added another config option: buffer-size = 8192 And the problem went away.

Thanks a lot to Bastian who helped me debug this problem!