diff --git a/commerce_coordinator/apps/commercetools/tasks.py b/commerce_coordinator/apps/commercetools/tasks.py index dab53759..c79195fd 100644 --- a/commerce_coordinator/apps/commercetools/tasks.py +++ b/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,9 +60,12 @@ 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( @@ -68,9 +73,10 @@ def refund_from_stripe_task( 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 diff --git a/commerce_coordinator/apps/commercetools/tests/test_tasks.py b/commerce_coordinator/apps/commercetools/tests/test_tasks.py index 3b2e6863..69b4d04a 100644 --- a/commerce_coordinator/apps/commercetools/tests/test_tasks.py +++ b/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" ) diff --git a/commerce_coordinator/apps/core/clients.py b/commerce_coordinator/apps/core/clients.py index dc48d64b..359da0e3 100644 --- a/commerce_coordinator/apps/core/clients.py +++ b/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): diff --git a/commerce_coordinator/apps/lms/clients.py b/commerce_coordinator/apps/lms/clients.py index 6e9d0675..1938a568 100644 --- a/commerce_coordinator/apps/lms/clients.py +++ b/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 diff --git a/commerce_coordinator/apps/lms/tasks.py b/commerce_coordinator/apps/lms/tasks.py index c276f97b..2bf7fabd 100644 --- a/commerce_coordinator/apps/lms/tasks.py +++ b/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