fix: Improve logging messages

commerce_coordinator/apps/commercetools/tasks.py

@@ -30,6 +30,7 @@ def update_line_item_state_on_fulfillment_completion(
     """
     client = CommercetoolsAPIClient()
     try:
+        logger.info(f"[update_line_item_state] Updating line item {line_item_id} for order {order_id}.")
         updated_order = client.update_line_item_transition_state_on_fulfillment(
             order_id,
             order_version,
@@ -38,10 +39,11 @@ def update_line_item_state_on_fulfillment_completion(
             from_state_id,
             to_state_key
         )
+        logger.info(f"[update_line_item_state] Successfully updated line item {line_item_id} for order {order_id}.")
         return updated_order
     except CommercetoolsError as err:
-        logger.error(f"Unable to update line item [ {line_item_id} ] state on fulfillment "
-                     f"result with error {err.errors} and correlation id {err.correlation_id}")
+        logger.error(f"[update_line_item_state] Failed to update line item {line_item_id} for order {order_id} "
+                     f"with error: {err.errors} and Correlation ID: {err.correlation_id}")
         return None
 
 
@@ -58,19 +60,23 @@ def refund_from_stripe_task(
     stripe_refund = stripe.Refund.construct_from(stripe_refund, stripe.api_key)
     client = CommercetoolsAPIClient()
     try:
+        logger.info(
+            f"[refund_from_stripe_task] Initiating refund transaction for Payment Intent ID {payment_intent_id} "
+            f"and Stripe Refund ID {stripe_refund.id}.")
         payment = client.get_payment_by_key(payment_intent_id)
         if has_full_refund_transaction(payment):
-            logger.info(f"Stripe charge.refunded event received, but Payment with ID {payment.id} "
+            logger.info(f"[refund_from_stripe_task] Event received, but Payment with ID {payment.id} "
                         f"already has a full refund. Skipping task to add refund transaction")
             return None
         updated_payment = client.create_return_payment_transaction(
             payment_id=payment.id,
             payment_version=payment.version,
             stripe_refund=stripe_refund
         )
+        logger.info(f"[refund_from_stripe_task] Successfully created refund transaction for Payment {payment.id}.")
         return updated_payment
     except CommercetoolsError as err:
-        logger.error(f"Unable to create refund transaction for payment [ {payment.id} ] "
+        logger.error(f"[refund_from_stripe_task] Unable to create refund transaction for payment [ {payment.id} ] "
                      f"on Stripe refund {stripe_refund.id} "
                      f"with error {err.errors} and correlation id {err.correlation_id}")
         return None

commerce_coordinator/apps/commercetools/tests/test_tasks.py

@@ -3,7 +3,7 @@
 """
 
 import logging
-from unittest.mock import patch
+from unittest.mock import call, patch
 
 import stripe
 from commercetools import CommercetoolsError
@@ -78,8 +78,10 @@ def test_exception_handling(self, mock_logger, mock_client):
         result = fulfillment_uut(*self.unpack_for_uut(EXAMPLE_UPDATE_LINE_ITEM_SIGNAL_PAYLOAD))
 
         mock_logger.error.assert_called_once_with(
-            f"Unable to update line item [ {EXAMPLE_UPDATE_LINE_ITEM_SIGNAL_PAYLOAD['line_item_id']} ] "
-            "state on fulfillment result with error Some error message and correlation id 123456"
+            f"[update_line_item_state] Failed to update line item "
+            f"{EXAMPLE_UPDATE_LINE_ITEM_SIGNAL_PAYLOAD['line_item_id']} "
+            f"for order {EXAMPLE_UPDATE_LINE_ITEM_SIGNAL_PAYLOAD['order_id']} "
+            f"with error: Some error message and Correlation ID: 123456"
         )
 
         assert result is None
@@ -123,10 +125,10 @@ def test_correct_arguments_passed(self, mock_client):
         )
 
     def test_full_refund_already_exists(self, mock_client):
-        '''
+        """
         Check if the payment already has a full refund, the task logs the
-        appropriate message and skips creating a refund transaction.
-        '''
+        appropriate messages and skips creating a refund transaction.
+        """
         mock_payment = gen_payment_with_multiple_transactions(
             TransactionType.CHARGE, 4900,
             TransactionType.REFUND, 4900
@@ -135,13 +137,23 @@ def test_full_refund_already_exists(self, mock_client):
 
         mock_client.return_value.get_payment_by_key.return_value = mock_payment
 
+        # Extract values from EXAMPLE_RETURNED_ORDER_STRIPE_SIGNAL_PAYLOAD
+        payment_intent_id = EXAMPLE_RETURNED_ORDER_STRIPE_SIGNAL_PAYLOAD['payment_intent_id']
+        stripe_refund_id = EXAMPLE_RETURNED_ORDER_STRIPE_SIGNAL_PAYLOAD['stripe_refund']['id']
+
         with patch('commerce_coordinator.apps.commercetools.tasks.logger') as mock_logger:
             result = refund_from_stripe_task(*self.unpack_for_uut(EXAMPLE_RETURNED_ORDER_STRIPE_SIGNAL_PAYLOAD))
             self.assertIsNone(result)
-            mock_logger.info.assert_called_once_with(
-                f"Stripe charge.refunded event received, but Payment with ID {mock_payment.id} "
-                f"already has a full refund. Skipping task to add refund transaction"
-            )
+
+            # Check that both info messages were logged in the expected order
+            mock_logger.info.assert_has_calls([
+                call(
+                    f"[refund_from_stripe_task] "
+                    f"Initiating refund transaction for Payment Intent ID {payment_intent_id} "
+                    f"and Stripe Refund ID {stripe_refund_id}."),
+                call(f"[refund_from_stripe_task] Event received, but Payment with ID {mock_payment.id} "
+                     f"already has a full refund. Skipping task to add refund transaction")
+            ])
 
     @patch('commerce_coordinator.apps.commercetools.tasks.logger')
     def test_exception_handling(self, mock_logger, mock_client):
@@ -162,7 +174,7 @@ def test_exception_handling(self, mock_logger, mock_client):
         returned_uut(*self.unpack_for_uut(EXAMPLE_RETURNED_ORDER_STRIPE_SIGNAL_PAYLOAD))
 
         mock_logger.error.assert_called_once_with(
-            f"Unable to create refund transaction for payment [ {mock_payment.id} ] "
+            f"[refund_from_stripe_task] Unable to create refund transaction for payment [ {mock_payment.id} ] "
             f"on Stripe refund {EXAMPLE_RETURNED_ORDER_STRIPE_CLIENT_PAYLOAD['stripe_refund']['id']} "
             f"with error Some error message and correlation id 123456"
         )

commerce_coordinator/apps/core/clients.py

@@ -73,12 +73,13 @@ def log_request_response(self, ext_logger, response):
                 derived class) is running in.
             response: A successful Response object from the requests library.
         """
-        ext_logger.debug('Request URL: %s', response.request.url)
-        ext_logger.debug('Request method: %s', response.request.method)
-        ext_logger.debug('Request body: %s', response.request.body)
-        ext_logger.debug('Request headers: %s', response.request.headers)
-        ext_logger.debug('Response status: %s %s', response.status_code, response.reason)
-        ext_logger.debug('Response text: %s', response.text)
+        ext_logger.debug(
+            f"The API client call for url: {response.request.url} "
+            f"with request_body: {response.request.body or 'N/A'}, "
+            f"request_headers: {response.request.headers or 'N/A'} "
+            f"was successful with status_code: {response.status_code}, "
+            f"response_body: {response.text or 'N/A'}"
+        )
 
     def log_request_exception(self, ext_logger, exc):
         """
@@ -87,15 +88,16 @@ def log_request_exception(self, ext_logger, exc):
         Args:
             ext_logger: The logger of the module the Client (or Client-
                 derived class) is running in.
-            response: A RequestException object from the requests library.
+            exc: A RequestException object from the requests library.
         """
-        ext_logger.error(exc)
-        ext_logger.info('Request URL: %s', exc.request.url)
-        ext_logger.info('Request method: %s', exc.request.method)
-        ext_logger.info('Request body: %s', exc.request.body)
-        ext_logger.debug('Request headers: %s', exc.request.headers)
-        ext_logger.info('Response status: %s %s', exc.response.status_code, exc.response.reason)
-        ext_logger.info('Response body: %s', exc.response.text)
+        ext_logger.error(
+            f"The API client call for url: {exc.request.url} "
+            f"with request_body: {exc.request.body or 'N/A'}, "
+            f"request_headers: {exc.request.headers or 'N/A'} failed with "
+            f"status_code: {exc.response.status_code if exc.response else 'N/A'}, "
+            f"response_body: {exc.response.text if exc.response else 'N/A'} "
+            f"and error: {exc}"
+        )
 
 
 class BaseEdxOAuthClient(Client):

commerce_coordinator/apps/lms/clients.py

@@ -40,18 +40,22 @@ def deactivate_user(self, username, ct_message_id):
         Intended use is on SDN check failure.
         """
         try:
-            logger.info(f'Calling LMS to deactivate account for user with username {username}'
-                        f'after receiving subsctiption message with ID: {ct_message_id}')
+            logger.info(
+                f"[LMSAPIClient] Initiating account deactivation for user '{username}'. "
+                f"Triggered by subscription message ID: {ct_message_id}."
+            )
             response = self.client.post(
                 self.deactivate_user_api_url.format(username=username),
                 timeout=self.normal_timeout,
             )
             response.raise_for_status()
         except (ConnectionError, RequestException) as exc:
-            logger.info(f'Unsuccessful call to LMS to deactivate account for user with username {username}'
-                        f'with details: [message_id: {ct_message_id}]')
+            logger.error(
+                f"[LMSAPIClient] Failed to deactivate account for user '{username}' "
+                f"(Subscription Message ID: {ct_message_id}). Error: {exc}"
+            )
             logger.exception(
-                f'An error occurred while deactivating account for user with username {username}: {exc}'
+                f"[LMSAPIClient] Exception occurred while deactivating account for user '{username}'."
             )
             raise
 
@@ -62,11 +66,11 @@ def enroll_user_in_course(
             fulfillment_logging_obj
     ):
         """
-        Send a POST request to LMS Enrollment API endpoint
+        Send a POST request to LMS Enrollment API endpoint.
         Arguments:
             enrollment_data: dictionary to send to the API resource.
         Returns:
-            dict: Dictionary represention of JSON returned from API
+            dict: Dictionary representation of JSON returned from API.
         """
         return self.post(
             url=self.api_enrollment_base_url,
@@ -78,7 +82,7 @@ def enroll_user_in_course(
 
     def post(self, url, json, line_item_state_payload, logging_obj, timeout=None):
         """
-        Send a POST request to a url with json payload.
+        Send a POST request to a URL with JSON payload.
         """
         if not timeout:   # pragma no cover
             timeout = self.normal_timeout
@@ -103,26 +107,28 @@ def post(self, url, json, line_item_state_payload, logging_obj, timeout=None):
                 'is_fulfilled': True
             }
             logger.info(
-                f"Successful fulfillment for user: {logging_obj['user']} with details: "
-                f"[lms user id: {logging_obj['lms_user_id']}, order id: {logging_obj['order_id']}, "
-                f"course id: {logging_obj['course_id']}, message_id: {logging_obj['message_id']}, "
-                f"celery_task_id: {logging_obj['celery_task_id']}]"
+                f"[LMSAPIClient] Successful fulfillment for user '{logging_obj['user']}'. "
+                f"Details: [lms_user_id: {logging_obj['lms_user_id']}, Order ID: {logging_obj['order_id']}, "
+                f"Course ID: {logging_obj['course_id']}, Subscription Message ID: {logging_obj['message_id']}, "
+                f"Celery Task ID: {logging_obj['celery_task_id']}]."
             )
         except RequestException as exc:
             self.log_request_exception(logger, exc)
+
             fulfill_line_item_state_payload = {
                 **line_item_state_payload,
                 'is_fulfilled': False
             }
+
             fulfillment_completed_signal.send_robust(
                 sender=self.__class__,
                 **fulfill_line_item_state_payload
             )
-            logger.info(
-                f"Unsuccessful fulfillment for user: {logging_obj['user']} with details: "
-                f"[lms user id: {logging_obj['lms_user_id']}, order id: {logging_obj['order_id']}, "
-                f"course id: {logging_obj['course_id']}, message_id: {logging_obj['message_id']}, "
-                f"celery_task_id: {logging_obj['celery_task_id']}]"
+            logger.error(
+                f"[LMSAPIClient] Unsuccessful fulfillment for user '{logging_obj['user']}'. "
+                f"Details: [lms_user_id: {logging_obj['lms_user_id']}, Order ID: {logging_obj['order_id']}, "
+                f"Course ID: {logging_obj['course_id']}, Subscription Message ID: {logging_obj['message_id']}, "
+                f"Celery Task ID: {logging_obj['celery_task_id']}]. Error: {exc}"
             )
             raise
 

commerce_coordinator/apps/lms/tasks.py

@@ -95,10 +95,7 @@ def fulfill_order_placed_send_enroll_in_course_task(
     """
     Celery task for order placed fulfillment and enrollment via LMS Enrollment API.
     """
-    logger.info(
-        f'LMS fulfill_order_placed_send_enroll_in_course_task fired with {locals()},'
-    )
-
+    logger.info(f"[fulfill_order_task] Starting task with Order ID: {order_id}, Line Item ID: {line_item_id}.")
     user = User.objects.get(lms_user_id=edx_lms_user_id)
 
     enrollment_data = {
@@ -147,6 +144,7 @@ def fulfill_order_placed_send_enroll_in_course_task(
 
     # Updating the order version and stateID after the transition to 'Fulfillment Failure'
     if self.request.retries > 0:
+        logger.warning(f"[fulfill_order_task] Retry {self.request.retries} for Order ID {order_id}.")
         client = CommercetoolsAPIClient()
         # A retry means the current line item state on the order would be a failure state
         line_item_state_id = client.get_state_by_key(TwoUKeys.FAILURE_FULFILMENT_STATE).id