search

opendatapress / open_data_press

Google Sheets to Open Data Publishing Tool
MIT License
13 stars 0 forks source link

Occasional 'invalid_grant' Error On Login #22

Open craig552uk opened 10 years ago

craig552uk commented 10 years ago

Occasionally, when logging in and invalid_grant exception is thrown.

I'm not sure exactly what conditions cause this to arise, but I feel it has something to do with session/credentials expiry.

Below is a log of this error occurring.

INFO     2013-11-14 09:50:35,177 sdk_update_checker.py:245] Checking for updates to the SDK.
INFO     2013-11-14 09:50:35,339 sdk_update_checker.py:273] The SDK is up to date.
WARNING  2013-11-14 09:50:38,521 simple_search_stub.py:1018] Could not read search indexes from /tmp/appengine.opendatapress.craig/search_indexes
INFO     2013-11-14 09:50:38,523 api_server.py:139] Starting API server at: http://localhost:59971
INFO     2013-11-14 09:50:38,540 dispatcher.py:171] Starting module "default" running at: http://localhost:8080
INFO     2013-11-14 09:50:38,544 admin_server.py:117] Starting admin server at: http://localhost:8000
INFO     2013-11-14 09:51:45,868 module.py:608] default: "GET / HTTP/1.1" 200 1487
INFO     2013-11-14 09:51:45,982 module.py:608] default: "GET /css/style.css HTTP/1.1" 304 -
INFO     2013-11-14 09:51:45,991 module.py:608] default: "GET /css/bootstrap.min.css HTTP/1.1" 304 -
INFO     2013-11-14 09:51:46,177 module.py:608] default: "GET /favicon.ico HTTP/1.1" 304 -
INFO     2013-11-14 09:51:46,234 module.py:608] default: "GET /favicon.ico HTTP/1.1" 304 -
INFO     2013-11-14 09:51:50,198 module.py:608] default: "GET /dashboard HTTP/1.1" 302 -
INFO     2013-11-14 09:51:50,545 module.py:608] default: "GET /auth/login HTTP/1.1" 302 -
INFO     2013-11-14 09:51:51,052 session.py:47] Code: 4/wD-MwFd4jpBxlAmXHG5cXccYzI9V.wiKXJf4tSgwaOl05ti8ZT3aRfRCshAI
INFO     2013-11-14 09:51:51,052 session.py:48] Session: {}
INFO     2013-11-14 09:51:51,515 client.py:1296] Successfully retrieved access token
INFO     2013-11-14 09:51:51,816 session.py:76] Refresh Token: None
INFO     2013-11-14 09:51:51,819 module.py:608] default: "GET /auth/oauth2callback?code=4/wD-MwFd4jpBxlAmXHG5cXccYzI9V.wiKXJf4tSgwaOl05ti8ZT3aRfRCshAI HTTP/1.1" 302 -
INFO     2013-11-14 09:51:51,875 module.py:608] default: "GET /auth/login?approval_prompt HTTP/1.1" 302 -
INFO     2013-11-14 09:51:57,100 session.py:47] Code: 4/cSUpPQgSmHUGyKJ8kpp1rqW3Ov8k.gswazNcCqEkfOl05ti8ZT3bjqxCshAI
INFO     2013-11-14 09:51:57,101 session.py:48] Session: {}
INFO     2013-11-14 09:51:57,723 client.py:1296] Successfully retrieved access token
INFO     2013-11-14 09:51:58,086 session.py:76] Refresh Token: None
INFO     2013-11-14 09:51:58,119 module.py:608] default: "GET /auth/oauth2callback?code=4/cSUpPQgSmHUGyKJ8kpp1rqW3Ov8k.gswazNcCqEkfOl05ti8ZT3bjqxCshAI HTTP/1.1" 302 -
INFO     2013-11-14 09:51:58,143 module.py:608] default: "GET /dashboard HTTP/1.1" 302 -
INFO     2013-11-14 09:51:58,177 module.py:608] default: "GET /auth/login HTTP/1.1" 302 -
INFO     2013-11-14 09:51:58,499 session.py:47] Code: 4/GyZJSANgLymZ3nmXjykg3bZ53pjy.IskAUJWlB00WOl05ti8ZT3YJuBCshAI
INFO     2013-11-14 09:51:58,500 session.py:48] Session: {u'current_user': u'115993905952655688554'}
INFO     2013-11-14 09:51:58,858 client.py:1296] Successfully retrieved access token
INFO     2013-11-14 09:51:59,035 client.py:493] Refreshing due to a 401
INFO     2013-11-14 09:51:59,035 client.py:680] Refreshing access_token
INFO     2013-11-14 09:51:59,353 client.py:699] Failed to retrieve access token: {"error" : "invalid_grant"}
ERROR    2013-11-14 09:51:59,353 root.py:27] GET http://localhost:8080/auth/oauth2callback [] 500 'invalid_grant' <class 'oauth2client.client.AccessTokenRefreshError'>
INFO     2013-11-14 09:51:59,357 module.py:608] default: "GET /auth/oauth2callback?code=4/GyZJSANgLymZ3nmXjykg3bZ53pjy.IskAUJWlB00WOl05ti8ZT3YJuBCshAI HTTP/1.1" 500 936
INFO     2013-11-14 09:51:59,416 module.py:608] default: "GET /css/style.css HTTP/1.1" 304 -
INFO     2013-11-14 09:51:59,418 module.py:608] default: "GET /js/script.js HTTP/1.1" 200 -
INFO     2013-11-14 09:51:59,562 module.py:608] default: "GET /favicon.ico HTTP/1.1" 304 -
INFO     2013-11-14 09:51:59,640 module.py:608] default: "GET /favicon.ico HTTP/1.1" 304 -
craig552uk commented 10 years ago

I've added a series of debug logging in controllers/session/py in an attempt to understand what's causing this problem.

Run the development server with debug logging like so:

~/.gae/dev_appserver.py --log_level debug .
craig552uk commented 10 years ago

Another log of the problem, following previous changes:

INFO     2013-11-21 12:21:54,267 module.py:608] default: "GET /dashboard HTTP/1.1" 302 -
DEBUG    2013-11-21 12:21:54,279 session.py:30] Redirect to: https://accounts.google.com/o/oauth2/auth?client_id=351298984682.apps.googleusercontent.com&response_type=code&redirect_uri=http%3A%2F%2Flocalhost%3A8080%2Fauth%2Foauth2callback&scope=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fdrive+https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fuserinfo.email+https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fuserinfo.profile+https%3A%2F%2Fspreadsheets.google.com%2Ffeeds&access_type=offline
INFO     2013-11-21 12:21:54,283 module.py:608] default: "GET /auth/login HTTP/1.1" 302 -
DEBUG    2013-11-21 12:21:54,651 session.py:49] Auth Code: 4/X-fC3sU43CHpIibQiVOtyaCLJsxW.0kSu5vaA6rkROl05ti8ZT3Y_Wzz1hAI
DEBUG    2013-11-21 12:21:54,652 session.py:50] Session (at start): {u'current_user': u'115993905952655688554'}
INFO     2013-11-21 12:21:54,882 client.py:1296] Successfully retrieved access token
DEBUG    2013-11-21 12:21:55,100 session.py:80] User Refresh Token: None
DEBUG    2013-11-21 12:21:55,100 session.py:94] Fetching Refresh Token
DEBUG    2013-11-21 12:21:55,100 session.py:95] Redirect to: /auth/login?approval_prompt
INFO     2013-11-21 12:21:55,104 module.py:608] default: "GET /auth/oauth2callback?code=4/X-fC3sU43CHpIibQiVOtyaCLJsxW.0kSu5vaA6rkROl05ti8ZT3Y_Wzz1hAI HTTP/1.1" 302 -
DEBUG    2013-11-21 12:21:55,126 session.py:30] Redirect to: https://accounts.google.com/o/oauth2/auth?client_id=351298984682.apps.googleusercontent.com&response_type=code&approval_prompt=force&access_type=offline&redirect_uri=http%3A%2F%2Flocalhost%3A8080%2Fauth%2Foauth2callback&scope=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fdrive+https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fuserinfo.email+https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fuserinfo.profile+https%3A%2F%2Fspreadsheets.google.com%2Ffeeds
INFO     2013-11-21 12:21:55,130 module.py:608] default: "GET /auth/login?approval_prompt HTTP/1.1" 302 -
DEBUG    2013-11-21 12:21:58,243 session.py:49] Auth Code: 4/VhkY6S3OSPWZbobwqYhdHb5cGmxO.chx0XZ3VzQweOl05ti8ZT3aHdTz1hAI
DEBUG    2013-11-21 12:21:58,243 session.py:50] Session (at start): {u'current_user': u'115993905952655688554'}
INFO     2013-11-21 12:21:58,830 client.py:1296] Successfully retrieved access token
DEBUG    2013-11-21 12:21:59,131 session.py:80] User Refresh Token: None
DEBUG    2013-11-21 12:21:59,131 session.py:89] Storing Refresh Token for User
DEBUG    2013-11-21 12:21:59,148 session.py:119] Session (at end): {u'current_user': u'115993905952655688554'}
DEBUG    2013-11-21 12:21:59,148 session.py:120] Redirect to: /dashboard
INFO     2013-11-21 12:21:59,152 module.py:608] default: "GET /auth/oauth2callback?code=4/VhkY6S3OSPWZbobwqYhdHb5cGmxO.chx0XZ3VzQweOl05ti8ZT3aHdTz1hAI HTTP/1.1" 302 -
INFO     2013-11-21 12:21:59,172 module.py:608] default: "GET /dashboard HTTP/1.1" 302 -
DEBUG    2013-11-21 12:21:59,188 session.py:30] Redirect to: https://accounts.google.com/o/oauth2/auth?client_id=351298984682.apps.googleusercontent.com&response_type=code&redirect_uri=http%3A%2F%2Flocalhost%3A8080%2Fauth%2Foauth2callback&scope=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fdrive+https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fuserinfo.email+https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fuserinfo.profile+https%3A%2F%2Fspreadsheets.google.com%2Ffeeds&access_type=offline
INFO     2013-11-21 12:21:59,192 module.py:608] default: "GET /auth/login HTTP/1.1" 302 -
DEBUG    2013-11-21 12:21:59,494 session.py:49] Auth Code: 4/errAMXF0_Msx3knTJKYJ7LQdQxjQ.InKiITgUayQTOl05ti8ZT3ZXgTz1hAI
DEBUG    2013-11-21 12:21:59,494 session.py:50] Session (at start): {u'current_user': u'115993905952655688554'}
INFO     2013-11-21 12:21:59,723 client.py:1296] Successfully retrieved access token
INFO     2013-11-21 12:21:59,890 client.py:493] Refreshing due to a 401
INFO     2013-11-21 12:21:59,890 client.py:680] Refreshing access_token
INFO     2013-11-21 12:22:00,169 client.py:699] Failed to retrieve access token: {"error" : "invalid_grant"}
ERROR    2013-11-21 12:22:00,170 root.py:27] GET http://localhost:8080/auth/oauth2callback [] 500 'invalid_grant' <class 'oauth2client.client.AccessTokenRefreshError'>
INFO     2013-11-21 12:22:00,174 module.py:608] default: "GET /auth/oauth2callback?code=4/errAMXF0_Msx3knTJKYJ7LQdQxjQ.InKiITgUayQTOl05ti8ZT3ZXgTz1hAI HTTP/1.1" 500 1737
craig552uk commented 10 years ago

It looks like the dashboard handler is incorrectly redirecting to the login, even though the session has a current user. This may have something to do with DB latency. There were similar problems with the dashboard still showing deleted items, hence the slight delay in static/js/dashboard.js:37.

Given this, I think that allowing the Google auth prompt to be optional seems to be confounding the problem.

To render data views publicly, the app needs a refresh token for the users drive account so that it can access the spreadsheet data on the users behalf. Refresh tokens are only provided when the approval_prompt=force flag is set in the request. This has the effect of requiring the user to authorize access to their account with a prompt form Google.

I had wanted to avoid this prompt appearing every time the user logs in, but it seems this may not be possible.

I need to look in to this problem more deeply, but I am not yet able to replicate it.

For now the application will always prompt users to authorize, every time they log in.

craig552uk commented 10 years ago

Haven't seen this again since applying the previous mentioned change.

I'll leave this open and leave the comments in the source. A contributor may have a better approach for this.