Open abhinavsingh opened 3 years ago
MattBlack85
commented
3 years ago @abhinavsingh could you provide additional debugging info? 1) does the request reach the token view? 2) no views here are async ready, I'm wondering if that's the issue? Tho I would simply expect the o/token to block, do its stuff and return 3) could you bump your loggin level to verbose and chek at which point it hangs and which components are hit?
abhinavsingh
commented
3 years ago Hi @MattBlack85 , thanks for response and apologies for a) missing it and b) unable to get back to it earlier.
asgi and wsgi, behind a LB in production.access_token simply hangs when running under asgi.Logs below are for oauth related libraries. Here 1st line indicates successful authorization, 2nd is for client side redirect and 3rd is for client side access_token which hangs.
[2021-03-31 05:41:09,199] DEBUG oauthlib.oauth2.rfc6749.grant_types.authorization_code - authorization_code:create_authorization_response:278 - Saving grant {'code': 'byrOuK00bIX5gFvUENGViBHs7Pi2Kw', 'state': 'jOhFYuTp0tNh9rrVvhFgBPLrvil6NYJH'} for <oauthlib.Request SANITIZED>.
[2021-03-31 05:41:09,245] DEBUG oauth2_provider - base:form_valid:137 - Success url for the request: http://91883269ebec.ngrok.io/social/complete/custom/?redirect_state=jOhFYuTp0tNh9rrVvhFgBPLrvil6NYJH&code=byrOuK00bIX5gFvUENGViBHs7Pi2Kw&state=jOhFYuTp0tNh9rrVvhFgBPLrvil6NYJH
[2021-03-31 05:41:09,900] DEBUG urllib3.connectionpool - connectionpool:_new_conn:227 - Starting new HTTP connection (1): localhost:8000Following log lines indicates successful redirect to client:
[2021-03-31 05:41:09,248] INFO django.channels.server - runserver:log_action:153 - HTTP POST /o/authorize/?client_id=UJ9d4YuWb7l27JcJkcbVa9k9RZ6AUczxOVivh5Sb&redirect_uri=http%3A%2F%2F91883269ebec.ngrok.io%2Fsocial%2Fcomplete%2Fcustom%2F%3Fredirect_state%3DjOhFYuTp0tNh9rrVvhFgBPLrvil6NYJH&state=jOhFYuTp0tNh9rrVvhFgBPLrvil6NYJH&response_type=code 302 [0.54, 127.0.0.1:50023]Below lines are from Daphne server log, see explanation inline.
# User presses accept
[2021-03-31 05:41:08,713] DEBUG daphne.http_protocol - http_protocol:process:160 - HTTP b'POST' request for ['127.0.0.1', 50023]
# Provider redirects
[2021-03-31 05:41:09,247] DEBUG daphne.http_protocol - http_protocol:handle_reply:255 - HTTP 302 response started for ['127.0.0.1', 50023]
[2021-03-31 05:41:09,247] DEBUG daphne.http_protocol - http_protocol:finish:223 - HTTP close for ['127.0.0.1', 50023]
[2021-03-31 05:41:09,248] DEBUG daphne.http_protocol - http_protocol:handle_reply:269 - HTTP response complete for ['127.0.0.1', 50023]
# Client handles redirect
[2021-03-31 05:41:09,847] DEBUG daphne.http_protocol - http_protocol:process:160 - HTTP b'GET' request for ['127.0.0.1', 50030]
# Provider receives access_token request
[2021-03-31 05:41:09,903] DEBUG daphne.http_protocol - http_protocol:process:160 - HTTP b'POST' request for ['127.0.0.1', 50032]
# After timeout interval, following log lines are printed
# Finally client redirect handler gives up
[2021-03-31 05:46:09,865] DEBUG daphne.http_protocol - http_protocol:connectionLost:213 - HTTP disconnect for ['127.0.0.1', 50030]
# This is probably a auto re-attempt by browser to again serve the client redirect url
[2021-03-31 05:46:10,791] DEBUG daphne.http_protocol - http_protocol:process:160 - HTTP b'GET' request for ['127.0.0.1', 50055]
# Daphne prints following log about log running task being killed
[2021-03-31 05:46:20,398] WARNING daphne.server - server:application_checker:270 - Application instance <Task pending name='Task-4' coro=<StaticFilesWrapper.__call__() running at /Users/abhinavsingh/Dev/j-a-x-l/backend/custom-django-project/venv/lib/python3.9/site-packages/channels/staticfiles.py:44> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /usr/local/Cellar/python@3.9/3.9.1_3/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/futures.py:384, <TaskWakeupMethWrapper object at 0x109ae4310>()]>> for connection <WebRequest at 0x109afc1f0 method=GET uri=/social/complete/custom/?redirect_state=jOhFYuTp0tNh9rrVvhFgBPLrvil6NYJH&code=byrOuK00bIX5gFvUENGViBHs7Pi2Kw&state=jOhFYuTp0tNh9rrVvhFgBPLrvil6NYJH clientproto=HTTP/1.1> took too long to shut down and was killed.
Describe the bug
We have a Django project which serves multiple sites via a
virtualhostmiddlewaresetup (not via Django site framework). This allows us to serve multiple sites from a single Django project instance, using the same settings.py but dynamic urlconf.In this setup, there is a single auth provider, imagine
localhost. Other sites uselocalhostas auth provider. E.g.myapp1.localhostis an OAuth client forlocalhost(provider). We are using Django social auth pipeline with custom OAuth backend to setup custom OAuth provider.Everything works fine (from CLI). However,
tokenPOST request calls hangs indefinitely underASGImode. After some digging, we were able to confirm this behavior by running underWSGImode, under which everything works fine.In gist, here is how the flow looks like:
myapp1.localhost:8000/social/login/custom/localhost:8000/o/authorize/?......localhost:8000myapp1.localhost:8000/social/complete/custom/localhost:8000/o/token/which unfortunately hangs indefinitely.Looking at logs, it hangs here:
If we disable ASGI mode, everything works smoothly. Then logs look like:
To Reproduce
To reproduce:
request.urlconfbased upon incoming host. Forlocalhosturlconf is similar to that of a provider. Formyapp1.localhosturlconf simply offers OAuth login/complete/disconnect URLs (using django python social)myapp1.localhost:8000/social/login/custom/will result in above error.Disable ASGI and everything will start to work fine. Let me know if a working project is necessary to debug and reproduce this.
Expected behavior
Behavior for ASGI and WSGI should be same. Currently workflow hangs under ASGI mode.
Version
django-oauth-toolkit==1.4.0