PermissionDenied exception raised every now and then because 'socialaccount_state' not found in session

[Morpho]

In about 5% of all social userlogins django-allauth fails with exception:

Traceback (most recent call last):
File "/var/www/virtualenvs/project/local/lib/python2.7/site-packages/newrelic-2.10.1.9/newrelic/hooks/framework_django.py", line 494, in wrapper return wrapped(*args, **kwargs)
File "/var/www/virtualenvs/project/local/lib/python2.7/site-packages/allauth/socialaccount/providers/oauth2/views.py", line 51, in view return self.dispatch(request, *args, **kwargs)
File "/var/www/virtualenvs/project/local/lib/python2.7/site-packages/allauth/socialaccount/providers/oauth2/views.py", line 105, in dispatch request.REQUEST.get('state'))
File "/var/www/virtualenvs/project/local/lib/python2.7/site-packages/allauth/socialaccount/models.py", line 282, in verify_and_unstash_state raise PermissionDenied()
PermissionDenied

URL: /accounts/facebook/login/callback/

HTTP_USER_AGENT: Mozilla/5.0 (Linux; U; Android 2.3.6; es-us; GT-B5510L Build/GINGERBREAD) AppleWebKit/533.1 (KHTML, like Gecko) Version/4.0 Mobile Safari/533.1
REQUEST_METHOD: GET

The exception is raised in this location:

    @classmethod
    def verify_and_unstash_state(cls, request, verifier):
        if 'socialaccount_state' not in request.session:
            raise PermissionDenied()

So it seems like 'socialaccount_state' cannot be found in the session. Why is that the case? How can it happen that sometimes this doesnt get included in the session?

UPDATE: I got hold of one of the session object that doesnt contain "socialaccount_state". Here are two example dicts:

{'_session_key': '665mdtp4t9sl3wcv2k6fitd2bag1m6h7', 'modified': False, 'server': <redis.client.StrictRedis object at 0x3e9e3d0>, '_session_cache': {'_auth_user_id': 13349L, '_auth_user_backend': 'allauth.account.auth_backends.AuthenticationBackend', 'account_verified_email': None}, 'accessed': True, 'serializer': <class 'django.contrib.sessions.serializers.PickleSerializer'>}

{'_session_key': 'd4bnstesbwnpq1o34ulmx3cf9e5w4akr', 'modified': False, 'server': <redis.client.StrictRedis object at 0x3e42990>, '_session_cache': {'socialaccount_sociallogin': {'user': {u'username': u'', u'first_name': u'Sandra', u'last_name': u'----- removed by me -----', u'is_active': True, u'id': None, u'is_superuser': False, u'is_staff': False, u'last_login': u'2014-04-08T17:08:31.519Z', u'password': u'!', u'email': u'', u'date_joined': u'2014-04-08T17:08:31.520Z'}, 'token': {u'account_id': None, u'app_id': 1, u'expires_at': u'2014-06-07T17:08:30.992Z', u'token': u'----------removed by me----------', u'id': None, u'token_secret': u''}, 'account': {u'user_id': None, u'uid': u'----- removed by me -----', u'last_login': None, u'provider': u'facebook', u'extra_data': {u'first_name': u'Sandra', u'last_name': u'----- removed by me -----', u'verified': True, u'name': u'Sandra ----- removed by me -----', u'locale': u'en_US', u'gender': u'female', u'work': [{u'employer': {u'id': u'----- removed by me -----', u'name': u'----- removed by me -----'}}, {u'position': {u'id': u'----- removed by me -----', u'name': u'Home Depot'}, u'start_date': u'0000-00', u'location': {u'id': u'108215395870424', u'name': u'Lake Park, Georgia'}, u'description': u'House keeping', u'employer': {u'id': u'----- removed by me -----', u'name': u'"----- removed by me -----".'}}], u'updated_time': u'2014-03-23T00:52:47+0000', u'languages': [{u'id': u'110867825605119', u'name': u'English'}, {u'id': u'108177092548456', u'name': u'Espa\xf1ol'}], u'link': u'https://www.facebook. com/profile. php?id=100----- removed by me -----', u'location': {u'id': u'113132652033783', u'name': u'Omaha, Nebraska'}, u'hometown': {u'id': u'109434842408576', u'name': u'Birmingham, Alabama'}, u'timezone': -4, u'education': [{u'school': {u'id': u'----- removed by me -----', u'name': u'----- removed by me -----'}, u'type': u'High School', u'year': {u'id': u'----- removed by me -----', u'name': u'2000'}}, {u'school': {u'id': u'----- removed by me -----', u'name': u'----- removed by me -----'}, u'type': u'High School', u'year': {u'id': u'----- removed by me -----', u'name': u'1993'}}], u'id': u'----- removed by me -----'}, u'id': None, u'date_joined': None}, 'email_addresses': [], 'state': {'process': 'login', 'next': u'/vid/ next-url. html'}}}, 'accessed': True, 'serializer': <class 'django.contrib.sessions. serializers. PickleSerializer'>}  

I tried it with django's database backend and a redis session-backend. In both cases the error appears.

We re using Django 1.5.4 with django-allauth 1.16.1. Anybody knows what's going on?

[Morpho]

Ok, I found a temporary improvement, I just exchanged "request.session.pop" with "request.session.get" in here: https://github.com/pennersr/django-allauth/blob/master/allauth/socialaccount/models.py#L283. So it seems the 'socialaccount_state' gets popped out in some race condition too early sometimes, which leads to the PermissionDenied exception. I still get the exception, but only in about 0.5% of all cases.

[pennersr]

While removing the pop will help in situations where a race condition is ongoing, the question remains why the race condition is there in the first place. The whole idea of storing the state in the session and retrieving it in a destructive manner (pop) is to prevent replay attacks. So, it seems as if in those 5% of your requests a replay is ongoing.

In theory, this could happen if the browser somehow issues the same request multiple times. For example, if a user nervously clicks a form submit button twice you may also run into situations like these. However, during the OAuth handshake there is no button to press. Could it be that your server is taking too long to respond, causing the users to press reload or something like that?

[Morpho]

You were completly right, it looks like the reason for this really are the users that reload the OAuth2CallbackView so the session state gets "unstashed". Check new relic's traceback:
http://content.screencast.com/users/m.rph/folders/Jing/media/c76e2be4-b99d-4cc6-88d9-0080e72d98cd/2014-04-10_1640.png
First arrow: verify_and_unstash_state is called from OAuth2CallbackView.dispatch()
Second arrow: facebook delays
Third arrow: redis delays
Somewhere after the first arrow the user probaby hits refresh.

Thanks for your hints and quick help. Thats very unfortunate. Maybe instead of showing a plain PermissionDenied exception the user should get redirected to try authentication again?

[Morpho]

Ok, as loading times are clearly not related to my server but to facebook's graph api, there should be some mechanism for the user to try again to authenticate after it failed because he hit the refresh button.

Here are some more transaction traces:

• http://screencast.com/t/SWlgUamwDh
• http://screencast.com/t/nDsCkmncP
• http://screencast.com/t/t8Yssmsc

In our app I will redirect the user back to the login-page and show them an errormessage via messages framework. Once again, thanks for your help!

This is my diff, what do you think? Morpho@0dcd4d0