Merge branch 'main' into jolivier/SONIC-561/Anonymize-Retired-User-CT

commerce_coordinator/apps/commercetools/clients.py

@@ -176,6 +176,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(
@@ -187,15 +189,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)
 
@@ -205,7 +212,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
@@ -218,6 +226,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,
@@ -240,6 +249,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],
@@ -270,17 +281,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]:
         """
@@ -329,6 +344,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,
@@ -368,6 +385,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,
@@ -400,6 +419,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()
@@ -449,6 +471,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

@@ -206,6 +206,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
 
@@ -233,9 +235,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
 
@@ -304,9 +310,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()
@@ -327,9 +335,15 @@ 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')
@@ -38,12 +40,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 +86,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):
@@ -109,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

@@ -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
 
@@ -30,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
 
@@ -40,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