feat: additional logging (#253)

* feat: additional logging

* fix: coverage

* fix: quality

* fix: removed potential pii log

* fix: re-added log

commerce_coordinator/apps/commercetools/clients.py

@@ -174,6 +174,8 @@ def get_customer_by_lms_user_id(self, lms_user_id: int) -> Optional[CTCustomer]:
              is returned.
         """
 
+        logger.info(f"[CommercetoolsAPIClient] - Attempting to get customer with LMS user id: {lms_user_id}")
+
         edx_lms_user_id_key = EdXFieldNames.LMS_USER_ID
 
         results = self.base_client.customers.query(
@@ -185,15 +187,20 @@ def get_customer_by_lms_user_id(self, lms_user_id: int) -> Optional[CTCustomer]:
         if results.count > 1:
             # We are unable due to CT Limitations to enforce unique LMS ID values on Customers on the catalog side, so
             #   let's do a backhanded check by trying to pull 2 users and erroring if we find a discrepancy.
+            logger.info(f"[CommercetoolsAPIClient] - More than one customer found with LMS "
+                        f"user id: {lms_user_id}, raising error")
             raise ValueError("More than one user was returned from the catalog with this edX LMS User ID, these must "
                              "be unique.")
 
         if results.count == 0:
+            logger.info(f"[CommercetoolsAPIClient] - No customer found with LMS user id: {lms_user_id}")
             return None
         else:
+            logger.info(f"[CommercetoolsAPIClient] - Customer found with LMS user id: {lms_user_id}")
             return results.results[0]
 
-    def get_order_by_id(self, order_id: str, expand: ExpandList = DEFAULT_ORDER_EXPANSION) -> CTOrder:
+    def get_order_by_id(self, order_id: str, expand: ExpandList = DEFAULT_ORDER_EXPANSION) \
+            -> CTOrder:  # pragma no cover
         """
         Fetch an order by the Order ID (UUID)
 
@@ -203,7 +210,8 @@ def get_order_by_id(self, order_id: str, expand: ExpandList = DEFAULT_ORDER_EXPA
 
         Returns (CTOrder): Order with Expanded Properties
         """
-        return self.base_client.orders.get_by_id(order_id, expand=list(expand))  # pragma no cover
+        logger.info(f"[CommercetoolsAPIClient] - Attempting to find order with id: {order_id}")
+        return self.base_client.orders.get_by_id(order_id, expand=list(expand))
 
     def get_order_by_number(self, order_number: str, expand: ExpandList = DEFAULT_ORDER_EXPANSION)  \
             -> CTOrder:  # pragma no cover
@@ -216,6 +224,7 @@ def get_order_by_number(self, order_number: str, expand: ExpandList = DEFAULT_OR
 
         Returns (CTOrder): Order with Expanded Properties
         """
+        logger.info(f"[CommercetoolsAPIClient] - Attempting to find order with number {order_number}")
         return self.base_client.orders.get_by_order_number(order_number, expand=list(expand))
 
     def get_orders(self, customer: CTCustomer, offset=0,
@@ -238,6 +247,8 @@ def get_orders(self, customer: CTCustomer, offset=0,
         See sample response in tests.py
 
         """
+        logger.info(f"[CommercetoolsAPIClient] - Attempting to find all completed orders for "
+                    f"customer with ID {customer.id}")
         order_where_clause = f"orderState=\"{order_state}\""
         values = self.base_client.orders.query(
             where=["customerId=:cid", order_where_clause],
@@ -268,17 +279,21 @@ def get_orders_for_customer(self, edx_lms_user_id: int, offset=0,
 
         return orders, customer
 
-    def get_customer_by_id(self, customer_id: str) -> CTCustomer:
-        return self.base_client.customers.get_by_id(customer_id)  # pragma no cover
+    def get_customer_by_id(self, customer_id: str) -> CTCustomer:  # pragma no cover
+        logger.info(f"[CommercetoolsAPIClient] - Attempting to find customer with ID {customer_id}")
+        return self.base_client.customers.get_by_id(customer_id)
 
-    def get_state_by_id(self, state_id: str) -> CTLineItemState:
-        return self.base_client.states.get_by_id(state_id)  # pragma no cover
+    def get_state_by_id(self, state_id: str) -> CTLineItemState:  # pragma no cover
+        logger.info(f"[CommercetoolsAPIClient] - Attempting to find state with id {state_id}")
+        return self.base_client.states.get_by_id(state_id)
 
-    def get_state_by_key(self, state_key: str) -> CTLineItemState:
-        return self.base_client.states.get_by_key(state_key)  # pragma no cover
+    def get_state_by_key(self, state_key: str) -> CTLineItemState:  # pragma no cover
+        logger.info(f"[CommercetoolsAPIClient] - Attempting to find state with key {state_key}")
+        return self.base_client.states.get_by_key(state_key)
 
-    def get_payment_by_key(self, payment_key: str) -> CTPayment:
-        return self.base_client.payments.get_by_key(payment_key)  # pragma no cover
+    def get_payment_by_key(self, payment_key: str) -> CTPayment:  # pragma no cover
+        logger.info(f"[CommercetoolsAPIClient] - Attempting to find payment with key {payment_key}")
+        return self.base_client.payments.get_by_key(payment_key)
 
     def get_product_variant_by_course_run(self, cr_id: str) -> Optional[CTProductVariant]:
         """
@@ -327,6 +342,8 @@ def create_return_for_order(self, order_id: str, order_version: int, order_line_
             return_item_draft_comment = f'Creating return item for order {order_id} with ' \
                                         f'order line item ID {order_line_item_id}'
 
+            logger.info(f"[CommercetoolsAPIClient] - {return_item_draft_comment}")
+
             return_item_draft = ReturnItemDraft(
                 quantity=1,
                 line_item_id=order_line_item_id,
@@ -366,6 +383,8 @@ def update_return_payment_state_after_successful_refund(self, order_id: str,
         Raises Exception: Error if update was unsuccessful.
         """
         try:
+            logger.info(f"[CommercetoolsAPIClient] - Updating payment state for return "
+                        f"with id {return_line_item_return_id} to '{ReturnPaymentState.REFUNDED}'.")
 
             return_payment_state_action = OrderSetReturnPaymentStateAction(
                 return_item_id=return_line_item_return_id,
@@ -398,6 +417,9 @@ def create_return_payment_transaction(
         Raises Exception: Error if creation was unsuccessful.
         """
         try:
+            logger.info(f"[CommercetoolsAPIClient] - Creating refund transaction for payment with ID {payment_id} "
+                        f"following successful Stripe refund {stripe_refund.id}")
+
             amount_as_money = CTMoney(
                 cent_amount=stripe_refund.amount,
                 currency_code=stripe_refund.currency.upper()
@@ -447,6 +469,9 @@ def update_line_item_transition_state_on_fulfillment(self, order_id: str, order_
 
         from_state_key = self.get_state_by_id(from_state_id).key
 
+        logger.info(f"[CommercetoolsAPIClient] - Transitioning line item state for order with ID {order_id}"
+                    f"from {from_state_key} to {new_state_key}")
+
         try:
             if new_state_key != from_state_key:
                 transition_line_item_state_action = OrderTransitionLineItemStateAction(

commerce_coordinator/apps/commercetools/filters.py

@@ -10,7 +10,7 @@ class OrderRefundRequested(OpenEdxPublicFilter):
     filter_type = "org.edx.coordinator.commercetools.order.refund.requested.v1"
 
     @classmethod
-    def run_filter(cls, order_id, return_line_item_return_id):
+    def run_filter(cls, order_id, return_line_item_return_id, message_id):
         """
         Call the PipelineStep(s) defined for this filter.
         Arguments:
@@ -19,4 +19,6 @@ def run_filter(cls, order_id, return_line_item_return_id):
         Returns:
             order_refund: Updated order with return item attached
         """
-        return super().run_pipeline(order_id=order_id, return_line_item_return_id=return_line_item_return_id)
+        return super().run_pipeline(order_id=order_id,
+                                    return_line_item_return_id=return_line_item_return_id,
+                                    message_id=message_id)

commerce_coordinator/apps/commercetools/pipeline.py

@@ -205,6 +205,8 @@ def run_filter(
             returned_line_item_return_id (str): Updated Commercetools order's return item ID
 
         """
+        tag = type(self).__name__
+
         if active_order_management_system != COMMERCETOOLS_ORDER_MANAGEMENT_SYSTEM:  # pragma no cover
             return PipelineCommand.CONTINUE.value
 
@@ -232,9 +234,13 @@ def run_filter(
                     f'order line item id {order_line_item_id}')
         except CommercetoolsError as err:  # pragma no cover
             # TODO: FIX Per SONIC-354
+            log.info(f"[{tag}] Unsuccessful attempt to create order return with details: "
+                     f"[order_id: {order_id}, order_line_item_id: {order_line_item_id}")
             log.exception(f"[{type(self).__name__}] Commercetools Error: {err}, {err.errors}")
             raise OpenEdxFilterException(str(err)) from err
-        except HTTPError as err:
+        except HTTPError as err:  # pragma no cover
+            log.info(f"[{tag}] Unsuccessful attempt to create order return with details: "
+                     f"[order_id: {order_id}, order_line_item_id: {order_line_item_id}")
             log.exception(f"[{type(self).__name__}] HTTP Error: {err}")
             return PipelineCommand.CONTINUE.value
 
@@ -303,9 +309,11 @@ def run_filter(
         tag = type(self).__name__
 
         if active_order_management_system != COMMERCETOOLS_ORDER_MANAGEMENT_SYSTEM:  # pragma no cover
+            log.info(f"[{tag}] active order management system is not {COMMERCETOOLS_ORDER_MANAGEMENT_SYSTEM}, skipping")
             return PipelineCommand.CONTINUE.value
 
         if refund_response == "charge_already_refunded" or has_been_refunded:
+            log.info(f"[{tag}] refund has already been processed, skipping refund payment transaction creation")
             return PipelineCommand.CONTINUE.value
 
         ct_api_client = CommercetoolsAPIClient()
@@ -326,8 +334,14 @@ def run_filter(
                 'returned_payment': updated_payment
             }
         except CommercetoolsError as err:  # pragma no cover
+            log.info(f"[{tag}] Unsuccessful attempt to create refund payment transaction with details: "
+                     f"[stripe_payment_intent_id: {refund_response['payment_intent']}, "
+                     f"payment_id: {payment_on_order.id}], message_id: {kwargs['message_id']}")
             log.exception(f"[{tag}] Commercetools Error: {err}, {err.errors}")
             return PipelineCommand.CONTINUE.value
         except HTTPError as err:  # pragma no cover
+            log.info(f"[{tag}] Unsuccessful attempt to create refund payment transaction with details: "
+                     f"[stripe_payment_intent_id: {refund_response['payment_intent']}, "
+                     f"payment_id: {payment_on_order.id}], message_id: {kwargs['message_id']}")
             log.exception(f"[{tag}] HTTP Error: {err}")
             return PipelineCommand.CONTINUE.value

commerce_coordinator/apps/commercetools/serializers.py

@@ -8,11 +8,13 @@ class OrderSanctionedViewMessageDetailSerializer(CoordinatorSerializer):
     """
     Serializer for CommerceTools message 'detail'
     """
+    id = serializers.CharField()
     resource = serializers.DictField(child=serializers.CharField())
     type = serializers.CharField(allow_null=False)
 
     def to_representation(self, instance):
         representation = super().to_representation(instance)
+        representation['message_id'] = representation.pop('id')
         representation['type'] = representation.pop('type')
 
         order_id = representation['resource'].get('id')
@@ -112,11 +114,13 @@ class OrderReturnedViewMessageDetailSerializer(CoordinatorSerializer):
     """
     Serializer for OrderReturnedView message detail.
     """
+    id = serializers.CharField()
     resource = serializers.DictField(child=serializers.CharField())
     returnInfo = OrderReturnedViewMessageReturnInfoSerializer()
 
     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

commerce_coordinator/apps/commercetools/sub_messages/signals_delayed.py

@@ -31,6 +31,7 @@ def fulfill_order_sanctioned_message_signal(**kwargs):
     """ CoordinatorSignal receiver to invoke Celery Task fulfill_order_sanctioned_message_signal"""
     async_result = fulfill_order_sanctioned_message_signal_task.delay(
         order_id=kwargs['order_id'],
+        message_id=kwargs['message_id']
     )
     return async_result.id
 
@@ -41,5 +42,6 @@ def fulfill_order_returned_signal(**kwargs):
     async_result = fulfill_order_returned_signal_task.delay(
         order_id=kwargs['order_id'],
         return_line_item_return_id=kwargs['return_line_item_return_id'],
+        message_id=kwargs['message_id']
     )
     return async_result.id

commerce_coordinator/apps/commercetools/sub_messages/tasks.py

@@ -139,6 +139,7 @@ def fulfill_order_placed_message_signal_task(
 @shared_task(autoretry_for=(RequestException, CommercetoolsError), retry_kwargs={'max_retries': 5, 'countdown': 3})
 def fulfill_order_sanctioned_message_signal_task(
     order_id,
+    message_id
 ):
     """Celery task for an order sanctioned message."""
 
@@ -153,7 +154,7 @@ def fulfill_order_sanctioned_message_signal_task(
 
     order_workflow_state = get_edx_order_workflow_state_key(order)
     if not order_workflow_state:
-        logger.debug(f'[CT-{tag}] order %s has no workflow/transition state', order_id)
+        logger.info(f'[CT-{tag}] order {order_id} has no workflow/transition state')
 
     try:
         customer = client.get_customer_by_id(order.customer_id)
@@ -163,21 +164,19 @@ def fulfill_order_sanctioned_message_signal_task(
         return False
 
     if not (customer and order and is_edx_lms_order(order)):
-        logger.info(f'[CT-{tag}] order %s is not an edX order', order_id)
+        logger.info(f'[CT-{tag}] order {order_id} is not an edX order')
         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 %s', lms_user_name)
+        logger.info(f'[CT-{tag}] calling lms to deactivate user {lms_user_name}.')
 
-        LMSAPIClient().deactivate_user(lms_user_name)
+        LMSAPIClient().deactivate_user(lms_user_name, message_id)
         return True
     else:
         logger.error(
-            f'[CT-{tag}] order state for order %s is not %s. Actual value is %s',
-            order_id,
-            TwoUKeys.SDN_SANCTIONED_ORDER_STATE,
-            order_workflow_state
+            f'[CT-{tag}] order state for order {order_id} is not {TwoUKeys.SDN_SANCTIONED_ORDER_STATE}. '
+            f'Actual value is {order_workflow_state}'
         )
         return False
 
@@ -186,7 +185,8 @@ def fulfill_order_sanctioned_message_signal_task(
 @shared_task(autoretry_for=(RequestException, CommercetoolsError), retry_kwargs={'max_retries': 5, 'countdown': 3})
 def fulfill_order_returned_signal_task(
     order_id,
-    return_line_item_return_id
+    return_line_item_return_id,
+    message_id
 ):
     """Celery task for an order return (and refunded) message."""
 
@@ -241,41 +241,40 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_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 '
+        logger.error(f'[CT-{tag}] Customer not found: {order.customer_id} for order {order_id} with '
                      f'CT error {err}, {err.errors}')
         return False
 
     if not (customer and order and is_edx_lms_order(order)):  # pragma no cover
-        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')
         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 %s', payment_intent_id)
+    logger.debug(f'[CT-{tag}] calling stripe to refund payment intent {payment_intent_id}')
 
     # Return payment if payment intent id is set
     if payment_intent_id is not None:
         result = OrderRefundRequested.run_filter(
-            order_id=order_id, return_line_item_return_id=return_line_item_return_id
+            order_id=order_id, return_line_item_return_id=return_line_item_return_id, message_id=message_id
         )
 
         if 'refund_response' in result and result['refund_response']:
             if result['refund_response'] == 'charge_already_refunded':
-                logger.debug(f'[CT-{tag}] payment intent %s already has refund transaction, '
-                             f'sending Zendesk email', payment_intent_id)
+                logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} already has refund transaction, '
+                             f'sending Zendesk email')
                 send_refund_notification(customer, order_id)
             else:
-                logger.debug(f'[CT-{tag}] payment intent %s refunded', payment_intent_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 %s in %s',
-                        lms_user_name, course_run
+                        f'[CT-{tag}] calling lms to unenroll user {lms_user_name} in {course_run}'
                     )
 
                     product = {
@@ -302,7 +301,7 @@ 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 %s not refunded', payment_intent_id)
+            logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} not refunded. Message_id: {message_id}')
             return send_refund_notification(customer, order_id)
 
     return True

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

@@ -56,6 +56,7 @@ class SanctionedOrderPlacedMessageSignalTest(CoordinatorSignalReceiverTestCase):
     """ Commercetools Sanctioned Order Placed Signal Tester"""
     mock_parameters = {
         'order_id': uuid4_str(),
+        'message_id': uuid4_str()
     }
 
     def test_correct_arguments_passed(self, mock_task):
@@ -84,6 +85,7 @@ class ReturnedOrderPlacedMessageSignalTest(CoordinatorSignalReceiverTestCase):
     mock_parameters = {
         'order_id': uuid4_str(),
         'return_line_item_return_id': uuid4_str(),
+        'message_id': uuid4_str()
     }
 
     def test_correct_arguments_passed(self, mock_task):