Merge pull request #14262 from edx/efischer/expand_except

Retry on all exceptions on failed subsection grade update

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(

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))