fix: Improve logging messages

Author: attiyaIshaque

commerce_coordinator/apps/commercetools/clients.py

@@ -433,7 +433,8 @@ def create_return_for_order(self, order_id: str, order_version: int, order_line_
             )
             return returned_order
         except CommercetoolsError as err:
-            handle_commercetools_error(err, f"Unable to create return for order {order_id}")
+            handle_commercetools_error("[CommercetoolsAPIClient.create_return_for_order]",
+                                       err, f"Unable to create return for order {order_id}")
             raise err
 
     def update_return_payment_state_after_successful_refund(
@@ -498,7 +499,8 @@ def update_return_payment_state_after_successful_refund(
             logger.info("Updated transaction with return item id")
             return updated_order
         except CommercetoolsError as err:
-            handle_commercetools_error(err, f"Unable to update ReturnPaymentState of order {order_id}")
+            handle_commercetools_error("[CommercetoolsAPIClient.update_return_payment_state_after_successful_refund]",
+                                       err, f"Unable to update ReturnPaymentState of order {order_id}")
             raise OpenEdxFilterException(str(err)) from err
 
     def _preprocess_refund_object(self, refund: Refund, psp: str) -> Refund:
@@ -560,7 +562,7 @@ def create_return_payment_transaction(
                 f"Unable to create refund payment transaction for payment {payment_id}, refund {refund['id']} "
                 f"with PSP: {psp}"
             )
-            handle_commercetools_error(err, context)
+            handle_commercetools_error("[CommercetoolsAPIClient.create_return_payment_transaction]", err, context)
             raise err
 
     def update_line_item_transition_state_on_fulfillment(
@@ -611,13 +613,15 @@ def update_line_item_transition_state_on_fulfillment(
                 return updated_fulfillment_line_item_order
             else:
                 logger.info(
-                    f"The line item {line_item_id} already has the correct state {new_state_key}. "
-                    "Not attempting to transition LineItemState"
+                    f"[CommercetoolsAPIClient] - The line item {line_item_id} "
+                    f"already has the correct state {new_state_key}. "
+                    f"Not attempting to transition LineItemState for order id {order_id}"
                 )
                 return self.get_order_by_id(order_id)
         except CommercetoolsError as err:
+            context_prefix = "[CommercetoolsAPIClient.update_line_item_state_on_fulfillment_completion]"
             # Logs & ignores version conflict errors due to duplicate Commercetools messages
-            handle_commercetools_error(err, f"Unable to update LineItemState of order {order_id}", True)
+            handle_commercetools_error(context_prefix, err, f"Unable to update LineItemState of order {order_id}")
             return None
 
     def update_line_items_transition_state(
@@ -676,6 +680,7 @@ def update_line_items_transition_state(
         except CommercetoolsError as err:
             # Logs & ignores version conflict errors due to duplicate Commercetools messages
             handle_commercetools_error(
+                "[CommercetoolsAPIClient.update_line_items_transition_state]",
                 err,
                 f"Failed to update LineItemStates for order ID '{order_id}'. "
                 f"Line Item IDs: {', '.join(item.id for item in line_items)}",
@@ -770,6 +775,7 @@ def is_first_time_discount_eligible(self, email: str, code: str) -> bool:
             return True
         except CommercetoolsError as err:  # pragma no cover
             # Logs & ignores version conflict errors due to duplicate Commercetools messages
-            handle_commercetools_error(err, f"Unable to check if user {email} is eligible for a "
+            handle_commercetools_error("[CommercetoolsAPIClient.is_first_time_discount_eligible]",
+                                       err, f"Unable to check if user {email} is eligible for a "
                                             f"first time discount", True)
             return True

commerce_coordinator/apps/commercetools/sub_messages/tasks.py

@@ -78,11 +78,11 @@ def fulfill_order_placed_message_signal_task(
         return False
 
     if not (customer and order and is_edx_lms_order(order)):
-        logger.debug(f'[CT-{tag}] order {order_id} is not an edX order, message id: {message_id}')
+        logger.info(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 {order_id}, message id: {message_id}')
+    logger.info(f'[CT-{tag}] processing edX order {order_id}, message id: {message_id}')
 
     lms_user_id = get_edx_lms_user_id(customer)
 
@@ -266,7 +266,7 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_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, message id: {message_id}')
+        logger.info(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)
@@ -286,13 +286,13 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_id):
                 logger.info(f'[CT-{tag}] payment intent {payment_intent_id} already has refunded transaction, '
                             f'sending Slack notification, message id: {message_id}')
             else:
-                logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} refunded. message id: {message_id}')
+                logger.info(f'[CT-{tag}] payment intent {payment_intent_id} refunded for 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(
+                    logger.info(
                         f'[CT-{tag}] calling lms to unenroll user {lms_user_name} in {course_run}'
                         f', message id: {message_id}'
                     )

commerce_coordinator/apps/commercetools/tasks.py

@@ -31,20 +31,16 @@ def update_line_item_state_on_fulfillment_completion(
     Task for fulfillment completed and order line item state update via Commercetools API.
     """
     client = CommercetoolsAPIClient()
-    try:
-        updated_order = client.update_line_item_transition_state_on_fulfillment(
-            order_id,
-            order_version,
-            line_item_id,
-            item_quantity,
-            from_state_id,
-            to_state_key
-        )
-        return updated_order
-    except CommercetoolsError as err:
-        logger.error(f"Unable to update line item [ {line_item_id} ] state on fulfillment "
-                     f"result with error {err.errors} and correlation id {err.correlation_id}")
-        return None
+
+    updated_order = client.update_line_item_transition_state_on_fulfillment(
+        order_id,
+        order_version,
+        line_item_id,
+        item_quantity,
+        from_state_id,
+        to_state_key
+    )
+    return updated_order
 
 
 @shared_task(autoretry_for=(CommercetoolsError,), retry_kwargs={'max_retries': 5, 'countdown': 3})
@@ -58,9 +54,12 @@ def refund_from_stripe_task(
     """
     client = CommercetoolsAPIClient()
     try:
+        logger.info(
+            f"[refund_from_stripe_task] Initiating creation of CT payment's refund transaction object "
+            f"for payment Intent ID {payment_intent_id}.")
         payment = client.get_payment_by_key(payment_intent_id)
         if has_full_refund_transaction(payment):
-            logger.info(f"Stripe charge.refunded event received, but Payment with ID {payment.id} "
+            logger.info(f"[refund_from_stripe_task] Event 'charge.refunded' received, but Payment with ID {payment.id} "
                         f"already has a full refund. Skipping task to add refund transaction")
             return None
         updated_payment = client.create_return_payment_transaction(
@@ -70,8 +69,8 @@ def refund_from_stripe_task(
         )
         return updated_payment
     except CommercetoolsError as err:
-        logger.error(f"Unable to create refund transaction for payment [ {payment.id} ] "
-                     f"on Stripe refund {stripe_refund['id']} "
+        logger.error(f"[refund_from_stripe_task] Unable to create CT payment's refund transaction "
+                     f"object for [ {payment.id} ] on Stripe refund {stripe_refund['id']} "
                      f"with error {err.errors} and correlation id {err.correlation_id}")
         return None
 
@@ -100,7 +99,8 @@ def refund_from_paypal_task(
         )
         return updated_payment
     except CommercetoolsError as err:
-        logger.error(f"Unable to create refund transaction for payment {payment.key} "
+        logger.error(f"[refund_from_paypal_task] Unable to create CT payment's refund "
+                     f"transaction object for payment {payment.key} "
                      f"on PayPal refund {refund.get('id')} "
                      f"with error {err.errors} and correlation id {err.correlation_id}")
         return None

commerce_coordinator/apps/commercetools/tests/test_clients.py

@@ -470,8 +470,8 @@ def test_create_return_for_order_exception(self):
                 exception = cm.exception
 
                 expected_message = (
-                    f"[CommercetoolsError] Unable to create return for "
-                    f"order mock_order_id "
+                    f"[CommercetoolsError] [CommercetoolsAPIClient.create_return_for_order] "
+                    f"Unable to create return for order mock_order_id "
                     f"- Correlation ID: {exception.correlation_id}, Details: {exception.errors}"
                 )
 
@@ -604,7 +604,8 @@ def test_create_refund_transaction_exception(self):
                 exception = cm.exception
 
                 expected_message = (
-                    f"[CommercetoolsError] Unable to create refund payment transaction for "
+                    f"[CommercetoolsError] [CommercetoolsAPIClient.create_return_payment_transaction] "
+                    f"Unable to create refund payment transaction for "
                     f"payment mock_payment_id, refund {mock_stripe_refund.id} with PSP: stripe_edx "
                     f"- Correlation ID: {exception.correlation_id}, Details: {exception.errors}"
                 )
@@ -672,7 +673,7 @@ def test_update_line_item_state_exception(self, mock_state_by_id):
                 status_code=409
             )
 
-            with patch('commerce_coordinator.apps.commercetools.clients.logging.Logger.info') as log_mock:
+            with patch('commerce_coordinator.apps.commercetools.clients.logging.Logger.error') as log_mock:
                 self.client_set.client.update_line_item_transition_state_on_fulfillment(
                     "mock_order_id",
                     1,
@@ -683,7 +684,8 @@ def test_update_line_item_state_exception(self, mock_state_by_id):
                 )
 
                 expected_message = (
-                    f"[CommercetoolsError] Unable to update LineItemState "
+                    f"[CommercetoolsError] [CommercetoolsAPIClient.update_line_item_state_on_fulfillment_completion] "
+                    f"Unable to update LineItemState "
                     f"of order mock_order_id "
                     f"- Correlation ID: {mock_error_response['correlation_id']}, "
                     f"Details: {mock_error_response['errors']}"
@@ -763,7 +765,8 @@ def test_update_all_line_items_state_exception(self, mock_state_by_id):
                 )
 
                 expected_message = (
-                    f"[CommercetoolsError] Failed to update LineItemStates "
+                    f"[CommercetoolsError] [CommercetoolsAPIClient.update_line_items_transition_state] "
+                    f"Failed to update LineItemStates "
                     f"for order ID 'mock_order_id'. Line Item IDs: {mock_order.line_items[0].id} "
                     f"- Correlation ID: {mock_error_response['correlation_id']}, "
                     f"Details: {mock_error_response['errors']}"
@@ -795,8 +798,8 @@ def test_order_line_item_in_correct_state(self, mock_order_by_id, mock_state_by_
             )
 
             expected_message = (
-                f"The line item {line_item_id} already has the correct state {mock_line_item_state.key}. "
-                f"Not attempting to transition LineItemState"
+                f"[CommercetoolsAPIClient] - The line item {line_item_id} already has the correct state "
+                f"{mock_line_item_state.key}. Not attempting to transition LineItemState for order id mock_order_id"
             )
 
             log_mock.assert_called_with(expected_message)

commerce_coordinator/apps/commercetools/tests/test_tasks.py

@@ -3,7 +3,7 @@
 """
 
 import logging
-from unittest.mock import patch
+from unittest.mock import call, patch
 
 import stripe
 from commercetools import CommercetoolsError
@@ -62,28 +62,6 @@ def test_correct_arguments_passed(self, mock_client):
             *list(EXAMPLE_UPDATE_LINE_ITEM_SIGNAL_PAYLOAD.values())
         )
 
-    @patch('commerce_coordinator.apps.commercetools.tasks.logger')
-    def test_exception_handling(self, mock_logger, mock_client):
-        '''
-        Check if an error in the client results in a logged error
-        and None returned.
-        '''
-        mock_client().update_line_item_transition_state_on_fulfillment.side_effect = CommercetoolsError(
-            message="Could not update ReturnPaymentState",
-            errors="Some error message",
-            response={},
-            correlation_id="123456"
-        )
-
-        result = fulfillment_uut(*self.unpack_for_uut(EXAMPLE_UPDATE_LINE_ITEM_SIGNAL_PAYLOAD))
-
-        mock_logger.error.assert_called_once_with(
-            f"Unable to update line item [ {EXAMPLE_UPDATE_LINE_ITEM_SIGNAL_PAYLOAD['line_item_id']} ] "
-            "state on fulfillment result with error Some error message and correlation id 123456"
-        )
-
-        assert result is None
-
 
 @patch('commerce_coordinator.apps.commercetools.tasks.CommercetoolsAPIClient')
 class ReturnedOrderfromStripeTaskTest(TestCase):
@@ -123,10 +101,10 @@ def test_correct_arguments_passed(self, mock_client):
         )
 
     def test_full_refund_already_exists(self, mock_client):
-        '''
+        """
         Check if the payment already has a full refund, the task logs the
-        appropriate message and skips creating a refund transaction.
-        '''
+        appropriate messages and skips creating a refund transaction.
+        """
         mock_payment = gen_payment_with_multiple_transactions(
             TransactionType.CHARGE, 4900,
             TransactionType.REFUND, 4900
@@ -135,13 +113,22 @@ def test_full_refund_already_exists(self, mock_client):
 
         mock_client.return_value.get_payment_by_key.return_value = mock_payment
 
+        payment_intent_id = EXAMPLE_RETURNED_ORDER_STRIPE_SIGNAL_PAYLOAD['payment_intent_id']
+
         with patch('commerce_coordinator.apps.commercetools.tasks.logger') as mock_logger:
             result = refund_from_stripe_task(*self.unpack_for_uut(EXAMPLE_RETURNED_ORDER_STRIPE_SIGNAL_PAYLOAD))
             self.assertIsNone(result)
-            mock_logger.info.assert_called_once_with(
-                f"Stripe charge.refunded event received, but Payment with ID {mock_payment.id} "
-                f"already has a full refund. Skipping task to add refund transaction"
-            )
+
+            # Check that both info messages were logged in the expected order
+            mock_logger.info.assert_has_calls([
+                call(
+                    f"[refund_from_stripe_task] "
+                    f"Initiating creation of CT payment's refund transaction object "
+                    f"for payment Intent ID {payment_intent_id}."),
+                call(f"[refund_from_stripe_task] Event 'charge.refunded' received, "
+                     f"but Payment with ID {mock_payment.id} "
+                     f"already has a full refund. Skipping task to add refund transaction")
+            ])
 
     @patch('commerce_coordinator.apps.commercetools.tasks.logger')
     def test_exception_handling(self, mock_logger, mock_client):
@@ -162,7 +149,8 @@ def test_exception_handling(self, mock_logger, mock_client):
         returned_uut(*self.unpack_for_uut(EXAMPLE_RETURNED_ORDER_STRIPE_SIGNAL_PAYLOAD))
 
         mock_logger.error.assert_called_once_with(
-            f"Unable to create refund transaction for payment [ {mock_payment.id} ] "
+            f"[refund_from_stripe_task] Unable to create CT payment's refund transaction "
+            f"object for [ {mock_payment.id} ] "
             f"on Stripe refund {EXAMPLE_RETURNED_ORDER_STRIPE_CLIENT_PAYLOAD['stripe_refund']['id']} "
             f"with error Some error message and correlation id 123456"
         )

commerce_coordinator/apps/commercetools/utils.py

@@ -35,9 +35,10 @@ def get_braze_client():
     )
 
 
-def handle_commercetools_error(err: CommercetoolsError, context: str, is_info=False):
+def handle_commercetools_error(context_prefix, err: CommercetoolsError, context: str, is_info=False):
     """Handles commercetools errors."""
-    error_message = f"[CommercetoolsError] {context} - Correlation ID: {err.correlation_id}, Details: {err.errors}"
+    error_message = (f"[CommercetoolsError] {context_prefix} {context} "
+                     f"- Correlation ID: {err.correlation_id}, Details: {err.errors}")
     if is_info:
         logger.info(error_message)
     else:

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: {input_data}')
+        logger.info(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: {input_data}')
+        logger.info(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: {input_data}')
+        logger.info(f'[CT-{tag}] Message received from commercetools with details: {input_data}')
 
         message_details = OrderReturnedViewMessageInputSerializer(data=input_data)
         message_details.is_valid(raise_exception=True)