Slow transactions in requests made with OAuth2 tokens hold open per-request row exclusive locks

[ryanpetrello]

ISSUE TYPE

• Bug Report

SUMMARY

1. Create an OAuth2.0 token.
2. Run a request that results in an especially time consuming database transaction. For example, to simulate a slow query, this code diff makes an HTTP GET request to /api/ very slow:

diff --git a/awx/api/views/root.py b/awx/api/views/root.py
index 922041c8b..711907f8d 100644
--- a/awx/api/views/root.py
+++ b/awx/api/views/root.py
@@ -50,6 +50,8 @@ class ApiRootView(APIView):
     def get(self, request, format=None):
         ''' List supported API versions '''

+        for x in Instance.objects.raw('SELECT id, pg_sleep(30) FROM main_instance'):
+            print(x)
         v2 = reverse('api:api_v2_root_view', kwargs={'version': 'v2'})
         data = OrderedDict()
         data['description'] = _('AWX REST API')

~curl -sk -H 'Authorization: Bearer TOKEN' 'https://awx.example.org/api/'

3. Observe that step 2 takes 30 seconds. During this time, an exclusive row lock is held on the row for that OAuth2.0 token:

SELECT t.relname,l.locktype,page,virtualtransaction,pid,mode,granted FROM pg_locks l, pg_stat_all_tables t WHERE l.relation=t.relid ORDER BY relation ASC;
main_oauth2accesstoken | relation |      | 5/99223            | 20896 | RowExclusiveLock | t

4. Simultaneously, perform an HTTP request on a different unrelated API endpoint using the same OAuth2.0 token:

~curl -sk -H 'Authorization: Bearer TOKEN' 'https://awx.example.org/api/v2/settings/'

Observe the second request does not complete until the first request completes.

[ryanpetrello]

It looks like this code is responsible for obtaining the row lock at the top of the transaction:

https://github.com/ansible/awx/blob/devel/awx/main/models/oauth.py#L122-L124

  /venv/awx/lib64/python3.6/site-packages/django/core/handlers/base.py(113)_get_response()
  /usr/lib64/python3.6/contextlib.py(52)inner()
  /venv/awx/lib64/python3.6/site-packages/django/views/decorators/csrf.py(54)wrapped_view()
  /venv/awx/lib64/python3.6/site-packages/django/views/generic/base.py(71)view()
  /awx_devel/awx/api/generics.py(294)dispatch()
  /venv/awx/lib64/python3.6/site-packages/rest_framework/views.py(478)dispatch()
  /awx_devel/awx/api/generics.py(170)initialize_request()
  /venv/awx/lib64/python3.6/site-packages/rest_framework/request.py(223)user()
  /venv/awx/lib64/python3.6/site-packages/rest_framework/request.py(376)_authenticate()
  /awx_devel/awx
/api/authentication.py(46)authenticate()
  /venv/awx/lib64/python3.6/site-packages/oauth2_provider/contrib/rest_framework/authentication.py(29)authenticate()
  /venv/awx/lib64/python3.6/site-packages/oauth2_provider/oauth2_backends.py(169)verify_request()
  /venv/awx/lib64/python3.6/site-packages/oauthlib/oauth2/rfc6749/endpoints/base.py(87)wrapper()
  /venv/awx/lib64/python3.6/site-packages/oauthlib/oauth2/rfc6749/endpoints/resource.py(75)verify_request()
  /venv/awx/lib64/python3.6/site-packages/oauthlib/oauth2/rfc6749/tokens.py(351)validate_request()
  /venv/awx/lib64/python3.6/site-packages/oauth2_provider/oauth2_validators.py(377)validate_bearer_token()
> /awx_devel/awx/main/models/oauth.py(124)is_valid()

[kdelee]

@ryanpetrello please help me with this this looks horrible

[ryanpetrello]

😂 let's chat about it

[kdelee]

😄 Ok it was not that horrible :)

I make a token and applied the suggested diff to make GET to /api very slow

Using the same token in two windows, while

curl -k -H "Authorization: Bearer ${TOWER_TOKEN}" "${TOWER_HOST}/api/"

hung for a long time (by design), I still got very snappy response from

 curl -k -H "Authorization: Bearer ${TOWER_TOKEN}" "${TOWER_HOST}/api/v2/"

in a different terminal (same host, same token).

Additionally, while the slow request was running, I did not see the RowExclusiveLock, rather I saw

        relname         | locktype | page | virtualtransaction | pid  |      mode       | granted 
------------------------+----------+------+--------------------+------+-----------------+---------
 pg_class               | relation |      | 7/31141            | 7407 | AccessShareLock | t
 pg_index               | relation |      | 7/31141            | 7407 | AccessShareLock | t
 pg_namespace           | relation |      | 7/31141            | 7407 | AccessShareLock | t
 auth_user              | relation |      | 8/23058            | 7521 | AccessShareLock | t
 main_instance          | relation |      | 8/23058            | 7521 | AccessShareLock | t
 main_oauth2application | relation |      | 8/23058            | 7521 | AccessShareLock | t
 main_oauth2accesstoken | relation |      | 8/23058            | 7521 | AccessShareLock | t

Going to touch base with you, but I think this is good to be closed. Thanks!

[ryanpetrello]

Yep, this looks good @kdelee!

[kdelee]

sounds good, thanks!