Add logging to detect concurrent token refreshes for most OAuth APIs

lms/services/oauth_http.py

@@ -1,3 +1,4 @@
+import logging
 from datetime import datetime, timedelta
 
 from marshmallow import fields
@@ -13,6 +14,8 @@
 from lms.validation import RequestsResponseSchema
 from lms.validation.authentication import OAuthTokenResponseSchema
 
+LOG = logging.getLogger(__name__)
+
 
 class _OAuthAccessTokenErrorResponseSchema(RequestsResponseSchema):
     """Schema for parsing OAuth 2 access token error response bodies."""
@@ -117,14 +120,16 @@ def refresh_access_token(
         ):
             return old_token.access_token
 
-        if prevent_concurrent_refreshes:
-            # Prevent concurrent refresh attempts. If acquiring the lock fails,
-            # the client should wait briefly and try again, at which point it
-            # should find the refreshed token already available and skip the
-            # refresh.
-            try:
-                self._oauth2_token_service.try_lock_for_refresh(self.service)
-            except CouldNotAcquireLock as exc:
+        # Check for concurrent refresh attempts.
+        try:
+            self._oauth2_token_service.try_lock_for_refresh(self.service)
+        except CouldNotAcquireLock as exc:
+            LOG.debug('Concurrent OAuth token refresh with token URL "%s"', token_url)
+            if prevent_concurrent_refreshes:
+                # Prevent concurrent refresh attempts. If acquiring the lock
+                # fails, the client should wait briefly and try again, at which
+                # point it should find the refreshed token already available and
+                # skip the refresh.
                 raise ConcurrentTokenRefreshError() from exc
 
         try:

tests/unit/lms/services/oauth_http_test.py

@@ -241,12 +241,25 @@ def test_refresh_access_token_acquires_refresh_lock(
             sentinel.auth,
             prevent_concurrent_refreshes=prevent_concurrent_refreshes,
         )
-        if prevent_concurrent_refreshes:
-            oauth2_token_service.try_lock_for_refresh.assert_called_once()
-        else:
-            oauth2_token_service.try_lock_for_refresh.assert_not_called()
 
-    def test_refresh_access_token_raises_ConcurrentTokenRefreshError_on_concurrent_refresh(
+        # We acquire the lock whether or not concurrent refreshes are allowed,
+        # but only raise if not allowed.
+        oauth2_token_service.try_lock_for_refresh.assert_called_once()
+
+    def test_refresh_access_does_not_raise_if_concurrent_refreshes_allowed(
+        self,
+        svc,
+        oauth2_token_service,
+    ):
+        oauth2_token_service.try_lock_for_refresh.side_effect = CouldNotAcquireLock()
+        svc.refresh_access_token(
+            sentinel.token_url,
+            sentinel.redirect_uri,
+            sentinel.auth,
+            prevent_concurrent_refreshes=False,
+        )
+
+    def test_refresh_access_token_raises_if_concurrent_refreshes_prevented(
         self,
         svc,
         oauth2_token_service,