From 45849276881bfa37b116ea5970521d517ab655fc Mon Sep 17 00:00:00 2001 From: "Glenn R. Martin" Date: Mon, 15 Jul 2024 15:50:02 -0400 Subject: [PATCH 1/2] 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 --- .../apps/commercetools/sub_messages/tasks.py | 59 +++++++++++++------ 1 file changed, 40 insertions(+), 19 deletions(-) diff --git a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py index 94e660af..1c0a4812 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 %s is not an edX order, message id: %s', order_id) return True - logger.debug(f'[CT-{tag}] processing edX order %s', order_id) + logger.debug(f'[CT-{tag}] processing edX order %s, message id: %s', order_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 %s, line item %s, message id: %s', + order_id, item.variant.sku, 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 From c697565414427bd0d5afe6988f65aebd5757d079 Mon Sep 17 00:00:00 2001 From: "Glenn R. Martin" Date: Tue, 16 Jul 2024 08:01:45 -0400 Subject: [PATCH 2/2] 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 | 10 +++++----- .../commercetools/tests/sub_messages/test_tasks.py | 4 ---- commerce_coordinator/apps/commercetools/views.py | 6 +++--- 3 files changed, 8 insertions(+), 12 deletions(-) diff --git a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py index 1c0a4812..bf6ae36b 100644 --- a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py +++ b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py @@ -70,11 +70,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 %s is not an edX order, message id: %s', 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, message id: %s', order_id, message_id) + logger.debug(f'[CT-{tag}] processing edX order {order_id}, message id: {message_id}') lms_user_id = get_edx_lms_user_id(customer) @@ -92,8 +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, message id: %s', - order_id, item.variant.sku, message_id) + 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, @@ -319,7 +319,7 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_id): properties=segment_event_properties ) else: # pragma no cover - logger.info(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}, ' 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)