Merge branch 'main' into bilalqamar95/dockerfile-setup-removal

commerce_coordinator/apps/commercetools/clients.py

@@ -260,9 +260,6 @@ def get_orders(self, customer_id: str, offset=0,
                     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},
@@ -271,22 +268,8 @@ def get_orders(self, customer_id: str, 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 result
+        return PaginatedResult(values.results, values.total, values.offset)
 
     def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, limit=ORDER_HISTORY_PER_SYSTEM_REQ_LIMIT,
                                 customer_id=None, email=None,
@@ -298,12 +281,6 @@ def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, limit=ORDER_HI
             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
-        )
-
         if not customer_id:
             customer = self.get_customer_by_lms_user_id(edx_lms_user_id)
 
@@ -325,19 +302,7 @@ def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, limit=ORDER_HI
                 )
             )
 
-        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()
-        )
-
-        start_time = datetime.datetime.now()
-        logger.info("[UserOrdersView] Get CT orders call started at %s",
-                    start_time)
         orders = self.get_orders(customer_id, 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
 
@@ -582,7 +547,7 @@ def update_line_item_transition_state_on_fulfillment(self, order_id: str, order_
                 return self.get_order_by_id(order_id)
         except CommercetoolsError as err:
             # Logs & ignores version conflict errors due to duplicate Commercetools messages
-            handle_commercetools_error(err, f"Unable to update LineItemState of order {order_id}")
+            handle_commercetools_error(err, f"Unable to update LineItemState of order {order_id}", True)
             return None
 
     def retire_customer_anonymize_fields(self, customer_id: str, customer_version: int,

commerce_coordinator/apps/commercetools/pipeline.py

@@ -2,7 +2,6 @@
 Commercetools filter pipelines
 """
 import decimal
-from datetime import datetime
 from logging import getLogger
 
 import attrs
@@ -45,9 +44,6 @@ 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
 
@@ -62,34 +58,14 @@ 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/commercetools/sub_messages/tasks.py

@@ -104,6 +104,8 @@ def fulfill_order_placed_message_signal_task(
             line_item_state_id,
             TwoUKeys.PROCESSING_FULFILMENT_STATE
         )
+        if not updated_order:
+            return True
 
         # from here we will always be transitioning from a 'Fulfillment Processing' state
         line_item_state_id = client.get_state_by_key(TwoUKeys.PROCESSING_FULFILMENT_STATE).id

commerce_coordinator/apps/commercetools/tests/test_clients.py

@@ -672,7 +672,7 @@ def test_update_line_item_state_exception(self, mock_state_by_id):
                 status_code=409
             )
 
-            with patch('commerce_coordinator.apps.commercetools.clients.logging.Logger.error') as log_mock:
+            with patch('commerce_coordinator.apps.commercetools.clients.logging.Logger.info') as log_mock:
                 self.client_set.client.update_line_item_transition_state_on_fulfillment(
                     "mock_order_id",
                     1,
@@ -689,7 +689,7 @@ def test_update_line_item_state_exception(self, mock_state_by_id):
                     f"Details: {mock_error_response['errors']}"
                 )
 
-                log_mock.assert_called_once_with(expected_message)
+                log_mock.assert_called_with(expected_message)
 
     @patch('commerce_coordinator.apps.commercetools.clients.CommercetoolsAPIClient.get_state_by_id')
     @patch('commerce_coordinator.apps.commercetools.clients.CommercetoolsAPIClient.get_order_by_id')

commerce_coordinator/apps/commercetools/utils.py

@@ -35,9 +35,13 @@ def get_braze_client():
     )
 
 
-def handle_commercetools_error(err: CommercetoolsError, context: str):
+def handle_commercetools_error(err: CommercetoolsError, context: str, is_info=False):
+    """Handles commercetools errors."""
     error_message = f"[CommercetoolsError] {context} - Correlation ID: {err.correlation_id}, Details: {err.errors}"
-    logger.error(error_message)
+    if is_info:
+        logger.info(error_message)
+    else:
+        logger.error(error_message)
 
 
 def send_order_confirmation_email(

commerce_coordinator/apps/ecommerce/clients.py

@@ -2,7 +2,6 @@
 API clients for ecommerce app.
 """
 import logging
-from datetime import datetime
 
 from django.conf import settings
 from requests.exceptions import RequestException
@@ -36,17 +35,7 @@ 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:

commerce_coordinator/apps/ecommerce/pipeline.py

@@ -1,7 +1,6 @@
 """
 Ecommerce filter pipelines
 """
-from datetime import datetime
 from logging import getLogger
 
 from django.conf import settings
@@ -40,9 +39,6 @@ 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.
         new_params['page'] = params['page'] + 1
@@ -53,10 +49,6 @@ 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/tests/test_views.py

@@ -44,6 +44,7 @@ class OrdersViewTests(TestCase):
     test_user_username = 'test'  # Different from ORDER_HISTORY_GET_PARAMETERS username.
     test_user_email = '[email protected]'
     test_user_password = 'secret'
+    url = reverse('frontend_app_ecommerce:order_history')
 
     def setUp(self):
         """Create test user before test starts."""
@@ -69,7 +70,7 @@ def test_view_rejects_post(self, _mock_ctorders, _mock_ecommerce_client):
         self.client.login(username=self.test_user_username, password=self.test_user_password)
 
         # Perform POST
-        response = self.client.post(reverse('frontend_app_ecommerce:order_history'), ORDER_HISTORY_GET_PARAMETERS)
+        response = self.client.post(self.url, ORDER_HISTORY_GET_PARAMETERS)
 
         # Check 405 Method Not Allowed
         self.assertEqual(response.status_code, 405)
@@ -78,7 +79,7 @@ def test_view_rejects_unauthorized(self, _mock_ctorders, _mock_ecommerce_client)
         """Check unauthorized users querying orders are redirected to login page."""
 
         # Perform GET without logging in.
-        response = self.client.get(reverse('frontend_app_ecommerce:order_history'), ORDER_HISTORY_GET_PARAMETERS)
+        response = self.client.get(self.url, ORDER_HISTORY_GET_PARAMETERS)
 
         # Check 302 Found with redirect to login page.
         self.assertEqual(response.status_code, 302)
@@ -91,7 +92,7 @@ def test_view_returns_ok(self, _mock_ctorders, _mock_ecommerce_client):
         self.client.login(username=self.test_user_username, password=self.test_user_password)
 
         # Perform GET
-        response = self.client.get(reverse('frontend_app_ecommerce:order_history'), ORDER_HISTORY_GET_PARAMETERS)
+        response = self.client.get(self.url, ORDER_HISTORY_GET_PARAMETERS)
         # Check 200 OK
         self.assertEqual(response.status_code, 200)
 
@@ -104,7 +105,7 @@ def test_view_returns_expected_ecommerce_response(self, is_redirect_mock, _mock_
         self.client.login(username=self.test_user_username, password=self.test_user_password)
 
         # Perform GET
-        response = self.client.get(reverse('frontend_app_ecommerce:order_history'), ORDER_HISTORY_GET_PARAMETERS)
+        response = self.client.get(self.url, ORDER_HISTORY_GET_PARAMETERS)
 
         # Check expected response
         self.assertEqual(response.json()['results'][1], ECOMMERCE_REQUEST_EXPECTED_RESPONSE['results'][0])
@@ -116,14 +117,33 @@ def test_view_passes_username(self, _mock_ctorders, mock_ecommerce_client):
         self.client.login(username=self.test_user_username, password=self.test_user_password)
 
         # Perform GET
-        self.client.get(reverse('frontend_app_ecommerce:order_history'), ORDER_HISTORY_GET_PARAMETERS)
+        self.client.get(self.url, ORDER_HISTORY_GET_PARAMETERS)
 
         # Get username sent to ecommerce client
         request_username = mock_ecommerce_client.call_args.args[0]['username']
 
         # Check username is passed to ecommerce client
         self.assertEqual(request_username, self.test_user_username)
 
+    @patch(
+        'commerce_coordinator.apps.commercetools.pipeline.GetCommercetoolsOrders.run_filter',
+        side_effect=Exception('Something went wrong')
+    )
+    def test_view_crashes_with_some_error(self, _mock_pipeline, _mock_ctorders, _mock_ecommerce_client):
+        """Check exception is handled gracefully if pipeline crashes."""
+
+        # Login
+        self.client.login(username=self.test_user_username, password=self.test_user_password)
+
+        # Perform GET request
+        response = self.client.get(self.url, ORDER_HISTORY_GET_PARAMETERS)
+
+        # Assert the response status is 400
+        self.assertEqual(response.status_code, status.HTTP_400_BAD_REQUEST)
+
+        # Assert the response content matches the error message
+        self.assertEqual(response.data, 'Something went wrong!')
+
 
 @ddt.ddt
 class ReceiptRedirectViewTests(APITestCase):

commerce_coordinator/apps/frontend_app_ecommerce/views.py

@@ -10,7 +10,7 @@
 from edx_rest_framework_extensions.permissions import LoginRedirectIfUnauthenticated
 from rest_framework.exceptions import PermissionDenied
 from rest_framework.response import Response
-from rest_framework.status import HTTP_303_SEE_OTHER
+from rest_framework.status import HTTP_303_SEE_OTHER, HTTP_400_BAD_REQUEST
 from rest_framework.throttling import UserRateThrottle
 from rest_framework.views import APIView
 
@@ -74,9 +74,6 @@ 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")
         # build parameters
@@ -97,40 +94,23 @@ 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)
-        }
+        try:
+            order_data = OrderHistoryRequested.run_filter(request, params)
+
+            output_orders = []
+
+            for order_set in order_data:
+                output_orders.extend(order_set['results'])
 
-        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())
+            output = {
+                # This suppresses the ecomm mfe Order History Pagination control
+                "count": request.query_params['page_size'],
+                "next": None,
+                "previous": None,
+                "results": sorted(output_orders, key=lambda item: date_conv(item["date_placed"]), reverse=True)
+            }
 
-        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)
+            return Response(output)
+        except Exception as exc:  # pylint: disable=broad-except
+            logger.error(f'[UserOrdersView] An error occured while fetching Order History.\n Data: [{exc}]')
+            return Response(status=HTTP_400_BAD_REQUEST, data='Something went wrong!')