diff --git a/enterprise_access/apps/subsidy_access_policy/models.py b/enterprise_access/apps/subsidy_access_policy/models.py index 063c0c9c..1839b9e3 100644 --- a/enterprise_access/apps/subsidy_access_policy/models.py +++ b/enterprise_access/apps/subsidy_access_policy/models.py @@ -554,6 +554,16 @@ def will_exceed_spend_limit(self, content_key, content_metadata=None): return self.content_would_exceed_limit(self.total_redeemed, self.spend_limit, content_price) + def _log_redeemability(self, is_redeemable, reason, lms_user_id, content_key, extra=None): + """ + Helper to log decision points in the can_redeem() function. + """ + message = ( + '[POLICY REDEEMABILITY]: policy: %s, is_redeemable: %s, reason: %s' + 'lms_user_id: %s, content_key: %s, extra=%s' + ) + logger.info(message, self.uuid, is_redeemable, reason, lms_user_id, content_key, extra) + def can_redeem(self, lms_user_id, content_key, skip_customer_user_check=False): """ Check that a given learner can redeem the given content. @@ -570,17 +580,24 @@ def can_redeem(self, lms_user_id, content_key, skip_customer_user_check=False): * second element contains a reason code if the content is not redeemable, * third a list of any transactions representing existing redemptions (any state). """ + logger.info( + '[POLICY REDEEMABILITY] Checking for policy: %s, lms_user_id: %s, content_key: %s', + self.uuid, lms_user_id, content_key, + ) # inactive policy if not self.is_redemption_enabled: + self._log_redeemability(False, REASON_POLICY_EXPIRED, lms_user_id, content_key) return (False, REASON_POLICY_EXPIRED, []) # learner not associated to enterprise if not skip_customer_user_check: if not self.lms_api_client.enterprise_contains_learner(self.enterprise_customer_uuid, lms_user_id): + self._log_redeemability(False, REASON_LEARNER_NOT_IN_ENTERPRISE, lms_user_id, content_key) return (False, REASON_LEARNER_NOT_IN_ENTERPRISE, []) # no content key in catalog if not self.catalog_contains_content_key(content_key): + self._log_redeemability(False, REASON_CONTENT_NOT_IN_CATALOG, lms_user_id, content_key) return (False, REASON_CONTENT_NOT_IN_CATALOG, []) # Wait to fetch content metadata with a call to the enterprise-subsidy @@ -589,6 +606,7 @@ def can_redeem(self, lms_user_id, content_key, skip_customer_user_check=False): # no content key in content metadata if not content_metadata: + self._log_redeemability(False, REASON_CONTENT_NOT_IN_CATALOG, lms_user_id, content_key) return (False, REASON_CONTENT_NOT_IN_CATALOG, []) # TODO: Add Course Upgrade/Registration Deadline Passed Error here @@ -608,16 +626,24 @@ def can_redeem(self, lms_user_id, content_key, skip_customer_user_check=False): # inactive subsidy? if not active_subsidy: + self._log_redeemability(False, REASON_SUBSIDY_EXPIRED, lms_user_id, content_key) return (False, REASON_SUBSIDY_EXPIRED, []) # can_redeem false from subsidy if not subsidy_can_redeem_payload.get('can_redeem', False): + self._log_redeemability( + False, REASON_NOT_ENOUGH_VALUE_IN_SUBSIDY, lms_user_id, content_key, extra=existing_transactions, + ) return (False, REASON_NOT_ENOUGH_VALUE_IN_SUBSIDY, existing_transactions) # not enough funds on policy if self.will_exceed_spend_limit(content_key, content_metadata=content_metadata): + self._log_redeemability( + False, REASON_POLICY_SPEND_LIMIT_REACHED, lms_user_id, content_key, extra=existing_transactions + ) return (False, REASON_POLICY_SPEND_LIMIT_REACHED, existing_transactions) + self._log_redeemability(True, None, lms_user_id, content_key) return (True, None, existing_transactions) def has_credit_available_with_spend_limit(self): @@ -954,7 +980,7 @@ def can_redeem(self, lms_user_id, content_key, skip_customer_user_check=False): # learner can redeem the subsidy access policy return (True, None, existing_redemptions) - def credit_available(self, lms_user_id, *args, **kwargs): # pylint: disable=unused-argument + def credit_available(self, lms_user_id, *args, **kwargs): """ Determine whether a learner has credit available for the subsidy access policy. """ @@ -1014,6 +1040,7 @@ def can_redeem(self, lms_user_id, content_key, skip_customer_user_check=False): skip_customer_user_check, ) if not should_attempt_redemption: + self._log_redeemability(False, reason, lms_user_id, content_key, extra=existing_redemptions) return (False, reason, existing_redemptions) has_per_learner_spend_limit = self.per_learner_spend_limit is not None @@ -1023,12 +1050,16 @@ def can_redeem(self, lms_user_id, content_key, skip_customer_user_check=False): spent_amount = existing_learner_transaction_aggregates.get('total_quantity') or 0 content_price = self.get_content_price(content_key) if self.content_would_exceed_limit(spent_amount, self.per_learner_spend_limit, content_price): + self._log_redeemability( + False, REASON_LEARNER_MAX_SPEND_REACHED, lms_user_id, content_key, extra=existing_redemptions, + ) return (False, REASON_LEARNER_MAX_SPEND_REACHED, existing_redemptions) # learner can redeem the subsidy access policy + self._log_redeemability(True, None, lms_user_id, content_key) return (True, None, existing_redemptions) - def credit_available(self, lms_user_id, *args, **kwargs): # pylint: disable=unused-argument + def credit_available(self, lms_user_id, *args, **kwargs): """ Determine whether a learner has credit available for the subsidy access policy. """ @@ -1181,25 +1212,39 @@ def can_redeem(self, lms_user_id, content_key, skip_customer_user_check=False): skip_customer_user_check, ) if not should_attempt_redemption: + self._log_redeemability(False, reason, lms_user_id, content_key, extra=existing_redemptions) return (False, reason, existing_redemptions) # Now that the default checks are complete, proceed with the custom checks for this assignment policy type. found_assignment = self.get_assignment(lms_user_id, content_key) if not found_assignment: + self._log_redeemability( + False, REASON_LEARNER_NOT_ASSIGNED_CONTENT, lms_user_id, content_key, extra=existing_redemptions, + ) return (False, REASON_LEARNER_NOT_ASSIGNED_CONTENT, existing_redemptions) elif found_assignment.state == LearnerContentAssignmentStateChoices.CANCELLED: + self._log_redeemability( + False, REASON_LEARNER_ASSIGNMENT_CANCELLED, lms_user_id, content_key, extra=existing_redemptions, + ) return (False, REASON_LEARNER_ASSIGNMENT_CANCELLED, existing_redemptions) elif found_assignment.state == LearnerContentAssignmentStateChoices.ERRORED: + self._log_redeemability( + False, REASON_LEARNER_ASSIGNMENT_FAILED, lms_user_id, content_key, extra=existing_redemptions, + ) return (False, REASON_LEARNER_ASSIGNMENT_FAILED, existing_redemptions) elif found_assignment.state == LearnerContentAssignmentStateChoices.ACCEPTED: # This should never happen. Even if the frontend had a bug that called the redemption endpoint for already # redeemed content, we already check for existing redemptions at the beginning of this function and fail # fast. Reaching this block would be extremely weird. + self._log_redeemability( + False, REASON_LEARNER_NOT_ASSIGNED_CONTENT, lms_user_id, content_key, extra=existing_redemptions, + ) return (False, REASON_LEARNER_NOT_ASSIGNED_CONTENT, existing_redemptions) # Learner can redeem the subsidy access policy + self._log_redeemability(True, None, lms_user_id, content_key) return (True, None, existing_redemptions) - def credit_available(self, lms_user_id, *args, **kwargs): # pylint: disable=unused-argument + def credit_available(self, lms_user_id, *args, **kwargs): """ Determine whether a learner has credit available for the subsidy access policy, determined based on the presence of unacknowledged assignments. diff --git a/enterprise_access/utils.py b/enterprise_access/utils.py index 2de546d9..9dba5f60 100644 --- a/enterprise_access/utils.py +++ b/enterprise_access/utils.py @@ -103,7 +103,8 @@ def get_automatic_expiration_date_and_reason( fetched and subsequently cached from the content metadata API. """ assignment_configuration = assignment.assignment_configuration - subsidy_access_policy = assignment_configuration.subsidy_access_policy # pylint: disable=no-member + # pylint: disable=no-member,useless-suppression + subsidy_access_policy = assignment_configuration.subsidy_access_policy # subsidy expiration subsidy_expiration_datetime = _get_subsidy_expiration(assignment)