diff --git a/lms/djangoapps/grades/tasks.py b/lms/djangoapps/grades/tasks.py index d213ec46e2..c58647adc4 100644 --- a/lms/djangoapps/grades/tasks.py +++ b/lms/djangoapps/grades/tasks.py @@ -5,6 +5,7 @@ This module contains tasks for asynchronous execution of grade updates. from celery import task from django.conf import settings from django.contrib.auth.models import User +from django.core.exceptions import ValidationError from django.db.utils import DatabaseError from logging import getLogger @@ -30,6 +31,8 @@ from .transformer import GradesTransformer log = getLogger(__name__) +KNOWN_RETRY_ERRORS = (DatabaseError, ValidationError) # Errors we expect occasionally, should be resolved on retry + @task(default_retry_delay=30, routing_key=settings.RECALCULATE_GRADES_ROUTING_KEY) def recalculate_subsection_grade( @@ -72,41 +75,46 @@ def recalculate_subsection_grade_v2(**kwargs): event_transaction_type(string): human-readable type of the event at the root of the current event transaction. """ - course_key = CourseLocator.from_string(kwargs['course_id']) - if not PersistentGradesEnabledFlag.feature_enabled(course_key): - return + try: + course_key = CourseLocator.from_string(kwargs['course_id']) + if not PersistentGradesEnabledFlag.feature_enabled(course_key): + return - score_deleted = kwargs['score_deleted'] - scored_block_usage_key = UsageKey.from_string(kwargs['usage_id']).replace(course_key=course_key) - expected_modified_time = from_timestamp(kwargs['expected_modified_time']) + score_deleted = kwargs['score_deleted'] + scored_block_usage_key = UsageKey.from_string(kwargs['usage_id']).replace(course_key=course_key) + expected_modified_time = from_timestamp(kwargs['expected_modified_time']) - # The request cache is not maintained on celery workers, - # where this code runs. So we take the values from the - # main request cache and store them in the local request - # cache. This correlates model-level grading events with - # higher-level ones. - set_event_transaction_id(kwargs.pop('event_transaction_id', None)) - set_event_transaction_type(kwargs.pop('event_transaction_type', None)) + # The request cache is not maintained on celery workers, + # where this code runs. So we take the values from the + # main request cache and store them in the local request + # cache. This correlates model-level grading events with + # higher-level ones. + set_event_transaction_id(kwargs.pop('event_transaction_id', None)) + set_event_transaction_type(kwargs.pop('event_transaction_type', None)) - # Verify the database has been updated with the scores when the task was - # created. This race condition occurs if the transaction in the task - # creator's process hasn't committed before the task initiates in the worker - # process. - if not _has_database_updated_with_new_score( - kwargs['user_id'], scored_block_usage_key, expected_modified_time, score_deleted, - ): - raise _retry_recalculate_subsection_grade(**kwargs) + # Verify the database has been updated with the scores when the task was + # created. This race condition occurs if the transaction in the task + # creator's process hasn't committed before the task initiates in the worker + # process. + if not _has_database_updated_with_new_score( + kwargs['user_id'], scored_block_usage_key, expected_modified_time, score_deleted, + ): + raise _retry_recalculate_subsection_grade(**kwargs) - _update_subsection_grades( - course_key, - scored_block_usage_key, - kwargs['only_if_higher'], - kwargs['course_id'], - kwargs['user_id'], - kwargs['usage_id'], - kwargs['expected_modified_time'], - score_deleted, - ) + _update_subsection_grades( + course_key, + scored_block_usage_key, + kwargs['only_if_higher'], + kwargs['user_id'], + ) + + except Exception as exc: # pylint: disable=broad-except + if not isinstance(exc, KNOWN_RETRY_ERRORS): + log.info("tnl-6244 grades unexpected failure: {}. kwargs={}".format( + repr(exc), + kwargs + )) + raise _retry_recalculate_subsection_grade(exc=exc, **kwargs) def _has_database_updated_with_new_score( @@ -138,7 +146,7 @@ def _has_database_updated_with_new_score( if api_score is None: # Same case as the initial 'if' above, for submissions-specific scores return score_deleted - reported_modified_time = api_score.created_at + reported_modified_time = api_score['created_at'] else: reported_modified_time = score.modified @@ -149,11 +157,7 @@ def _update_subsection_grades( course_key, scored_block_usage_key, only_if_higher, - course_id, user_id, - usage_id, - expected_modified_time, - score_deleted, ): """ A helper function to update subsection grades in the database @@ -174,31 +178,19 @@ def _update_subsection_grades( course = store.get_course(course_key, depth=0) subsection_grade_factory = SubsectionGradeFactory(student, course, course_structure) - try: - for subsection_usage_key in subsections_to_update: - if subsection_usage_key in course_structure: - subsection_grade = subsection_grade_factory.update( - course_structure[subsection_usage_key], - only_if_higher, - ) - SUBSECTION_SCORE_CHANGED.send( - sender=recalculate_subsection_grade, - course=course, - course_structure=course_structure, - user=student, - subsection_grade=subsection_grade, - ) - - except DatabaseError as exc: - raise _retry_recalculate_subsection_grade( - user_id, - course_id, - usage_id, - only_if_higher, - expected_modified_time, - score_deleted, - exc, - ) + for subsection_usage_key in subsections_to_update: + if subsection_usage_key in course_structure: + subsection_grade = subsection_grade_factory.update( + course_structure[subsection_usage_key], + only_if_higher, + ) + SUBSECTION_SCORE_CHANGED.send( + sender=recalculate_subsection_grade, + course=course, + course_structure=course_structure, + user=student, + subsection_grade=subsection_grade, + ) def _retry_recalculate_subsection_grade( diff --git a/lms/djangoapps/grades/tests/test_tasks.py b/lms/djangoapps/grades/tests/test_tasks.py index 50691d5275..2cfde45b3c 100644 --- a/lms/djangoapps/grades/tests/test_tasks.py +++ b/lms/djangoapps/grades/tests/test_tasks.py @@ -235,6 +235,18 @@ class RecalculateSubsectionGradeTest(ModuleStoreTestCase): ) self._assert_retry_called(mock_retry) + @patch('lms.djangoapps.grades.tasks.recalculate_subsection_grade_v2.retry') + def test_retry_subsection_grade_on_update_not_complete_sub(self, mock_retry): + self.set_up_course() + with patch('lms.djangoapps.grades.tasks.sub_api.get_score') as mock_sub_score: + mock_sub_score.return_value = { + 'created_at': datetime.utcnow().replace(tzinfo=pytz.UTC) - timedelta(days=1) + } + self._apply_recalculate_subsection_grade( + mock_score=MagicMock(module_type='openassessment') + ) + self._assert_retry_called(mock_retry) + @patch('lms.djangoapps.grades.tasks.recalculate_subsection_grade_v2.retry') def test_retry_subsection_grade_on_no_score(self, mock_retry): self.set_up_course() @@ -262,6 +274,32 @@ class RecalculateSubsectionGradeTest(ModuleStoreTestCase): self._apply_recalculate_subsection_grade() self.assertEquals(mock_course_signal.call_count, 1) + @patch('lms.djangoapps.grades.tasks.log') + @patch('lms.djangoapps.grades.tasks.recalculate_subsection_grade_v2.retry') + @patch('lms.djangoapps.grades.new.subsection_grade.SubsectionGradeFactory.update') + def test_log_unknown_error(self, mock_update, mock_retry, mock_log): + """ + Ensures that unknown errors are logged before a retry. + """ + self.set_up_course() + mock_update.side_effect = Exception("General exception with no further detail!") + self._apply_recalculate_subsection_grade() + self.assertIn("General exception with no further detail!", mock_log.info.call_args[0][0]) + self._assert_retry_called(mock_retry) + + @patch('lms.djangoapps.grades.tasks.log') + @patch('lms.djangoapps.grades.tasks.recalculate_subsection_grade_v2.retry') + @patch('lms.djangoapps.grades.new.subsection_grade.SubsectionGradeFactory.update') + def test_no_log_known_error(self, mock_update, mock_retry, mock_log): + """ + Ensures that known errors are not logged before a retry. + """ + self.set_up_course() + mock_update.side_effect = IntegrityError("race condition oh noes") + self._apply_recalculate_subsection_grade() + self.assertFalse(mock_log.info.called) + self._assert_retry_called(mock_retry) + def _apply_recalculate_subsection_grade( self, mock_score=MagicMock(modified=datetime.utcnow().replace(tzinfo=pytz.UTC) + timedelta(days=1))