diff --git a/commerce_coordinator/apps/commercetools/clients.py b/commerce_coordinator/apps/commercetools/clients.py index 0df503e9..5e7047a1 100644 --- a/commerce_coordinator/apps/commercetools/clients.py +++ b/commerce_coordinator/apps/commercetools/clients.py @@ -258,6 +258,10 @@ 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}\"" + + start_time = datetime.datetime.now() + logger.info( + "[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}, @@ -266,8 +270,22 @@ def get_orders(self, customer: CTCustomer, offset=0, offset=offset, expand=list(expand) ) + end_time = datetime.datetime.now() + logger.info( + "[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() + 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] Pagination of CT orders finished at %s with total duration: %ss', + end_time, (end_time - start_time).total_seconds()) - return PaginatedResult(values.results, values.total, values.offset) + 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): @@ -278,12 +296,28 @@ def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, offset: limit: """ + start_time = datetime.datetime.now() + logger.info( + "[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] 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 raise ValueError(f'Unable to locate customer with ID #{edx_lms_user_id}') + start_time = datetime.datetime.now() + 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] 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 f2a938fa..09c2ea29 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,6 +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: """ + method_start_time = datetime.now() + 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 @@ -56,14 +59,34 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- offset=params["page"] * params["page_size"] ) + start_time = datetime.now() + log.info( + "[UserOrdersView] CT orders to attrs objects processing started at %s", + 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] 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() + 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] 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: %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 1f04d4f5..8f526719 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 @@ -35,10 +36,21 @@ def get_orders(self, query_params): """ try: resource_url = urljoin_directory(self.api_base_url, '/orders') + start_time = datetime.now() + logger.info( + '[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] 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) except RequestException as exc: self.log_request_exception(logger, exc) raise + return response.json() diff --git a/commerce_coordinator/apps/ecommerce/pipeline.py b/commerce_coordinator/apps/ecommerce/pipeline.py index 32edd8e3..a7d9df85 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,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 """ + start_time = datetime.now() + 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. @@ -50,6 +53,10 @@ def run_filter(self, request, params, order_data): # pylint: disable=arguments- order_data.append(ecommerce_response) + end_time = datetime.now() + log.info( + "[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 a46a98f9..dca74a6f 100644 --- a/commerce_coordinator/apps/frontend_app_ecommerce/views.py +++ b/commerce_coordinator/apps/frontend_app_ecommerce/views.py @@ -74,6 +74,8 @@ class UserOrdersView(APIView): def get(self, request): """Return paginated response of user's order history.""" + 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") @@ -93,13 +95,27 @@ def get(self, request): if not request.user.lms_user_id: # pragma: no cover raise PermissionDenied(detail="Could not detect LMS user id.") + start_time = datetime.now() + 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: %ss", + end_time, (end_time - start_time).total_seconds()) output_orders = [] + start_time = datetime.now() + 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 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) output = { "count": request.query_params['page_size'], # This suppresses the ecomm mfe Order History Pagination ctrl "next": None, @@ -107,4 +123,12 @@ def get(self, request): "results": sorted(output_orders, key=lambda item: date_conv(item["date_placed"]), reverse=True) } + end_time = datetime.now() + logger.info( + "[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: %ss", request_end_time, + (request_end_time - request_start_time).total_seconds()) return Response(output)