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/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}')

commerce_coordinator/apps/lms/tasks.py

@@ -2,6 +2,8 @@
 LMS Celery tasks
 """
 
+from datetime import datetime
+
 from celery import shared_task
 from celery.utils.log import get_task_logger
 from django.contrib.auth import get_user_model
@@ -92,7 +94,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,