Merge pull request #143 from edx/jsa/xcom-381

log incoming payments and their application to orders.

ecommerce/extensions/analytics/utils.py

@@ -53,3 +53,26 @@ def log_exceptions(msg):
                 raise
         return wrapper
     return decorator
+
+
+def log_payment_received(processor_name, reference, amount, basket_id):
+    """Emit a log entry indicating that we were notified about a successful payment.
+
+    This should be called immediately after the notification has been received and interpreted (i.e.
+    after `handle_payment`).
+    """
+    logger.info(
+        'payment_received: processor_name="%s", reference="%s", amount="%s", basket_id="%s"',
+        processor_name,
+        reference,
+        amount,
+        basket_id,
+    )
+
+
+def log_payment_applied(amount, basket_id, user_id):
+    """Emit a log entry indicating that a payment was successfully applied to an order.
+
+    This should be called immediately after the order has been saved to db (i.e. after `handle_order_placement`).
+    """
+    logger.info('payment_applied: amount="%s", basket_id="%s", user_id="%s"', amount, basket_id, user_id)

ecommerce/extensions/checkout/mixins.py

@@ -4,6 +4,7 @@ import abc
 from oscar.apps.checkout.mixins import OrderPlacementMixin
 from oscar.core.loading import get_class
 
+from ecommerce.extensions.analytics.utils import log_payment_received, log_payment_applied
 
 post_checkout = get_class('checkout.signals', 'post_checkout')
 
@@ -35,8 +36,10 @@ class EdxOrderPlacementMixin(OrderPlacementMixin):
 
         self.add_payment_source(source)
         self.add_payment_event(payment_event)
+        log_payment_received(payment_event.processor_name, payment_event.reference, payment_event.amount, basket.id)
 
     def handle_successful_order(self, order):
         # Send a signal so that receivers can perform relevant tasks (e.g. fulfill the order).
         post_checkout.send_robust(sender=self, order=order)
+        log_payment_applied(order.total_excl_tax, order.basket.id, order.user.id)
         return order

ecommerce/extensions/checkout/tests/test_signals.py → ecommerce/extensions/checkout/tests/test_mixins.py

 """
 Tests for the ecommerce.extensions.checkout.mixins module.
 """
+from decimal import Decimal
+
 from django.test import TestCase, override_settings
-from mock import patch
+from mock import Mock, patch
 from oscar.test.newfactories import UserFactory
+from testfixtures import LogCapture
 
 from ecommerce.extensions.checkout.mixins import EdxOrderPlacementMixin
 from ecommerce.extensions.refund.tests.mixins import RefundTestMixin
 from ecommerce.tests.mixins import BusinessIntelligenceMixin
 
 
+LOGGER_NAME = 'ecommerce.extensions.analytics.utils'
+
+
 @override_settings(SEGMENT_KEY='dummy-key')
 @patch('analytics.track')
 class EdxOrderPlacementMixinTests(BusinessIntelligenceMixin, RefundTestMixin, TestCase):
@@ -22,6 +28,37 @@ class EdxOrderPlacementMixinTests(BusinessIntelligenceMixin, RefundTestMixin, Te
         self.user = UserFactory()
         self.order = self.create_order()
 
+    def test_handle_payment_logging(self, __mock_track):
+        """
+        Ensure that we emit a log entry upon receipt of a payment notification.
+        """
+        mock_payment_event = Mock(
+            processor_name='test-processor-name',
+            reference='test-reference',
+            amount=Decimal('9.99'),
+        )
+        mock_handle_processor_response = Mock(return_value=(None, mock_payment_event))
+        mock_payment_processor = Mock(handle_processor_response=mock_handle_processor_response)
+
+        with patch(
+            'ecommerce.extensions.checkout.mixins.EdxOrderPlacementMixin.payment_processor',
+            mock_payment_processor
+        ):
+            with LogCapture(LOGGER_NAME) as l:
+                EdxOrderPlacementMixin().handle_payment(Mock(), Mock(id='test-basket-id'))
+                l.check(
+                    (
+                        LOGGER_NAME,
+                        'INFO',
+                        'payment_received: processor_name="{}", reference="{}", amount="{}", basket_id="{}"'.format(
+                            'test-processor-name',
+                            'test-reference',
+                            '9.99',
+                            'test-basket-id',
+                        )
+                    )
+                )
+
     def test_handle_successful_order(self, mock_track):
         """
         Ensure that tracking events are fired with correct content when order
@@ -30,19 +67,32 @@ class EdxOrderPlacementMixinTests(BusinessIntelligenceMixin, RefundTestMixin, Te
         tracking_context = {'lms_user_id': 'test-user-id', 'lms_client_id': 'test-client-id'}
         self.user.tracking_context = tracking_context
         self.user.save()
-        EdxOrderPlacementMixin().handle_successful_order(self.order)
-        # ensure event is being tracked
-        self.assertTrue(mock_track.called)
-        # ensure event data is correct
-        self.assert_correct_event(
-            mock_track,
-            self.order,
-            tracking_context['lms_user_id'],
-            tracking_context['lms_client_id'],
-            self.order.number,
-            self.order.currency,
-            self.order.total_excl_tax
-        )
+
+        with LogCapture(LOGGER_NAME) as l:
+            EdxOrderPlacementMixin().handle_successful_order(self.order)
+            # ensure event is being tracked
+            self.assertTrue(mock_track.called)
+            # ensure event data is correct
+            self.assert_correct_event(
+                mock_track,
+                self.order,
+                tracking_context['lms_user_id'],
+                tracking_context['lms_client_id'],
+                self.order.number,
+                self.order.currency,
+                self.order.total_excl_tax
+            )
+            l.check(
+                (
+                    LOGGER_NAME,
+                    'INFO',
+                    'payment_applied: amount="{}", basket_id="{}", user_id="{}"'.format(
+                        self.order.total_excl_tax,
+                        self.order.basket.id,
+                        self.order.user.id,
+                    )
+                )
+            )
 
     def test_handle_successful_free_order(self, mock_track):
         """Verify that tracking events are not emitted for free orders."""