diff --git a/common/djangoapps/enrollment/tests/test_views.py b/common/djangoapps/enrollment/tests/test_views.py index 7fa5cf9e10..9baca37201 100644 --- a/common/djangoapps/enrollment/tests/test_views.py +++ b/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) + 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 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 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 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 diff --git a/common/djangoapps/enrollment/views.py b/common/djangoapps/enrollment/views.py index a8943d7c3b..8cfb06cc34 100644 --- a/common/djangoapps/enrollment/views.py +++ b/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 + ) diff --git a/lms/djangoapps/commerce/tests/test_utils.py b/lms/djangoapps/commerce/tests/test_utils.py new file mode 100644 index 0000000000..df25b7e7b9 --- /dev/null +++ b/lms/djangoapps/commerce/tests/test_utils.py @@ -0,0 +1,18 @@ +"""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)) diff --git a/lms/djangoapps/commerce/tests/test_views.py b/lms/djangoapps/commerce/tests/test_views.py index 4a5cbc5a47..7598c732b8 100644 --- a/lms/djangoapps/commerce/tests/test_views.py +++ b/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: diff --git a/lms/djangoapps/commerce/utils.py b/lms/djangoapps/commerce/utils.py new file mode 100644 index 0000000000..4d25a58a41 --- /dev/null +++ b/lms/djangoapps/commerce/utils.py @@ -0,0 +1,34 @@ +"""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) diff --git a/lms/djangoapps/commerce/views.py b/lms/djangoapps/commerce/views.py index 03394c4ebb..7a3ecb0eb5 100644 --- a/lms/djangoapps/commerce/views.py +++ b/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 diff --git a/lms/djangoapps/verify_student/tests/test_views.py b/lms/djangoapps/verify_student/tests/test_views.py index c97593fe84..b93fa1dedb 100644 --- a/lms/djangoapps/verify_student/tests/test_views.py +++ b/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) diff --git a/lms/djangoapps/verify_student/views.py b/lms/djangoapps/verify_student/views.py index 173c7152d2..288a86710b 100644 --- a/lms/djangoapps/verify_student/views.py +++ b/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):