From f4364994b60ed36031d5a59c7534070e5296e206 Mon Sep 17 00:00:00 2001 From: NoyanAziz Date: Mon, 2 Dec 2024 00:43:38 +0500 Subject: [PATCH] chore: added logs to note time for commercetools calls (#304) --- commerce_coordinator/apps/commercetools/clients.py | 10 ++++++++++ commerce_coordinator/apps/commercetools/pipeline.py | 7 +++++++ .../apps/commercetools/sub_messages/tasks.py | 5 +++++ commerce_coordinator/apps/lms/tasks.py | 5 +++++ 4 files changed, 27 insertions(+) diff --git a/commerce_coordinator/apps/commercetools/clients.py b/commerce_coordinator/apps/commercetools/clients.py index c00410db..fad2cd67 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 ddb557f6..9a13d90c 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/sub_messages/tasks.py b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py index e244ddbd..0c0e9c3d 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}') diff --git a/commerce_coordinator/apps/lms/tasks.py b/commerce_coordinator/apps/lms/tasks.py index 5e941fd7..5a825256 100644 --- a/commerce_coordinator/apps/lms/tasks.py +++ b/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,