diff --git a/commerce_coordinator/apps/commercetools/clients.py b/commerce_coordinator/apps/commercetools/clients.py index c00410db0..fad2cd674 100644 --- a/commerce_coordinator/apps/commercetools/clients.py +++ b/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 diff --git a/commerce_coordinator/apps/commercetools/pipeline.py b/commerce_coordinator/apps/commercetools/pipeline.py index ddb557f60..9a13d90c9 100644 --- a/commerce_coordinator/apps/commercetools/pipeline.py +++ b/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, diff --git a/commerce_coordinator/apps/commercetools/serializers.py b/commerce_coordinator/apps/commercetools/serializers.py index fafac844e..5a3775817 100644 --- a/commerce_coordinator/apps/commercetools/serializers.py +++ b/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): diff --git a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py index e244ddbd8..b6505d6ff 100644 --- a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py +++ b/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 diff --git a/commerce_coordinator/apps/commercetools/utils.py b/commerce_coordinator/apps/commercetools/utils.py index 8f4f6ca60..49a0b239e 100644 --- a/commerce_coordinator/apps/commercetools/utils.py +++ b/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. diff --git a/commerce_coordinator/apps/lms/signal_handlers.py b/commerce_coordinator/apps/lms/signal_handlers.py index e9cccfef1..da72e3533 100644 --- a/commerce_coordinator/apps/lms/signal_handlers.py +++ b/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 diff --git a/commerce_coordinator/apps/lms/tasks.py b/commerce_coordinator/apps/lms/tasks.py index 5e941fd74..4cd2bc93d 100644 --- a/commerce_coordinator/apps/lms/tasks.py +++ b/commerce_coordinator/apps/lms/tasks.py @@ -1,14 +1,18 @@ """ 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 @@ -16,7 +20,48 @@ 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, diff --git a/commerce_coordinator/settings/base.py b/commerce_coordinator/settings/base.py index 491d659bc..a51d87cbe 100644 --- a/commerce_coordinator/settings/base.py +++ b/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 diff --git a/commerce_coordinator/settings/local.py b/commerce_coordinator/settings/local.py index 17bd5c978..6d7803d6e 100644 --- a/commerce_coordinator/settings/local.py +++ b/commerce_coordinator/settings/local.py @@ -7,6 +7,7 @@ 'host.docker.internal', 'localhost', '.ngrok-free.app', + '.share.zrok.io', ) INSTALLED_APPS += (