Andal.LND/edx-platform
6
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge pull request #8698 from edx/renzo/fulfillment-logging

Browse Source 
Improve logging of ecommerce interactions
This commit is contained in:
Renzo Lucioni
2015-06-30 21:31:41 -04:00
parent 5f95226b00 d330831871
commit 39dadb57f0
8 changed files with 131 additions and 20 deletions
Download Patch File Download Diff File Expand all files Collapse all files

34
common/djangoapps/enrollment/tests/test_views.py
View File

@@ -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

14
common/djangoapps/enrollment/views.py
View File

@@ -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
)

18
lms/djangoapps/commerce/tests/test_utils.py Normal file
View File

@@ -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))

6
lms/djangoapps/commerce/tests/test_views.py
View File

@@ -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:

34
lms/djangoapps/commerce/utils.py Normal file
View File

@@ -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)

11
lms/djangoapps/commerce/views.py
View File

@@ -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

21
lms/djangoapps/verify_student/tests/test_views.py
View File

@@ -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)

13
lms/djangoapps/verify_student/views.py
View File

@@ -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):