From 151e5e0766c94a92f4772d89b50c4396e026452f Mon Sep 17 00:00:00 2001 From: "Glenn R. Martin" Date: Tue, 16 Jul 2024 08:04:24 -0400 Subject: [PATCH] fix: more logging in tasks in prep for 100% catalog. (#254) * fix: more logging in tasks in prep for 100% catalog. - Adding new info's - Propagating Message IDs to logs - Converting some important debugs to info * chore: fixing tests, universalizing format strings We should avoid testing one the logger. Instead test that actions taken arent or that an expected action is. Logging shouldnt break tests as it may change frequently. --- .../apps/commercetools/sub_messages/tasks.py | 59 +++++++++++++------ .../tests/sub_messages/test_tasks.py | 4 -- .../apps/commercetools/views.py | 6 +- 3 files changed, 43 insertions(+), 26 deletions(-) diff --git a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py index 94e660af..bf6ae36b 100644 --- a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py +++ b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py @@ -50,27 +50,31 @@ def fulfill_order_placed_message_signal_task( tag = "fulfill_order_placed_message_signal_task" + logger.info(f'[CT-{tag}] Processing order {order_id}, ' + f'line item {line_item_state_id}, source system {source_system}, message id: {message_id}') + client = CommercetoolsAPIClient() try: order = client.get_order_by_id(order_id) except CommercetoolsError as err: # pragma no cover - logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors}') + logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors},' + f'message id: {message_id}') return False try: customer = client.get_customer_by_id(order.customer_id) except CommercetoolsError as err: # pragma no cover logger.error(f'[CT-{tag}] Customer not found: {order.customer_id} for order {order_id} with ' - f'CT error {err}, {err.errors}') + f'CT error {err}, {err.errors}, message id: {message_id}') return False if not (customer and order and is_edx_lms_order(order)): - logger.debug(f'[CT-{tag}] order %s is not an edX order', order_id) + logger.debug(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 %s', order_id) + logger.debug(f'[CT-{tag}] processing edX order {order_id}, message id: {message_id}') lms_user_id = get_edx_lms_user_id(customer) @@ -88,7 +92,8 @@ 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 %s, line item %s', order_id, item.variant.sku) + logger.debug(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, order.version, @@ -132,6 +137,9 @@ def fulfill_order_placed_message_signal_task( send_order_confirmation_email(lms_user_id, customer.email, canvas_entry_properties) TieredCache.set_all_tiers(cache_key, value="SENT", django_cache_timeout=EMAIL_NOTIFICATION_CACHE_TTL_SECS) + logger.info(f'[CT-{tag}] Finished order {order_id}, ' + f'line item {line_item_state_id}, source system {source_system}, message id: {message_id}') + return True @@ -145,38 +153,43 @@ def fulfill_order_sanctioned_message_signal_task( tag = "fulfill_order_sanctioned_message_signal_task" + logger.info(f'[CT-{tag}] Processing sanctions for {order_id}, message id: {message_id}') + client = CommercetoolsAPIClient() try: order = client.get_order_by_id(order_id) except CommercetoolsError as err: # pragma no cover - logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors}') + logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors}, ' + f'message id: {message_id}') return False order_workflow_state = get_edx_order_workflow_state_key(order) if not order_workflow_state: - logger.info(f'[CT-{tag}] order {order_id} has no workflow/transition state') + logger.info(f'[CT-{tag}] order {order_id} has no workflow/transition state, message id: {message_id}') try: customer = client.get_customer_by_id(order.customer_id) except CommercetoolsError as err: # pragma no cover logger.error(f'[CT-{tag}] Customer not found: {order.customer_id} for order {order_id} with ' - f'CT error {err}, {err.errors}') + f'CT error {err}, {err.errors}, message id: {message_id}') return False if not (customer and order and is_edx_lms_order(order)): - logger.info(f'[CT-{tag}] order {order_id} is not an edX order') + logger.info(f'[CT-{tag}] order {order_id} is not an edX order, message id: {message_id}') return True if get_edx_is_sanctioned(order): lms_user_name = get_edx_lms_user_name(customer) - logger.info(f'[CT-{tag}] calling lms to deactivate user {lms_user_name}.') + logger.info(f'[CT-{tag}] calling lms to deactivate user {lms_user_name}, message id: {message_id}.') LMSAPIClient().deactivate_user(lms_user_name, message_id) + + logger.info(f'[CT-{tag}] Finished sanctions for {order_id}, message id: {message_id}') return True else: logger.error( f'[CT-{tag}] order state for order {order_id} is not {TwoUKeys.SDN_SANCTIONED_ORDER_STATE}. ' - f'Actual value is {order_workflow_state}' + f'Actual value is {order_workflow_state}, message id: {message_id}' ) return False @@ -230,30 +243,34 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_id): tag = "fulfill_order_returned_signal_task" + logger.info(f'[CT-{tag}] Processing return for order: {order_id}, line item: {return_line_item_return_id}, ' + f'message id: {message_id}') + client = CommercetoolsAPIClient() try: order = client.get_order_by_id(order_id) except CommercetoolsError as err: # pragma no cover - logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors}') + logger.error(f'[CT-{tag}] Order not found: {order_id} with CT error {err}, {err.errors}' + f', message id: {message_id}') return False try: customer = client.get_customer_by_id(order.customer_id) except CommercetoolsError as err: # pragma no cover logger.error(f'[CT-{tag}] Customer not found: {order.customer_id} for order {order_id} with ' - f'CT error {err}, {err.errors}') + f'CT error {err}, {err.errors}, message id: {message_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') + logger.debug(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) lms_user_name = get_edx_lms_user_name(customer) lms_user_id = get_edx_lms_user_id(customer) - logger.debug(f'[CT-{tag}] calling stripe to refund payment intent {payment_intent_id}') + logger.info(f'[CT-{tag}] calling stripe to refund payment intent {payment_intent_id}, message id: {message_id}') # Return payment if payment intent id is set if payment_intent_id is not None: @@ -263,11 +280,11 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_id): if 'refund_response' in result and result['refund_response']: if result['refund_response'] == 'charge_already_refunded': - logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} already has refund transaction, ' - f'sending Zendesk email') + logger.info(f'[CT-{tag}] payment intent {payment_intent_id} already has refund transaction, ' + f'sending Zendesk email, message id: {message_id}') send_refund_notification(customer, order_id) else: - logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} refunded. Message_id: {message_id}') + logger.debug(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): @@ -275,6 +292,7 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_id): # TODO: Remove LMS Enrollment logger.debug( f'[CT-{tag}] calling lms to unenroll user {lms_user_name} in {course_run}' + f', message id: {message_id}' ) product = { @@ -301,7 +319,10 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_id): properties=segment_event_properties ) else: # pragma no cover - logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} not refunded. Message_id: {message_id}') + logger.info(f'[CT-{tag}] payment intent {payment_intent_id} not refunded. message id: {message_id}') return send_refund_notification(customer, order_id) + logger.info(f'[CT-{tag}] Finished return for order: {order_id}, line item: {return_line_item_return_id}, ' + f'message id: {message_id}') + return True diff --git a/commerce_coordinator/apps/commercetools/tests/sub_messages/test_tasks.py b/commerce_coordinator/apps/commercetools/tests/sub_messages/test_tasks.py index 84491ede..8db5f563 100644 --- a/commerce_coordinator/apps/commercetools/tests/sub_messages/test_tasks.py +++ b/commerce_coordinator/apps/commercetools/tests/sub_messages/test_tasks.py @@ -319,12 +319,10 @@ def test_correct_arguments_passed_valid_stripe_refund( @patch('commerce_coordinator.apps.commercetools.sub_messages.tasks.send_refund_notification') @patch('commerce_coordinator.apps.commercetools.sub_messages.tasks.get_edx_payment_intent_id') - @patch('commerce_coordinator.apps.commercetools.sub_messages.tasks.logger.debug') @patch('commerce_coordinator.apps.commercetools.sub_messages.tasks.OrderRefundRequested.run_filter') def test_refund_already_charged( self, _return_filter_mock: MagicMock, - _mock_logger, _mock_payment_intent: MagicMock, _mock_zendesk: MagicMock ): @@ -338,6 +336,4 @@ def test_refund_already_charged( _mock_payment_intent.return_value = 'mock_payment_intent_id' self.get_uut()(*self.unpack_for_uut(self.mock.example_payload)) - _mock_logger.assert_called_with('[CT-fulfill_order_returned_signal_task] payment intent ' - 'mock_payment_intent_id already has refund transaction, sending Zendesk email') _mock_zendesk.assert_called_once() diff --git a/commerce_coordinator/apps/commercetools/views.py b/commerce_coordinator/apps/commercetools/views.py index b1bbe92b..f159248a 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: %s', input_data) + logger.debug(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: %s', input_data) + logger.debug(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: %s', input_data) + logger.debug(f'[CT-{tag}] Message received from commercetools with details: {input_data}') message_details = OrderReturnedViewMessageInputSerializer(data=input_data) message_details.is_valid(raise_exception=True)