Merge pull request #22108 from edx/aj/improve-logging

Improve logging against Problem grade report

lms/djangoapps/instructor_task/tasks_helper/grades.py

@@ -509,9 +509,22 @@ class ProblemGradeReport(object):
         Generate a CSV containing all students' problem grades within a given
         `course_id`.
         """
+
+        def log_task_info(message):
+            """
+            Updates the status on the celery task to the given message.
+            Also logs the update.
+            """
+            fmt = u'Task: {task_id}, InstructorTask ID: {entry_id}, Course: {course_id}, Input: {task_input}'
+            task_info_string = fmt.format(
+                task_id=task_id, entry_id=_entry_id, course_id=course_id, task_input=_task_input
+            )
+            TASK_LOG.info(u'%s, Task type: %s, %s, %s', task_info_string, action_name, message, task_progress.state)
+
         start_time = time()
         start_date = datetime.now(UTC)
         status_interval = 100
+        task_id = _xmodule_instance_args.get('task_id') if _xmodule_instance_args is not None else None
         enrolled_students = CourseEnrollment.objects.users_enrolled_in(course_id, include_inactive=True)
         task_progress = TaskProgress(action_name, enrolled_students.count(), start_time)
 
@@ -521,6 +534,7 @@ class ProblemGradeReport(object):
         header_row = OrderedDict([('id', 'Student ID'), ('email', 'Email'), ('username', 'Username')])
 
         course = get_course_by_id(course_id)
+        log_task_info(u'Retrieving graded scorable blocks')
         graded_scorable_blocks = cls._graded_scorable_blocks_to_header(course)
 
         # Just generate the static fields for now.
@@ -528,10 +542,10 @@ class ProblemGradeReport(object):
             list(header_row.values()) + ['Enrollment Status', 'Grade'] + _flatten(list(graded_scorable_blocks.values()))
         ]
         error_rows = [list(header_row.values()) + ['error_msg']]
-        current_step = {'step': 'Calculating Grades'}
 
         # Bulk fetch and cache enrollment states so we can efficiently determine
         # whether each user is currently enrolled in the course.
+        log_task_info(u'Fetching enrollment status')
         CourseEnrollment.bulk_fetch_enrollment_states(enrolled_students, course_id)
 
         for student, course_grade, error in CourseGradeFactory().iter(enrolled_students, course):
@@ -565,8 +579,12 @@ class ProblemGradeReport(object):
 
             task_progress.succeeded += 1
             if task_progress.attempted % status_interval == 0:
-                task_progress.update_task_state(extra_meta=current_step)
+                step = u'Calculating Grades'
+                task_progress.update_task_state(extra_meta={'step': step})
+                log_message = u'{0} {1}/{2}'.format(step, task_progress.attempted, task_progress.total)
+                log_task_info(log_message)
 
+        log_task_info('Uploading CSV to store')
         # Perform the upload if any students have been successfully graded
         if len(rows) > 1:
             upload_csv_to_report_store(rows, 'problem_grade_report', course_id, start_date)

lms/djangoapps/instructor_task/tasks_helper/runner.py

@@ -32,6 +32,19 @@ class TaskProgress(object):
         self.failed = 0
         self.preassigned = 0
 
+    @property
+    def state(self):
+        return {
+            'action_name': self.action_name,
+            'attempted': self.attempted,
+            'succeeded': self.succeeded,
+            'skipped': self.skipped,
+            'failed': self.failed,
+            'total': self.total,
+            'preassigned': self.preassigned,
+            'duration_ms': int((time() - self.start_time) * 1000),
+        }
+
     def update_task_state(self, extra_meta=None):
         """
         Update the current celery task's state to the progress state
@@ -45,16 +58,7 @@ class TaskProgress(object):
         Returns:
             dict: The current task's progress dict
         """
-        progress_dict = {
-            'action_name': self.action_name,
-            'attempted': self.attempted,
-            'succeeded': self.succeeded,
-            'skipped': self.skipped,
-            'failed': self.failed,
-            'total': self.total,
-            'preassigned': self.preassigned,
-            'duration_ms': int((time() - self.start_time) * 1000),
-        }
+        progress_dict = self.state
         if extra_meta is not None:
             progress_dict.update(extra_meta)
         _get_current_task().update_state(state=PROGRESS, meta=progress_dict)