From c48996c0fc485d1cceb035b5578562495eae05c7 Mon Sep 17 00:00:00 2001 From: Sanford Student Date: Tue, 6 Sep 2016 13:39:08 -0400 Subject: [PATCH] logging for persistent grades rollout --- lms/djangoapps/grades/models.py | 13 +++- lms/djangoapps/grades/new/course_grade.py | 16 ++++- lms/djangoapps/grades/new/subsection_grade.py | 65 +++++++++++++++---- lms/djangoapps/grades/tests/test_models.py | 43 ++++++++---- 4 files changed, 110 insertions(+), 27 deletions(-) diff --git a/lms/djangoapps/grades/models.py b/lms/djangoapps/grades/models.py index 837445a91c..2a9d83c0be 100644 --- a/lms/djangoapps/grades/models.py +++ b/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)) diff --git a/lms/djangoapps/grades/new/course_grade.py b/lms/djangoapps/grades/new/course_grade.py index 152838011e..9f85ff8b7f 100644 --- a/lms/djangoapps/grades/new/course_grade.py +++ b/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()) diff --git a/lms/djangoapps/grades/new/subsection_grade.py b/lms/djangoapps/grades/new/subsection_grade.py index 72993640af..05fde13d21 100644 --- a/lms/djangoapps/grades/new/subsection_grade.py +++ b/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): """ diff --git a/lms/djangoapps/grades/tests/test_models.py b/lms/djangoapps/grades/tests/test_models.py index d1d9b5e683..f2ba29824c 100644 --- a/lms/djangoapps/grades/tests/test_models.py +++ b/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) + )