fix: Improve logging messages

commerce_coordinator/apps/commercetools/tasks.py

@@ -3,7 +3,6 @@
 """
 
 import logging
-
 import stripe
 from celery import shared_task
 from commercetools import CommercetoolsError
@@ -30,6 +29,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 +38,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"Error: {err.errors}, Correlation ID: {err.correlation_id}")
         return None
 
 
@@ -58,19 +59,19 @@ 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] Processing refund for PaymentIntent {payment_intent_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} "
-                        f"already has a full refund. Skipping task to add refund transaction")
+            logger.info(f"[refund_from_stripe_task] Payment {payment.id} already fully refunded. Skipping.")
             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} ] "
-                     f"on Stripe refund {stripe_refund.id} "
-                     f"with error {err.errors} and correlation id {err.correlation_id}")
+        logger.error(f"[refund_from_stripe_task] Failed to create refund transaction for Payment {payment_intent_id}. "
+                     f"Stripe Refund ID: {stripe_refund.id}. Error: {err.errors}, Correlation ID: {err.correlation_id}")
         return None

commerce_coordinator/apps/core/clients.py

@@ -3,7 +3,6 @@
 """
 import logging
 from urllib.parse import urljoin
-
 from django.conf import settings
 from edx_rest_api_client.client import OAuthAPIClient
 
@@ -73,12 +72,11 @@ 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"Request Details - URL: {response.request.url}, "
+            f"Method: {response.request.method}, Body: {response.request.body}, "
+            f"Headers: {response.request.headers}, Response: {response.text}"
+        )
 
     def log_request_exception(self, ext_logger, exc):
         """
@@ -89,14 +87,10 @@ def log_request_exception(self, ext_logger, exc):
                 derived class) is running in.
             response: 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"Request Exception - URL: {exc.request.url}, "
+            f"Method: {exc.request.method}, Error: {exc}, Response: {exc.response.text if exc.response else 'N/A'}"
+        )
 
 class BaseEdxOAuthClient(Client):
     """

commerce_coordinator/apps/lms/clients.py

@@ -40,18 +40,18 @@ 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'Deactivating account for user {username}'
+                        f'after subscription message with 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.info(f'Failed to deactivate account for user {username}'
+                        f'(Message ID: {ct_message_id}). Error: {exc}')
             logger.exception(
-                f'An error occurred while deactivating account for user with username {username}: {exc}'
+                f'Exception occurred while deactivating account for user {username}: {exc}'
             )
             raise
 
@@ -62,11 +62,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 +78,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
@@ -110,10 +110,12 @@ def post(self, url, json, line_item_state_payload, logging_obj, timeout=None):
             )
         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

commerce_coordinator/apps/lms/tasks.py

@@ -11,8 +11,7 @@
 from commerce_coordinator.apps.commercetools.clients import CommercetoolsAPIClient
 from commerce_coordinator.apps.lms.clients import LMSAPIClient
 
-# Use the special Celery logger for our tasks
-logger = get_task_logger(__name__)
+logger = get_task_logger("lms.tasks")
 User = get_user_model()
 
 
@@ -37,10 +36,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 = {
@@ -87,10 +83,9 @@ def fulfill_order_placed_send_enroll_in_course_task(
             'value': provider_id,
         })
 
-    # 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
         order_version = client.get_order_by_id(order_id).version