From c0e3bd76e7e5439bdecb67c73884a8ccbfe611a3 Mon Sep 17 00:00:00 2001 From: Mushtaq Rossier Date: Wed, 3 Jul 2024 12:13:11 +0200 Subject: [PATCH] feat: Added logging for fulfillment events --- .../apps/commercetools/serializers.py | 3 +++ .../sub_messages/signals_delayed.py | 1 + .../apps/commercetools/sub_messages/tasks.py | 6 +++-- .../sub_messages/test_signals_delayed.py | 1 + .../tests/sub_messages/test_tasks.py | 4 +++- .../apps/commercetools/views.py | 4 +++- commerce_coordinator/apps/lms/clients.py | 22 +++++++++++++++++-- .../apps/lms/signal_handlers.py | 1 + commerce_coordinator/apps/lms/tasks.py | 12 +++++++++- .../apps/lms/tests/constants.py | 10 +++++++++ .../apps/lms/tests/test_clients.py | 8 ++++++- .../apps/lms/tests/test_signals.py | 1 + .../apps/lms/tests/test_tasks.py | 10 ++++++--- 13 files changed, 72 insertions(+), 11 deletions(-) diff --git a/commerce_coordinator/apps/commercetools/serializers.py b/commerce_coordinator/apps/commercetools/serializers.py index 291f153f9..5f4470a26 100644 --- a/commerce_coordinator/apps/commercetools/serializers.py +++ b/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): diff --git a/commerce_coordinator/apps/commercetools/sub_messages/signals_delayed.py b/commerce_coordinator/apps/commercetools/sub_messages/signals_delayed.py index f25fa5f14..6e56b43ff 100644 --- a/commerce_coordinator/apps/commercetools/sub_messages/signals_delayed.py +++ b/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 diff --git a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py index ef3a0b310..89da51e35 100644 --- a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py +++ b/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.""" @@ -56,7 +57,7 @@ def fulfill_order_placed_message_signal_task( except CommercetoolsError as err: # pragma no cover logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors}') return False - + # breakpoint() try: customer = client.get_customer_by_id(order.customer_id) except CommercetoolsError as err: # pragma no cover @@ -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 diff --git a/commerce_coordinator/apps/commercetools/tests/sub_messages/test_signals_delayed.py b/commerce_coordinator/apps/commercetools/tests/sub_messages/test_signals_delayed.py index 9e44906ef..f06192867 100644 --- a/commerce_coordinator/apps/commercetools/tests/sub_messages/test_signals_delayed.py +++ b/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): diff --git a/commerce_coordinator/apps/commercetools/tests/sub_messages/test_tasks.py b/commerce_coordinator/apps/commercetools/tests/sub_messages/test_tasks.py index de915e3f4..d42d5ec55 100644 --- a/commerce_coordinator/apps/commercetools/tests/sub_messages/test_tasks.py +++ b/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 diff --git a/commerce_coordinator/apps/commercetools/views.py b/commerce_coordinator/apps/commercetools/views.py index bd1b788f7..97b32fd54 100644 --- a/commerce_coordinator/apps/commercetools/views.py +++ b/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) diff --git a/commerce_coordinator/apps/lms/clients.py b/commerce_coordinator/apps/lms/clients.py index b221695d2..3845a41f4 100644 --- a/commerce_coordinator/apps/lms/clients.py +++ b/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( diff --git a/commerce_coordinator/apps/lms/signal_handlers.py b/commerce_coordinator/apps/lms/signal_handlers.py index da45d5e4f..e9cccfef1 100644 --- a/commerce_coordinator/apps/lms/signal_handlers.py +++ b/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 diff --git a/commerce_coordinator/apps/lms/tasks.py b/commerce_coordinator/apps/lms/tasks.py index c76e5cbb0..8a5ee2e73 100644 --- a/commerce_coordinator/apps/lms/tasks.py +++ b/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) diff --git a/commerce_coordinator/apps/lms/tests/constants.py b/commerce_coordinator/apps/lms/tests/constants.py index ed08ec8d4..a9f05f194 100644 --- a/commerce_coordinator/apps/lms/tests/constants.py +++ b/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 +} diff --git a/commerce_coordinator/apps/lms/tests/test_clients.py b/commerce_coordinator/apps/lms/tests/test_clients.py index d35bdc508..69da22596 100644 --- a/commerce_coordinator/apps/lms/tests/test_clients.py +++ b/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, ) diff --git a/commerce_coordinator/apps/lms/tests/test_signals.py b/commerce_coordinator/apps/lms/tests/test_signals.py index 15f61ccae..10336858f 100644 --- a/commerce_coordinator/apps/lms/tests/test_signals.py +++ b/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): diff --git a/commerce_coordinator/apps/lms/tests/test_tasks.py b/commerce_coordinator/apps/lms/tests/test_tasks.py index 51448fcae..a5b2fa84f 100644 --- a/commerce_coordinator/apps/lms/tests/test_tasks.py +++ b/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):