From 26e5b6fbe2b1368a77d754c2a3e5f24eb349c443 Mon Sep 17 00:00:00 2001 From: Attiya Ishaque Date: Wed, 20 Nov 2024 19:16:18 +0500 Subject: [PATCH] fix: Improve logging messages --- .../apps/commercetools/clients.py | 13 +++--- .../apps/commercetools/sub_messages/tasks.py | 12 +++--- .../apps/commercetools/tasks.py | 18 +++++---- .../apps/commercetools/tests/test_clients.py | 13 +++--- .../apps/commercetools/tests/test_tasks.py | 34 +++++++++++----- .../apps/commercetools/utils.py | 4 +- .../apps/commercetools/views.py | 6 +-- commerce_coordinator/apps/core/clients.py | 30 +++----------- commerce_coordinator/apps/core/middleware.py | 2 +- commerce_coordinator/apps/core/views.py | 2 +- .../apps/ecommerce/clients.py | 3 +- commerce_coordinator/apps/lms/clients.py | 40 +++++++++---------- commerce_coordinator/apps/lms/tasks.py | 7 ++-- commerce_coordinator/apps/lms/views.py | 2 +- commerce_coordinator/apps/titan/clients.py | 3 +- commerce_coordinator/apps/titan/pipeline.py | 4 +- commerce_coordinator/apps/titan/views.py | 4 +- 17 files changed, 94 insertions(+), 103 deletions(-) diff --git a/commerce_coordinator/apps/commercetools/clients.py b/commerce_coordinator/apps/commercetools/clients.py index e6dc617d..2d65aec0 100644 --- a/commerce_coordinator/apps/commercetools/clients.py +++ b/commerce_coordinator/apps/commercetools/clients.py @@ -432,7 +432,7 @@ def create_return_for_order(self, order_id: str, order_version: int, order_line_ ) return returned_order except CommercetoolsError as err: - handle_commercetools_error(err, f"Unable to create return for order {order_id}") + handle_commercetools_error("[CommercetoolsAPIClient.create_return_for_order]",err, f"Unable to create return for order {order_id}") raise err def update_return_payment_state_after_successful_refund( @@ -497,7 +497,7 @@ def update_return_payment_state_after_successful_refund( logger.info("Updated transaction with return item id") return updated_order except CommercetoolsError as err: - handle_commercetools_error(err, f"Unable to update ReturnPaymentState of order {order_id}") + handle_commercetools_error("[CommercetoolsAPIClient.update_return_payment_state_after_successful_refund]",err, f"Unable to update ReturnPaymentState of order {order_id}") raise OpenEdxFilterException(str(err)) from err def _preprocess_refund_object(self, refund: Refund, psp: str) -> Refund: @@ -559,7 +559,7 @@ def create_return_payment_transaction( f"Unable to create refund payment transaction for payment {payment_id}, refund {refund['id']} " f"with PSP: {psp}" ) - handle_commercetools_error(err, context) + handle_commercetools_error("[CommercetoolsAPIClient.create_return_payment_transaction]",err, context) raise err def update_line_item_transition_state_on_fulfillment( @@ -610,13 +610,14 @@ def update_line_item_transition_state_on_fulfillment( return updated_fulfillment_line_item_order else: logger.info( - f"The line item {line_item_id} already has the correct state {new_state_key}. " - "Not attempting to transition LineItemState" + f"[CommercetoolsAPIClient] - The line item {line_item_id} already has the correct state {new_state_key}. " + f"Not attempting to transition LineItemState for order id {order_id}" ) return self.get_order_by_id(order_id) except CommercetoolsError as err: + context_prefix ="[CommercetoolsAPIClient.update_line_item_state_on_fulfillment_completion]" # Logs & ignores version conflict errors due to duplicate Commercetools messages - handle_commercetools_error(err, f"Unable to update LineItemState of order {order_id}", True) + handle_commercetools_error(context_prefix, err, f"Unable to update LineItemState of order {order_id}") return None def retire_customer_anonymize_fields( diff --git a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py index a1d5590a..3aac58e9 100644 --- a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py +++ b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py @@ -78,11 +78,11 @@ def fulfill_order_placed_message_signal_task( return False if not (customer and order and is_edx_lms_order(order)): - logger.debug(f'[CT-{tag}] order {order_id} is not an edX order, message id: {message_id}') + logger.info(f'[CT-{tag}] order {order_id} is not an edX order, message id: {message_id}') return True - logger.debug(f'[CT-{tag}] processing edX order {order_id}, message id: {message_id}') + logger.info(f'[CT-{tag}] processing edX order {order_id}, message id: {message_id}') lms_user_id = get_edx_lms_user_id(customer) @@ -99,7 +99,7 @@ def fulfill_order_placed_message_signal_task( canvas_entry_properties.update(extract_ct_order_information_for_braze_canvas(customer, order)) for item in get_edx_items(order): - logger.debug(f'[CT-{tag}] processing edX order {order_id}, line item {item.variant.sku}, ' + logger.info(f'[CT-{tag}] processing edX order {order_id}, line item {item.variant.sku}, ' f'message id: {message_id}') updated_order = client.update_line_item_transition_state_on_fulfillment( order.id, @@ -263,7 +263,7 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_id): return False if not (customer and order and is_edx_lms_order(order)): # pragma no cover - logger.debug(f'[CT-{tag}] order {order_id} is not an edX order, message id: {message_id}') + logger.info(f'[CT-{tag}] order {order_id} is not an edX order, message id: {message_id}') return True payment_intent_id = get_edx_payment_intent_id(order) @@ -283,13 +283,13 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_id): logger.info(f'[CT-{tag}] payment intent {payment_intent_id} already has refunded transaction, ' f'sending Slack notification, message id: {message_id}') else: - logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} refunded. message id: {message_id}') + logger.info(f'[CT-{tag}] payment intent {payment_intent_id} refunded. message id: {message_id}') segment_event_properties = _prepare_segment_event_properties(order, return_line_item_return_id) for line_item in get_edx_items(order): course_run = get_edx_product_course_run_key(line_item) # TODO: Remove LMS Enrollment - logger.debug( + logger.info( f'[CT-{tag}] calling lms to unenroll user {lms_user_name} in {course_run}' f', message id: {message_id}' ) diff --git a/commerce_coordinator/apps/commercetools/tasks.py b/commerce_coordinator/apps/commercetools/tasks.py index 14dbccf7..4a640d8f 100644 --- a/commerce_coordinator/apps/commercetools/tasks.py +++ b/commerce_coordinator/apps/commercetools/tasks.py @@ -42,8 +42,8 @@ def update_line_item_state_on_fulfillment_completion( ) 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 +58,12 @@ def refund_from_stripe_task( """ client = CommercetoolsAPIClient() try: + logger.info( + f"[refund_from_stripe_task] Initiating creation of CT payment's refund transaction object " + f"for payment Intent ID {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} " + logger.info(f"[refund_from_stripe_task] Event 'charge.refunded' 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( @@ -70,8 +73,8 @@ def refund_from_stripe_task( ) 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']} " + logger.error(f"[refund_from_stripe_task] Unable to create CT payment's refund transaction " + f"object for [ {payment.id} ] on Stripe refund {stripe_refund['id']} " f"with error {err.errors} and correlation id {err.correlation_id}") return None @@ -89,8 +92,6 @@ def refund_from_paypal_task( try: payment = client.get_payment_by_transaction_interaction_id(paypal_capture_id) if has_full_refund_transaction(payment): - logger.info(f"PayPal PAYMENT.CAPTURE.REFUNDED event received, but Payment with ID {payment.id} " - f"already has a refund with ID: {refund.get('id')}. Skipping task to add refund transaction.") return None updated_payment = client.create_return_payment_transaction( payment_id=payment.id, @@ -100,7 +101,8 @@ def refund_from_paypal_task( ) return updated_payment except CommercetoolsError as err: - logger.error(f"Unable to create refund transaction for payment {payment.key} " + logger.error(f"[refund_from_paypal_task] Unable to create CT payment's refund " + f"transaction object for payment {payment.key} " f"on PayPal refund {refund.get('id')} " f"with error {err.errors} and correlation id {err.correlation_id}") return None diff --git a/commerce_coordinator/apps/commercetools/tests/test_clients.py b/commerce_coordinator/apps/commercetools/tests/test_clients.py index a3b6cfde..9352b256 100644 --- a/commerce_coordinator/apps/commercetools/tests/test_clients.py +++ b/commerce_coordinator/apps/commercetools/tests/test_clients.py @@ -470,8 +470,8 @@ def test_create_return_for_order_exception(self): exception = cm.exception expected_message = ( - f"[CommercetoolsError] Unable to create return for " - f"order mock_order_id " + f"[CommercetoolsError] [CommercetoolsAPIClient.create_return_for_order] " + f"Unable to create return for order mock_order_id " f"- Correlation ID: {exception.correlation_id}, Details: {exception.errors}" ) @@ -604,7 +604,8 @@ def test_create_refund_transaction_exception(self): exception = cm.exception expected_message = ( - f"[CommercetoolsError] Unable to create refund payment transaction for " + f"[CommercetoolsError] [CommercetoolsAPIClient.create_return_payment_transaction] " + f"Unable to create refund payment transaction for " f"payment mock_payment_id, refund {mock_stripe_refund.id} with PSP: stripe_edx " f"- Correlation ID: {exception.correlation_id}, Details: {exception.errors}" ) @@ -683,7 +684,7 @@ def test_update_line_item_state_exception(self, mock_state_by_id): ) expected_message = ( - f"[CommercetoolsError] Unable to update LineItemState " + f"[CommercetoolsAPIClient] Unable to update LineItemState " f"of order mock_order_id " f"- Correlation ID: {mock_error_response['correlation_id']}, " f"Details: {mock_error_response['errors']}" @@ -715,8 +716,8 @@ def test_order_line_item_in_correct_state(self, mock_order_by_id, mock_state_by_ ) expected_message = ( - f"The line item {line_item_id} already has the correct state {mock_line_item_state.key}. " - f"Not attempting to transition LineItemState" + f"[CommercetoolsAPIClient] - The line item {line_item_id} already has the correct state " + f"{mock_line_item_state.key}. Not attempting to transition LineItemState for order id mock_order_id" ) log_mock.assert_called_with(expected_message) diff --git a/commerce_coordinator/apps/commercetools/tests/test_tasks.py b/commerce_coordinator/apps/commercetools/tests/test_tasks.py index 15dcd241..7ddd4907 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 creation of CT payment's refund transaction object " + f"for payment Intent ID {payment_intent_id}."), + call(f"[refund_from_stripe_task] Event 'charge.refunded' 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 CT payment's refund transaction object for [ {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/commercetools/utils.py b/commerce_coordinator/apps/commercetools/utils.py index 95557128..293bd433 100644 --- a/commerce_coordinator/apps/commercetools/utils.py +++ b/commerce_coordinator/apps/commercetools/utils.py @@ -35,9 +35,9 @@ def get_braze_client(): ) -def handle_commercetools_error(err: CommercetoolsError, context: str, is_info=False): +def handle_commercetools_error(context_prefix, err: CommercetoolsError, context: str, is_info=False): """Handles commercetools errors.""" - error_message = f"[CommercetoolsError] {context} - Correlation ID: {err.correlation_id}, Details: {err.errors}" + error_message = f"[CommercetoolsError] {context_prefix} {context} - Correlation ID: {err.correlation_id}, Details: {err.errors}" if is_info: logger.info(error_message) else: diff --git a/commerce_coordinator/apps/commercetools/views.py b/commerce_coordinator/apps/commercetools/views.py index f159248a..ad573b71 100644 --- a/commerce_coordinator/apps/commercetools/views.py +++ b/commerce_coordinator/apps/commercetools/views.py @@ -41,7 +41,7 @@ def post(self, request): **request.data } - logger.debug(f'[CT-{tag}] Message received from commercetools with details: {input_data}') + logger.info(f'[CT-{tag}] Message received from commercetools with details: {input_data}') message_details = OrderLineItemMessageInputSerializer(data=input_data) message_details.is_valid(raise_exception=True) @@ -85,7 +85,7 @@ def post(self, request): **request.data } - logger.debug(f'[CT-{tag}] Message received from commercetools with details: {input_data}') + logger.info(f'[CT-{tag}] Message received from commercetools with details: {input_data}') message_details = OrderSanctionedViewMessageInputSerializer(data=input_data) message_details.is_valid(raise_exception=True) @@ -127,7 +127,7 @@ def post(self, request): **request.data } - logger.debug(f'[CT-{tag}] Message received from commercetools with details: {input_data}') + logger.info(f'[CT-{tag}] Message received from commercetools with details: {input_data}') message_details = OrderReturnedViewMessageInputSerializer(data=input_data) message_details.is_valid(raise_exception=True) diff --git a/commerce_coordinator/apps/core/clients.py b/commerce_coordinator/apps/core/clients.py index dc48d64b..052eceb8 100644 --- a/commerce_coordinator/apps/core/clients.py +++ b/commerce_coordinator/apps/core/clients.py @@ -64,38 +64,18 @@ def normal_timeout(self): settings.REQUEST_READ_TIMEOUT_SECONDS ) - def log_request_response(self, ext_logger, response): - """ - Log requests.Request Response. - - Args: - ext_logger: The logger of the module the Client (or Client- - 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) - - def log_request_exception(self, ext_logger, exc): + def log_request_exception(self, context_prefix, ext_logger, exc): """ Log requests.Request exceptions. 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"{context_prefix} - The API call failed with status code: " + f"{exc.response.status_code if exc.response else ''}. Reason: {exc}.") class BaseEdxOAuthClient(Client): diff --git a/commerce_coordinator/apps/core/middleware.py b/commerce_coordinator/apps/core/middleware.py index 3861a34c..82c81376 100644 --- a/commerce_coordinator/apps/core/middleware.py +++ b/commerce_coordinator/apps/core/middleware.py @@ -40,7 +40,7 @@ def log_drf_exceptions(exc, context): 'type: [%s], via [%s] on path: [%s] with exception: [%s].', status_code, view_name, exception_type, method, path, exc, ) - logger.debug( + logger.info( 'Context for DRF Exception in APIView: status code: [%s] on ' 'view: [%s] of type: [%s], via [%s] on path: [%s] with exception: [%s], ' 'from request query_params: [%s], and data: [%s].', diff --git a/commerce_coordinator/apps/core/views.py b/commerce_coordinator/apps/core/views.py index eb085591..1f97331f 100644 --- a/commerce_coordinator/apps/core/views.py +++ b/commerce_coordinator/apps/core/views.py @@ -130,7 +130,7 @@ def _is_running(view: str, identifier: str): key = SingleInvocationAPIView._view_cache_key(view, identifier) cache_value = TieredCache.get_cached_response(key) if cache_value.is_found or cache_value.get_value_or_default(False): - logger.debug(f'[CT-{view}] Currently processing request for %s, ignoring invocation', identifier) + logger.info(f'[CT-{view}] Currently processing request for %s, ignoring invocation', identifier) return True return False diff --git a/commerce_coordinator/apps/ecommerce/clients.py b/commerce_coordinator/apps/ecommerce/clients.py index 69c1d78d..9d5c807c 100644 --- a/commerce_coordinator/apps/ecommerce/clients.py +++ b/commerce_coordinator/apps/ecommerce/clients.py @@ -37,9 +37,8 @@ def get_orders(self, query_params): resource_url = urljoin_directory(self.api_base_url, '/orders') response = self.client.get(resource_url, params=query_params) response.raise_for_status() - self.log_request_response(logger, response) except RequestException as exc: - self.log_request_exception(logger, exc) + self.log_request_exception("[EcommerceAPIClient.get_orders]",logger, exc) raise return response.json() diff --git a/commerce_coordinator/apps/lms/clients.py b/commerce_coordinator/apps/lms/clients.py index 6e9d0675..4bf2e902 100644 --- a/commerce_coordinator/apps/lms/clients.py +++ b/commerce_coordinator/apps/lms/clients.py @@ -40,18 +40,19 @@ 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.deactivate_user] Initiating account deactivation on LMS for user '{username}'. " + f"Triggered by CT 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.exception( - f'An error occurred while deactivating account for user with username {username}: {exc}' + logger.error( + f"[LMSAPIClient.deactivate_user] Failed to deactivate account for user '{username}' " + f"(triggered by CT subscription Message ID: {ct_message_id}). Error: {exc}" ) raise @@ -62,11 +63,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 +79,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 @@ -97,33 +98,30 @@ def post(self, url, json, line_item_state_payload, logging_obj, timeout=None): timeout=timeout, ) response.raise_for_status() - self.log_request_response(logger, response) fulfill_line_item_state_payload = { **line_item_state_payload, '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.post] LMS fulfillment successful for user '{logging_obj['user']}'. " + f"Details: lms_user_id: {logging_obj['lms_user_id']}, CT order ID: {logging_obj['order_id']}, " + f"course ID: {logging_obj['course_id']}, CT 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) + context_prefix = f"[LMSAPIClient] lms_user_id:{logging_obj['lms_user_id']}, CT order ID: {logging_obj['order_id']}" + f"course ID: {logging_obj['course_id']}, celery task ID: {logging_obj['celery_task_id']}" + self.log_request_exception(context_prefix, 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']}]" - ) raise fulfillment_completed_signal.send_robust( diff --git a/commerce_coordinator/apps/lms/tasks.py b/commerce_coordinator/apps/lms/tasks.py index c276f97b..15837977 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_placed_send_enroll_in_course_task] Starting task with details: {locals()}.") user = User.objects.get(lms_user_id=edx_lms_user_id) enrollment_data = { @@ -147,6 +144,8 @@ 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_placed_send_enroll_in_course_task] " + f"Task retry count# {self.request.retries} for CT 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 diff --git a/commerce_coordinator/apps/lms/views.py b/commerce_coordinator/apps/lms/views.py index d5b5981a..360a003c 100644 --- a/commerce_coordinator/apps/lms/views.py +++ b/commerce_coordinator/apps/lms/views.py @@ -93,7 +93,7 @@ def _redirect_response_payment(self, request): ) redirect = HttpResponseRedirect(redirect_url, status=HTTP_303_SEE_OTHER) redirect.headers[HttpHeadersNames.CONTENT_TYPE.value] = MediaTypes.JSON.value - logger.debug( + logger.info( f"{self._redirect_response_payment.__qualname__} Redirecting 303 via {redirect}." ) return redirect diff --git a/commerce_coordinator/apps/titan/clients.py b/commerce_coordinator/apps/titan/clients.py index 1059b14e..49c71f92 100644 --- a/commerce_coordinator/apps/titan/clients.py +++ b/commerce_coordinator/apps/titan/clients.py @@ -61,9 +61,8 @@ def _request(self, request_method, resource_path, params=None, json=None, header headers=headers, ) response.raise_for_status() - self.log_request_response(logger, response) except RequestException as exc: - self.log_request_exception(logger, exc) + self.log_request_exception("[TitanAPIClient]",logger, exc) raise return response.json() diff --git a/commerce_coordinator/apps/titan/pipeline.py b/commerce_coordinator/apps/titan/pipeline.py index 9ecd5c50..a5817821 100644 --- a/commerce_coordinator/apps/titan/pipeline.py +++ b/commerce_coordinator/apps/titan/pipeline.py @@ -138,11 +138,11 @@ def run_filter(self, order_data, **kwargs): # pylint: disable=arguments-differ basket_id) return PipelineCommand.HALT.value elif recent_payment['state'] == PaymentState.FAILED.value: - logger.debug('Failed payment [%s] found. Continue pipeline for order: [%s]', + logger.info('Failed payment [%s] found. Continue pipeline for order: [%s]', recent_payment['payment_number'], basket_id) return PipelineCommand.CONTINUE.value - logger.debug('Draft payment [%s] exists. Add draft payment to pipeline for order: [%s]', + logger.info('Draft payment [%s] exists. Add draft payment to pipeline for order: [%s]', recent_payment['payment_number'], basket_id) return { diff --git a/commerce_coordinator/apps/titan/views.py b/commerce_coordinator/apps/titan/views.py index ee914eea..b90db9a2 100644 --- a/commerce_coordinator/apps/titan/views.py +++ b/commerce_coordinator/apps/titan/views.py @@ -46,8 +46,8 @@ def post(self, request): fulfill_order_placed_signal.send_robust which processed the request. """ - logger.debug(f'Titan OrderFulfillView.post() request object: {request.data}.') - logger.debug(f'Titan OrderFulfillView.post() headers: {request.headers}.') + logger.info(f'Titan OrderFulfillView.post() request object: {request.data}.') + logger.info(f'Titan OrderFulfillView.post() headers: {request.headers}.') params = { 'course_id': request.data.get('course_id'),