Merge pull request #37593 from mitodl/arslan/6850-add-lti-logging

chore(logging): add additional logs for LTI launch flow

Author: pdpinch

lms/djangoapps/lti_provider/users.py

@@ -3,6 +3,7 @@
 that an individual has in the campus LMS platform and on edX.
 """
 
+import logging
 
 import random
 import string
@@ -18,6 +19,8 @@
 from lms.djangoapps.lti_provider.models import LtiUser
 from openedx.core.djangoapps.safe_sessions.middleware import mark_user_change_as_expected
 
+log = logging.getLogger("edx.lti_provider")
+
 
 def get_lti_user_details(request):
     """
@@ -54,21 +57,47 @@ def authenticate_lti_user(request, lti_user_id, lti_consumer):
         if lti_consumer.require_user_account:
             # Verify that the email from the LTI Launch and the logged-in user are the same
             # before linking the LtiUser with the edx_user.
+            log.info(
+                'LTI consumer requires existing user account for LTI user ID: %s from request path: %s',
+                lti_user_id,
+                request.path
+            )
             if request.user.is_authenticated and request.user.email.lower() == profile["email"]:
                 lti_user = create_lti_user(lti_user_id, lti_consumer, profile)
             else:
+                log.error(
+                    'LTI user account linking failed for LTI user ID: %s for request path: %s: '
+                    'either user is not logged in or email mismatched',
+                    lti_user_id,
+                    request.path
+                )
                 # Ask the user to login before linking.
                 raise PermissionDenied() from exc
         elif lti_consumer.use_lti_pii:
+            log.info(
+                'Creating LTI user with PII for LTI user ID: %s from request path: %s',
+                lti_user_id,
+                request.path
+            )
             profile["username"] = lti_user_id
             lti_user = create_lti_user(lti_user_id, lti_consumer, profile)
         else:
+            log.info(
+                'Creating LTI user without PII for LTI user ID: %s from request path: %s',
+                lti_user_id,
+                request.path
+            )
             lti_user = create_lti_user(lti_user_id, lti_consumer)
 
     if not (request.user.is_authenticated and
             request.user == lti_user.edx_user):
         # The user is not authenticated, or is logged in as somebody else.
         # Switch them to the LTI user
+        log.info(
+            'Switching logged-in user to LTI user ID: %s for request path: %s',
+            lti_user_id,
+            request.path
+        )
         switch_user(request, lti_user, lti_consumer)
 
 
@@ -102,6 +131,10 @@ def create_lti_user(lti_user_id, lti_consumer, profile=None):
                     edx_user_profile.save()
                     created = True
             except IntegrityError:
+                log.error(
+                    'LTI user creation failed for LTI user ID %s. Retrying with a new username',
+                    lti_user_id,
+                )
                 edx_user_id = generate_random_edx_username()
                 # The random edx_user_id wasn't unique. Since 'created' is still
                 # False, we will retry with a different random ID.
@@ -128,6 +161,7 @@ def switch_user(request, lti_user, lti_consumer):
     if not edx_user:
         # This shouldn't happen, since we've created edX accounts for any LTI
         # users by this point, but just in case we can return a 403.
+        log.error('Switching user failed for LTI user ID: %s from request path: %s', lti_user.lti_user_id, request.path)
         raise PermissionDenied()
     login(request, edx_user)
     mark_user_change_as_expected(edx_user.id)

lms/djangoapps/lti_provider/views.py

@@ -56,12 +56,14 @@ def lti_launch(request, course_id, usage_id):
           pair
     """
     if not settings.FEATURES['ENABLE_LTI_PROVIDER']:
+        log.info('LTI provider feature is disabled.')
         return HttpResponseForbidden()
 
     # Check the LTI parameters, and return 400 if any required parameters are
     # missing
     params = get_required_parameters(request.POST)
     if not params:
+        log.info('Missing required LTI parameters in LTI request path: %s', request.path)
         return HttpResponseBadRequest()
     params.update(get_optional_parameters(request.POST))
     params.update(get_custom_parameters(request.POST))
@@ -74,31 +76,48 @@ def lti_launch(request, course_id, usage_id):
             params['oauth_consumer_key']
         )
     except LtiConsumer.DoesNotExist:
+        log.error(
+            'LTI consumer lookup failed because no matching consumer was found against '
+            'consumer key: %s and instance GUID: %s for request path: %s',
+            params['oauth_consumer_key'],
+            params.get('tool_consumer_instance_guid', None),
+            request.path
+        )
         return HttpResponseForbidden()
 
     # Check the OAuth signature on the message
     if not SignatureValidator(lti_consumer).verify(request):
+        log.error(
+            'Invalid OAuth signature for LTI launch from request path: %s',
+            request.path
+        )
         return HttpResponseForbidden()
 
     # Add the course and usage keys to the parameters array
     try:
         course_key, usage_key = parse_course_and_usage_keys(course_id, usage_id)
     except InvalidKeyError:
         log.error(
-            'Invalid course key %s or usage key %s from request %s',
+            'Invalid course key %s or usage key %s from request path %s',
             course_id,
             usage_id,
-            request
+            request.path
         )
         raise Http404()  # lint-amnesty, pylint: disable=raise-missing-from
     params['course_key'] = course_key
     params['usage_key'] = usage_key
 
-    # Create an edX account if the user identifed by the LTI launch doesn't have
+    # Create an edX account if the user identified by the LTI launch doesn't have
     # one already, and log the edX account into the platform.
     try:
-        authenticate_lti_user(request, params['user_id'], lti_consumer)
+        user_id = params["user_id"]
+        authenticate_lti_user(request, user_id, lti_consumer)
     except PermissionDenied:
+        log.info(
+            'LTI user authentication failed for user Id: %s from request path: %s',
+            user_id,
+            request.path
+        )
         request.session.flush()
         context = {
             "login_link": request.build_absolute_uri(settings.LOGIN_URL),