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)