Standardize logged errors

For easier consumption by splunk, match the pattern used by other grades-
related log statements. Also, reduce the firehose of events being logged
in splunk.

lms/djangoapps/grades/new/course_grade.py

@@ -40,7 +40,6 @@ class CourseGrade(object):
                     graded_total = subsection_grade.graded_total
                     if graded_total.possible > 0:
                         subsections_by_format[subsection_grade.format].append(graded_total)
-        self._log_event(log.info, u"subsections_by_format")
         return subsections_by_format
 
     @lazy
@@ -52,7 +51,6 @@ 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)
-        self._log_event(log.info, u"locations_to_weighted_scores")
         return locations_to_weighted_scores
 
     @lazy
@@ -66,7 +64,10 @@ class CourseGrade(object):
             self.subsection_grade_totals_by_format,
             generate_random_scores=settings.GENERATE_PROFILE_SCORES
         )
-        self._log_event(log.info, u"grade_value")
+        # can't use the existing properties due to recursion issues caused by referencing self.grade_value
+        percent = self._calc_percent(grade_value)
+        letter_grade = self._compute_letter_grade(percent)
+        self._log_event(log.warning, u"grade_value, percent: {0}, grade: {1}".format(percent, letter_grade))
         return grade_value
 
     @property
@@ -82,7 +83,7 @@ class CourseGrade(object):
         """
         Returns a rounded percent from the overall grade.
         """
-        return round(self.grade_value['percent'] * 100 + 0.05) / 100
+        return self._calc_percent(self.grade_value)
 
     @property
     def letter_grade(self):
@@ -114,7 +115,6 @@ class CourseGrade(object):
         grade_summary['totaled_scores'] = self.subsection_grade_totals_by_format
         grade_summary['raw_scores'] = list(self.locations_to_weighted_scores.itervalues())
 
-        self._log_event(log.warning, u"grade_summary, percent: {0}, grade: {1}".format(self.percent, self.letter_grade))
         return grade_summary
 
     def compute_and_update(self, read_only=False):
@@ -123,7 +123,6 @@ class CourseGrade(object):
 
         If read_only is True, doesn't save any updates to the grades.
         """
-        self._log_event(log.warning, u"compute_and_update, read_only: {}".format(read_only))
         subsection_grade_factory = SubsectionGradeFactory(self.student, self.course, self.course_structure)
         for chapter_key in self.course_structure.get_children(self.course.location):
             chapter = self.course_structure[chapter_key]
@@ -139,10 +138,23 @@ class CourseGrade(object):
                 'sections': chapter_subsection_grades
             })
 
+        subsections_total = sum(len(x) for x in self.subsection_grade_totals_by_format.itervalues())
+        subsections_read = len(subsection_grade_factory._unsaved_subsection_grades)  # pylint: disable=protected-access
+        subsections_created = subsections_total - subsections_read
+        blocks_total = len(self.locations_to_weighted_scores)
         if not read_only:
             subsection_grade_factory.bulk_create_unsaved()
 
         self._signal_listeners_when_grade_computed()
+        self._log_event(
+            log.warning,
+            u"compute_and_update, read_only: {0}, subsections read/created: {1}/{2}, blocks accessed: {3}".format(
+                read_only,
+                subsections_read,
+                subsections_created,
+                blocks_total,
+            )
+        )
 
     def score_for_module(self, location):
         """
@@ -166,6 +178,13 @@ class CourseGrade(object):
             possible += child_possible
         return earned, possible
 
+    @staticmethod
+    def _calc_percent(grade_value):
+        """
+        Helper for percent calculation.
+        """
+        return round(grade_value['percent'] * 100 + 0.05) / 100
+
     def _compute_letter_grade(self, percentage):
         """
         Returns a letter grade as defined in grading_policy (e.g. 'A' 'B' 'C' for 6.002x) or None.

lms/djangoapps/grades/new/subsection_grade.py

@@ -33,7 +33,7 @@ def persistence_safe_fallback():
     except DatabaseError:
         # Error deliberately logged, then swallowed. It's assumed that the wrapped code is not guaranteed to succeed.
         # TODO: enqueue a celery task to finish the task asynchronously, see TNL-5471
-        log.warning("Persistent Grades: Persistence Error, falling back.\n{}".format(format_exc()))
+        log.warning("Persistent Grades: database_error.safe_fallback.\n{}".format(format_exc()))
 
 
 class SubsectionGrade(object):
@@ -80,7 +80,7 @@ class SubsectionGrade(object):
                 student, descendant_key, course_structure, scores_client, submissions_scores, persisted_values={},
             )
         self.all_total, self.graded_total = graders.aggregate_scores(self.scores, self.display_name, self.location)
-        self._log_event(log.warning, u"init_from_structure", student)
+        self._log_event(log.info, u"init_from_structure", student)
 
     def init_from_model(self, student, model, course_structure, scores_client, submissions_scores):
         """
@@ -112,7 +112,7 @@ class SubsectionGrade(object):
             section=self.display_name,
             module_id=self.location,
         )
-        self._log_event(log.warning, u"init_from_model", student)
+        self._log_event(log.info, u"init_from_model", student)
 
     @classmethod
     def bulk_create_models(cls, student, subsection_grades, course_key):
@@ -275,7 +275,7 @@ class SubsectionGradeFactory(object):
         If read_only is True, doesn't save any updates to the grades.
         """
         self._log_event(
-            log.warning, u"create, read_only: {0}, subsection: {1}".format(read_only, subsection.location)
+            log.info, u"create, read_only: {0}, subsection: {1}".format(read_only, subsection.location)
         )
 
         block_structure = self._get_block_structure(block_structure)
@@ -298,7 +298,7 @@ class SubsectionGradeFactory(object):
         """
         Bulk creates all the unsaved subsection_grades to this point.
         """
-        self._log_event(log.warning, u"bulk_create_unsaved")
+        self._log_event(log.info, u"bulk_create_unsaved")
 
         with persistence_safe_fallback():
             SubsectionGrade.bulk_create_models(self.student, self._unsaved_subsection_grades, self.course.id)

lms/djangoapps/grades/scores.py

@@ -89,7 +89,12 @@ def get_score(user, block, scores_client, submissions_scores_cache, weight, poss
         if possible is None:
             possible = score.total
         elif possible != score.total:
-            log.error(u"Persisted Grades: possible value {} != score.total value {}".format(possible, score.total))
+            log.error(
+                u"Persistent Grades: scores.get_score, possible value {} != score.total value {}".format(
+                    possible,
+                    score.total
+                )
+            )
     else:
         # This means we don't have a valid score entry and we don't have a
         # cached_max_score on hand. We know they've earned 0.0 points on this.