fix: more logging in tasks in prep for 100% catalog. (#254)

* fix: more logging in tasks in prep for 100% catalog. - Adding new info's - Propagating Message IDs to logs - Converting some important debugs to info * chore: fixing tests, universalizing format strings We should avoid testing one the logger. Instead test that actions taken arent or that an expected action is. Logging shouldnt break tests as it may change frequently.
edx · Jul 16, 2024 · 151e5e0 · 151e5e0
1 parent b2be7e2
commit 151e5e0
Show file tree

Hide file tree

Showing 3 changed files with 43 additions and 26 deletions.
diff --git a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py
@@ -50,27 +50,31 @@ def fulfill_order_placed_message_signal_task(
 
     tag = "fulfill_order_placed_message_signal_task"
 
+    logger.info(f'[CT-{tag}] Processing order {order_id}, '
+                f'line item {line_item_state_id}, source system {source_system}, message id: {message_id}')
+
     client = CommercetoolsAPIClient()
 
     try:
         order = client.get_order_by_id(order_id)
     except CommercetoolsError as err:  # pragma no cover
-        logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors}')
+        logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors},'
+                     f'message id: {message_id}')
         return False
 
     try:
         customer = client.get_customer_by_id(order.customer_id)
     except CommercetoolsError as err:  # pragma no cover
         logger.error(f'[CT-{tag}]  Customer not found: {order.customer_id} for order {order_id} with '
-                     f'CT error {err}, {err.errors}')
+                     f'CT error {err}, {err.errors}, message id: {message_id}')
         return False
 
     if not (customer and order and is_edx_lms_order(order)):
-        logger.debug(f'[CT-{tag}] order %s is not an edX order', order_id)
+        logger.debug(f'[CT-{tag}] order {order_id} is not an edX order, message id: {message_id}')
 
         return True
 
-    logger.debug(f'[CT-{tag}] processing edX order %s', order_id)
+    logger.debug(f'[CT-{tag}] processing edX order {order_id}, message id: {message_id}')
 
     lms_user_id = get_edx_lms_user_id(customer)
 
@@ -88,7 +92,8 @@ def fulfill_order_placed_message_signal_task(
     canvas_entry_properties.update(extract_ct_order_information_for_braze_canvas(customer, order))
 
     for item in get_edx_items(order):
-        logger.debug(f'[CT-{tag}] processing edX order %s, line item %s', order_id, item.variant.sku)
+        logger.debug(f'[CT-{tag}] processing edX order {order_id}, line item {item.variant.sku}, '
+                     f'message id: {message_id}')
         updated_order = client.update_line_item_transition_state_on_fulfillment(
             order.id,
             order.version,
@@ -132,6 +137,9 @@ def fulfill_order_placed_message_signal_task(
         send_order_confirmation_email(lms_user_id, customer.email, canvas_entry_properties)
         TieredCache.set_all_tiers(cache_key, value="SENT", django_cache_timeout=EMAIL_NOTIFICATION_CACHE_TTL_SECS)
 
+    logger.info(f'[CT-{tag}] Finished order {order_id}, '
+                f'line item {line_item_state_id}, source system {source_system}, message id: {message_id}')
+
     return True
 
 
@@ -145,38 +153,43 @@ def fulfill_order_sanctioned_message_signal_task(
 
     tag = "fulfill_order_sanctioned_message_signal_task"
 
+    logger.info(f'[CT-{tag}] Processing sanctions for {order_id}, message id: {message_id}')
+
     client = CommercetoolsAPIClient()
     try:
         order = client.get_order_by_id(order_id)
     except CommercetoolsError as err:  # pragma no cover
-        logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors}')
+        logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors}, '
+                     f'message id: {message_id}')
         return False
 
     order_workflow_state = get_edx_order_workflow_state_key(order)
     if not order_workflow_state:
-        logger.info(f'[CT-{tag}] order {order_id} has no workflow/transition state')
+        logger.info(f'[CT-{tag}] order {order_id} has no workflow/transition state, message id: {message_id}')
 
     try:
         customer = client.get_customer_by_id(order.customer_id)
     except CommercetoolsError as err:  # pragma no cover
         logger.error(f'[CT-{tag}]  Customer not found: {order.customer_id} for order {order_id} with '
-                     f'CT error {err}, {err.errors}')
+                     f'CT error {err}, {err.errors}, message id: {message_id}')
         return False
 
     if not (customer and order and is_edx_lms_order(order)):
-        logger.info(f'[CT-{tag}] order {order_id} is not an edX order')
+        logger.info(f'[CT-{tag}] order {order_id} is not an edX order, message id: {message_id}')
         return True
 
     if get_edx_is_sanctioned(order):
         lms_user_name = get_edx_lms_user_name(customer)
-        logger.info(f'[CT-{tag}] calling lms to deactivate user {lms_user_name}.')
+        logger.info(f'[CT-{tag}] calling lms to deactivate user {lms_user_name}, message id: {message_id}.')
 
         LMSAPIClient().deactivate_user(lms_user_name, message_id)
+
+        logger.info(f'[CT-{tag}] Finished sanctions for {order_id}, message id: {message_id}')
         return True
     else:
         logger.error(
             f'[CT-{tag}] order state for order {order_id} is not {TwoUKeys.SDN_SANCTIONED_ORDER_STATE}. '
-            f'Actual value is {order_workflow_state}'
+            f'Actual value is {order_workflow_state}, message id: {message_id}'
         )
         return False
 
@@ -230,30 +243,34 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_id):
 
     tag = "fulfill_order_returned_signal_task"
 
+    logger.info(f'[CT-{tag}] Processing return for order: {order_id}, line item: {return_line_item_return_id}, '
+                f'message id: {message_id}')
+
     client = CommercetoolsAPIClient()
 
     try:
         order = client.get_order_by_id(order_id)
     except CommercetoolsError as err:  # pragma no cover
-        logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors}')
+        logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors}'
+                     f', message id: {message_id}')
         return False
 
     try:
         customer = client.get_customer_by_id(order.customer_id)
     except CommercetoolsError as err:  # pragma no cover
         logger.error(f'[CT-{tag}] Customer not found: {order.customer_id} for order {order_id} with '
-                     f'CT error {err}, {err.errors}')
+                     f'CT error {err}, {err.errors}, message id: {message_id}')
         return False
 
     if not (customer and order and is_edx_lms_order(order)):  # pragma no cover
-        logger.debug(f'[CT-{tag}] order {order_id} is not an edX order')
+        logger.debug(f'[CT-{tag}] order {order_id} is not an edX order, message id: {message_id}')
         return True
 
     payment_intent_id = get_edx_payment_intent_id(order)
     lms_user_name = get_edx_lms_user_name(customer)
     lms_user_id = get_edx_lms_user_id(customer)
 
-    logger.debug(f'[CT-{tag}] calling stripe to refund payment intent {payment_intent_id}')
+    logger.info(f'[CT-{tag}] calling stripe to refund payment intent {payment_intent_id}, message id: {message_id}')
 
     # Return payment if payment intent id is set
     if payment_intent_id is not None:
@@ -263,18 +280,19 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_id):
 
         if 'refund_response' in result and result['refund_response']:
             if result['refund_response'] == 'charge_already_refunded':
-                logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} already has refund transaction, '
-                             f'sending Zendesk email')
+                logger.info(f'[CT-{tag}] payment intent {payment_intent_id} already has refund transaction, '
+                            f'sending Zendesk email, message id: {message_id}')
                 send_refund_notification(customer, order_id)
             else:
-                logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} refunded. Message_id: {message_id}')
+                logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} refunded. message id: {message_id}')
                 segment_event_properties = _prepare_segment_event_properties(order, return_line_item_return_id)
 
                 for line_item in get_edx_items(order):
                     course_run = get_edx_product_course_run_key(line_item)
                     # TODO: Remove LMS Enrollment
                     logger.debug(
                         f'[CT-{tag}] calling lms to unenroll user {lms_user_name} in {course_run}'
+                        f', message id: {message_id}'
                     )
 
                     product = {
@@ -301,7 +319,10 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_id):
                         properties=segment_event_properties
                     )
         else:  # pragma no cover
-            logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} not refunded. Message_id: {message_id}')
+            logger.info(f'[CT-{tag}] payment intent {payment_intent_id} not refunded. message id: {message_id}')
             return send_refund_notification(customer, order_id)
 
+    logger.info(f'[CT-{tag}] Finished return for order: {order_id}, line item: {return_line_item_return_id}, '
+                f'message id: {message_id}')
+
     return True
diff --git a/commerce_coordinator/apps/commercetools/tests/sub_messages/test_tasks.py b/commerce_coordinator/apps/commercetools/tests/sub_messages/test_tasks.py
@@ -319,12 +319,10 @@ def test_correct_arguments_passed_valid_stripe_refund(
 
     @patch('commerce_coordinator.apps.commercetools.sub_messages.tasks.send_refund_notification')
     @patch('commerce_coordinator.apps.commercetools.sub_messages.tasks.get_edx_payment_intent_id')
-    @patch('commerce_coordinator.apps.commercetools.sub_messages.tasks.logger.debug')
     @patch('commerce_coordinator.apps.commercetools.sub_messages.tasks.OrderRefundRequested.run_filter')
     def test_refund_already_charged(
         self,
         _return_filter_mock: MagicMock,
-        _mock_logger,
         _mock_payment_intent: MagicMock,
         _mock_zendesk: MagicMock
     ):
@@ -338,6 +336,4 @@ def test_refund_already_charged(
         _mock_payment_intent.return_value = 'mock_payment_intent_id'
 
         self.get_uut()(*self.unpack_for_uut(self.mock.example_payload))
-        _mock_logger.assert_called_with('[CT-fulfill_order_returned_signal_task] payment intent '
-                                        'mock_payment_intent_id already has refund transaction, sending Zendesk email')
         _mock_zendesk.assert_called_once()
diff --git a/commerce_coordinator/apps/commercetools/views.py b/commerce_coordinator/apps/commercetools/views.py
@@ -41,7 +41,7 @@ def post(self, request):
             **request.data
         }
 
-        logger.debug(f'[CT-{tag}] Message received from commercetools with details: %s', input_data)
+        logger.debug(f'[CT-{tag}] Message received from commercetools with details: {input_data}')
 
         message_details = OrderLineItemMessageInputSerializer(data=input_data)
         message_details.is_valid(raise_exception=True)
@@ -85,7 +85,7 @@ def post(self, request):
             **request.data
         }
 
-        logger.debug(f'[CT-{tag}] Message received from commercetools with details: %s', input_data)
+        logger.debug(f'[CT-{tag}] Message received from commercetools with details: {input_data}')
 
         message_details = OrderSanctionedViewMessageInputSerializer(data=input_data)
         message_details.is_valid(raise_exception=True)
@@ -127,7 +127,7 @@ def post(self, request):
             **request.data
         }
 
-        logger.debug(f'[CT-{tag}] Message received from commercetools with details: %s', input_data)
+        logger.debug(f'[CT-{tag}] Message received from commercetools with details: {input_data}')
 
         message_details = OrderReturnedViewMessageInputSerializer(data=input_data)
         message_details.is_valid(raise_exception=True)