feat: Added logging for fulfillment events

commerce_coordinator/apps/commercetools/serializers.py

@@ -38,12 +38,14 @@ class OrderLineItemMessageDetailSerializer(CoordinatorSerializer):
     """
     Serializer for CommerceTools message 'detail'
     """
+    id = serializers.CharField()
     resource = serializers.DictField(child=serializers.CharField())
     fromState = serializers.DictField(child=serializers.CharField())
     toState = serializers.DictField(child=serializers.CharField())
 
     def to_representation(self, instance):
         representation = super().to_representation(instance)
+        representation['message_id'] = representation.pop('id')
         order_id = representation['resource'].get('id')
         if order_id:  # pragma no cover
             representation['order_id'] = order_id
@@ -82,6 +84,7 @@ class OrderFulfillViewInputSerializer(CoordinatorSerializer):
     source_system = serializers.CharField(allow_null=False)
     line_item_state_id = serializers.CharField(allow_null=False)
     edx_lms_user_id = serializers.IntegerField(allow_null=False)
+    message_id = serializers.CharField(allow_null=False)
 
 
 class OrderReturnedViewMessageLineItemReturnItemSerializer(CoordinatorSerializer):

commerce_coordinator/apps/commercetools/sub_messages/signals_delayed.py

@@ -21,6 +21,7 @@ def fulfill_order_placed_message_signal(**kwargs):
         order_id=kwargs['order_id'],
         line_item_state_id=kwargs['line_item_state_id'],
         source_system=kwargs['source_system'],
+        message_id=kwargs['message_id']
     )
     return async_result.id
 

commerce_coordinator/apps/commercetools/sub_messages/tasks.py

@@ -44,6 +44,7 @@ def fulfill_order_placed_message_signal_task(
     order_id,
     line_item_state_id,
     source_system,
+    message_id
 ):
     """Celery task for fulfilling an order placed message."""
 
@@ -108,7 +109,8 @@ def fulfill_order_placed_message_signal_task(
             'course_id': get_edx_product_course_run_key(item),  # likely not correct
             'line_item_id': item.id,
             'item_quantity': item.quantity,
-            'line_item_state_id': line_item_state_id
+            'line_item_state_id': line_item_state_id,
+            'message_id': message_id
         })
 
         # the following throws and thus doesn't need to be a conditional

commerce_coordinator/apps/commercetools/tests/sub_messages/test_signals_delayed.py

@@ -26,6 +26,7 @@ class FulfillOrderPlacedMessageSignalTest(CoordinatorSignalReceiverTestCase):
         'order_id': uuid4_str(),
         'line_item_state_id': uuid4_str(),
         'source_system': SOURCE_SYSTEM,
+        'message_id': uuid4_str()
     }
 
     def test_correct_arguments_passed(self, mock_task):

commerce_coordinator/apps/commercetools/tests/sub_messages/test_tasks.py

@@ -46,6 +46,7 @@ def gen_example_fulfill_payload():
         'line_item_state_id': uuid4_str(),
         'order_line_id': uuid4_str(),
         'source_system': SOURCE_SYSTEM,
+        'message_id': uuid4_str()
     }
 
 
@@ -105,7 +106,8 @@ def unpack_for_uut(values):
         return (
             values['order_id'],
             values['line_item_state_id'],
-            values['source_system']
+            values['source_system'],
+            values['message_id']
         )
 
     @staticmethod

commerce_coordinator/apps/commercetools/views.py

@@ -48,6 +48,7 @@ def post(self, request):
 
         order_id = message_details.data['order_id']
         line_item_state_id = message_details.data['to_state']['id']
+        message_id = message_details.data['message_id']
 
         if self._is_running(tag, order_id):  # pragma no cover
             self.meta_should_mark_not_running = False
@@ -59,7 +60,8 @@ def post(self, request):
             sender=self,
             order_id=order_id,
             line_item_state_id=line_item_state_id,
-            source_system=SOURCE_SYSTEM
+            source_system=SOURCE_SYSTEM,
+            message_id=message_id
         )
 
         return Response(status=status.HTTP_200_OK)

commerce_coordinator/apps/lms/clients.py

@@ -51,7 +51,12 @@ def deactivate_user(self, username):
             )
             raise
 
-    def enroll_user_in_course(self, enrollment_data, line_item_state_payload):
+    def enroll_user_in_course(
+            self,
+            enrollment_data,
+            line_item_state_payload,
+            fulfillment_logging_obj
+    ):
         """
         Send a POST request to LMS Enrollment API endpoint
         Arguments:
@@ -63,10 +68,11 @@ def enroll_user_in_course(self, enrollment_data, line_item_state_payload):
             url=self.api_enrollment_base_url,
             json=enrollment_data,
             line_item_state_payload=line_item_state_payload,
+            logging_obj=fulfillment_logging_obj,
             timeout=settings.FULFILLMENT_TIMEOUT
         )
 
-    def post(self, url, json, line_item_state_payload, timeout=None):
+    def post(self, url, json, line_item_state_payload, logging_obj, timeout=None):
         """
         Send a POST request to a url with json payload.
         """
@@ -92,6 +98,12 @@ def post(self, url, json, line_item_state_payload, timeout=None):
                 **line_item_state_payload,
                 'is_fulfilled': True
             }
+            logger.info(
+                f"Successful fulfillment for user: {logging_obj['user']} with details: "
+                f"[lms user id: {logging_obj['lms_user_id']}, order id: {logging_obj['order_id']}, "
+                f"course id: {logging_obj['course_id']}, message_id: {logging_obj['message_id']}, "
+                f"celery_task_id: {logging_obj['celery_task_id']}]"
+            )
         except RequestException as exc:
             self.log_request_exception(logger, exc)
             fulfill_line_item_state_payload = {
@@ -102,6 +114,12 @@ def post(self, url, json, line_item_state_payload, timeout=None):
                 sender=self.__class__,
                 **fulfill_line_item_state_payload
             )
+            logger.info(
+                f"Unsuccessful fulfillment for user: {logging_obj['user']} with details: "
+                f"[lms user id: {logging_obj['lms_user_id']}, order id: {logging_obj['order_id']}, "
+                f"course id: {logging_obj['course_id']}, message_id: {logging_obj['message_id']}, "
+                f"celery_task_id: {logging_obj['celery_task_id']}]"
+            )
             raise
 
         fulfillment_completed_signal.send_robust(

commerce_coordinator/apps/lms/signal_handlers.py

@@ -28,5 +28,6 @@ def fulfill_order_placed_send_enroll_in_course(**kwargs):
         line_item_id=kwargs['line_item_id'],
         item_quantity=kwargs['item_quantity'],
         line_item_state_id=kwargs['line_item_state_id'],
+        message_id=kwargs['message_id']
     )
     return async_result.id

commerce_coordinator/apps/lms/tasks.py

@@ -31,6 +31,7 @@ def fulfill_order_placed_send_enroll_in_course_task(
     line_item_id,
     item_quantity,
     line_item_state_id,
+    message_id
 ):
     """
     Celery task for order placed fulfillment and enrollment via LMS Enrollment API.
@@ -100,4 +101,13 @@ def fulfill_order_placed_send_enroll_in_course_task(
         'line_item_state_id': line_item_state_id,
     }
 
-    return LMSAPIClient().enroll_user_in_course(enrollment_data, line_item_state_payload)
+    fulfillment_logging_obj = {
+        'user': user.username,
+        'lms_user_id': user.lms_user_id,
+        'order_id': order_id,
+        'course_id': course_id,
+        'message_id': message_id,
+        'celery_task_id': self.request.id
+    }
+
+    return LMSAPIClient().enroll_user_in_course(enrollment_data, line_item_state_payload, fulfillment_logging_obj)

commerce_coordinator/apps/lms/tests/constants.py

@@ -29,6 +29,7 @@
     'line_item_id': '822d77c4-00a6-4fb9-909b-094ef0b8c4b9',
     'item_quantity': 1,
     'line_item_state_id': '8f2e888e-9777-4557-9a7f-c649153770c2',
+    'message_id': '1063f19c-08f3-41a4-a952-a8577374373c'
 }
 
 EXAMPLE_FULFILLMENT_REQUEST_PAYLOAD = {
@@ -104,3 +105,12 @@
         'pacing_type': 'Instructor Paced'
     },
 }
+
+EXAMPLE_FULFILLMENT_LOGGING_OBJ = {
+    'user': 'test-user',
+    'lms_user_id': 4,
+    'order_id': '61ec1afa-1b0e-4234-ae28-f997728054fa',
+    'course_id': 'course-v1:edX+DemoX+Demo_Course',
+    'message_id': '1063f19c-08f3-41a4-a952-a8577374373c',
+    'celery_task_id': None
+}

commerce_coordinator/apps/lms/tests/test_clients.py

@@ -11,6 +11,7 @@
 from commerce_coordinator.apps.core.tests.utils import CoordinatorOAuthClientTestCase
 from commerce_coordinator.apps.lms.clients import LMSAPIClient
 from commerce_coordinator.apps.lms.tests.constants import (
+    EXAMPLE_FULFILLMENT_LOGGING_OBJ,
     EXAMPLE_FULFILLMENT_REQUEST_PAYLOAD,
     EXAMPLE_FULFILLMENT_RESPONSE_PAYLOAD,
     EXAMPLE_LINE_ITEM_STATE_PAYLOAD
@@ -56,6 +57,7 @@ def test_order_create_success(self, mock_signal):
             input_kwargs={
                 'enrollment_data': EXAMPLE_FULFILLMENT_REQUEST_PAYLOAD,
                 'line_item_state_payload': EXAMPLE_LINE_ITEM_STATE_PAYLOAD,
+                'fulfillment_logging_obj': EXAMPLE_FULFILLMENT_LOGGING_OBJ
             },
             expected_request=EXAMPLE_FULFILLMENT_REQUEST_PAYLOAD,
             mock_url=self.url,
@@ -71,7 +73,11 @@ def test_order_create_failure(self, mock_signal):
         with self.assertRaises(HTTPError):
             self.assertJSONClientResponse(
                 uut=self.client.enroll_user_in_course,
-                input_kwargs={'enrollment_data': '', 'line_item_state_payload': EXAMPLE_LINE_ITEM_STATE_PAYLOAD},
+                input_kwargs={
+                    'enrollment_data': '',
+                    'line_item_state_payload': EXAMPLE_LINE_ITEM_STATE_PAYLOAD,
+                    'fulfillment_logging_obj': EXAMPLE_FULFILLMENT_LOGGING_OBJ
+                },
                 mock_url=self.url,
                 mock_status=400,
             )

commerce_coordinator/apps/lms/tests/test_signals.py

@@ -35,6 +35,7 @@ class FulfillOrderPlacedSendEnrollInCourseTest(CoordinatorSignalReceiverTestCase
         'line_item_id': 11,
         'item_quantity': 1,
         'line_item_state_id': 12,
+        'message_id': 13
     }
 
     def test_correct_arguments_passed(self, mock_task):

commerce_coordinator/apps/lms/tests/test_tasks.py

@@ -10,6 +10,7 @@
 from commerce_coordinator.apps.core.models import User
 from commerce_coordinator.apps.lms.tasks import fulfill_order_placed_send_enroll_in_course_task
 from commerce_coordinator.apps.lms.tests.constants import (
+    EXAMPLE_FULFILLMENT_LOGGING_OBJ,
     EXAMPLE_FULFILLMENT_REQUEST_PAYLOAD,
     EXAMPLE_FULFILLMENT_SIGNAL_PAYLOAD,
     EXAMPLE_LINE_ITEM_STATE_PAYLOAD
@@ -44,7 +45,8 @@ def unpack_for_uut(values):
             values['source_system'],
             values['line_item_id'],
             values['item_quantity'],
-            values['line_item_state_id']
+            values['line_item_state_id'],
+            values['message_id']
         )
 
     def setUp(self):
@@ -59,7 +61,8 @@ def test_correct_arguments_passed(self, mock_client):
         logger.info('mock_client().mock_calls: %s', mock_client().mock_calls)
         mock_client().enroll_user_in_course.assert_called_once_with(
             EXAMPLE_FULFILLMENT_REQUEST_PAYLOAD,
-            EXAMPLE_LINE_ITEM_STATE_PAYLOAD
+            EXAMPLE_LINE_ITEM_STATE_PAYLOAD,
+            EXAMPLE_FULFILLMENT_LOGGING_OBJ
         )
 
     def test_correct_arguments_passed_credit(self, mock_client):
@@ -86,7 +89,8 @@ def test_correct_arguments_passed_credit(self, mock_client):
         logger.info('mock_client().mock_calls: %s', mock_client().mock_calls)
         mock_client().enroll_user_in_course.assert_called_once_with(
             credit_expected_data,
-            EXAMPLE_LINE_ITEM_STATE_PAYLOAD
+            EXAMPLE_LINE_ITEM_STATE_PAYLOAD,
+            EXAMPLE_FULFILLMENT_LOGGING_OBJ
         )
 
     def test_passes_through_client_return(self, mock_client):