diff --git a/commerce_coordinator/apps/commercetools/clients.py b/commerce_coordinator/apps/commercetools/clients.py index c54b7494..1e768155 100644 --- a/commerce_coordinator/apps/commercetools/clients.py +++ b/commerce_coordinator/apps/commercetools/clients.py @@ -174,6 +174,8 @@ def get_customer_by_lms_user_id(self, lms_user_id: int) -> Optional[CTCustomer]: is returned. """ + logger.info(f"[CommercetoolsAPIClient] - Attempting to get customer with LMS user id: {lms_user_id}") + edx_lms_user_id_key = EdXFieldNames.LMS_USER_ID results = self.base_client.customers.query( @@ -185,15 +187,20 @@ def get_customer_by_lms_user_id(self, lms_user_id: int) -> Optional[CTCustomer]: if results.count > 1: # We are unable due to CT Limitations to enforce unique LMS ID values on Customers on the catalog side, so # let's do a backhanded check by trying to pull 2 users and erroring if we find a discrepancy. + logger.info(f"[CommercetoolsAPIClient] - More than one customer found with LMS " + f"user id: {lms_user_id}, raising error") raise ValueError("More than one user was returned from the catalog with this edX LMS User ID, these must " "be unique.") if results.count == 0: + logger.info(f"[CommercetoolsAPIClient] - No customer found with LMS user id: {lms_user_id}") return None else: + logger.info(f"[CommercetoolsAPIClient] - Customer found with LMS user id: {lms_user_id}") return results.results[0] - def get_order_by_id(self, order_id: str, expand: ExpandList = DEFAULT_ORDER_EXPANSION) -> CTOrder: + def get_order_by_id(self, order_id: str, expand: ExpandList = DEFAULT_ORDER_EXPANSION) \ + -> CTOrder: # pragma no cover """ Fetch an order by the Order ID (UUID) @@ -203,7 +210,8 @@ def get_order_by_id(self, order_id: str, expand: ExpandList = DEFAULT_ORDER_EXPA Returns (CTOrder): Order with Expanded Properties """ - return self.base_client.orders.get_by_id(order_id, expand=list(expand)) # pragma no cover + logger.info(f"[CommercetoolsAPIClient] - Attempting to find order with id: {order_id}") + return self.base_client.orders.get_by_id(order_id, expand=list(expand)) def get_order_by_number(self, order_number: str, expand: ExpandList = DEFAULT_ORDER_EXPANSION) \ -> CTOrder: # pragma no cover @@ -216,6 +224,7 @@ def get_order_by_number(self, order_number: str, expand: ExpandList = DEFAULT_OR Returns (CTOrder): Order with Expanded Properties """ + logger.info(f"[CommercetoolsAPIClient] - Attempting to find order with number {order_number}") return self.base_client.orders.get_by_order_number(order_number, expand=list(expand)) def get_orders(self, customer: CTCustomer, offset=0, @@ -238,6 +247,8 @@ def get_orders(self, customer: CTCustomer, offset=0, See sample response in tests.py """ + logger.info(f"[CommercetoolsAPIClient] - Attempting to find all completed orders for " + f"customer with ID {customer.id}") order_where_clause = f"orderState=\"{order_state}\"" values = self.base_client.orders.query( where=["customerId=:cid", order_where_clause], @@ -268,17 +279,21 @@ def get_orders_for_customer(self, edx_lms_user_id: int, offset=0, return orders, customer - def get_customer_by_id(self, customer_id: str) -> CTCustomer: - return self.base_client.customers.get_by_id(customer_id) # pragma no cover + def get_customer_by_id(self, customer_id: str) -> CTCustomer: # pragma no cover + logger.info(f"[CommercetoolsAPIClient] - Attempting to find customer with ID {customer_id}") + return self.base_client.customers.get_by_id(customer_id) - def get_state_by_id(self, state_id: str) -> CTLineItemState: - return self.base_client.states.get_by_id(state_id) # pragma no cover + def get_state_by_id(self, state_id: str) -> CTLineItemState: # pragma no cover + logger.info(f"[CommercetoolsAPIClient] - Attempting to find state with id {state_id}") + return self.base_client.states.get_by_id(state_id) - def get_state_by_key(self, state_key: str) -> CTLineItemState: - return self.base_client.states.get_by_key(state_key) # pragma no cover + def get_state_by_key(self, state_key: str) -> CTLineItemState: # pragma no cover + logger.info(f"[CommercetoolsAPIClient] - Attempting to find state with key {state_key}") + return self.base_client.states.get_by_key(state_key) - def get_payment_by_key(self, payment_key: str) -> CTPayment: - return self.base_client.payments.get_by_key(payment_key) # pragma no cover + def get_payment_by_key(self, payment_key: str) -> CTPayment: # pragma no cover + logger.info(f"[CommercetoolsAPIClient] - Attempting to find payment with key {payment_key}") + return self.base_client.payments.get_by_key(payment_key) def get_product_variant_by_course_run(self, cr_id: str) -> Optional[CTProductVariant]: """ @@ -327,6 +342,8 @@ def create_return_for_order(self, order_id: str, order_version: int, order_line_ return_item_draft_comment = f'Creating return item for order {order_id} with ' \ f'order line item ID {order_line_item_id}' + logger.info(f"[CommercetoolsAPIClient] - {return_item_draft_comment}") + return_item_draft = ReturnItemDraft( quantity=1, line_item_id=order_line_item_id, @@ -366,6 +383,8 @@ def update_return_payment_state_after_successful_refund(self, order_id: str, Raises Exception: Error if update was unsuccessful. """ try: + logger.info(f"[CommercetoolsAPIClient] - Updating payment state for return " + f"with id {return_line_item_return_id} to '{ReturnPaymentState.REFUNDED}'.") return_payment_state_action = OrderSetReturnPaymentStateAction( return_item_id=return_line_item_return_id, @@ -398,6 +417,9 @@ def create_return_payment_transaction( Raises Exception: Error if creation was unsuccessful. """ try: + logger.info(f"[CommercetoolsAPIClient] - Creating refund transaction for payment with ID {payment_id} " + f"following successful Stripe refund {stripe_refund.id}") + amount_as_money = CTMoney( cent_amount=stripe_refund.amount, currency_code=stripe_refund.currency.upper() @@ -447,6 +469,9 @@ def update_line_item_transition_state_on_fulfillment(self, order_id: str, order_ from_state_key = self.get_state_by_id(from_state_id).key + logger.info(f"[CommercetoolsAPIClient] - Transitioning line item state for order with ID {order_id}" + f"from {from_state_key} to {new_state_key}") + try: if new_state_key != from_state_key: transition_line_item_state_action = OrderTransitionLineItemStateAction( diff --git a/commerce_coordinator/apps/commercetools/filters.py b/commerce_coordinator/apps/commercetools/filters.py index fbb92b2c..7177a169 100644 --- a/commerce_coordinator/apps/commercetools/filters.py +++ b/commerce_coordinator/apps/commercetools/filters.py @@ -10,7 +10,7 @@ class OrderRefundRequested(OpenEdxPublicFilter): filter_type = "org.edx.coordinator.commercetools.order.refund.requested.v1" @classmethod - def run_filter(cls, order_id, return_line_item_return_id): + def run_filter(cls, order_id, return_line_item_return_id, message_id): """ Call the PipelineStep(s) defined for this filter. Arguments: @@ -19,4 +19,6 @@ def run_filter(cls, order_id, return_line_item_return_id): Returns: order_refund: Updated order with return item attached """ - return super().run_pipeline(order_id=order_id, return_line_item_return_id=return_line_item_return_id) + return super().run_pipeline(order_id=order_id, + return_line_item_return_id=return_line_item_return_id, + message_id=message_id) diff --git a/commerce_coordinator/apps/commercetools/pipeline.py b/commerce_coordinator/apps/commercetools/pipeline.py index b57b971a..6b762f80 100644 --- a/commerce_coordinator/apps/commercetools/pipeline.py +++ b/commerce_coordinator/apps/commercetools/pipeline.py @@ -205,6 +205,8 @@ def run_filter( returned_line_item_return_id (str): Updated Commercetools order's return item ID """ + tag = type(self).__name__ + if active_order_management_system != COMMERCETOOLS_ORDER_MANAGEMENT_SYSTEM: # pragma no cover return PipelineCommand.CONTINUE.value @@ -232,9 +234,13 @@ def run_filter( f'order line item id {order_line_item_id}') except CommercetoolsError as err: # pragma no cover # TODO: FIX Per SONIC-354 + log.info(f"[{tag}] Unsuccessful attempt to create order return with details: " + f"[order_id: {order_id}, order_line_item_id: {order_line_item_id}") log.exception(f"[{type(self).__name__}] Commercetools Error: {err}, {err.errors}") raise OpenEdxFilterException(str(err)) from err - except HTTPError as err: + except HTTPError as err: # pragma no cover + log.info(f"[{tag}] Unsuccessful attempt to create order return with details: " + f"[order_id: {order_id}, order_line_item_id: {order_line_item_id}") log.exception(f"[{type(self).__name__}] HTTP Error: {err}") return PipelineCommand.CONTINUE.value @@ -303,9 +309,11 @@ def run_filter( tag = type(self).__name__ if active_order_management_system != COMMERCETOOLS_ORDER_MANAGEMENT_SYSTEM: # pragma no cover + log.info(f"[{tag}] active order management system is not {COMMERCETOOLS_ORDER_MANAGEMENT_SYSTEM}, skipping") return PipelineCommand.CONTINUE.value if refund_response == "charge_already_refunded" or has_been_refunded: + log.info(f"[{tag}] refund has already been processed, skipping refund payment transaction creation") return PipelineCommand.CONTINUE.value ct_api_client = CommercetoolsAPIClient() @@ -326,8 +334,14 @@ def run_filter( 'returned_payment': updated_payment } except CommercetoolsError as err: # pragma no cover + log.info(f"[{tag}] Unsuccessful attempt to create refund payment transaction with details: " + f"[stripe_payment_intent_id: {refund_response['payment_intent']}, " + f"payment_id: {payment_on_order.id}], message_id: {kwargs['message_id']}") log.exception(f"[{tag}] Commercetools Error: {err}, {err.errors}") return PipelineCommand.CONTINUE.value except HTTPError as err: # pragma no cover + log.info(f"[{tag}] Unsuccessful attempt to create refund payment transaction with details: " + f"[stripe_payment_intent_id: {refund_response['payment_intent']}, " + f"payment_id: {payment_on_order.id}], message_id: {kwargs['message_id']}") log.exception(f"[{tag}] HTTP Error: {err}") return PipelineCommand.CONTINUE.value diff --git a/commerce_coordinator/apps/commercetools/serializers.py b/commerce_coordinator/apps/commercetools/serializers.py index 5f4470a2..fafac844 100644 --- a/commerce_coordinator/apps/commercetools/serializers.py +++ b/commerce_coordinator/apps/commercetools/serializers.py @@ -8,11 +8,13 @@ class OrderSanctionedViewMessageDetailSerializer(CoordinatorSerializer): """ Serializer for CommerceTools message 'detail' """ + id = serializers.CharField() resource = serializers.DictField(child=serializers.CharField()) type = serializers.CharField(allow_null=False) def to_representation(self, instance): representation = super().to_representation(instance) + representation['message_id'] = representation.pop('id') representation['type'] = representation.pop('type') order_id = representation['resource'].get('id') @@ -112,11 +114,13 @@ class OrderReturnedViewMessageDetailSerializer(CoordinatorSerializer): """ Serializer for OrderReturnedView message detail. """ + id = serializers.CharField() resource = serializers.DictField(child=serializers.CharField()) returnInfo = OrderReturnedViewMessageReturnInfoSerializer() def to_representation(self, instance): representation = super().to_representation(instance) + representation['message_id'] = representation.pop('id') order_id = representation['resource'].get('id') if order_id: # pragma no cover representation['order_id'] = order_id diff --git a/commerce_coordinator/apps/commercetools/sub_messages/signals_delayed.py b/commerce_coordinator/apps/commercetools/sub_messages/signals_delayed.py index 6e56b43f..bb953af4 100644 --- a/commerce_coordinator/apps/commercetools/sub_messages/signals_delayed.py +++ b/commerce_coordinator/apps/commercetools/sub_messages/signals_delayed.py @@ -31,6 +31,7 @@ def fulfill_order_sanctioned_message_signal(**kwargs): """ CoordinatorSignal receiver to invoke Celery Task fulfill_order_sanctioned_message_signal""" async_result = fulfill_order_sanctioned_message_signal_task.delay( order_id=kwargs['order_id'], + message_id=kwargs['message_id'] ) return async_result.id @@ -41,5 +42,6 @@ def fulfill_order_returned_signal(**kwargs): async_result = fulfill_order_returned_signal_task.delay( order_id=kwargs['order_id'], return_line_item_return_id=kwargs['return_line_item_return_id'], + message_id=kwargs['message_id'] ) return async_result.id diff --git a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py index 202a9c78..94e660af 100644 --- a/commerce_coordinator/apps/commercetools/sub_messages/tasks.py +++ b/commerce_coordinator/apps/commercetools/sub_messages/tasks.py @@ -139,6 +139,7 @@ def fulfill_order_placed_message_signal_task( @shared_task(autoretry_for=(RequestException, CommercetoolsError), retry_kwargs={'max_retries': 5, 'countdown': 3}) def fulfill_order_sanctioned_message_signal_task( order_id, + message_id ): """Celery task for an order sanctioned message.""" @@ -153,7 +154,7 @@ def fulfill_order_sanctioned_message_signal_task( order_workflow_state = get_edx_order_workflow_state_key(order) if not order_workflow_state: - logger.debug(f'[CT-{tag}] order %s has no workflow/transition state', order_id) + logger.info(f'[CT-{tag}] order {order_id} has no workflow/transition state') try: customer = client.get_customer_by_id(order.customer_id) @@ -163,21 +164,19 @@ def fulfill_order_sanctioned_message_signal_task( return False if not (customer and order and is_edx_lms_order(order)): - logger.info(f'[CT-{tag}] order %s is not an edX order', order_id) + logger.info(f'[CT-{tag}] order {order_id} is not an edX order') 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 %s', lms_user_name) + logger.info(f'[CT-{tag}] calling lms to deactivate user {lms_user_name}.') - LMSAPIClient().deactivate_user(lms_user_name) + LMSAPIClient().deactivate_user(lms_user_name, message_id) return True else: logger.error( - f'[CT-{tag}] order state for order %s is not %s. Actual value is %s', - order_id, - TwoUKeys.SDN_SANCTIONED_ORDER_STATE, - order_workflow_state + f'[CT-{tag}] order state for order {order_id} is not {TwoUKeys.SDN_SANCTIONED_ORDER_STATE}. ' + f'Actual value is {order_workflow_state}' ) return False @@ -186,7 +185,8 @@ def fulfill_order_sanctioned_message_signal_task( @shared_task(autoretry_for=(RequestException, CommercetoolsError), retry_kwargs={'max_retries': 5, 'countdown': 3}) def fulfill_order_returned_signal_task( order_id, - return_line_item_return_id + return_line_item_return_id, + message_id ): """Celery task for an order return (and refunded) message.""" @@ -241,41 +241,40 @@ def _prepare_segment_event_properties(in_order, return_line_item_return_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 ' + logger.error(f'[CT-{tag}] Customer not found: {order.customer_id} for order {order_id} with ' f'CT error {err}, {err.errors}') return False if not (customer and order and is_edx_lms_order(order)): # pragma no cover - 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') 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 %s', payment_intent_id) + logger.debug(f'[CT-{tag}] calling stripe to refund payment intent {payment_intent_id}') # Return payment if payment intent id is set if payment_intent_id is not None: result = OrderRefundRequested.run_filter( - order_id=order_id, return_line_item_return_id=return_line_item_return_id + order_id=order_id, return_line_item_return_id=return_line_item_return_id, message_id=message_id ) if 'refund_response' in result and result['refund_response']: if result['refund_response'] == 'charge_already_refunded': - logger.debug(f'[CT-{tag}] payment intent %s already has refund transaction, ' - f'sending Zendesk email', payment_intent_id) + logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} already has refund transaction, ' + f'sending Zendesk email') send_refund_notification(customer, order_id) else: - logger.debug(f'[CT-{tag}] payment intent %s refunded', payment_intent_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): course_run = get_edx_product_course_run_key(line_item) # TODO: Remove LMS Enrollment logger.debug( - f'[CT-{tag}] calling lms to unenroll user %s in %s', - lms_user_name, course_run + f'[CT-{tag}] calling lms to unenroll user {lms_user_name} in {course_run}' ) product = { @@ -302,7 +301,7 @@ 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 %s not refunded', payment_intent_id) + logger.debug(f'[CT-{tag}] payment intent {payment_intent_id} not refunded. Message_id: {message_id}') return send_refund_notification(customer, order_id) return True diff --git a/commerce_coordinator/apps/commercetools/tests/sub_messages/test_signals_delayed.py b/commerce_coordinator/apps/commercetools/tests/sub_messages/test_signals_delayed.py index f0619286..04419373 100644 --- a/commerce_coordinator/apps/commercetools/tests/sub_messages/test_signals_delayed.py +++ b/commerce_coordinator/apps/commercetools/tests/sub_messages/test_signals_delayed.py @@ -56,6 +56,7 @@ class SanctionedOrderPlacedMessageSignalTest(CoordinatorSignalReceiverTestCase): """ Commercetools Sanctioned Order Placed Signal Tester""" mock_parameters = { 'order_id': uuid4_str(), + 'message_id': uuid4_str() } def test_correct_arguments_passed(self, mock_task): @@ -84,6 +85,7 @@ class ReturnedOrderPlacedMessageSignalTest(CoordinatorSignalReceiverTestCase): mock_parameters = { 'order_id': uuid4_str(), 'return_line_item_return_id': uuid4_str(), + 'message_id': uuid4_str() } def test_correct_arguments_passed(self, mock_task): 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 d42d5ec5..84491ede 100644 --- a/commerce_coordinator/apps/commercetools/tests/sub_messages/test_tasks.py +++ b/commerce_coordinator/apps/commercetools/tests/sub_messages/test_tasks.py @@ -155,6 +155,7 @@ def unpack_for_uut(values): """ Unpack the dictionary in the order required for the UUT """ return ( values['order_id'], + values['message_id'] ) @staticmethod @@ -262,6 +263,7 @@ def unpack_for_uut(values): return ( values['order_id'], values['order_line_id'], + values['message_id'] ) @staticmethod @@ -314,3 +316,28 @@ def test_correct_arguments_passed_valid_stripe_refund( mock_values.order_mock.assert_has_calls([call(mock_values.order_id), call(order_id=mock_values.order_id)]) mock_values.customer_mock.assert_called_once_with(mock_values.customer_id) _stripe_api_mock.return_value.refund_payment_intent.assert_called_once() + + @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 + ): + """ + Check calling uut with mock_parameters yields call to client with + expected_data. + """ + mock_values = self.mock + mock_values.order_mock.return_value.return_info = [] + _return_filter_mock.return_value = {'refund_response': 'charge_already_refunded'} + _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/tests/test_clients.py b/commerce_coordinator/apps/commercetools/tests/test_clients.py index 2ba78f01..e30059d3 100644 --- a/commerce_coordinator/apps/commercetools/tests/test_clients.py +++ b/commerce_coordinator/apps/commercetools/tests/test_clients.py @@ -636,7 +636,7 @@ def test_order_line_item_in_correct_state(self, mock_order_by_id, mock_state_by_ f"Not attempting to transition LineItemState" ) - log_mock.assert_called_once_with(expected_message) + log_mock.assert_called_with(expected_message) self.assertEqual(result.id, mock_order.id) self.assertEqual(result.version, mock_order.version) diff --git a/commerce_coordinator/apps/commercetools/tests/test_pipeline.py b/commerce_coordinator/apps/commercetools/tests/test_pipeline.py index bf221545..5fa71239 100644 --- a/commerce_coordinator/apps/commercetools/tests/test_pipeline.py +++ b/commerce_coordinator/apps/commercetools/tests/test_pipeline.py @@ -168,6 +168,21 @@ def test_commercetools_transaction_create_no_payment_data(self, mock_returned_pa self.assertEqual(mock_payment_result, self.returned_payment) self.assertEqual(mock_payment_result.transactions[0].type, TransactionType.REFUND) + @patch('commerce_coordinator.apps.commercetools.utils.has_refund_transaction') + @patch('commerce_coordinator.apps.commercetools.pipeline.log.info') + def test_commercetools_transaction_create_has_refund(self, mock_logger, mock_has_refund): + mock_has_refund.return_value = True + + refund_pipe = CreateReturnPaymentTransaction("test_pipe", None) + refund_pipe.run_filter( + payment_data=self.mock_response_payment, + refund_response="charge_already_refunded", + active_order_management_system=COMMERCETOOLS_ORDER_MANAGEMENT_SYSTEM, + has_been_refunded=True + ) + mock_logger.assert_called_once_with('[CreateReturnPaymentTransaction] refund has already been processed, ' + 'skipping refund payment transaction creation') + class OrderReturnPipelineTests(TestCase): """Commercetools pipeline testcase for order updates on returns""" diff --git a/commerce_coordinator/apps/commercetools/views.py b/commerce_coordinator/apps/commercetools/views.py index 97b32fd5..b1bbe92b 100644 --- a/commerce_coordinator/apps/commercetools/views.py +++ b/commerce_coordinator/apps/commercetools/views.py @@ -91,6 +91,7 @@ def post(self, request): message_details.is_valid(raise_exception=True) order_id = message_details.data['order_id'] + message_id = message_details.data['message_id'] if self._is_running(tag, order_id): # pragma no cover self.meta_should_mark_not_running = False @@ -101,6 +102,7 @@ def post(self, request): fulfill_order_sanctioned_message_signal.send_robust( sender=self, order_id=order_id, + message_id=message_id ) return Response(status=status.HTTP_200_OK) @@ -131,6 +133,7 @@ def post(self, request): message_details.is_valid(raise_exception=True) order_id = message_details.data['order_id'] return_line_item_return_id = message_details.get_return_line_item_return_id() + message_id = message_details.data['message_id'] if self._is_running(tag, order_id): # pragma no cover self.meta_should_mark_not_running = False @@ -141,7 +144,8 @@ def post(self, request): fulfill_order_returned_signal.send_robust( sender=self, order_id=order_id, - return_line_item_return_id=return_line_item_return_id + return_line_item_return_id=return_line_item_return_id, + message_id=message_id ) return Response(status=status.HTTP_200_OK) diff --git a/commerce_coordinator/apps/lms/clients.py b/commerce_coordinator/apps/lms/clients.py index 3845a41f..6e9d0675 100644 --- a/commerce_coordinator/apps/lms/clients.py +++ b/commerce_coordinator/apps/lms/clients.py @@ -33,19 +33,23 @@ def deactivate_user_api_url(self): settings.LMS_URL_ROOT, '/api/user/v1/accounts/{username}/deactivate/' ) - def deactivate_user(self, username): + def deactivate_user(self, username, ct_message_id): """ Call up the LMS to deactivate a user account. 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}') 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}' ) diff --git a/commerce_coordinator/apps/lms/tests/test_clients.py b/commerce_coordinator/apps/lms/tests/test_clients.py index 69da2259..5674cc51 100644 --- a/commerce_coordinator/apps/lms/tests/test_clients.py +++ b/commerce_coordinator/apps/lms/tests/test_clients.py @@ -88,9 +88,10 @@ def test_deactivate_user(self): self.assertJSONClientResponse( uut=self.client.deactivate_user, input_kwargs={ - 'username': 'test_user' + 'username': 'test_user', + 'ct_message_id': 'mock_message_id' }, - mock_url=self.deactivate_user_url.format(username='test_user'), + mock_url=self.deactivate_user_url.format(username='test_user', ct_message_id='mock_message_id'), ) def test_deactivate_user_api_error(self): @@ -99,8 +100,9 @@ def test_deactivate_user_api_error(self): self.assertJSONClientResponse( uut=self.client.deactivate_user, input_kwargs={ - 'username': 'test_user' + 'username': 'test_user', + 'ct_message_id': 'mock_message_id' }, - mock_url=self.deactivate_user_url.format(username='test_user'), + mock_url=self.deactivate_user_url.format(username='test_user', ct_message_id='mock_message_id'), mock_status=400, ) diff --git a/commerce_coordinator/apps/lms/views.py b/commerce_coordinator/apps/lms/views.py index 8cd4d5d7..2e4cb1c4 100644 --- a/commerce_coordinator/apps/lms/views.py +++ b/commerce_coordinator/apps/lms/views.py @@ -115,12 +115,16 @@ def get(self, request): - 401: if user is unauthorized. """ + logger.info(f"{self.get.__qualname__} request object: {request.data}.") + params = dict(request.GET.items()) if not params.get('order_number', None): return HttpResponseBadRequest('Invalid order number supplied.') redirect_url = self._get_redirect_url(params) + logger.info(f"[OrderDetailsRedirectView] - Redirecting 303 via {redirect_url}") + return HttpResponseRedirect(redirect_url, status=HTTP_303_SEE_OTHER) @staticmethod @@ -134,6 +138,8 @@ def _get_redirect_url(params): """ order_number = params.get('order_number') + logger.info(f"[OrderDetailsRedirectView] - Determining redirect url for order with number {order_number}") + if is_legacy_order(order_number): url = urljoin(settings.ECOMMERCE_URL, f'{settings.ECOMMERCE_ORDER_DETAILS_DASHBOARD_PATH}{order_number}') else: @@ -188,6 +194,8 @@ def post(self, request) -> Response: input_data = {**request.data} + logger.info(f"{self.post.__qualname__} request object: {input_data}.") + input_details = CourseRefundInputSerializer(data=input_data) try: input_details.is_valid(raise_exception=True) diff --git a/commerce_coordinator/apps/stripe/pipeline.py b/commerce_coordinator/apps/stripe/pipeline.py index 70ea1446..740acbc9 100644 --- a/commerce_coordinator/apps/stripe/pipeline.py +++ b/commerce_coordinator/apps/stripe/pipeline.py @@ -283,4 +283,7 @@ def run_filter( 'refund_response': ret_val } except StripeError as ex: # pragma: no cover + logger.info(f'[CT-{tag}] Unsuccessful Stripe refund with details:' + f'[order_id: {order_id}, payment_intent_id: {payment_intent_id}' + f'message_id: {kwargs["message_id"]}') raise StripeIntentRefundAPIError from ex