Skip to content

Commit

Permalink
feat: added logs for investigating time of each call inside UserOrder…
Browse files Browse the repository at this point in the history
…sView on stage
  • Loading branch information
Muhammad Noyan Aziz authored and Muhammad Noyan Aziz committed Nov 7, 2024
1 parent 8cba004 commit 09259ca
Show file tree
Hide file tree
Showing 5 changed files with 68 additions and 0 deletions.
19 changes: 19 additions & 0 deletions commerce_coordinator/apps/commercetools/clients.py
Original file line number Diff line number Diff line change
Expand Up @@ -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},
Expand All @@ -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)

Expand All @@ -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

Expand Down
24 changes: 24 additions & 0 deletions commerce_coordinator/apps/commercetools/pipeline.py
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@
Commercetools filter pipelines
"""
import decimal
from datetime import datetime
from logging import getLogger

import attrs
Expand Down Expand Up @@ -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
}
Expand Down
13 changes: 13 additions & 0 deletions commerce_coordinator/apps/ecommerce/clients.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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()
3 changes: 3 additions & 0 deletions commerce_coordinator/apps/ecommerce/pipeline.py
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
"""
Ecommerce filter pipelines
"""
from datetime import datetime
from logging import getLogger

from django.conf import settings
Expand Down Expand Up @@ -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.
Expand All @@ -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
}
Expand Down
9 changes: 9 additions & 0 deletions commerce_coordinator/apps/frontend_app_ecommerce/views.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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)

0 comments on commit 09259ca

Please sign in to comment.