diff --git a/lms/djangoapps/courseware/task_queue.py b/lms/djangoapps/courseware/task_queue.py index 85649c29f2..b408dacdc6 100644 --- a/lms/djangoapps/courseware/task_queue.py +++ b/lms/djangoapps/courseware/task_queue.py @@ -224,6 +224,7 @@ def _get_course_task_log_status(task_id): 'updated': number of attempts that "succeeded" 'total': number of possible subtasks to attempt 'action_name': user-visible verb to use in status messages. Should be past-tense. + 'duration_ms': how long the task has (or had) been running. 'task_traceback': optional, returned if task failed and produced a traceback. 'succeeded': on complete tasks, indicates if the task outcome was successful: did it achieve what it set out to do. diff --git a/lms/djangoapps/courseware/tasks.py b/lms/djangoapps/courseware/tasks.py index 3ad3b9a830..af01403e38 100644 --- a/lms/djangoapps/courseware/tasks.py +++ b/lms/djangoapps/courseware/tasks.py @@ -1,19 +1,18 @@ import json -from time import sleep +from time import sleep, time + from django.contrib.auth.models import User from django.db import transaction from celery import task, current_task -# from celery.signals import worker_ready from celery.utils.log import get_task_logger import mitxmako.middleware as middleware from courseware.models import StudentModule from courseware.model_data import ModelDataCache -# from courseware.module_render import get_module from courseware.module_render import get_module_for_descriptor_internal from xmodule.modulestore.django import modulestore @@ -40,14 +39,18 @@ def _update_problem_module_state(course_id, module_state_key, student, update_fc fmt = 'Starting to update problem modules as task "{task_id}": course "{course_id}" problem "{state_key}": nothing {action} yet' task_log.info(fmt.format(task_id=task_id, course_id=course_id, state_key=module_state_key, action=action_name)) + # get start time for task: + start_time = time() + # add task_id to xmodule_instance_args, so that it can be output with tracking info: xmodule_instance_args['task_id'] = task_id - - # add hack so that mako templates will work on celery worker server: - # The initialization of Make templating is usually done when Django is + + # Hack to get mako templates to work on celery worker server's worker thread. + # The initialization of Mako templating is usually done when Django is # initializing middleware packages as part of processing a server request. # When this is run on a celery worker server, no such initialization is - # called. So we look for the result: the defining of the lookup paths + # called. Using @worker_ready.connect doesn't run in the right container. + # So we look for the result: the defining of the lookup paths # for templates. if 'main' not in middleware.lookup: task_log.info("Initializing Mako middleware explicitly") @@ -74,14 +77,16 @@ def _update_problem_module_state(course_id, module_state_key, student, update_fc num_total = len(modules_to_update) # TODO: make this more efficient. Count()? def get_task_progress(): + current_time = time() progress = {'action_name': action_name, 'attempted': num_attempted, 'updated': num_updated, 'total': num_total, + 'start_ms': int(start_time * 1000), + 'duration_ms': int((current_time - start_time) * 1000), } return progress - for module_to_update in modules_to_update: num_attempted += 1 # There is no try here: if there's an error, we let it throw, and the task will @@ -102,7 +107,8 @@ def _update_problem_module_state(course_id, module_state_key, student, update_fc task_progress = get_task_progress() current_task.update_state(state='PROGRESS', meta=task_progress) - task_log.info("Finished processing task") + fmt = 'Finishing task "{task_id}": course "{course_id}" problem "{state_key}": final: {progress}' + task_log.info(fmt.format(task_id=task_id, course_id=course_id, state_key=module_state_key, progress=task_progress)) return task_progress @@ -288,11 +294,15 @@ def delete_problem_state_for_all_students(course_id, problem_url, xmodule_instan xmodule_instance_args=xmodule_instance_args) +# Using @worker_ready.connect was an effort to call middleware initialization +# only once, when the worker was coming up. However, the actual worker task +# was not getting initialized, so it was likely running in a separate process +# from the worker server. #@worker_ready.connect #def initialize_middleware(**kwargs): -# # The initialize Django middleware - some middleware components +# # Initialize Django middleware - some middleware components # # are initialized lazily when the first request is served. Since -# # the celery workers do not serve request, the components never +# # the celery workers do not serve requests, the components never # # get initialized, causing errors in some dependencies. # # In particular, the Mako template middleware is used by some xmodules # task_log.info("Initializing all middleware from worker_ready.connect hook") diff --git a/lms/djangoapps/courseware/tests/test_tasks.py b/lms/djangoapps/courseware/tests/test_tasks.py index 51f5f4cffc..094f1632d2 100644 --- a/lms/djangoapps/courseware/tests/test_tasks.py +++ b/lms/djangoapps/courseware/tests/test_tasks.py @@ -19,7 +19,8 @@ from student.tests.factories import CourseEnrollmentFactory, UserFactory, AdminF from courseware.model_data import StudentModule from courseware.task_queue import (submit_regrade_problem_for_all_students, submit_regrade_problem_for_student, - course_task_log_status) + course_task_log_status, + submit_reset_problem_attempts_for_all_students) from courseware.tests.tests import LoginEnrollmentTestCase, TEST_DATA_MONGO_MODULESTORE @@ -228,7 +229,7 @@ class TestRegrading(TestRegradingBase): self.create_student('u4') self.logout() - def testRegradingOptionProblem(self): + def test_regrading_option_problem(self): '''Run regrade scenario on option problem''' # get descriptor: problem_url_name = 'H1P1' @@ -280,7 +281,7 @@ class TestRegrading(TestRegradingBase): display_name=str(problem_url_name), data=problem_xml) - def testRegradingFailure(self): + def test_regrading_failure(self): """Simulate a failure in regrading a problem""" problem_url_name = 'H1P1' self.define_option_problem(problem_url_name) @@ -307,19 +308,19 @@ class TestRegrading(TestRegradingBase): status = json.loads(response.content) self.assertEqual(status['message'], expected_message) - def testRegradingNonProblem(self): + def test_regrading_non_problem(self): """confirm that a non-problem will not submit""" problem_url_name = self.problem_section.location.url() with self.assertRaises(NotImplementedError): self.regrade_all_student_answers('instructor', problem_url_name) - def testRegradingNonexistentProblem(self): + def test_regrading_nonexistent_problem(self): """confirm that a non-existent problem will not submit""" problem_url_name = 'NonexistentProblem' with self.assertRaises(ItemNotFoundError): self.regrade_all_student_answers('instructor', problem_url_name) - def testRegradingCodeProblem(self): + def test_regrading_code_problem(self): '''Run regrade scenario on problem with code submission''' problem_url_name = 'H1P2' self.define_code_response_problem(problem_url_name) @@ -338,3 +339,84 @@ class TestRegrading(TestRegradingBase): response = course_task_log_status(mock_request, task_id=course_task_log.task_id) status = json.loads(response.content) self.assertEqual(status['message'], "Problem's definition does not support regrading") + + +class TestResetAttempts(TestRegradingBase): + userlist = ['u1', 'u2', 'u3', 'u4'] + + def setUp(self): + self.initialize_course() + self.create_instructor('instructor') + for username in self.userlist: + self.create_student(username) + self.logout() + + def get_num_attempts(self, username, descriptor): + module = self.get_student_module(username, descriptor) + state = json.loads(module.state) + return state['attempts'] + + def reset_problem_attempts(self, instructor, problem_url_name): + """Submits the current problem for resetting""" + return submit_reset_problem_attempts_for_all_students(self._create_task_request(instructor), self.course.id, + TestRegradingBase.problem_location(problem_url_name)) + + def test_reset_attempts_on_problem(self): + '''Run reset-attempts scenario on option problem''' + # get descriptor: + problem_url_name = 'H1P1' + self.define_option_problem(problem_url_name) + location = TestRegradingBase.problem_location(problem_url_name) + descriptor = self.module_store.get_instance(self.course.id, location) + num_attempts = 3 + # first store answers for each of the separate users: + for _ in range(num_attempts): + for username in self.userlist: + self.submit_student_answer(username, problem_url_name, ['Option 1', 'Option 1']) + + for username in self.userlist: + self.assertEquals(self.get_num_attempts(username, descriptor), num_attempts) + + self.reset_problem_attempts('instructor', problem_url_name) + + for username in self.userlist: + self.assertEquals(self.get_num_attempts(username, descriptor), 0) + + def test_reset_failure(self): + """Simulate a failure in resetting attempts on a problem""" + problem_url_name = 'H1P1' + self.define_option_problem(problem_url_name) + self.submit_student_answer('u1', problem_url_name, ['Option 1', 'Option 1']) + + expected_message = "bad things happened" + with patch('courseware.models.StudentModule.save') as mock_save: + mock_save.side_effect = ZeroDivisionError(expected_message) + course_task_log = self.reset_problem_attempts('instructor', problem_url_name) + + # check task_log returned + self.assertEqual(course_task_log.task_state, 'FAILURE') + self.assertEqual(course_task_log.student, None) + self.assertEqual(course_task_log.requester.username, 'instructor') + self.assertEqual(course_task_log.task_name, 'reset_problem_attempts') + self.assertEqual(course_task_log.task_args, TestRegrading.problem_location(problem_url_name)) + status = json.loads(course_task_log.task_progress) + self.assertEqual(status['exception'], 'ZeroDivisionError') + self.assertEqual(status['message'], expected_message) + + # check status returned: + mock_request = Mock() + response = course_task_log_status(mock_request, task_id=course_task_log.task_id) + status = json.loads(response.content) + self.assertEqual(status['message'], expected_message) + + def test_reset_non_problem(self): + """confirm that a non-problem can still be successfully reset""" + problem_url_name = self.problem_section.location.url() + course_task_log = self.reset_problem_attempts('instructor', problem_url_name) + self.assertEqual(course_task_log.task_state, 'SUCCESS') + + def test_reset_nonexistent_problem(self): + """confirm that a non-existent problem will not submit""" + problem_url_name = 'NonexistentProblem' + with self.assertRaises(ItemNotFoundError): + self.reset_problem_attempts('instructor', problem_url_name) diff --git a/lms/djangoapps/instructor/views.py b/lms/djangoapps/instructor/views.py index cde47c4b7a..1aab347f97 100644 --- a/lms/djangoapps/instructor/views.py +++ b/lms/djangoapps/instructor/views.py @@ -1308,25 +1308,34 @@ def get_background_task_table(course_id, problem_url, student=None): "Task Id", "Requester", "Submitted", - "Updated", + "Duration", "Task State", "Task Status", "Message"] datatable['data'] = [] for i, course_task in enumerate(history_entries): + # get duration info, if known: + duration_ms = 'unknown' + if hasattr(course_task, 'task_progress'): + task_progress = json.loads(course_task.task_progress) + if 'duration_ms' in task_progress: + duration_ms = task_progress['duration_ms'] + # get progress status message: success, message = task_queue.get_task_completion_message(course_task) if success: status = "Complete" else: status = "Incomplete" + # generate row for this task: row = ["#{0}".format(len(history_entries) - i), str(course_task.task_name), str(course_task.student), str(course_task.task_id), str(course_task.requester), course_task.created.strftime("%Y/%m/%d %H:%M:%S"), - course_task.updated.strftime("%Y/%m/%d %H:%M:%S"), + duration_ms, + #course_task.updated.strftime("%Y/%m/%d %H:%M:%S"), str(course_task.task_state), status, message]