logging for persistent grades rollout

lms/djangoapps/grades/models.py

@@ -258,7 +258,7 @@ class PersistentSubsectionGrade(TimeStampedModel):
             self.user_id,
             self.course_version,
             self.usage_key,
-            self.visible_blocks.hashed,
+            self.visible_blocks_id,
             self.earned_graded,
             self.possible_graded,
             self.earned_all,
@@ -273,6 +273,7 @@ class PersistentSubsectionGrade(TimeStampedModel):
         """
         user_id = kwargs.pop('user_id')
         usage_key = kwargs.pop('usage_key')
+
         try:
             with transaction.atomic():
                 grade, is_created = cls.objects.get_or_create(
@@ -281,8 +282,17 @@ class PersistentSubsectionGrade(TimeStampedModel):
                     usage_key=usage_key,
                     defaults=kwargs,
                 )
+                log.info(u"Persistent Grades: Grade model saved: {0}".format(grade))
         except IntegrityError:
             cls.update_grade(user_id=user_id, usage_key=usage_key, **kwargs)
+            log.warning(
+                u"Persistent Grades: Integrity error trying to save grade for user: {0}, usage key: {1}, defaults: {2}"
+                .format(
+                    user_id,
+                    usage_key,
+                    **kwargs
+                )
+            )
         else:
             if not is_created:
                 grade.update(**kwargs)
@@ -368,3 +378,4 @@ class PersistentSubsectionGrade(TimeStampedModel):
         self.possible_graded = possible_graded
         self.visible_blocks_id = visible_blocks_hash  # pylint: disable=attribute-defined-outside-init
         self.save()
+        log.info(u"Persistent Grades: Grade model updated: {0}".format(self))

lms/djangoapps/grades/new/course_grade.py

@@ -40,6 +40,10 @@ class CourseGrade(object):
                     graded_total = subsection_grade.graded_total
                     if graded_total.possible > 0:
                         subsections_by_format[subsection_grade.format].append(graded_total)
+        log.info(u"Persistent Grades: Calculated subsections_by_format. course id: {0}, user: {1}".format(
+            self.course.location,
+            self.student.id
+        ))
         return subsections_by_format
 
     @lazy
@@ -51,6 +55,10 @@ class CourseGrade(object):
         for chapter in self.chapter_grades:
             for subsection_grade in chapter['sections']:
                 locations_to_weighted_scores.update(subsection_grade.locations_to_weighted_scores)
+        log.info(u"Persistent Grades: Calculated locations_to_weighted_scores. course id: {0}, user: {1}".format(
+            self.course.id,
+            self.student.id
+        ))
         return locations_to_weighted_scores
 
     @lazy
@@ -60,10 +68,15 @@ class CourseGrade(object):
         """
         # Grading policy might be overriden by a CCX, need to reset it
         self.course.set_grading_policy(self.course.grading_policy)
-        return self.course.grader.grade(
+        grade_value = self.course.grader.grade(
             self.subsection_grade_totals_by_format,
             generate_random_scores=settings.GENERATE_PROFILE_SCORES
         )
+        log.info(u"Persistent Grades: Calculated grade_value. course id: {0}, user: {1}".format(
+            self.course.location,
+            self.student.id
+        ))
+        return grade_value
 
     @property
     def has_access_to_course(self):
@@ -107,7 +120,6 @@ class CourseGrade(object):
         # doesn't get displayed differently than it gets grades
         grade_summary['percent'] = self.percent
         grade_summary['grade'] = self.letter_grade
-
         grade_summary['totaled_scores'] = self.subsection_grade_totals_by_format
         grade_summary['raw_scores'] = list(self.locations_to_weighted_scores.itervalues())
 

lms/djangoapps/grades/new/subsection_grade.py

@@ -3,7 +3,7 @@ SubsectionGrade Class
 """
 from collections import OrderedDict
 from lazy import lazy
-
+from logging import getLogger
 from courseware.model_data import ScoresClient
 from lms.djangoapps.grades.scores import get_score, possibly_scored
 from lms.djangoapps.grades.models import BlockRecord, PersistentSubsectionGrade
@@ -14,6 +14,9 @@ from xmodule import block_metadata_utils, graders
 from xmodule.graders import Score
 
 
+log = getLogger(__name__)
+
+
 class SubsectionGrade(object):
     """
     Class for Subsection Grades.
@@ -36,22 +39,19 @@ class SubsectionGrade(object):
         """
         List of all problem scores in the subsection.
         """
+        log.info(u"Persistent Grades: calculated scores property for subsection {0}".format(self.location))
         return [score for score, _ in self.locations_to_weighted_scores.itervalues()]
 
     def compute(self, student, course_structure, scores_client, submissions_scores):
         """
         Compute the grade of this subsection for the given student and course.
         """
-        try:
-            for descendant_key in course_structure.post_order_traversal(
-                    filter_func=possibly_scored,
-                    start_node=self.location,
-            ):
-                self._compute_block_score(student, descendant_key, course_structure, scores_client, submissions_scores)
-        finally:
-            # self.scores may hold outdated data, force it to refresh on next access
-            lazy.invalidate(self, 'scores')
-
+        lazy.invalidate(self, 'scores')
+        for descendant_key in course_structure.post_order_traversal(
+                filter_func=possibly_scored,
+                start_node=self.location,
+        ):
+            self._compute_block_score(student, descendant_key, course_structure, scores_client, submissions_scores)
         self.all_total, self.graded_total = graders.aggregate_scores(self.scores, self.display_name, self.location)
 
     def save(self, student, subsection, course):
@@ -105,6 +105,20 @@ class SubsectionGrade(object):
             module_id=self.location,
         )
 
+    def __unicode__(self):
+        """
+        Provides a unicode representation of the scoring
+        data for this subsection. Used for logging.
+        """
+        return u"SubsectionGrade|total: {0}/{1}|graded: {2}/{3}|location: {4}|display name: {5}".format(
+            self.all_total.earned,
+            self.all_total.possible,
+            self.graded_total.earned,
+            self.graded_total.possible,
+            self.location,
+            self.display_name
+        )
+
     def _compute_block_score(
             self,
             student,
@@ -204,8 +218,28 @@ class SubsectionGradeFactory(object):
                 )
                 subsection_grade = SubsectionGrade(subsection)
                 subsection_grade.load_from_data(model, course_structure, self._scores_client, self._submissions_scores)
+                log.warning(
+                    u"Persistent Grades: Loaded grade for course id: {0}, version: {1}, subtree edited on: {2},"
+                    u" grade: {3}, user: {4}".format(
+                        course.id,
+                        getattr(course, 'course_version', None),
+                        course.subtree_edited_on,
+                        subsection_grade,
+                        self.student.id
+                    )
+                )
                 return subsection_grade
             except PersistentSubsectionGrade.DoesNotExist:
+                log.warning(
+                    u"Persistent Grades: Could not find grade for course id: {0}, version: {1}, subtree edited"
+                    u" on: {2}, subsection: {3}, user: {4}".format(
+                        course.id,
+                        getattr(course, 'course_version', None),
+                        course.subtree_edited_on,
+                        subsection.location,
+                        self.student.id
+                    )
+                )
                 return None
 
     def _save_grade(self, subsection_grade, subsection, course):  # pylint: disable=unused-argument
@@ -214,6 +248,15 @@ class SubsectionGradeFactory(object):
         """
         if PersistentGradesEnabledFlag.feature_enabled(course.id):
             subsection_grade.save(self.student, subsection, course)
+        log.warning(u"Persistent Grades: Saved grade for course id: {0}, version: {1}, subtree_edited_on: {2}, grade: "
+                    u"{3}, user: {4}"
+                    .format(
+                        course.id,
+                        getattr(course, 'course_version', None),
+                        course.subtree_edited_on,
+                        subsection_grade,
+                        self.student.id
+                    ))
 
     def _prefetch_scores(self, course_structure, course):
         """

lms/djangoapps/grades/tests/test_models.py

@@ -173,10 +173,10 @@ class PersistentSubsectionGradeTest(GradesModelTestCase):
             "usage_key": self.usage_key,
             "course_version": "deadbeef",
             "subtree_edited_timestamp": "2016-08-01 18:53:24.354741",
-            "earned_all": 6,
-            "possible_all": 12,
-            "earned_graded": 6,
-            "possible_graded": 8,
+            "earned_all": 6.0,
+            "possible_all": 12.0,
+            "earned_graded": 6.0,
+            "possible_graded": 8.0,
             "visible_blocks": [self.record_a, self.record_b],
         }
 
@@ -212,15 +212,21 @@ class PersistentSubsectionGradeTest(GradesModelTestCase):
         with self.assertRaises(PersistentSubsectionGrade.DoesNotExist):
             PersistentSubsectionGrade.update_grade(**self.params)
         PersistentSubsectionGrade.objects.create(**self.params)
-        self.params['earned_all'] = 12
-        self.params['earned_graded'] = 8
-        PersistentSubsectionGrade.update_grade(**self.params)
-        read_grade = PersistentSubsectionGrade.read_grade(
-            user_id=self.params["user_id"],
-            usage_key=self.params["usage_key"],
-        )
-        self.assertEqual(read_grade.earned_all, 12)
-        self.assertEqual(read_grade.earned_graded, 8)
+        self.params['earned_all'] = 12.0
+        self.params['earned_graded'] = 8.0
+
+        with patch('lms.djangoapps.grades.models.log') as log_mock:
+            PersistentSubsectionGrade.update_grade(**self.params)
+            read_grade = PersistentSubsectionGrade.read_grade(
+                user_id=self.params["user_id"],
+                usage_key=self.params["usage_key"],
+            )
+            log_mock.info.assert_called_with(
+                u"Persistent Grades: Grade model updated: {0}".format(read_grade)
+            )
+
+        self.assertEqual(read_grade.earned_all, 12.0)
+        self.assertEqual(read_grade.earned_graded, 8.0)
 
     @ddt.data(True, False)
     def test_save(self, already_created):
@@ -235,3 +241,14 @@ class PersistentSubsectionGradeTest(GradesModelTestCase):
                 PersistentSubsectionGrade.save_grade(**self.params)
                 self.assertTrue(mock_get_or_create.called)
                 self.assertEqual(mock_update.called, already_created)
+
+    def test_logging_for_save(self):
+        with patch('lms.djangoapps.grades.models.log') as log_mock:
+            PersistentSubsectionGrade.save_grade(**self.params)
+            read_grade = PersistentSubsectionGrade.read_grade(
+                user_id=self.params["user_id"],
+                usage_key=self.params["usage_key"],
+            )
+            log_mock.info.assert_called_with(
+                u"Persistent Grades: Grade model saved: {0}".format(read_grade)
+            )