chore: added logs to note time for commercetools calls (#304)

commerce_coordinator/apps/commercetools/clients.py

@@ -187,11 +187,14 @@ def get_customer_by_lms_user_id(self, lms_user_id: int) -> Optional[CTCustomer]:
 
         edx_lms_user_id_key = EdXFieldNames.LMS_USER_ID
 
+        start_time = datetime.datetime.now()
         results = self.base_client.customers.query(
             where=f'custom(fields({edx_lms_user_id_key}=:id))',
             limit=2,
             predicate_var={'id': f"{lms_user_id}"}
         )
+        duration = (datetime.datetime.now() - start_time).total_seconds()
+        logger.info(f"[Performance Check] - customerId query took {duration} seconds")
 
         if results.count > 1:
             # We are unable due to CT Limitations to enforce unique LMS ID values on Customers on the catalog side, so
@@ -260,6 +263,7 @@ def get_orders(self, customer_id: str, offset=0,
                     f"customer with ID {customer_id}")
         order_where_clause = f"orderState=\"{order_state}\""
 
+        start_time = datetime.datetime.now()
         values = self.base_client.orders.query(
             where=["customerId=:cid", order_where_clause],
             predicate_var={'cid': customer_id},
@@ -268,6 +272,8 @@ def get_orders(self, customer_id: str, offset=0,
             offset=offset,
             expand=list(expand)
         )
+        duration = (datetime.datetime.now() - start_time).total_seconds()
+        logger.info(f"[Performance Check] get_orders call took {duration} seconds")
 
         return PaginatedResult(values.results, values.total, values.offset)
 
@@ -327,7 +333,11 @@ def get_product_variant_by_course_run(self, cr_id: str) -> Optional[CTProductVar
         Args:
             cr_id: variant course run key
         """
+        start_time = datetime.datetime.now()
         results = self.base_client.product_projections.search(False, filter=f"variants.sku:\"{cr_id}\"").results
+        duration = (datetime.datetime.now() - start_time).total_seconds()
+        logger.info(
+            f"[Performance Check] get_product_variant_by_course_run took {duration} seconds")
 
         if len(results) < 1:  # pragma no cover
             return None

commerce_coordinator/apps/commercetools/pipeline.py

@@ -2,6 +2,7 @@
 Commercetools filter pipelines
 """
 import decimal
+from datetime import datetime
 from logging import getLogger
 
 import attrs
@@ -102,7 +103,10 @@ def run_filter(self, active_order_management_system, order_number, **kwargs):  #
 
         try:
             ct_api_client = CommercetoolsAPIClient()
+            start_time = datetime.now()
             ct_order = ct_api_client.get_order_by_number(order_number=order_number)
+            duration = (datetime.now() - start_time).total_seconds()
+            log.info(f"[Performance Check] get_order_by_number call took {duration} seconds")
 
             ret_val = {
                 "order_data": ct_order,
@@ -155,7 +159,10 @@ def run_filter(self, active_order_management_system, order_id, **kwargs):  # pyl
 
         try:
             ct_api_client = CommercetoolsAPIClient()
+            start_time = datetime.now()
             ct_order = ct_api_client.get_order_by_id(order_id=order_id)
+            duration = (datetime.now() - start_time).total_seconds()
+            log.info(f"[Performance Check] get_order_by_id call took {duration} seconds")
 
             ret_val = {
                 "order_data": ct_order,

commerce_coordinator/apps/commercetools/serializers.py

@@ -87,6 +87,9 @@ class OrderFulfillViewInputSerializer(CoordinatorSerializer):
     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)
+    course_title = serializers.CharField(allow_null=False)
+    user_first_name = serializers.CharField(allow_null=False)
+    user_email = serializers.EmailField(allow_null=False)
 
 
 class OrderReturnedViewMessageLineItemReturnItemSerializer(CoordinatorSerializer):

commerce_coordinator/apps/commercetools/sub_messages/tasks.py

@@ -1,6 +1,8 @@
 """
 Commercetools Subscription Message tasks (Celery)
 """
+from datetime import datetime
+
 from celery import shared_task
 from celery.utils.log import get_task_logger
 from commercetools import CommercetoolsError
@@ -59,7 +61,10 @@ def fulfill_order_placed_message_signal_task(
     client = CommercetoolsAPIClient()
 
     try:
+        start_time = datetime.now()
         order = client.get_order_by_id(order_id)
+        duration = (datetime.now() - start_time).total_seconds()
+        logger.info(f"[Performance Check] get_order_by_id call took {duration} seconds")
     except CommercetoolsError as err:  # pragma no cover
         logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors},'
                      f'message id: {message_id}')
@@ -120,7 +125,10 @@ def fulfill_order_placed_message_signal_task(
             'course_mode': get_course_mode_from_ct_order(item),
             'item_quantity': item.quantity,
             'line_item_state_id': line_item_state_id,
-            'message_id': message_id
+            'message_id': message_id,
+            'user_first_name': customer.first_name,
+            'user_email': customer.email,
+            'course_title': item.name.get('en-US', '')
         })
 
         # the following throws and thus doesn't need to be a conditional

commerce_coordinator/apps/commercetools/utils.py

@@ -65,6 +65,27 @@ def send_order_confirmation_email(
         logger.exception(f"Encountered exception sending Order confirmation email. Exception: {exc}")
 
 
+def send_fulfillment_error_email(
+    lms_user_id, lms_user_email, canvas_entry_properties
+):
+    """ Sends fulfillment error email via Braze. """
+    recipients = [{"external_user_id": lms_user_id, "attributes": {
+        "email": lms_user_email,
+    }}]
+    canvas_id = settings.BRAZE_CT_FULFILLMENT_ERROR_CANVAS_ID
+
+    try:
+        braze_client = get_braze_client()
+        if braze_client:
+            braze_client.send_canvas_message(
+                canvas_id=canvas_id,
+                recipients=recipients,
+                canvas_entry_properties=canvas_entry_properties,
+            )
+    except Exception as exc:  # pylint: disable=broad-exception-caught
+        logger.exception(f"Encountered exception sending Fulfillment Error email. Exception: {exc}")
+
+
 def format_amount_for_braze_canvas(centAmount):
     """
     Utility to convert amount to dollar with 2 decimals percision. Also adds the Dollar signs to resulting value.

commerce_coordinator/apps/lms/signal_handlers.py

@@ -28,6 +28,9 @@ 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']
+        message_id=kwargs['message_id'],
+        user_first_name=kwargs['user_first_name'],
+        user_email=kwargs['user_email'],
+        course_title=kwargs['course_title']
     )
     return async_result.id

commerce_coordinator/apps/lms/tasks.py

@@ -1,22 +1,67 @@
 """
 LMS Celery tasks
 """
+import json
 
-from celery import shared_task
+from datetime import datetime
+
+from celery import Task, shared_task
 from celery.utils.log import get_task_logger
 from django.contrib.auth import get_user_model
 from requests import RequestException
 
 from commerce_coordinator.apps.commercetools.catalog_info.constants import TwoUKeys
 from commerce_coordinator.apps.commercetools.clients import CommercetoolsAPIClient
+from commerce_coordinator.apps.commercetools.utils import send_fulfillment_error_email
 from commerce_coordinator.apps.lms.clients import LMSAPIClient
 
 # Use the special Celery logger for our tasks
 logger = get_task_logger(__name__)
 User = get_user_model()
 
 
-@shared_task(bind=True, autoretry_for=(RequestException,), retry_kwargs={'max_retries': 5, 'countdown': 3})
+class CourseEnrollTaskAfterReturn(Task):
+    def on_failure(self, exc, task_id, args, kwargs, einfo):
+        error_message = json.loads(exc.response.text).get('message', '')
+        edx_lms_user_id = kwargs.get('edx_lms_user_id')
+        user_email = kwargs.get('user_email')
+        order_number = kwargs.get('order_number')
+        user_first_name = kwargs.get('user_first_name')
+        course_title = kwargs.get('course_title')
+
+        logger.error(
+            f"Task {self.name} failed after max retries with error message: {error_message} "
+            f"for user with User Id: {edx_lms_user_id}, Email: {user_email}, "
+            f"Order Number: {order_number}, Course Title: {course_title}"
+        )
+
+        if (
+            self.request.retries >= self.max_retries
+            and "course mode is expired or otherwise unavailable for course run" in error_message
+        ):
+
+            logger.info(
+                f"Sending Fulfillment Error Email for user with "
+                f"User ID: {edx_lms_user_id}, Email: {user_email}, "
+                f"Order Number: {order_number}, Course Title: {course_title}"
+            )
+
+            canvas_entry_properties = {
+                'order_number': order_number,
+                'product_type': 'course',
+                'product_name': course_title,
+                'first_name': user_first_name,
+            }
+            # Send failure notification email
+            send_fulfillment_error_email(edx_lms_user_id, user_email, canvas_entry_properties)
+
+
+@shared_task(
+    bind=True,
+    autoretry_for=(RequestException,),
+    retry_kwargs={'max_retries': 5, 'countdown': 3},
+    base=CourseEnrollTaskAfterReturn,
+)
 def fulfill_order_placed_send_enroll_in_course_task(
     self,
     course_id,
@@ -32,7 +77,10 @@ def fulfill_order_placed_send_enroll_in_course_task(
     line_item_id,
     item_quantity,
     line_item_state_id,
-    message_id
+    message_id,
+    user_first_name,
+    user_email,
+    course_title
 ):
     """
     Celery task for order placed fulfillment and enrollment via LMS Enrollment API.
@@ -92,7 +140,10 @@ def fulfill_order_placed_send_enroll_in_course_task(
         client = CommercetoolsAPIClient()
         # A retry means the current line item state on the order would be a failure state
         line_item_state_id = client.get_state_by_key(TwoUKeys.FAILURE_FULFILMENT_STATE).id
+        start_time = datetime.now()
         order_version = client.get_order_by_id(order_id).version
+        duration = (datetime.now() - start_time).total_seconds()
+        logger.info(f"[Performance Check] get_order_by_id call took {duration} seconds")
 
     line_item_state_payload = {
         'order_id': order_id,

commerce_coordinator/settings/base.py

@@ -468,6 +468,7 @@ def root(*path_fragments):
 BRAZE_API_KEY = None
 BRAZE_API_SERVER = None
 BRAZE_CT_ORDER_CONFIRMATION_CANVAS_ID = ''
+BRAZE_CT_FULFILLMENT_ERROR_CANVAS_ID = ''
 
 # SEGMENT WRITE KEY
 SEGMENT_KEY = None

commerce_coordinator/settings/local.py

@@ -7,6 +7,7 @@
     'host.docker.internal',
     'localhost',
     '.ngrok-free.app',
+    '.share.zrok.io',
 )
 
 INSTALLED_APPS += (