Oauth flow completes, but not authorized to access resource
sverchdotgov opened this issue · 3 comments
sverchdotgov commented
I'm trying to set up the environment locally with a small test client, but I can't seem to authenticate. The same code authenticates against the sandbox environment, so I suspect I missed some steps.
I'm working off current master: * 7d711ac (origin/master, master) Merge pull request #497 from CMSgov/develop.
I looked at https://github.com/CMSgov/bluebutton-web-server#setup, but it references a file that doesn't seem to exist (hhs_oauth_server/settings/local_sample.txt), so I'm guessing things have changed since that was written.
Steps I took to set the local instance up:
docker-compose up- From another tab:
docker-compose exec web docker-compose/migrate.sh - From another tab:
docker-compose exec web python manage.py create_test_user_and_application - Then I logged in locally
- Then I made sure the callback URL matched
- Then I ran my test client and went through the oauth flow
Test client code:
from requests_oauthlib import OAuth2Session
from flask import Flask, request, redirect, session, url_for
from flask.json import jsonify
import os
app = Flask(__name__)
# https://stackoverflow.com/questions/27785375/testing-flask-oauthlib-locally-without-https
os.environ['OAUTHLIB_INSECURE_TRANSPORT'] = '1'
# This information is obtained upon registration of a new GitHub OAuth
# application here: https://github.com/settings/applications/new
client_id = "R7wsHFuiUzLBvVBkCrViLfQL2vRcyc0LmSuuBpX4"
client_secret = "XXXXX"
authorization_base_url = 'http://localhost:8000/v1/o/authorize/'
token_url = 'http://localhost:8000/v1/o/token/'
redirect_uri = "http://localhost:5000/callback"
#client_id = "Vx5H94QUhKhTd7j2ZeTIgv2WJdZhoshwiod5kiKd"
#client_secret = "XXXXX"
#authorization_base_url = 'https://sandbox.bluebutton.cms.gov/v1/o/authorize/'
#token_url = 'https://sandbox.bluebutton.cms.gov/v1/o/token/'
#redirect_uri = "http://localhost:5000/callback"
@app.route("/")
def demo():
"""Step 1: User Authorization.
Redirect the user/resource owner to the OAuth provider (i.e. Github)
using an URL with a few key OAuth parameters.
"""
app.logger.debug("Step 1: User Authorization.")
github = OAuth2Session(client_id, redirect_uri=redirect_uri)
authorization_url, state = github.authorization_url(authorization_base_url)
app.logger.debug("Authorization URL: %s", authorization_url)
# State is used to prevent CSRF, keep this for later.
session['oauth_state'] = state
app.logger.debug("OAuth State: %s", session['oauth_state'])
return redirect(authorization_url)
# Step 2: User authorization, this happens on the provider.
@app.route("/callback", methods=["GET"])
def callback():
""" Step 3: Retrieving an access token.
The user has been redirected back from the provider to your registered
callback URL. With this redirection comes an authorization code included
in the redirect URL. We will use that to obtain an access token.
"""
app.logger.debug("Step 1: Retrieving Access Token.")
github = OAuth2Session(client_id, state=session['oauth_state'], redirect_uri=redirect_uri)
app.logger.debug("Authorization Response: %s", request.url)
app.logger.debug("Token URL: %s", token_url)
token = github.fetch_token(token_url, client_secret=client_secret,
authorization_response=request.url)
# At this point you can fetch protected resources but lets save
# the token and show how this is done from a persisted token
# in /profile.
session['oauth_token'] = token
app.logger.debug("Token: %s", session['oauth_token'])
print session['oauth_token']
return redirect(url_for('.profile'))
@app.route("/profile", methods=["GET"])
def profile():
"""Fetching a protected resource using an OAuth 2 token.
"""
resource_url = 'https://sandbox.bluebutton.cms.gov/v1/connect/userinfo'
app.logger.debug("Fetching URL: %s with token %s", resource_url, session['oauth_token'])
github = OAuth2Session(client_id, token=session['oauth_token'], redirect_uri=redirect_uri)
res = github.get(resource_url)
app.logger.debug("Resource response code: %s", res.status_code)
return jsonify(res.json())
if __name__ == "__main__":
# This allows us to use a plain HTTP callback
os.environ['DEBUG'] = "1"
app.secret_key = os.urandom(24)
app.run(debug=True)
Running invocation and log output:
$ python test_oauth_client.py
* Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
* Restarting with stat
* Debugger is active!
* Debugger PIN: 780-654-211
--------------------------------------------------------------------------------
DEBUG in test_oauth_client [test_oauth_client.py:34]:
Step 1: User Authorization.
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
DEBUG in test_oauth_client [test_oauth_client.py:37]:
Authorization URL: http://localhost:8000/v1/o/authorize/?response_type=code&client_id=R7wsHFuiUzLBvVBkCrViLfQL2vRcyc0LmSuuBpX4&redirect_uri=http%3A%2F%2Flocalhost%3A5000%2Fcallback&state=MPvElFptoZKWRajVcNJ4pivLYK3Trw
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
DEBUG in test_oauth_client [test_oauth_client.py:41]:
OAuth State: MPvElFptoZKWRajVcNJ4pivLYK3Trw
--------------------------------------------------------------------------------
127.0.0.1 - - [15/Feb/2018 11:14:28] "GET / HTTP/1.1" 302 -
--------------------------------------------------------------------------------
DEBUG in test_oauth_client [test_oauth_client.py:55]:
Step 1: Retrieving Access Token.
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
DEBUG in test_oauth_client [test_oauth_client.py:57]:
Authorization Response: http://localhost:5000/callback?code=aHZ1qCYcHzNjTWf9yJys4GjfL4v5ss&state=MPvElFptoZKWRajVcNJ4pivLYK3Trw
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
DEBUG in test_oauth_client [test_oauth_client.py:58]:
Token URL: http://localhost:8000/v1/o/token/
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
DEBUG in test_oauth_client [test_oauth_client.py:66]:
Token: {u'token_type': u'Bearer', u'patient': u'20140000008325', u'refresh_token': u'lWijMeqxMaxtXPal49oKOiDUp1abV6', u'access_token': u'sample-token-string', u'scope': [u'profile', u'patient/Patient.read', u'patient/ExplanationOfBenefit.read', u'patient/Coverage.read'], u'expires_in': 86219.14765, u'expires_at': 1518797488.542184}
--------------------------------------------------------------------------------
{u'token_type': u'Bearer', u'patient': u'20140000008325', u'refresh_token': u'lWijMeqxMaxtXPal49oKOiDUp1abV6', u'access_token': u'sample-token-string', u'scope': [u'profile', u'patient/Patient.read', u'patient/ExplanationOfBenefit.read', u'patient/Coverage.read'], u'expires_in': 86219.14765, u'expires_at': 1518797488.542184}
127.0.0.1 - - [15/Feb/2018 11:14:29] "GET /callback?code=aHZ1qCYcHzNjTWf9yJys4GjfL4v5ss&state=MPvElFptoZKWRajVcNJ4pivLYK3Trw HTTP/1.1" 302 -
--------------------------------------------------------------------------------
DEBUG in test_oauth_client [test_oauth_client.py:77]:
Fetching URL: https://sandbox.bluebutton.cms.gov/v1/connect/userinfo with token {u'patient': u'20140000008325', u'access_token': u'sample-token-string', u'expires_in': 86219.14765, u'expires_at': 1518797488.542184, u'token_type': u'Bearer', u'scope': [u'profile', u'patient/Patient.read', u'patient/ExplanationOfBenefit.read', u'patient/Coverage.read'], u'refresh_token': u'lWijMeqxMaxtXPal49oKOiDUp1abV6'}
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
DEBUG in test_oauth_client [test_oauth_client.py:80]:
Resource response code: 403
--------------------------------------------------------------------------------
127.0.0.1 - - [15/Feb/2018 11:14:29] "GET /profile HTTP/1.1" 500 -
Traceback (most recent call last):
File "/home/sverch/USDS/HHS/repos/bluebutton-web-server/env/lib/python2.7/site-packages/flask/app.py", line 1997, in __call__
return self.wsgi_app(environ, start_response)
File "/home/sverch/USDS/HHS/repos/bluebutton-web-server/env/lib/python2.7/site-packages/flask/app.py", line 1985, in wsgi_app
response = self.handle_exception(e)
File "/home/sverch/USDS/HHS/repos/bluebutton-web-server/env/lib/python2.7/site-packages/flask/app.py", line 1540, in handle_exception
reraise(exc_type, exc_value, tb)
File "/home/sverch/USDS/HHS/repos/bluebutton-web-server/env/lib/python2.7/site-packages/flask/app.py", line 1982, in wsgi_app
response = self.full_dispatch_request()
File "/home/sverch/USDS/HHS/repos/bluebutton-web-server/env/lib/python2.7/site-packages/flask/app.py", line 1614, in full_dispatch_request
rv = self.handle_user_exception(e)
File "/home/sverch/USDS/HHS/repos/bluebutton-web-server/env/lib/python2.7/site-packages/flask/app.py", line 1517, in handle_user_exception
reraise(exc_type, exc_value, tb)
File "/home/sverch/USDS/HHS/repos/bluebutton-web-server/env/lib/python2.7/site-packages/flask/app.py", line 1612, in full_dispatch_request
rv = self.dispatch_request()
File "/home/sverch/USDS/HHS/repos/bluebutton-web-server/env/lib/python2.7/site-packages/flask/app.py", line 1598, in dispatch_request
return self.view_functions[rule.endpoint](**req.view_args)
File "/home/sverch/USDS/HHS/repos/bluebutton-web-server/test_oauth_client.py", line 81, in profile
return jsonify(res.json())
File "/home/sverch/USDS/HHS/repos/bluebutton-web-server/env/lib/python2.7/site-packages/requests/models.py", line 892, in json
return complexjson.loads(self.text, **kwargs)
File "/usr/lib64/python2.7/json/__init__.py", line 339, in loads
return _default_decoder.decode(s)
File "/usr/lib64/python2.7/json/decoder.py", line 364, in decode
obj, end = self.raw_decode(s, idx=_w(s, 0).end())
File "/usr/lib64/python2.7/json/decoder.py", line 382, in raw_decode
raise ValueError("No JSON object could be decoded")
ValueError: No JSON object could be decoded
127.0.0.1 - - [15/Feb/2018 11:14:29] "GET /profile?__debugger__=yes&cmd=resource&f=style.css HTTP/1.1" 200 -
127.0.0.1 - - [15/Feb/2018 11:14:29] "GET /profile?__debugger__=yes&cmd=resource&f=jquery.js HTTP/1.1" 200 -
127.0.0.1 - - [15/Feb/2018 11:14:29] "GET /profile?__debugger__=yes&cmd=resource&f=debugger.js HTTP/1.1" 200 -
127.0.0.1 - - [15/Feb/2018 11:14:29] "GET /profile?__debugger__=yes&cmd=resource&f=console.png HTTP/1.1" 200 -
127.0.0.1 - - [15/Feb/2018 11:14:29] "GET /profile?__debugger__=yes&cmd=resource&f=console.png HTTP/1.1" 200 -
Log output from local server:
web_1 | 2018-02-15 16:13:34,751 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:13:34.750845 request 2c38a8e0-126b-11e8-9a1f-0242ac120003 1 /v1/o/applications/1/update/ +0:00:00
web_1 | 2018-02-15 16:13:34,752 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:13:34.752321 response 2c38a8e0-126b-11e8-9a1f-0242ac120003 2 /v1/o/applications/1/update/ +0:00:00.001476 302 => /v1/accounts/mfa/login?next=/v1/o/applications/1/update/
web_1 | [15/Feb/2018 16:13:34] "GET /v1/o/applications/1/update/ HTTP/1.1" 302 0
web_1 | 2018-02-15 16:13:34,763 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:13:34.763667 request 2c3a96f0-126b-11e8-b547-0242ac120003 1 /v1/accounts/mfa/login +0:00:00
web_1 | 2018-02-15 16:13:34,786 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:13:34.786530 response 2c3a96f0-126b-11e8-b547-0242ac120003 2 /v1/accounts/mfa/login +0:00:00.022863 200 (7630b)
web_1 | [15/Feb/2018 16:13:34] "GET /v1/accounts/mfa/login?next=/v1/o/applications/1/update/ HTTP/1.1" 200 7630
web_1 | 2018-02-15 16:13:45,374 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:13:45.374379 request 328dabc8-126b-11e8-9d99-0242ac120003 1 /v1/accounts/mfa/login +0:00:00
web_1 | 2018-02-15 16:13:45,429 INFO [10] hhs_oauth_server.accounts line:129 Successful login from 172.18.0.1
web_1 | 2018-02-15 16:13:45,429 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:13:45.429487 response 328dabc8-126b-11e8-9d99-0242ac120003 2 /v1/accounts/mfa/login +0:00:00.055108 302 => /v1/o/applications/1/update/
web_1 | [15/Feb/2018 16:13:45] "POST /v1/accounts/mfa/login?next=/v1/o/applications/1/update/ HTTP/1.1" 302 0
web_1 | 2018-02-15 16:13:45,434 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:13:45.434474 request 3296d1e4-126b-11e8-b0a7-0242ac120003 1 /v1/o/applications/1/update/ +0:00:00
web_1 | 2018-02-15 16:13:45,473 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:13:45.473164 response 3296d1e4-126b-11e8-b0a7-0242ac120003 2 /v1/o/applications/1/update/ +0:00:00.038690 200 (13375b)
web_1 | [15/Feb/2018 16:13:45] "GET /v1/o/applications/1/update/ HTTP/1.1" 200 13375
web_1 | 2018-02-15 16:13:54,055 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:13:54.054953 request 37ba3814-126b-11e8-b9f4-0242ac120003 1 /v1/o/applications/1/update/ +0:00:00
web_1 | 2018-02-15 16:13:54,071 INFO [10] hhs_server.apps.dot_ext.models line:57 fred agreed to https://cmsgov.github.io/bluebutton-developer-help/api-terms-of-use.html for the application TestApp on 2018-02-15 16:13:54.068875+00:00
web_1 | 2018-02-15 16:13:54,073 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:13:54.073842 response 37ba3814-126b-11e8-b9f4-0242ac120003 2 /v1/o/applications/1/update/ +0:00:00.018889 302 => /v1/o/applications/1/
web_1 | [15/Feb/2018 16:13:54] "POST /v1/o/applications/1/update/ HTTP/1.1" 302 0
web_1 | 2018-02-15 16:13:54,076 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:13:54.076671 request 37bd82d0-126b-11e8-a86b-0242ac120003 1 /v1/o/applications/1/ +0:00:00
web_1 | 2018-02-15 16:13:54,097 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:13:54.097223 response 37bd82d0-126b-11e8-a86b-0242ac120003 2 /v1/o/applications/1/ +0:00:00.020552 200 (10032b)
web_1 | [15/Feb/2018 16:13:54] "GET /v1/o/applications/1/ HTTP/1.1" 200 10032
web_1 | 2018-02-15 16:14:03,619 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:14:03.619136 request 3d6d9936-126b-11e8-9096-0242ac120003 1 /v1/o/authorize/ +0:00:00
web_1 | 2018-02-15 16:14:03,648 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:14:03.648802 response 3d6d9936-126b-11e8-9096-0242ac120003 2 /v1/o/authorize/ +0:00:00.029666 200 (4431b)
web_1 | [15/Feb/2018 16:14:03] "GET /v1/o/authorize/?response_type=code&client_id=R7wsHFuiUzLBvVBkCrViLfQL2vRcyc0LmSuuBpX4&redirect_uri=http%3A%2F%2Flocalhost%3A5000%2Fcallback&state=8OAUsepwyvKskuNvbyZdVQCq17bMC8 HTTP/1.1" 200 4431
web_1 | 2018-02-15 16:14:05,182 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:14:05.182018 request 3e5c1354-126b-11e8-8a94-0242ac120003 1 /v1/o/authorize/ +0:00:00
web_1 | 2018-02-15 16:14:05,197 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:14:05.196985 response 3e5c1354-126b-11e8-8a94-0242ac120003 2 /v1/o/authorize/ +0:00:00.014967 302 => http://localhost:5000/callback?code=ejBtExTJjiCq9LXAsN8of3FEKVefAH&state=8OAUsepwyvKskuNvbyZdVQCq17bMC8
web_1 | [15/Feb/2018 16:14:05] "POST /v1/o/authorize/?response_type=code&client_id=R7wsHFuiUzLBvVBkCrViLfQL2vRcyc0LmSuuBpX4&redirect_uri=http%3A%2F%2Flocalhost%3A5000%2Fcallback&state=8OAUsepwyvKskuNvbyZdVQCq17bMC8 HTTP/1.1" 302 0
web_1 | 2018-02-15 16:14:05,204 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:14:05.204006 request 3e5f69c8-126b-11e8-a450-0242ac120003 1 /v1/o/token/ +0:00:00
web_1 | 2018-02-15 16:14:05,226 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:14:05.226129 response 3e5f69c8-126b-11e8-a450-0242ac120003 2 /v1/o/token/ +0:00:00.022123 200 (268b)
web_1 | [15/Feb/2018 16:14:05] "POST /v1/o/token/ HTTP/1.1" 200 268
web_1 | 2018-02-15 16:14:28,202 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:14:28.202332 request 4c14b6b8-126b-11e8-aba2-0242ac120003 1 /v1/o/authorize/ +0:00:00
web_1 | 2018-02-15 16:14:28,229 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:14:28.229411 response 4c14b6b8-126b-11e8-aba2-0242ac120003 2 /v1/o/authorize/ +0:00:00.027079 200 (4431b)
web_1 | [15/Feb/2018 16:14:28] "GET /v1/o/authorize/?response_type=code&client_id=R7wsHFuiUzLBvVBkCrViLfQL2vRcyc0LmSuuBpX4&redirect_uri=http%3A%2F%2Flocalhost%3A5000%2Fcallback&state=MPvElFptoZKWRajVcNJ4pivLYK3Trw HTTP/1.1" 200 4431
web_1 | 2018-02-15 16:14:29,462 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:14:29.462081 request 4cd4f874-126b-11e8-b971-0242ac120003 1 /v1/o/authorize/ +0:00:00
web_1 | 2018-02-15 16:14:29,498 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:14:29.498174 response 4cd4f874-126b-11e8-b971-0242ac120003 2 /v1/o/authorize/ +0:00:00.036093 302 => http://localhost:5000/callback?code=aHZ1qCYcHzNjTWf9yJys4GjfL4v5ss&state=MPvElFptoZKWRajVcNJ4pivLYK3Trw
web_1 | [15/Feb/2018 16:14:29] "POST /v1/o/authorize/?response_type=code&client_id=R7wsHFuiUzLBvVBkCrViLfQL2vRcyc0LmSuuBpX4&redirect_uri=http%3A%2F%2Flocalhost%3A5000%2Fcallback&state=MPvElFptoZKWRajVcNJ4pivLYK3Trw HTTP/1.1" 302 0
web_1 | 2018-02-15 16:14:29,508 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:14:29.507863 request 4cdbe45e-126b-11e8-b3a2-0242ac120003 1 /v1/o/token/ +0:00:00
web_1 | 2018-02-15 16:14:29,540 INFO [10] performance.hhs_oauth_server.request_logging line:64 2018-02-15T16:14:29.540167 response 4cdbe45e-126b-11e8-b3a2-0242ac120003 2 /v1/o/token/ +0:00:00.032304 200 (267b)
web_1 | [15/Feb/2018 16:14:29] "POST /v1/o/token/ HTTP/1.1" 200 267
Is there some step I missed to actually get the data from the backing provider? It's strange though, because I'm just trying to get the profile information.
aviars commented
@sverchdotgov Perhaps your app is not configured to use all the scopes? Double check that. By default, all scopes are selected unless you check otherwise.
sverchdotgov commented
@aviars I checked, and I do seem to have all the scopes selected in the account I'm authorizing with.
whytheplatypus commented
@sverchdotgov if you're running it locally and loging in with the root user that you created during setup that user probably doesn't have an associated Crosswalk