Improve logging of ecommerce interactions

Adds standardized audit logging for checkout and enrollment change requests. XCOM-427.

common/djangoapps/enrollment/tests/test_views.py

@@ -75,21 +75,31 @@ class EnrollmentTestMixin(object):
         if as_server:
             extra['HTTP_X_EDX_API_KEY'] = self.API_KEY
 
-        url = reverse('courseenrollments')
-        response = self.client.post(url, json.dumps(data), content_type='application/json', **extra)
-        self.assertEqual(response.status_code, expected_status)
-
-        if expected_status == status.HTTP_200_OK:
-            data = json.loads(response.content)
-            self.assertEqual(course_id, data['course_details']['course_id'])
-
-            if mode is not None:
-                self.assertEqual(mode, data['mode'])
-
-            if is_active is not None:
-                self.assertEqual(is_active, data['is_active'])
-            else:
-                self.assertTrue(data['is_active'])
+        with patch('enrollment.views.audit_log') as mock_audit_log:
+            url = reverse('courseenrollments')
+            response = self.client.post(url, json.dumps(data), content_type='application/json', **extra)
+            self.assertEqual(response.status_code, expected_status)
+
+            if expected_status == status.HTTP_200_OK:
+                data = json.loads(response.content)
+                self.assertEqual(course_id, data['course_details']['course_id'])
+
+                if mode is not None:
+                    self.assertEqual(mode, data['mode'])
+
+                if is_active is not None:
+                    self.assertEqual(is_active, data['is_active'])
+                else:
+                    self.assertTrue(data['is_active'])
+
+                if as_server:
+                    # Verify that an audit message was logged.
+                    self.assertTrue(mock_audit_log.called)
+
+                    # If multiple enrollment calls are made in the scope of a
+                    # single test, we want to validate that audit messages are
+                    # logged for each call.
+                    mock_audit_log.reset_mock()
 
         return response
 

common/djangoapps/enrollment/views.py

@@ -10,6 +10,7 @@ from django.core.exceptions import ObjectDoesNotExist
 from django.utils.decorators import method_decorator
 from opaque_keys import InvalidKeyError
 from course_modes.models import CourseMode
+from lms.djangoapps.commerce.utils import audit_log
 from openedx.core.djangoapps.user_api.preferences.api import update_email_opt_in
 from openedx.core.lib.api.permissions import ApiKeyHeaderPermission, ApiKeyHeaderPermissionIsAuthenticated
 from rest_framework import status
@@ -489,3 +490,16 @@ class EnrollmentListView(APIView, ApiKeyPermissionMixIn):
                     ).format(username=username, course_id=course_id)
                 }
             )
+        finally:
+            # Assumes that the ecommerce service uses an API key to authenticate.
+            if has_api_key_permissions:
+                current_enrollment = api.get_enrollment(username, unicode(course_id))
+                audit_log(
+                    'enrollment_change_requested',
+                    course_id=unicode(course_id),
+                    requested_mode=mode,
+                    actual_mode=current_enrollment['mode'] if current_enrollment else None,
+                    requested_activation=is_active,
+                    actual_activation=current_enrollment['is_active'] if current_enrollment else None,
+                    user_id=user.id
+                )

lms/djangoapps/commerce/tests/test_utils.py

+"""Tests of commerce utilities."""
+from django.test import TestCase
+from mock import patch
+
+from commerce.utils import audit_log
+
+
+class AuditLogTests(TestCase):
+    """Tests of the commerce audit logging helper."""
+    @patch('commerce.utils.log')
+    def test_log_message(self, mock_log):
+        """Verify that log messages are constructed correctly."""
+        audit_log('foo', qux='quux', bar='baz')
+
+        # Verify that the logged message contains comma-separated
+        # key-value pairs ordered alphabetically by key.
+        message = 'foo: bar="baz", qux="quux"'
+        self.assertTrue(mock_log.info.called_with(message))

lms/djangoapps/commerce/tests/test_views.py

@@ -162,7 +162,11 @@ class BasketsViewTests(EnrollmentEventTestMixin, UserMixin, ModuleStoreTestCase)
         """
         Verifies that the view contacts the E-Commerce API with the correct data and headers.
         """
-        response = self._post_to_view()
+        with mock.patch('commerce.views.audit_log') as mock_audit_log:
+            response = self._post_to_view()
+
+            # Verify that an audit message was logged
+            self.assertTrue(mock_audit_log.called)
 
         # Validate the response content
         if is_completed:

lms/djangoapps/commerce/utils.py

+"""Utilities to assist with commerce tasks."""
+import logging
+
+
+log = logging.getLogger(__name__)
+
+
+def audit_log(name, **kwargs):
+    """DRY helper used to emit an INFO-level log message.
+
+    Messages logged with this function are used to construct an audit trail. Log messages
+    should be emitted immediately after the event they correspond to has occurred and, if
+    applicable, after the database has been updated. These log messages use a verbose
+    key-value pair syntax to make it easier to extract fields when parsing the application's
+    logs.
+
+    This function is variadic, accepting a variable number of keyword arguments.
+
+    Arguments:
+        name (str): The name of the message to log. For example, 'payment_received'.
+
+    Keyword Arguments:
+        Indefinite. Keyword arguments are strung together as comma-separated key-value
+        pairs ordered alphabetically by key in the resulting log message.
+
+    Returns:
+        None
+    """
+    # Joins sorted keyword argument keys and values with an "=", wraps each value
+    # in quotes, and separates each pair with a comma and a space.
+    payload = u', '.join(['{k}="{v}"'.format(k=k, v=v) for k, v in sorted(kwargs.items())])
+    message = u'{name}: {payload}'.format(name=name, payload=payload)
+
+    log.info(message)

lms/djangoapps/commerce/views.py

@@ -16,6 +16,7 @@ from commerce import ecommerce_api_client
 from commerce.constants import Messages
 from commerce.exceptions import InvalidResponseError
 from commerce.http import DetailResponse, InternalRequestErrorResponse
+from commerce.utils import audit_log
 from course_modes.models import CourseMode
 from courseware import courses
 from edxmako.shortcuts import render_to_response
@@ -126,7 +127,7 @@ class BasketsView(APIView):
                 # Pass data to the client to begin the payment flow.
                 return JsonResponse(payment_data)
             elif response_data['order']:
-                # The order was completed immediately because there isno charge.
+                # The order was completed immediately because there is no charge.
                 msg = Messages.ORDER_COMPLETED.format(order_number=response_data['order']['number'])
                 log.debug(msg)
                 return DetailResponse(msg)
@@ -140,6 +141,14 @@ class BasketsView(APIView):
         except (exceptions.SlumberBaseException, exceptions.Timeout) as ex:
             log.exception(ex.message)
             return InternalRequestErrorResponse(ex.message)
+        finally:
+            audit_log(
+                'checkout_requested',
+                course_id=course_id,
+                mode=honor_mode.slug,
+                processor_name=None,
+                user_id=user.id
+            )
 
 
 @csrf_exempt

lms/djangoapps/verify_student/tests/test_views.py

@@ -1028,7 +1028,7 @@ class TestCheckoutWithEcommerceService(ModuleStoreTestCase):
         ecommerce api, we correctly call to that api to create a basket.
         """
         user = UserFactory.create(username="test-username")
-        course_mode = CourseModeFactory(sku="test-sku")
+        course_mode = CourseModeFactory(sku="test-sku").to_tuple()  # pylint: disable=no-member
         expected_payment_data = {'foo': 'bar'}
         # mock out the payment processors endpoint
         httpretty.register_uri(
@@ -1037,15 +1037,26 @@ class TestCheckoutWithEcommerceService(ModuleStoreTestCase):
             body=json.dumps({'payment_data': expected_payment_data}),
             content_type="application/json",
         )
-        # call the function
-        actual_payment_data = checkout_with_ecommerce_service(user, 'dummy-course-key', course_mode, 'test-processor')
-        # check the api call
+
+        with mock.patch('verify_student.views.audit_log') as mock_audit_log:
+            # Call the function
+            actual_payment_data = checkout_with_ecommerce_service(
+                user,
+                'dummy-course-key',
+                course_mode,
+                'test-processor'
+            )
+
+            # Verify that an audit message was logged
+            self.assertTrue(mock_audit_log.called)
+
+        # Check the api call
         self.assertEqual(json.loads(httpretty.last_request().body), {
             'products': [{'sku': 'test-sku'}],
             'checkout': True,
             'payment_processor_name': 'test-processor',
         })
-        # check the response
+        # Check the response
         self.assertEqual(actual_payment_data, expected_payment_data)
 
 

lms/djangoapps/verify_student/views.py

@@ -29,6 +29,7 @@ from opaque_keys.edx.keys import CourseKey, UsageKey
 from opaque_keys import InvalidKeyError
 
 from commerce import ecommerce_api_client
+from commerce.utils import audit_log
 from course_modes.models import CourseMode
 from courseware.url_helpers import get_redirect_url
 from ecommerce_api_client.exceptions import SlumberBaseException
@@ -617,6 +618,7 @@ class PayAndVerifyView(View):
 
 def checkout_with_ecommerce_service(user, course_key, course_mode, processor):     # pylint: disable=invalid-name
     """ Create a new basket and trigger immediate checkout, using the E-Commerce API. """
+    course_id = unicode(course_key)
     try:
         api = ecommerce_api_client(user)
         # Make an API call to create the order and retrieve the results
@@ -625,12 +627,21 @@ def checkout_with_ecommerce_service(user, course_key, course_mode, processor):
             'checkout': True,
             'payment_processor_name': processor
         })
+
         # Pass the payment parameters directly from the API response.
         return result.get('payment_data')
     except SlumberBaseException:
-        params = {'username': user.username, 'mode': course_mode.slug, 'course_id': unicode(course_key)}
+        params = {'username': user.username, 'mode': course_mode.slug, 'course_id': course_id}
         log.exception('Failed to create order for %(username)s %(mode)s mode of %(course_id)s', params)
         raise
+    finally:
+        audit_log(
+            'checkout_requested',
+            course_id=course_id,
+            mode=course_mode.slug,
+            processor_name=processor,
+            user_id=user.id
+        )
 
 
 def checkout_with_shoppingcart(request, user, course_key, course_mode, amount):