diff --git a/commerce_coordinator/apps/commercetools/tasks.py b/commerce_coordinator/apps/commercetools/tasks.py index dab537594..76f145862 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"Error: {err.errors}, 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 3b2e68631..3f014e7b1 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"Error: Some error message, 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 dc48d64bf..47ae8c550 100644 --- a/commerce_coordinator/apps/core/clients.py +++ b/commerce_coordinator/apps/core/clients.py @@ -73,12 +73,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,13 +88,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): diff --git a/commerce_coordinator/apps/lms/clients.py b/commerce_coordinator/apps/lms/clients.py index 6e9d06757..4b8df8d59 100644 --- a/commerce_coordinator/apps/lms/clients.py +++ b/commerce_coordinator/apps/lms/clients.py @@ -40,18 +40,20 @@ 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"Initiating account deactivation for user '{username}'. " + f"Triggered by 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 +64,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 +80,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 +112,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 diff --git a/commerce_coordinator/apps/lms/tasks.py b/commerce_coordinator/apps/lms/tasks.py index 5e941fd74..0b04d9275 100644 --- a/commerce_coordinator/apps/lms/tasks.py +++ b/commerce_coordinator/apps/lms/tasks.py @@ -12,7 +12,7 @@ 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 +37,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 = { @@ -89,6 +86,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