feat: added logs for investigating UserOrdersView on stage (#289)

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
 

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
             }

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()

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
             }

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,18 +95,40 @@ 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,
             "previous": None,
             "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)