From 09259ca4c94b01d51d4c6f9ac592a1f61e7365c4 Mon Sep 17 00:00:00 2001 From: Muhammad Noyan Aziz Date: Thu, 7 Nov 2024 17:02:39 +0500 Subject: [PATCH 1/8] feat: added logs for investigating time of each call inside UserOrdersView on stage --- .../apps/commercetools/clients.py | 19 +++++++++++++++ .../apps/commercetools/pipeline.py | 24 +++++++++++++++++++ .../apps/ecommerce/clients.py | 13 ++++++++++ .../apps/ecommerce/pipeline.py | 3 +++ .../apps/frontend_app_ecommerce/views.py | 9 +++++++ 5 files changed, 68 insertions(+) diff --git a/commerce_coordinator/apps/commercetools/clients.py b/commerce_coordinator/apps/commercetools/clients.py index 0df503e9..3899bfb0 100644 --- a/commerce_coordinator/apps/commercetools/clients.py +++ b/commerce_coordinator/apps/commercetools/clients.py @@ -258,6 +258,9 @@ def get_orders(self, customer: CTCustomer, offset=0, logger.info(f"[CommercetoolsAPIClient] - Attempting to find all completed orders for " f"customer with ID {customer.id}") order_where_clause = f"orderState=\"{order_state}\"" + + logger.info( + "[UserOrdersView] [CommercetoolsAPIClient] - Get orders query call started at %s", datetime.datetime.now()) values = self.base_client.orders.query( where=["customerId=:cid", order_where_clause], predicate_var={'cid': customer.id}, @@ -266,6 +269,10 @@ def get_orders(self, customer: CTCustomer, offset=0, offset=offset, expand=list(expand) ) + logger.info( + "[UserOrdersView] [CommercetoolsAPIClient] - Get orders query call finished at %s", + datetime.datetime.now() + ) return PaginatedResult(values.results, values.total, values.offset) @@ -278,12 +285,24 @@ def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, offset: limit: """ + logger.info( + "[UserOrdersView] [CommercetoolsAPIClient] - Getting customer if from lms id call started at %s", + datetime.datetime.now() + ) customer = self.get_customer_by_lms_user_id(edx_lms_user_id) + logger.info( + "[UserOrdersView] [CommercetoolsAPIClient] - Getting customer if from lms id call finished at %s", + datetime.datetime.now() + ) if customer is None: # pragma: no cover raise ValueError(f'Unable to locate customer with ID #{edx_lms_user_id}') + logger.info("[UserOrdersView] [CommercetoolsAPIClient] - Get orders call started at %s", + datetime.datetime.now()) orders = self.get_orders(customer, offset, limit) + logger.info("[UserOrdersView] [CommercetoolsAPIClient] - Get orders call finished at %s", + datetime.datetime.now()) return orders, customer diff --git a/commerce_coordinator/apps/commercetools/pipeline.py b/commerce_coordinator/apps/commercetools/pipeline.py index f2a938fa..a8e48090 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 @@ -44,26 +45,49 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- order_data: any preliminary orders (from an earlier pipeline step) we want to append to Returns: """ + log.info("[UserOrdersView] [GetCommercetoolsOrders] Starting pipeline step execution at %s", datetime.now()) if not is_redirect_to_commercetools_enabled_for_user(request): return PipelineCommand.CONTINUE.value try: ct_api_client = CommercetoolsAPIClient() + log.info( + "[UserOrdersView] [GetCommercetoolsOrders] get_orders_for_customer call started at %s", + datetime.now() + ) ct_orders = ct_api_client.get_orders_for_customer( edx_lms_user_id=params["edx_lms_user_id"], limit=params["page_size"], offset=params["page"] * params["page_size"] ) + log.info( + "[UserOrdersView] [GetCommercetoolsOrders] get_orders_for_customer call finished at %s", + datetime.now() + ) + log.info( + "[UserOrdersView] [GetCommercetoolsOrders] orders to attrs objects processing started at %s", + datetime.now() + ) # noinspection PyTypeChecker converted_orders = [attrs.asdict(order_from_commercetools(x, ct_orders[1])) for x in ct_orders[0].results] + log.info( + "[UserOrdersView] [GetCommercetoolsOrders] orders to attrs objects processing finished at %s", + datetime.now() + ) + log.info("[UserOrdersView] [GetCommercetoolsOrders] Orders rebuild call started at %s", datetime.now()) order_data.append( ct_orders[0].rebuild(converted_orders) ) + log.info("[UserOrdersView] [GetCommercetoolsOrders] Orders rebuild call finished at %s", datetime.now()) + log.info( + "[UserOrdersView] [GetCommercetoolsOrders] Completed pipeline step execution at %s", + datetime.now() + ) return { "order_data": order_data } diff --git a/commerce_coordinator/apps/ecommerce/clients.py b/commerce_coordinator/apps/ecommerce/clients.py index 1f04d4f5..a40939ce 100644 --- a/commerce_coordinator/apps/ecommerce/clients.py +++ b/commerce_coordinator/apps/ecommerce/clients.py @@ -2,6 +2,7 @@ API clients for ecommerce app. """ import logging +from datetime import datetime from django.conf import settings from requests.exceptions import RequestException @@ -33,12 +34,24 @@ def get_orders(self, query_params): See sample response in tests.py """ + logger.info('[UserOrdersView] EcommerceAPIClient - get_orders method called at %s', datetime.now()) + try: resource_url = urljoin_directory(self.api_base_url, '/orders') + logger.info( + '[UserOrdersView] EcommerceAPIClient - Legacy ecommerce get_orders API called at: %s', + datetime.now() + ) response = self.client.get(resource_url, params=query_params) + logger.info( + '[UserOrdersView] EcommerceAPIClient - Legacy ecommerce get_orders API finished at: %s', + datetime.now() + ) response.raise_for_status() self.log_request_response(logger, response) except RequestException as exc: self.log_request_exception(logger, exc) raise + + logger.info('[UserOrdersView] EcommerceAPIClient - get_orders method finished at %s', datetime.now()) return response.json() diff --git a/commerce_coordinator/apps/ecommerce/pipeline.py b/commerce_coordinator/apps/ecommerce/pipeline.py index 32edd8e3..ae7cec95 100644 --- a/commerce_coordinator/apps/ecommerce/pipeline.py +++ b/commerce_coordinator/apps/ecommerce/pipeline.py @@ -1,6 +1,7 @@ """ Ecommerce filter pipelines """ +from datetime import datetime from logging import getLogger from django.conf import settings @@ -39,6 +40,7 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- params: arguments passed through from the original order history url querystring order_data: any preliminary orders (from an earlier pipeline step) we want to append to """ + log.info("[UserOrdersView] [GetEcommerceOrders] Starting pipeline step execution at %s", datetime.now()) new_params = params.copy() # Ecommerce starts pagination from 1, other systems from 0, since the invoker assumes 0, we're always 1 off. @@ -50,6 +52,7 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- order_data.append(ecommerce_response) + log.info("[UserOrdersView] [GetEcommerceOrders] Completed pipeline step execution at %s", datetime.now()) return { "order_data": order_data } diff --git a/commerce_coordinator/apps/frontend_app_ecommerce/views.py b/commerce_coordinator/apps/frontend_app_ecommerce/views.py index a46a98f9..8c2c11f3 100644 --- a/commerce_coordinator/apps/frontend_app_ecommerce/views.py +++ b/commerce_coordinator/apps/frontend_app_ecommerce/views.py @@ -75,6 +75,8 @@ class UserOrdersView(APIView): def get(self, request): """Return paginated response of user's order history.""" + logger.info("[UserOrdersView] GET method started at: %s", datetime.now()) + user = request.user user.add_lms_user_id("UserOrdersView GET method") # build parameters @@ -93,18 +95,25 @@ def get(self, request): if not request.user.lms_user_id: # pragma: no cover raise PermissionDenied(detail="Could not detect LMS user id.") + logger.info("[UserOrdersView] Filter run started at: %s", datetime.now()) order_data = OrderHistoryRequested.run_filter(request, params) + logger.info("[UserOrdersView] Filter run finished at: %s", datetime.now()) output_orders = [] + logger.info("[UserOrdersView] Looping through results starting at: %s", datetime.now()) for order_set in order_data: output_orders.extend(order_set['results']) + logger.info("[UserOrdersView] Looping through results finished at: %s", datetime.now()) + logger.info("[UserOrdersView] Sorting results for output starting at: %s", datetime.now()) output = { "count": request.query_params['page_size'], # This suppresses the ecomm mfe Order History Pagination ctrl "next": None, "previous": None, "results": sorted(output_orders, key=lambda item: date_conv(item["date_placed"]), reverse=True) } + logger.info("[UserOrdersView] Sorting results for output finished at: %s", datetime.now()) + logger.info("[UserOrdersView] GET method finished at: %s", datetime.now()) return Response(output) From da7b8b1b4f3a61e775df01f0f3fd259b55a74442 Mon Sep 17 00:00:00 2001 From: Muhammad Noyan Aziz Date: Thu, 7 Nov 2024 17:13:13 +0500 Subject: [PATCH 2/8] fix: log strings --- commerce_coordinator/apps/ecommerce/clients.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/commerce_coordinator/apps/ecommerce/clients.py b/commerce_coordinator/apps/ecommerce/clients.py index a40939ce..05e03913 100644 --- a/commerce_coordinator/apps/ecommerce/clients.py +++ b/commerce_coordinator/apps/ecommerce/clients.py @@ -34,17 +34,17 @@ def get_orders(self, query_params): See sample response in tests.py """ - logger.info('[UserOrdersView] EcommerceAPIClient - get_orders method called at %s', datetime.now()) + logger.info('[UserOrdersView] [EcommerceAPIClient] - get_orders method called at %s', datetime.now()) try: resource_url = urljoin_directory(self.api_base_url, '/orders') logger.info( - '[UserOrdersView] EcommerceAPIClient - Legacy ecommerce get_orders API called at: %s', + '[UserOrdersView] [EcommerceAPIClient] - Legacy ecommerce get_orders API called at: %s', datetime.now() ) response = self.client.get(resource_url, params=query_params) logger.info( - '[UserOrdersView] EcommerceAPIClient - Legacy ecommerce get_orders API finished at: %s', + '[UserOrdersView] [EcommerceAPIClient] - Legacy ecommerce get_orders API finished at: %s', datetime.now() ) response.raise_for_status() @@ -53,5 +53,5 @@ def get_orders(self, query_params): self.log_request_exception(logger, exc) raise - logger.info('[UserOrdersView] EcommerceAPIClient - get_orders method finished at %s', datetime.now()) + logger.info('[UserOrdersView] [EcommerceAPIClient] - get_orders method finished at %s', datetime.now()) return response.json() From b725fd975322cc13c50593e32095b96802bead6e Mon Sep 17 00:00:00 2001 From: Muhammad Noyan Aziz Date: Thu, 7 Nov 2024 19:22:36 +0500 Subject: [PATCH 3/8] fix: remove extra logs --- commerce_coordinator/apps/commercetools/pipeline.py | 8 -------- commerce_coordinator/apps/ecommerce/clients.py | 3 --- 2 files changed, 11 deletions(-) diff --git a/commerce_coordinator/apps/commercetools/pipeline.py b/commerce_coordinator/apps/commercetools/pipeline.py index a8e48090..903e91bf 100644 --- a/commerce_coordinator/apps/commercetools/pipeline.py +++ b/commerce_coordinator/apps/commercetools/pipeline.py @@ -52,19 +52,11 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- try: ct_api_client = CommercetoolsAPIClient() - log.info( - "[UserOrdersView] [GetCommercetoolsOrders] get_orders_for_customer call started at %s", - datetime.now() - ) ct_orders = ct_api_client.get_orders_for_customer( edx_lms_user_id=params["edx_lms_user_id"], limit=params["page_size"], offset=params["page"] * params["page_size"] ) - log.info( - "[UserOrdersView] [GetCommercetoolsOrders] get_orders_for_customer call finished at %s", - datetime.now() - ) log.info( "[UserOrdersView] [GetCommercetoolsOrders] orders to attrs objects processing started at %s", diff --git a/commerce_coordinator/apps/ecommerce/clients.py b/commerce_coordinator/apps/ecommerce/clients.py index 05e03913..6f1271f5 100644 --- a/commerce_coordinator/apps/ecommerce/clients.py +++ b/commerce_coordinator/apps/ecommerce/clients.py @@ -34,8 +34,6 @@ def get_orders(self, query_params): See sample response in tests.py """ - logger.info('[UserOrdersView] [EcommerceAPIClient] - get_orders method called at %s', datetime.now()) - try: resource_url = urljoin_directory(self.api_base_url, '/orders') logger.info( @@ -53,5 +51,4 @@ def get_orders(self, query_params): self.log_request_exception(logger, exc) raise - logger.info('[UserOrdersView] [EcommerceAPIClient] - get_orders method finished at %s', datetime.now()) return response.json() From 810cb9ef621daa337480ba678e8c64b2ba9cccc8 Mon Sep 17 00:00:00 2001 From: Muhammad Noyan Aziz Date: Thu, 7 Nov 2024 20:02:31 +0500 Subject: [PATCH 4/8] feat: added durations --- .../apps/commercetools/clients.py | 17 ++++++---- .../apps/commercetools/pipeline.py | 25 ++++++++++----- .../apps/ecommerce/clients.py | 9 ++++-- .../apps/ecommerce/pipeline.py | 8 +++-- .../apps/frontend_app_ecommerce/views.py | 31 +++++++++++++------ 5 files changed, 62 insertions(+), 28 deletions(-) diff --git a/commerce_coordinator/apps/commercetools/clients.py b/commerce_coordinator/apps/commercetools/clients.py index 3899bfb0..78d581f8 100644 --- a/commerce_coordinator/apps/commercetools/clients.py +++ b/commerce_coordinator/apps/commercetools/clients.py @@ -285,24 +285,29 @@ def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, offset: limit: """ + start_time = datetime.datetime.now() logger.info( "[UserOrdersView] [CommercetoolsAPIClient] - Getting customer if from lms id call started at %s", - datetime.datetime.now() + start_time ) customer = self.get_customer_by_lms_user_id(edx_lms_user_id) + end_time = datetime.datetime.now() logger.info( - "[UserOrdersView] [CommercetoolsAPIClient] - Getting customer if from lms id call finished at %s", - datetime.datetime.now() + "[UserOrdersView] [CommercetoolsAPIClient] - \ + Getting customer if from lms id call finished at %s with total duration: %s", + end_time, end_time - start_time ) if customer is None: # pragma: no cover raise ValueError(f'Unable to locate customer with ID #{edx_lms_user_id}') + start_time = datetime.datetime.now() logger.info("[UserOrdersView] [CommercetoolsAPIClient] - Get orders call started at %s", - datetime.datetime.now()) + start_time) orders = self.get_orders(customer, offset, limit) - logger.info("[UserOrdersView] [CommercetoolsAPIClient] - Get orders call finished at %s", - datetime.datetime.now()) + end_time = datetime.datetime.now() + logger.info("[UserOrdersView] [CommercetoolsAPIClient] - \ + Get orders call finished at %s with total duration: %s", end_time, end_time - start_time) return orders, customer diff --git a/commerce_coordinator/apps/commercetools/pipeline.py b/commerce_coordinator/apps/commercetools/pipeline.py index 903e91bf..d79fe0ad 100644 --- a/commerce_coordinator/apps/commercetools/pipeline.py +++ b/commerce_coordinator/apps/commercetools/pipeline.py @@ -45,7 +45,8 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- order_data: any preliminary orders (from an earlier pipeline step) we want to append to Returns: """ - log.info("[UserOrdersView] [GetCommercetoolsOrders] Starting pipeline step execution at %s", datetime.now()) + method_start_time = datetime.now() + log.info("[UserOrdersView] [GetCommercetoolsOrders] Starting pipeline step execution at %s", method_start_time) if not is_redirect_to_commercetools_enabled_for_user(request): return PipelineCommand.CONTINUE.value @@ -58,27 +59,35 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- offset=params["page"] * params["page_size"] ) + start_time = datetime.now() log.info( "[UserOrdersView] [GetCommercetoolsOrders] orders to attrs objects processing started at %s", - datetime.now() + start_time ) # noinspection PyTypeChecker converted_orders = [attrs.asdict(order_from_commercetools(x, ct_orders[1])) for x in ct_orders[0].results] + end_time = datetime.now() log.info( - "[UserOrdersView] [GetCommercetoolsOrders] orders to attrs objects processing finished at %s", - datetime.now() + "[UserOrdersView] [GetCommercetoolsOrders] \ + orders to attrs objects processing finished at %s with total duration: %s", + end_time, end_time - start_time ) - log.info("[UserOrdersView] [GetCommercetoolsOrders] Orders rebuild call started at %s", datetime.now()) + start_time = datetime.now() + log.info("[UserOrdersView] [GetCommercetoolsOrders] Orders rebuild call started at %s", start_time) order_data.append( ct_orders[0].rebuild(converted_orders) ) - log.info("[UserOrdersView] [GetCommercetoolsOrders] Orders rebuild call finished at %s", datetime.now()) + end_time = datetime.now() + log.info("[UserOrdersView] [GetCommercetoolsOrders] \ + Orders rebuild call finished at %s with total duration: %s", end_time, end_time - start_time) + method_end_time = datetime.now() log.info( - "[UserOrdersView] [GetCommercetoolsOrders] Completed pipeline step execution at %s", - datetime.now() + "[UserOrdersView] [GetCommercetoolsOrders] \ + Completed pipeline step execution at %s with total duration: %s", + method_end_time, method_end_time - method_start_time ) return { "order_data": order_data diff --git a/commerce_coordinator/apps/ecommerce/clients.py b/commerce_coordinator/apps/ecommerce/clients.py index 6f1271f5..da413c8e 100644 --- a/commerce_coordinator/apps/ecommerce/clients.py +++ b/commerce_coordinator/apps/ecommerce/clients.py @@ -36,14 +36,17 @@ def get_orders(self, query_params): """ try: resource_url = urljoin_directory(self.api_base_url, '/orders') + start_time = datetime.now() logger.info( '[UserOrdersView] [EcommerceAPIClient] - Legacy ecommerce get_orders API called at: %s', - datetime.now() + start_time ) response = self.client.get(resource_url, params=query_params) + end_time = datetime.now() logger.info( - '[UserOrdersView] [EcommerceAPIClient] - Legacy ecommerce get_orders API finished at: %s', - datetime.now() + '[UserOrdersView] [EcommerceAPIClient] \ + - Legacy ecommerce get_orders API finished at: %s with total duration: %s', + end_time, end_time - start_time ) response.raise_for_status() self.log_request_response(logger, response) diff --git a/commerce_coordinator/apps/ecommerce/pipeline.py b/commerce_coordinator/apps/ecommerce/pipeline.py index ae7cec95..953a8d24 100644 --- a/commerce_coordinator/apps/ecommerce/pipeline.py +++ b/commerce_coordinator/apps/ecommerce/pipeline.py @@ -40,7 +40,8 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- params: arguments passed through from the original order history url querystring order_data: any preliminary orders (from an earlier pipeline step) we want to append to """ - log.info("[UserOrdersView] [GetEcommerceOrders] Starting pipeline step execution at %s", datetime.now()) + start_time = datetime.now() + log.info("[UserOrdersView] [GetEcommerceOrders] Starting pipeline step execution at %s", start_time) new_params = params.copy() # Ecommerce starts pagination from 1, other systems from 0, since the invoker assumes 0, we're always 1 off. @@ -52,7 +53,10 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- order_data.append(ecommerce_response) - log.info("[UserOrdersView] [GetEcommerceOrders] Completed pipeline step execution at %s", datetime.now()) + end_time = datetime.now() + log.info( + "[UserOrdersView] [GetEcommerceOrders] Completed pipeline step execution at %s with total duration: %s", + end_time, end_time - start_time) return { "order_data": order_data } diff --git a/commerce_coordinator/apps/frontend_app_ecommerce/views.py b/commerce_coordinator/apps/frontend_app_ecommerce/views.py index 8c2c11f3..fe8cf5e7 100644 --- a/commerce_coordinator/apps/frontend_app_ecommerce/views.py +++ b/commerce_coordinator/apps/frontend_app_ecommerce/views.py @@ -74,8 +74,8 @@ class UserOrdersView(APIView): def get(self, request): """Return paginated response of user's order history.""" - - logger.info("[UserOrdersView] GET method started at: %s", datetime.now()) + request_start_time = datetime.now() + logger.info("[UserOrdersView] GET method started at: %s", request_start_time) user = request.user user.add_lms_user_id("UserOrdersView GET method") @@ -95,25 +95,38 @@ def get(self, request): if not request.user.lms_user_id: # pragma: no cover raise PermissionDenied(detail="Could not detect LMS user id.") - logger.info("[UserOrdersView] Filter run started at: %s", datetime.now()) + start_time = datetime.now() + logger.info("[UserOrdersView] Filter run started at: %s", start_time) order_data = OrderHistoryRequested.run_filter(request, params) - logger.info("[UserOrdersView] Filter run finished at: %s", datetime.now()) + end_time = datetime.now() + logger.info("[UserOrdersView] Filter run finished at: %s with total duration: %s", end_time, + end_time - start_time) output_orders = [] - logger.info("[UserOrdersView] Looping through results starting at: %s", datetime.now()) + start_time = datetime.now() + logger.info("[UserOrdersView] Looping through results starting at: %s", start_time) for order_set in order_data: output_orders.extend(order_set['results']) - logger.info("[UserOrdersView] Looping through results finished at: %s", datetime.now()) - logger.info("[UserOrdersView] Sorting results for output starting at: %s", datetime.now()) + end_time = datetime.now() + logger.info("[UserOrdersView] Looping through results finished at: %s with total duration: %s",end_time, + end_time - start_time) + + start_time = datetime.now() + logger.info("[UserOrdersView] Sorting results for output starting at: %s", start_time) output = { "count": request.query_params['page_size'], # This suppresses the ecomm mfe Order History Pagination ctrl "next": None, "previous": None, "results": sorted(output_orders, key=lambda item: date_conv(item["date_placed"]), reverse=True) } - logger.info("[UserOrdersView] Sorting results for output finished at: %s", datetime.now()) - logger.info("[UserOrdersView] GET method finished at: %s", datetime.now()) + end_time = datetime.now() + logger.info("[UserOrdersView] Sorting results for output finished at: %s with total duration: %s", + end_time, end_time - start_time) + + request_end_time = datetime.now() + logger.info("[UserOrdersView] GET method finished at: %s with total duration: %s", request_end_time, + request_end_time - request_start_time) return Response(output) From 614a5b38e8f68b63fb42d4f31d0cf602f801d274 Mon Sep 17 00:00:00 2001 From: Muhammad Noyan Aziz Date: Thu, 7 Nov 2024 20:07:25 +0500 Subject: [PATCH 5/8] feat: added log for pagination --- .../apps/commercetools/clients.py | 19 +++++++++++++++---- 1 file changed, 15 insertions(+), 4 deletions(-) diff --git a/commerce_coordinator/apps/commercetools/clients.py b/commerce_coordinator/apps/commercetools/clients.py index 78d581f8..5ed58544 100644 --- a/commerce_coordinator/apps/commercetools/clients.py +++ b/commerce_coordinator/apps/commercetools/clients.py @@ -259,8 +259,9 @@ def get_orders(self, customer: CTCustomer, offset=0, f"customer with ID {customer.id}") order_where_clause = f"orderState=\"{order_state}\"" + start_time = datetime.datetime.now() logger.info( - "[UserOrdersView] [CommercetoolsAPIClient] - Get orders query call started at %s", datetime.datetime.now()) + "[UserOrdersView] [CommercetoolsAPIClient] - Get orders query call started at %s", start_time) values = self.base_client.orders.query( where=["customerId=:cid", order_where_clause], predicate_var={'cid': customer.id}, @@ -269,12 +270,22 @@ def get_orders(self, customer: CTCustomer, offset=0, offset=offset, expand=list(expand) ) + end_time = datetime.datetime.now() logger.info( - "[UserOrdersView] [CommercetoolsAPIClient] - Get orders query call finished at %s", - datetime.datetime.now() + "[UserOrdersView] [CommercetoolsAPIClient] - Get orders query call finished at %s with total duration: %s", + end_time, end_time - start_time ) - return PaginatedResult(values.results, values.total, values.offset) + start_time = datetime.datetime.now() + logger.info('[UserOrdersView] [CommercetoolsAPIClient] - Pagination of CT orders started at %s', + start_time) + result = PaginatedResult(values.results, values.total, values.offset) + end_time = datetime.datetime.now() + logger.info( + '[UserOrdersView] [CommercetoolsAPIClient] - \ + Pagination of CT orders finished at %s with total duration: %s', end_time, end_time - start_time) + + return result def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, limit=ORDER_HISTORY_PER_SYSTEM_REQ_LIMIT) -> (PaginatedResult[CTOrder], CTCustomer): From d0a87e1985bee5fd759807b7cee5c9cf6e6b9d37 Mon Sep 17 00:00:00 2001 From: Muhammad Noyan Aziz Date: Thu, 7 Nov 2024 20:26:45 +0500 Subject: [PATCH 6/8] refactor: message strings --- .../apps/commercetools/clients.py | 21 +++++++++---------- .../apps/commercetools/pipeline.py | 16 +++++++------- .../apps/ecommerce/clients.py | 5 ++--- .../apps/ecommerce/pipeline.py | 4 ++-- .../apps/frontend_app_ecommerce/views.py | 18 +++++++++------- 5 files changed, 31 insertions(+), 33 deletions(-) diff --git a/commerce_coordinator/apps/commercetools/clients.py b/commerce_coordinator/apps/commercetools/clients.py index 5ed58544..32871e12 100644 --- a/commerce_coordinator/apps/commercetools/clients.py +++ b/commerce_coordinator/apps/commercetools/clients.py @@ -261,7 +261,7 @@ def get_orders(self, customer: CTCustomer, offset=0, start_time = datetime.datetime.now() logger.info( - "[UserOrdersView] [CommercetoolsAPIClient] - Get orders query call started at %s", start_time) + "[UserOrdersView] Get CT orders query call started at %s", start_time) values = self.base_client.orders.query( where=["customerId=:cid", order_where_clause], predicate_var={'cid': customer.id}, @@ -272,18 +272,18 @@ def get_orders(self, customer: CTCustomer, offset=0, ) end_time = datetime.datetime.now() logger.info( - "[UserOrdersView] [CommercetoolsAPIClient] - Get orders query call finished at %s with total duration: %s", + "[UserOrdersView] Get CT orders query call finished at %s with total duration: %s", end_time, end_time - start_time ) start_time = datetime.datetime.now() - logger.info('[UserOrdersView] [CommercetoolsAPIClient] - Pagination of CT orders started at %s', + logger.info('[UserOrdersView] Pagination of CT orders started at %s', start_time) result = PaginatedResult(values.results, values.total, values.offset) end_time = datetime.datetime.now() logger.info( - '[UserOrdersView] [CommercetoolsAPIClient] - \ - Pagination of CT orders finished at %s with total duration: %s', end_time, end_time - start_time) + '[UserOrdersView] Pagination of CT orders finished at %s with total duration: %s', + end_time, end_time - start_time) return result @@ -298,14 +298,13 @@ def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, """ start_time = datetime.datetime.now() logger.info( - "[UserOrdersView] [CommercetoolsAPIClient] - Getting customer if from lms id call started at %s", + "[UserOrdersView] For CT orders get customer id from lms id call started at %s", start_time ) customer = self.get_customer_by_lms_user_id(edx_lms_user_id) end_time = datetime.datetime.now() logger.info( - "[UserOrdersView] [CommercetoolsAPIClient] - \ - Getting customer if from lms id call finished at %s with total duration: %s", + "[UserOrdersView] For CT orders get customer id from lms id call finished at %s with total duration: %s", end_time, end_time - start_time ) @@ -313,12 +312,12 @@ def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, raise ValueError(f'Unable to locate customer with ID #{edx_lms_user_id}') start_time = datetime.datetime.now() - logger.info("[UserOrdersView] [CommercetoolsAPIClient] - Get orders call started at %s", + logger.info("[UserOrdersView] Get CT orders call started at %s", start_time) orders = self.get_orders(customer, offset, limit) end_time = datetime.datetime.now() - logger.info("[UserOrdersView] [CommercetoolsAPIClient] - \ - Get orders call finished at %s with total duration: %s", end_time, end_time - start_time) + logger.info("[UserOrdersView] Get CT orders call finished at %s with total duration: %s", + end_time, end_time - start_time) return orders, customer diff --git a/commerce_coordinator/apps/commercetools/pipeline.py b/commerce_coordinator/apps/commercetools/pipeline.py index d79fe0ad..e7994a79 100644 --- a/commerce_coordinator/apps/commercetools/pipeline.py +++ b/commerce_coordinator/apps/commercetools/pipeline.py @@ -46,7 +46,7 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- Returns: """ method_start_time = datetime.now() - log.info("[UserOrdersView] [GetCommercetoolsOrders] Starting pipeline step execution at %s", method_start_time) + log.info("[UserOrdersView] Starting CT orders pipeline step execution at %s", method_start_time) if not is_redirect_to_commercetools_enabled_for_user(request): return PipelineCommand.CONTINUE.value @@ -61,7 +61,7 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- start_time = datetime.now() log.info( - "[UserOrdersView] [GetCommercetoolsOrders] orders to attrs objects processing started at %s", + "[UserOrdersView] CT orders to attrs objects processing started at %s", start_time ) # noinspection PyTypeChecker @@ -69,24 +69,22 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- for x in ct_orders[0].results] end_time = datetime.now() log.info( - "[UserOrdersView] [GetCommercetoolsOrders] \ - orders to attrs objects processing finished at %s with total duration: %s", + "[UserOrdersView] CT orders to attrs objects processing finished at %s with total duration: %s", end_time, end_time - start_time ) start_time = datetime.now() - log.info("[UserOrdersView] [GetCommercetoolsOrders] Orders rebuild call started at %s", start_time) + log.info("[UserOrdersView] CT orders rebuild call started at %s", start_time) order_data.append( ct_orders[0].rebuild(converted_orders) ) end_time = datetime.now() - log.info("[UserOrdersView] [GetCommercetoolsOrders] \ - Orders rebuild call finished at %s with total duration: %s", end_time, end_time - start_time) + log.info("[UserOrdersView] CT orders rebuild call finished at %s with total duration: %s", + end_time, end_time - start_time) method_end_time = datetime.now() log.info( - "[UserOrdersView] [GetCommercetoolsOrders] \ - Completed pipeline step execution at %s with total duration: %s", + "[UserOrdersView] Completed CT pipeline step execution at %s with total duration: %s", method_end_time, method_end_time - method_start_time ) return { diff --git a/commerce_coordinator/apps/ecommerce/clients.py b/commerce_coordinator/apps/ecommerce/clients.py index da413c8e..516a5e73 100644 --- a/commerce_coordinator/apps/ecommerce/clients.py +++ b/commerce_coordinator/apps/ecommerce/clients.py @@ -38,14 +38,13 @@ def get_orders(self, query_params): resource_url = urljoin_directory(self.api_base_url, '/orders') start_time = datetime.now() logger.info( - '[UserOrdersView] [EcommerceAPIClient] - Legacy ecommerce get_orders API called at: %s', + '[UserOrdersView] Legacy ecommerce get_orders API called at: %s', start_time ) response = self.client.get(resource_url, params=query_params) end_time = datetime.now() logger.info( - '[UserOrdersView] [EcommerceAPIClient] \ - - Legacy ecommerce get_orders API finished at: %s with total duration: %s', + '[UserOrdersView] Legacy ecommerce get_orders API finished at: %s with total duration: %s', end_time, end_time - start_time ) response.raise_for_status() diff --git a/commerce_coordinator/apps/ecommerce/pipeline.py b/commerce_coordinator/apps/ecommerce/pipeline.py index 953a8d24..7de0c1d4 100644 --- a/commerce_coordinator/apps/ecommerce/pipeline.py +++ b/commerce_coordinator/apps/ecommerce/pipeline.py @@ -41,7 +41,7 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- order_data: any preliminary orders (from an earlier pipeline step) we want to append to """ start_time = datetime.now() - log.info("[UserOrdersView] [GetEcommerceOrders] Starting pipeline step execution at %s", start_time) + log.info("[UserOrdersView] Starting Ecommerce pipeline step execution at %s", start_time) new_params = params.copy() # Ecommerce starts pagination from 1, other systems from 0, since the invoker assumes 0, we're always 1 off. @@ -55,7 +55,7 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- end_time = datetime.now() log.info( - "[UserOrdersView] [GetEcommerceOrders] Completed pipeline step execution at %s with total duration: %s", + "[UserOrdersView] Completed Ecommerce pipeline step execution at %s with total duration: %s", end_time, end_time - start_time) return { "order_data": order_data diff --git a/commerce_coordinator/apps/frontend_app_ecommerce/views.py b/commerce_coordinator/apps/frontend_app_ecommerce/views.py index fe8cf5e7..6afbebb9 100644 --- a/commerce_coordinator/apps/frontend_app_ecommerce/views.py +++ b/commerce_coordinator/apps/frontend_app_ecommerce/views.py @@ -96,25 +96,26 @@ def get(self, request): raise PermissionDenied(detail="Could not detect LMS user id.") start_time = datetime.now() - logger.info("[UserOrdersView] Filter run started at: %s", start_time) + logger.info("[UserOrdersView] Pipline filter run started at: %s", start_time) order_data = OrderHistoryRequested.run_filter(request, params) end_time = datetime.now() - logger.info("[UserOrdersView] Filter run finished at: %s with total duration: %s", end_time, + logger.info("[UserOrdersView] Pipline filter run finished at: %s with total duration: %s", end_time, end_time - start_time) output_orders = [] start_time = datetime.now() - logger.info("[UserOrdersView] Looping through results starting at: %s", start_time) + logger.info("[UserOrdersView] Looping through combined orders results starting at: %s", start_time) for order_set in order_data: output_orders.extend(order_set['results']) end_time = datetime.now() - logger.info("[UserOrdersView] Looping through results finished at: %s with total duration: %s",end_time, - end_time - start_time) + logger.info( + "[UserOrdersView] Looping through combined orders results finished at: %s with total duration: %s", + end_time, end_time - start_time) start_time = datetime.now() - logger.info("[UserOrdersView] Sorting results for output starting at: %s", start_time) + logger.info("[UserOrdersView] Sorting combined orders results for output starting at: %s", start_time) output = { "count": request.query_params['page_size'], # This suppresses the ecomm mfe Order History Pagination ctrl "next": None, @@ -123,8 +124,9 @@ def get(self, request): } end_time = datetime.now() - logger.info("[UserOrdersView] Sorting results for output finished at: %s with total duration: %s", - end_time, end_time - start_time) + logger.info( + "[UserOrdersView] Sorting combined orders results for output finished at: %s with total duration: %s", + end_time, end_time - start_time) request_end_time = datetime.now() logger.info("[UserOrdersView] GET method finished at: %s with total duration: %s", request_end_time, From 6f9cae052372b95e2aa16a9e34b3c6a416389cfb Mon Sep 17 00:00:00 2001 From: Muhammad Noyan Aziz Date: Thu, 7 Nov 2024 20:32:45 +0500 Subject: [PATCH 7/8] fix: quality checks --- commerce_coordinator/apps/commercetools/clients.py | 2 +- commerce_coordinator/apps/frontend_app_ecommerce/views.py | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/commerce_coordinator/apps/commercetools/clients.py b/commerce_coordinator/apps/commercetools/clients.py index 32871e12..6991f551 100644 --- a/commerce_coordinator/apps/commercetools/clients.py +++ b/commerce_coordinator/apps/commercetools/clients.py @@ -299,7 +299,7 @@ def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, start_time = datetime.datetime.now() logger.info( "[UserOrdersView] For CT orders get customer id from lms id call started at %s", - start_time + start_time ) customer = self.get_customer_by_lms_user_id(edx_lms_user_id) end_time = datetime.datetime.now() diff --git a/commerce_coordinator/apps/frontend_app_ecommerce/views.py b/commerce_coordinator/apps/frontend_app_ecommerce/views.py index 6afbebb9..b48c2d24 100644 --- a/commerce_coordinator/apps/frontend_app_ecommerce/views.py +++ b/commerce_coordinator/apps/frontend_app_ecommerce/views.py @@ -99,8 +99,8 @@ def get(self, request): logger.info("[UserOrdersView] Pipline filter run started at: %s", start_time) order_data = OrderHistoryRequested.run_filter(request, params) end_time = datetime.now() - logger.info("[UserOrdersView] Pipline filter run finished at: %s with total duration: %s", end_time, - end_time - start_time) + logger.info("[UserOrdersView] Pipline filter run finished at: %s with total duration: %s", + end_time, end_time - start_time) output_orders = [] From ac0509098f592ba1edda6c89b3fb8f6066d8f08b Mon Sep 17 00:00:00 2001 From: Muhammad Noyan Aziz Date: Fri, 8 Nov 2024 11:13:43 +0500 Subject: [PATCH 8/8] fix: duration to seconds --- .../apps/commercetools/clients.py | 16 ++++++++-------- .../apps/commercetools/pipeline.py | 12 ++++++------ commerce_coordinator/apps/ecommerce/clients.py | 4 ++-- commerce_coordinator/apps/ecommerce/pipeline.py | 4 ++-- .../apps/frontend_app_ecommerce/views.py | 16 ++++++++-------- 5 files changed, 26 insertions(+), 26 deletions(-) diff --git a/commerce_coordinator/apps/commercetools/clients.py b/commerce_coordinator/apps/commercetools/clients.py index 6991f551..5e7047a1 100644 --- a/commerce_coordinator/apps/commercetools/clients.py +++ b/commerce_coordinator/apps/commercetools/clients.py @@ -272,8 +272,8 @@ def get_orders(self, customer: CTCustomer, offset=0, ) end_time = datetime.datetime.now() logger.info( - "[UserOrdersView] Get CT orders query call finished at %s with total duration: %s", - end_time, end_time - start_time + "[UserOrdersView] Get CT orders query call finished at %s with total duration: %ss", + end_time, (end_time - start_time).total_seconds() ) start_time = datetime.datetime.now() @@ -282,8 +282,8 @@ def get_orders(self, customer: CTCustomer, offset=0, result = PaginatedResult(values.results, values.total, values.offset) end_time = datetime.datetime.now() logger.info( - '[UserOrdersView] Pagination of CT orders finished at %s with total duration: %s', - end_time, end_time - start_time) + '[UserOrdersView] Pagination of CT orders finished at %s with total duration: %ss', + end_time, (end_time - start_time).total_seconds()) return result @@ -304,8 +304,8 @@ def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, customer = self.get_customer_by_lms_user_id(edx_lms_user_id) end_time = datetime.datetime.now() logger.info( - "[UserOrdersView] For CT orders get customer id from lms id call finished at %s with total duration: %s", - end_time, end_time - start_time + "[UserOrdersView] For CT orders get customer id from lms id call finished at %s with total duration: %ss", + end_time, (end_time - start_time).total_seconds() ) if customer is None: # pragma: no cover @@ -316,8 +316,8 @@ def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, start_time) orders = self.get_orders(customer, offset, limit) end_time = datetime.datetime.now() - logger.info("[UserOrdersView] Get CT orders call finished at %s with total duration: %s", - end_time, end_time - start_time) + logger.info("[UserOrdersView] Get CT orders call finished at %s with total duration: %ss", + end_time, (end_time - start_time).total_seconds()) return orders, customer diff --git a/commerce_coordinator/apps/commercetools/pipeline.py b/commerce_coordinator/apps/commercetools/pipeline.py index e7994a79..09c2ea29 100644 --- a/commerce_coordinator/apps/commercetools/pipeline.py +++ b/commerce_coordinator/apps/commercetools/pipeline.py @@ -69,8 +69,8 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- for x in ct_orders[0].results] end_time = datetime.now() log.info( - "[UserOrdersView] CT orders to attrs objects processing finished at %s with total duration: %s", - end_time, end_time - start_time + "[UserOrdersView] CT orders to attrs objects processing finished at %s with total duration: %ss", + end_time, (end_time - start_time).total_seconds() ) start_time = datetime.now() @@ -79,13 +79,13 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- ct_orders[0].rebuild(converted_orders) ) end_time = datetime.now() - log.info("[UserOrdersView] CT orders rebuild call finished at %s with total duration: %s", - end_time, end_time - start_time) + log.info("[UserOrdersView] CT orders rebuild call finished at %s with total duration: %ss", + end_time, (end_time - start_time).total_seconds()) method_end_time = datetime.now() log.info( - "[UserOrdersView] Completed CT pipeline step execution at %s with total duration: %s", - method_end_time, method_end_time - method_start_time + "[UserOrdersView] Completed CT pipeline step execution at %s with total duration: %ss", + method_end_time, (method_end_time - method_start_time).total_seconds() ) return { "order_data": order_data diff --git a/commerce_coordinator/apps/ecommerce/clients.py b/commerce_coordinator/apps/ecommerce/clients.py index 516a5e73..8f526719 100644 --- a/commerce_coordinator/apps/ecommerce/clients.py +++ b/commerce_coordinator/apps/ecommerce/clients.py @@ -44,8 +44,8 @@ def get_orders(self, query_params): response = self.client.get(resource_url, params=query_params) end_time = datetime.now() logger.info( - '[UserOrdersView] Legacy ecommerce get_orders API finished at: %s with total duration: %s', - end_time, end_time - start_time + '[UserOrdersView] Legacy ecommerce get_orders API finished at: %s with total duration: %ss', + end_time, (end_time - start_time).total_seconds() ) response.raise_for_status() self.log_request_response(logger, response) diff --git a/commerce_coordinator/apps/ecommerce/pipeline.py b/commerce_coordinator/apps/ecommerce/pipeline.py index 7de0c1d4..a7d9df85 100644 --- a/commerce_coordinator/apps/ecommerce/pipeline.py +++ b/commerce_coordinator/apps/ecommerce/pipeline.py @@ -55,8 +55,8 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- end_time = datetime.now() log.info( - "[UserOrdersView] Completed Ecommerce pipeline step execution at %s with total duration: %s", - end_time, end_time - start_time) + "[UserOrdersView] Completed Ecommerce pipeline step execution at %s with total duration: %ss", + end_time, (end_time - start_time).total_seconds()) return { "order_data": order_data } diff --git a/commerce_coordinator/apps/frontend_app_ecommerce/views.py b/commerce_coordinator/apps/frontend_app_ecommerce/views.py index b48c2d24..dca74a6f 100644 --- a/commerce_coordinator/apps/frontend_app_ecommerce/views.py +++ b/commerce_coordinator/apps/frontend_app_ecommerce/views.py @@ -99,8 +99,8 @@ def get(self, request): logger.info("[UserOrdersView] Pipline filter run started at: %s", start_time) order_data = OrderHistoryRequested.run_filter(request, params) end_time = datetime.now() - logger.info("[UserOrdersView] Pipline filter run finished at: %s with total duration: %s", - end_time, end_time - start_time) + logger.info("[UserOrdersView] Pipline filter run finished at: %s with total duration: %ss", + end_time, (end_time - start_time).total_seconds()) output_orders = [] @@ -111,8 +111,8 @@ def get(self, request): end_time = datetime.now() logger.info( - "[UserOrdersView] Looping through combined orders results finished at: %s with total duration: %s", - end_time, end_time - start_time) + "[UserOrdersView] Looping through combined orders results finished at: %s with total duration: %ss", + end_time, (end_time - start_time).total_seconds()) start_time = datetime.now() logger.info("[UserOrdersView] Sorting combined orders results for output starting at: %s", start_time) @@ -125,10 +125,10 @@ def get(self, request): end_time = datetime.now() logger.info( - "[UserOrdersView] Sorting combined orders results for output finished at: %s with total duration: %s", - end_time, end_time - start_time) + "[UserOrdersView] Sorting combined orders results for output finished at: %s with total duration: %ss", + end_time, (end_time - start_time).total_seconds()) request_end_time = datetime.now() - logger.info("[UserOrdersView] GET method finished at: %s with total duration: %s", request_end_time, - request_end_time - request_start_time) + logger.info("[UserOrdersView] GET method finished at: %s with total duration: %ss", request_end_time, + (request_end_time - request_start_time).total_seconds()) return Response(output)