def _reserve_task(course_id, task_type, task_key, task_input, requester): """ Creates a database entry to indicate that a task is in progress. Throws AlreadyRunningError if the task is already in progress. Includes the creation of an arbitrary value for task_id, to be submitted with the task call to celery. The InstructorTask.create method makes sure the InstructorTask entry is committed. When called from any view that is wrapped by TransactionMiddleware, and thus in a "commit-on-success" transaction, an autocommit buried within here will cause any pending transaction to be committed by a successful save here. Any future database operations will take place in a separate transaction. Note that there is a chance of a race condition here, when two users try to run the same task at almost exactly the same time. One user could be after the check and before the create when the second user gets to the check. At that point, both users are able to run their tasks simultaneously. This is deemed a small enough risk to not put in further safeguards. """ if _task_is_running(course_id, task_type, task_key): raise AlreadyRunningError("requested task is already running") # Create log entry now, so that future requests will know it's running. return InstructorTask.create(course_id, task_type, task_key, task_input, requester)
def _reserve_task(course_id, task_type, task_key, task_input, requester): """ Creates a database entry to indicate that a task is in progress. Throws AlreadyRunningError if the task is already in progress. Includes the creation of an arbitrary value for task_id, to be submitted with the task call to celery. Note that there is a chance of a race condition here, when two users try to run the same task at almost exactly the same time. One user could be after the check and before the create when the second user gets to the check. At that point, both users are able to run their tasks simultaneously. This is deemed a small enough risk to not put in further safeguards. """ if _task_is_running(course_id, task_type, task_key): log.warning("Duplicate task found for task_type %s and task_key %s", task_type, task_key) raise AlreadyRunningError("requested task is already running") try: most_recent_id = InstructorTask.objects.latest('id').id except InstructorTask.DoesNotExist: most_recent_id = "None found" finally: log.warning( "No duplicate tasks found: task_type %s, task_key %s, and most recent task_id = %s", task_type, task_key, most_recent_id ) # Create log entry now, so that future requests will know it's running. return InstructorTask.create(course_id, task_type, task_key, task_input, requester)
def on_failure(self, exc, task_id, args, kwargs, einfo): """ Update InstructorTask object corresponding to this task with info about failure. Fetches and updates exception and traceback information on failure. If an exception is raised internal to the task, it is caught by celery and provided here. The information is recorded in the InstructorTask object as a JSON-serialized dict stored in the task_output column. It contains the following keys: 'exception': type of exception object 'message': error message from exception object 'traceback': traceback information (truncated if necessary) Note that there is no way to record progress made within the task (e.g. attempted, succeeded, etc.) when such failures occur. """ TASK_LOG.debug(u'Task %s: failure returned', task_id) entry_id = args[0] try: entry = InstructorTask.objects.get(pk=entry_id) except InstructorTask.DoesNotExist: # if the InstructorTask object does not exist, then there's no point # trying to update it. TASK_LOG.error(u"Task (%s) has no InstructorTask object for id %s", task_id, entry_id) else: TASK_LOG.warning(u"Task (%s) failed", task_id, exc_info=True) entry.task_output = InstructorTask.create_output_for_failure(einfo.exception, einfo.traceback) entry.task_state = FAILURE entry.save_now()
def initialize_subtask_info(entry, action_name, total_num, subtask_id_list): """ Store initial subtask information to InstructorTask object. The InstructorTask's "task_output" field is initialized. This is a JSON-serialized dict. Counters for 'attempted', 'succeeded', 'failed', 'skipped' keys are initialized to zero, as is the 'duration_ms' value. A 'start_time' is stored for later duration calculations, and the total number of "things to do" is set, so the user can be told how much needs to be done overall. The `action_name` is also stored, to help with constructing more readable task_progress messages. The InstructorTask's "subtasks" field is also initialized. This is also a JSON-serialized dict. Keys include 'total', 'succeeded', 'retried', 'failed', which are counters for the number of subtasks. 'Total' is set here to the total number, while the other three are initialized to zero. Once the counters for 'succeeded' and 'failed' match the 'total', the subtasks are done and the InstructorTask's "status" will be changed to SUCCESS. The "subtasks" field also contains a 'status' key, that contains a dict that stores status information for each subtask. The value for each subtask (keyed by its task_id) is its subtask status, as defined by SubtaskStatus.to_dict(). This information needs to be set up in the InstructorTask before any of the subtasks start running. If not, there is a chance that the subtasks could complete before the parent task is done creating subtasks. Doing so also simplifies the save() here, as it avoids the need for locking. Monitoring code should assume that if an InstructorTask has subtask information, that it should rely on the status stored in the InstructorTask object, rather than status stored in the corresponding AsyncResult. """ task_progress = { 'action_name': action_name, 'attempted': 0, 'failed': 0, 'skipped': 0, 'succeeded': 0, 'total': total_num, 'duration_ms': int(0), 'start_time': time() } entry.task_output = InstructorTask.create_output_for_success(task_progress) entry.task_state = PROGRESS # Write out the subtasks information. num_subtasks = len(subtask_id_list) # Note that may not be necessary to store initial value with all those zeroes! # Write out as a dict, so it will go more smoothly into json. subtask_status = {subtask_id: (SubtaskStatus.create(subtask_id)).to_dict() for subtask_id in subtask_id_list} subtask_dict = { 'total': num_subtasks, 'succeeded': 0, 'failed': 0, 'status': subtask_status } entry.subtasks = json.dumps(subtask_dict) # and save the entry immediately, before any subtasks actually start work: entry.save_now() return task_progress
def test_wrong_course_id_in_task(self): """ Tests exception when the course_id in task is not the same as one explicitly passed in. """ email = CourseEmail(course_id=self.course.id, to_option=SEND_TO_ALL) email.save() entry = InstructorTask.create("bogus/task/id", "task_type", "task_key", "task_input", self.instructor) task_input = {"email_id": email.id} # pylint: disable=E1101 with self.assertRaisesRegexp(ValueError, "does not match task value"): perform_delegate_email_batches(entry.id, self.course.id, task_input, "action_name") # pylint: disable=E1101
def test_nonexistent_to_option(self): """ Tests exception when the to_option in the email doesn't exist """ email = CourseEmail(course_id=self.course.id, to_option="IDONTEXIST") email.save() entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) task_input = {"email_id": email.id} # pylint: disable=no-member with self.assertRaisesRegexp(Exception, 'Unexpected bulk email TO_OPTION found: IDONTEXIST'): perform_delegate_email_batches(entry.id, self.course.id, task_input, "action_name") # pylint: disable=no-member
def test_wrong_course_id_in_email(self): """ Tests exception when the course_id in CourseEmail is not the same as one explicitly passed in. """ email = CourseEmail(course_id=SlashSeparatedCourseKey("bogus", "course", "id"), to_option=SEND_TO_ALL) email.save() entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) task_input = {"email_id": email.id} # pylint: disable=no-member with self.assertRaisesRegexp(ValueError, 'does not match email value'): perform_delegate_email_batches(entry.id, self.course.id, task_input, "action_name") # pylint: disable=no-member
def test_send_email_undefined_subtask(self): # test at a lower level, to ensure that the course gets checked down below too. entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) entry_id = entry.id # pylint: disable=no-member to_list = ['*****@*****.**'] global_email_context = {'course_title': 'dummy course'} subtask_id = "subtask-id-value" subtask_status = SubtaskStatus.create(subtask_id) email_id = 1001 with self.assertRaisesRegexp(DuplicateTaskException, 'unable to find subtasks of instructor task'): send_course_email(entry_id, email_id, to_list, global_email_context, subtask_status.to_dict())
def test_nonexistent_course(self): """ Tests exception when the course in the email doesn't exist """ course_id = "I/DONT/EXIST" email = CourseEmail(course_id=course_id) email.save() entry = InstructorTask.create(course_id, "task_type", "task_key", "task_input", self.instructor) task_input = {"email_id": email.id} # pylint: disable=E1101 with self.assertRaisesRegexp(ValueError, "Course not found"): perform_delegate_email_batches(entry.id, course_id, task_input, "action_name") # pylint: disable=E1101
def test_nonexistent_course(self): """ Tests exception when the course in the email doesn't exist """ course_id = SlashSeparatedCourseKey("I", "DONT", "EXIST") email = CourseEmail(course_id=course_id) email.save() entry = InstructorTask.create(course_id, "task_type", "task_key", "task_input", self.instructor) task_input = {"email_id": email.id} # pylint: disable=no-member # (?i) is a regex for ignore case with self.assertRaisesRegexp(ValueError, r"(?i)course not found"): perform_delegate_email_batches(entry.id, course_id, task_input, "action_name") # pylint: disable=no-member
def test_send_email_missing_subtask(self): # test at a lower level, to ensure that the course gets checked down below too. entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) entry_id = entry.id # pylint: disable=no-member to_list = ['*****@*****.**'] global_email_context = {'course_title': 'dummy course'} subtask_id = "subtask-id-value" initialize_subtask_info(entry, "emailed", 100, [subtask_id]) different_subtask_id = "bogus-subtask-id-value" subtask_status = SubtaskStatus.create(different_subtask_id) bogus_email_id = 1001 with self.assertRaisesRegexp(DuplicateTaskException, 'unable to find status for subtask of instructor task'): send_course_email(entry_id, bogus_email_id, to_list, global_email_context, subtask_status.to_dict())
def test_send_email_running_subtask(self): # test at a lower level, to ensure that the course gets checked down below too. entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) entry_id = entry.id # pylint: disable=no-member subtask_id = "subtask-id-value" initialize_subtask_info(entry, "emailed", 100, [subtask_id]) subtask_status = SubtaskStatus.create(subtask_id) update_subtask_status(entry_id, subtask_id, subtask_status) check_subtask_is_valid(entry_id, subtask_id, subtask_status) bogus_email_id = 1001 to_list = ['*****@*****.**'] global_email_context = {'course_title': 'dummy course'} with self.assertRaisesRegexp(DuplicateTaskException, 'already being executed'): send_course_email(entry_id, bogus_email_id, to_list, global_email_context, subtask_status.to_dict())
def test_send_email_undefined_email(self): # test at a lower level, to ensure that the course gets checked down below too. entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) entry_id = entry.id # pylint: disable=E1101 to_list = ['*****@*****.**'] global_email_context = {'course_title': 'dummy course'} subtask_id = "subtask-id-value" subtask_status = create_subtask_status(subtask_id) bogus_email_id = 1001 with self.assertRaises(CourseEmail.DoesNotExist): # we skip the call that updates subtask status, since we've not set up the InstructorTask # for the subtask, and it's not important to the test. with patch('bulk_email.tasks.update_subtask_status'): send_course_email(entry_id, bogus_email_id, to_list, global_email_context, subtask_status)
def test_send_email_completed_subtask(self): # test at a lower level, to ensure that the course gets checked down below too. entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) entry_id = entry.id # pylint: disable=E1101 subtask_id = "subtask-id-value" initialize_subtask_info(entry, "emailed", 100, [subtask_id]) subtask_status = SubtaskStatus.create(subtask_id, state=SUCCESS) update_subtask_status(entry_id, subtask_id, subtask_status) bogus_email_id = 1001 to_list = ["*****@*****.**"] global_email_context = {"course_title": "dummy course"} new_subtask_status = SubtaskStatus.create(subtask_id) with self.assertRaisesRegexp(DuplicateTaskException, "already completed"): send_course_email(entry_id, bogus_email_id, to_list, global_email_context, new_subtask_status.to_dict())
def test_nonexistent_email(self, mock_log, result): """ Tests retries when the email doesn't exist """ # create an InstructorTask object to pass through course_id = self.course.id entry = InstructorTask.create(course_id, "task_type", "task_key", "task_input", self.instructor) task_input = {"email_id": -1} with self.assertRaises(CourseEmail.DoesNotExist): perform_delegate_email_batches(entry.id, course_id, task_input, "action_name") # pylint: disable=no-member ((log_str, __, email_id), __) = mock_log.warning.call_args self.assertTrue(mock_log.warning.called) self.assertIn('Failed to get CourseEmail with id', log_str) self.assertEqual(email_id, -1) self.assertFalse(result.called)
def test_send_email_undefined_email(self): # test at a lower level, to ensure that the course gets checked down below too. entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) entry_id = entry.id # pylint: disable=E1101 to_list = ["*****@*****.**"] global_email_context = {"course_title": "dummy course"} subtask_id = "subtask-id-undefined-email" initialize_subtask_info(entry, "emailed", 100, [subtask_id]) subtask_status = SubtaskStatus.create(subtask_id) bogus_email_id = 1001 with self.assertRaises(CourseEmail.DoesNotExist): # we skip the call that updates subtask status, since we've not set up the InstructorTask # for the subtask, and it's not important to the test. with patch("bulk_email.tasks.update_subtask_status"): send_course_email(entry_id, bogus_email_id, to_list, global_email_context, subtask_status.to_dict())
def test_send_email_with_locked_instructor_task(self): # test at a lower level, to ensure that the course gets checked down below too. entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) entry_id = entry.id # pylint: disable=no-member subtask_id = "subtask-id-locked-model" initialize_subtask_info(entry, "emailed", 100, [subtask_id]) subtask_status = SubtaskStatus.create(subtask_id) bogus_email_id = 1001 to_list = ['*****@*****.**'] global_email_context = {'course_title': 'dummy course'} with patch('instructor_task.subtasks.InstructorTask.save') as mock_task_save: mock_task_save.side_effect = DatabaseError with self.assertRaises(DatabaseError): send_course_email(entry_id, bogus_email_id, to_list, global_email_context, subtask_status.to_dict()) self.assertEquals(mock_task_save.call_count, MAX_DATABASE_LOCK_RETRIES)
def test_wrong_course_id_in_email(self): """ Tests exception when the course_id in CourseEmail is not the same as one explicitly passed in. """ email = CourseEmail.create( SlashSeparatedCourseKey("bogus", "course", "id"), self.instructor, [SEND_TO_MYSELF], "re: subject", "dummy body goes here" ) entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) task_input = {"email_id": email.id} with self.assertRaisesRegexp(ValueError, 'does not match email value'): perform_delegate_email_batches(entry.id, self.course.id, task_input, "action_name")
def test_nonexistent_email(self, mock_log, result): """ Tests retries when the email doesn't exist """ # create an InstructorTask object to pass through course_id = self.course.id entry = InstructorTask.create(course_id, "task_type", "task_key", "task_input", self.instructor) task_input = {"email_id": -1} with self.assertRaises(CourseEmail.DoesNotExist): perform_delegate_email_batches(entry.id, course_id, task_input, "action_name") # pylint: disable=E1101 ((log_str, _, email_id), _) = mock_log.warning.call_args self.assertTrue(mock_log.warning.called) self.assertIn('Failed to get CourseEmail with id', log_str) self.assertEqual(email_id, -1) self.assertFalse(result.called)
def test_send_email_missing_subtask(self): # test at a lower level, to ensure that the course gets checked down below too. entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) entry_id = entry.id # pylint: disable=E1101 to_list = ['*****@*****.**'] global_email_context = {'course_title': 'dummy course'} subtask_id = "subtask-id-value" initialize_subtask_info(entry, "emailed", 100, [subtask_id]) different_subtask_id = "bogus-subtask-id-value" subtask_status = SubtaskStatus.create(different_subtask_id) bogus_email_id = 1001 with self.assertRaisesRegexp( DuplicateTaskException, 'unable to find status for subtask of instructor task'): send_course_email(entry_id, bogus_email_id, to_list, global_email_context, subtask_status.to_dict())
def test_send_email_running_subtask(self): # test at a lower level, to ensure that the course gets checked down below too. entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) entry_id = entry.id # pylint: disable=E1101 subtask_id = "subtask-id-value" initialize_subtask_info(entry, "emailed", 100, [subtask_id]) subtask_status = SubtaskStatus.create(subtask_id) update_subtask_status(entry_id, subtask_id, subtask_status) check_subtask_is_valid(entry_id, subtask_id, subtask_status) bogus_email_id = 1001 to_list = ['*****@*****.**'] global_email_context = {'course_title': 'dummy course'} with self.assertRaisesRegexp(DuplicateTaskException, 'already being executed'): send_course_email(entry_id, bogus_email_id, to_list, global_email_context, subtask_status.to_dict())
def test_send_email_undefined_email(self): # test at a lower level, to ensure that the course gets checked down below too. entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) entry_id = entry.id # pylint: disable=no-member to_list = ['*****@*****.**'] global_email_context = {'course_title': 'dummy course'} subtask_id = "subtask-id-undefined-email" initialize_subtask_info(entry, "emailed", 100, [subtask_id]) subtask_status = SubtaskStatus.create(subtask_id) bogus_email_id = 1001 with self.assertRaises(CourseEmail.DoesNotExist): # we skip the call that updates subtask status, since we've not set up the InstructorTask # for the subtask, and it's not important to the test. with patch('bulk_email.tasks.update_subtask_status'): send_course_email(entry_id, bogus_email_id, to_list, global_email_context, subtask_status.to_dict())
def update_task_progress(state): """Return a dict containing info about current task""" current_time = datetime.now(UTC) status, data = state.split(' ') attempted, total = data.split('/') entry = InstructorTask.objects.get(pk=_entry_id) progress = { 'action_name': action_name, 'attempted': int(attempted), 'succeeded': int(attempted), 'total': int(total), 'duration_ms': int((current_time - start_time).total_seconds() * 1000), } entry.task_state = PROGRESS entry.task_output = InstructorTask.create_output_for_success(progress) entry.save_now()
def update_task_progress(state): """Return a dict containing info about current task""" current_time = datetime.now(UTC) status, data = state.split(' ') attempted, total = data.split('/') entry = InstructorTask.objects.get(pk=_entry_id) progress = { 'action_name': action_name, 'attempted': int(attempted), 'succeeded': int(attempted), 'total': int(total), 'duration_ms': int( (current_time - start_time).total_seconds() * 1000), } entry.task_state = PROGRESS entry.task_output = InstructorTask.create_output_for_success(progress) entry.save_now()
def test_send_email_retried_subtask(self): # test at a lower level, to ensure that the course gets checked down below too. entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) entry_id = entry.id # pylint: disable=no-member subtask_id = "subtask-id-value" initialize_subtask_info(entry, "emailed", 100, [subtask_id]) subtask_status = SubtaskStatus.create(subtask_id, state=RETRY, retried_nomax=2) update_subtask_status(entry_id, subtask_id, subtask_status) bogus_email_id = 1001 to_list = ['*****@*****.**'] global_email_context = {'course_title': 'dummy course'} # try running with a clean subtask: new_subtask_status = SubtaskStatus.create(subtask_id) with self.assertRaisesRegexp(DuplicateTaskException, 'already retried'): send_course_email(entry_id, bogus_email_id, to_list, global_email_context, new_subtask_status.to_dict()) # try again, with a retried subtask with lower count: new_subtask_status = SubtaskStatus.create(subtask_id, state=RETRY, retried_nomax=1) with self.assertRaisesRegexp(DuplicateTaskException, 'already retried'): send_course_email(entry_id, bogus_email_id, to_list, global_email_context, new_subtask_status.to_dict())
def test_send_email_with_locked_instructor_task(self): # test at a lower level, to ensure that the course gets checked down below too. entry = InstructorTask.create(self.course.id, "task_type", "task_key", "task_input", self.instructor) entry_id = entry.id # pylint: disable=no-member subtask_id = "subtask-id-locked-model" initialize_subtask_info(entry, "emailed", 100, [subtask_id]) subtask_status = SubtaskStatus.create(subtask_id) bogus_email_id = 1001 to_list = ['*****@*****.**'] global_email_context = {'course_title': 'dummy course'} with patch('instructor_task.subtasks.InstructorTask.save' ) as mock_task_save: mock_task_save.side_effect = DatabaseError with self.assertRaises(DatabaseError): send_course_email(entry_id, bogus_email_id, to_list, global_email_context, subtask_status.to_dict()) self.assertEquals(mock_task_save.call_count, MAX_DATABASE_LOCK_RETRIES)
def _reserve_task(course_id, task_type, task_key, task_input, requester): """ Creates a database entry to indicate that a task is in progress. Throws AlreadyRunningError if the task is already in progress. Includes the creation of an arbitrary value for task_id, to be submitted with the task call to celery. The InstructorTask.create method makes sure the InstructorTask entry is committed. When called from any view that is wrapped by TransactionMiddleware, and thus in a "commit-on-success" transaction, an autocommit buried within here will cause any pending transaction to be committed by a successful save here. Any future database operations will take place in a separate transaction. Note that there is a chance of a race condition here, when two users try to run the same task at almost exactly the same time. One user could be after the check and before the create when the second user gets to the check. At that point, both users are able to run their tasks simultaneously. This is deemed a small enough risk to not put in further safeguards. """ if _task_is_running(course_id, task_type, task_key): log.warning("Duplicate task found for task_type %s and task_key %s", task_type, task_key) raise AlreadyRunningError("requested task is already running") try: most_recent_id = InstructorTask.objects.latest('id').id except InstructorTask.DoesNotExist: most_recent_id = "None found" finally: log.warning( "No duplicate tasks found: task_type %s, task_key %s, and most recent task_id = %s", task_type, task_key, most_recent_id ) # Create log entry now, so that future requests will know it's running. return InstructorTask.create(course_id, task_type, task_key, task_input, requester)
def on_success(self, task_progress, task_id, args, kwargs): """ Update InstructorTask object corresponding to this task with info about success. Updates task_output and task_state. But it shouldn't actually do anything if the task is only creating subtasks to actually do the work. Assumes `task_progress` is a dict containing the task's result, with the following keys: 'attempted': number of attempts made 'succeeded': number of attempts that "succeeded" 'skipped': number of attempts that "skipped" 'failed': number of attempts that "failed" 'total': number of possible subtasks to attempt 'action_name': user-visible verb to use in status messages. Should be past-tense. Pass-through of input `action_name`. 'duration_ms': how long the task has (or had) been running. This is JSON-serialized and stored in the task_output column of the InstructorTask entry. """ TASK_LOG.debug('Task %s: success returned with progress: %s', task_id, task_progress) # We should be able to find the InstructorTask object to update # based on the task_id here, without having to dig into the # original args to the task. On the other hand, the entry_id # is the first value passed to all such args, so we'll use that. # And we assume that it exists, else we would already have had a failure. entry_id = args[0] entry = InstructorTask.objects.get(pk=entry_id) # Check to see if any subtasks had been defined as part of this task. # If not, then we know that we're done. (If so, let the subtasks # handle updating task_state themselves.) if len(entry.subtasks) == 0: entry.task_output = InstructorTask.create_output_for_success( task_progress) entry.task_state = SUCCESS entry.save_now()
def on_success(self, task_progress, task_id, args, kwargs): """ Update InstructorTask object corresponding to this task with info about success. Updates task_output and task_state. But it shouldn't actually do anything if the task is only creating subtasks to actually do the work. Assumes `task_progress` is a dict containing the task's result, with the following keys: 'attempted': number of attempts made 'succeeded': number of attempts that "succeeded" 'skipped': number of attempts that "skipped" 'failed': number of attempts that "failed" 'total': number of possible subtasks to attempt 'action_name': user-visible verb to use in status messages. Should be past-tense. Pass-through of input `action_name`. 'duration_ms': how long the task has (or had) been running. This is JSON-serialized and stored in the task_output column of the InstructorTask entry. """ TASK_LOG.debug('Task %s: success returned with progress: %s', task_id, task_progress) # We should be able to find the InstructorTask object to update # based on the task_id here, without having to dig into the # original args to the task. On the other hand, the entry_id # is the first value passed to all such args, so we'll use that. # And we assume that it exists, else we would already have had a failure. entry_id = args[0] entry = InstructorTask.objects.get(pk=entry_id) # Check to see if any subtasks had been defined as part of this task. # If not, then we know that we're done. (If so, let the subtasks # handle updating task_state themselves.) if len(entry.subtasks) == 0: entry.task_output = InstructorTask.create_output_for_success(task_progress) entry.task_state = SUCCESS entry.save_now()
def update_subtask_status(entry_id, current_task_id, new_subtask_status): """ Update the status of the subtask in the parent InstructorTask object tracking its progress. Uses select_for_update to lock the InstructorTask object while it is being updated. The operation is surrounded by a try/except/else that permit the manual transaction to be committed on completion, or rolled back on error. The InstructorTask's "task_output" field is updated. This is a JSON-serialized dict. Accumulates values for 'attempted', 'succeeded', 'failed', 'skipped' from `new_subtask_status` into the corresponding values in the InstructorTask's task_output. Also updates the 'duration_ms' value with the current interval since the original InstructorTask started. Note that this value is only approximate, since the subtask may be running on a different server than the original task, so is subject to clock skew. The InstructorTask's "subtasks" field is also updated. This is also a JSON-serialized dict. Keys include 'total', 'succeeded', 'retried', 'failed', which are counters for the number of subtasks. 'Total' is expected to have been set at the time the subtasks were created. The other three counters are incremented depending on the value of `status`. Once the counters for 'succeeded' and 'failed' match the 'total', the subtasks are done and the InstructorTask's "status" is changed to SUCCESS. The "subtasks" field also contains a 'status' key, that contains a dict that stores status information for each subtask. At the moment, the value for each subtask (keyed by its task_id) is the value of `status`, but could be expanded in future to store information about failure messages, progress made, etc. """ TASK_LOG.info("Preparing to update status for email subtask %s for instructor task %d with status %s", current_task_id, entry_id, new_subtask_status) try: entry = InstructorTask.objects.select_for_update().get(pk=entry_id) subtask_dict = json.loads(entry.subtasks) subtask_status_info = subtask_dict['status'] if current_task_id not in subtask_status_info: # unexpected error -- raise an exception format_str = "Unexpected task_id '{}': unable to update status for email subtask of instructor task '{}'" msg = format_str.format(current_task_id, entry_id) TASK_LOG.warning(msg) raise ValueError(msg) # Update status: subtask_status_info[current_task_id] = new_subtask_status # Update the parent task progress. # Set the estimate of duration, but only if it # increases. Clock skew between time() returned by different machines # may result in non-monotonic values for duration. task_progress = json.loads(entry.task_output) start_time = task_progress['start_time'] prev_duration = task_progress['duration_ms'] new_duration = int((time() - start_time) * 1000) task_progress['duration_ms'] = max(prev_duration, new_duration) # Update counts only when subtask is done. # In future, we can make this more responsive by updating status # between retries, by comparing counts that change from previous # retry. new_state = new_subtask_status['state'] if new_subtask_status is not None and new_state in READY_STATES: for statname in ['attempted', 'succeeded', 'failed', 'skipped']: task_progress[statname] += new_subtask_status[statname] # Figure out if we're actually done (i.e. this is the last task to complete). # This is easier if we just maintain a counter, rather than scanning the # entire new_subtask_status dict. if new_state == SUCCESS: subtask_dict['succeeded'] += 1 elif new_state in READY_STATES: subtask_dict['failed'] += 1 num_remaining = subtask_dict['total'] - subtask_dict['succeeded'] - subtask_dict['failed'] # If we're done with the last task, update the parent status to indicate that. # At present, we mark the task as having succeeded. In future, we should see # if there was a catastrophic failure that occurred, and figure out how to # report that here. if num_remaining <= 0: entry.task_state = SUCCESS entry.subtasks = json.dumps(subtask_dict) entry.task_output = InstructorTask.create_output_for_success(task_progress) TASK_LOG.info("Task output updated to %s for email subtask %s of instructor task %d", entry.task_output, current_task_id, entry_id) TASK_LOG.debug("about to save....") entry.save() except Exception: TASK_LOG.exception("Unexpected error while updating InstructorTask.") transaction.rollback() raise else: TASK_LOG.debug("about to commit....") transaction.commit() finally: _release_subtask_lock(current_task_id)
def update_problem_module_state(entry_id, update_fcn, action_name, filter_fcn, xmodule_instance_args): """ Performs generic update by visiting StudentModule instances with the update_fcn provided. The `entry_id` is the primary key for the InstructorTask entry representing the task. This function updates the entry on success and failure of the _perform_module_state_update function it wraps. It is setting the entry's value for task_state based on what Celery would set it to once the task returns to Celery: FAILURE if an exception is encountered, and SUCCESS if it returns normally. Other arguments are pass-throughs to _perform_module_state_update, and documented there. If no exceptions are raised, a dict containing the task's result is returned, with the following keys: 'attempted': number of attempts made '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. Pass-through of input `action_name`. 'duration_ms': how long the task has (or had) been running. Before returning, this is also JSON-serialized and stored in the task_output column of the InstructorTask entry. If an exception is raised internally, it is caught and recorded in the InstructorTask entry. This is also a JSON-serialized dict, stored in the task_output column, containing the following keys: 'exception': type of exception object 'message': error message from exception object 'traceback': traceback information (truncated if necessary) Once the exception is caught, it is raised again and allowed to pass up to the task-running level, so that it can also set the failure modes and capture the error trace in the result object that Celery creates. """ # get the InstructorTask to be updated. If this fails, then let the exception return to Celery. # There's no point in catching it here. entry = InstructorTask.objects.get(pk=entry_id) # get inputs to use in this task from the entry: task_id = entry.task_id course_id = entry.course_id task_input = json.loads(entry.task_input) module_state_key = task_input.get('problem_url') student_ident = task_input['student'] if 'student' in task_input else None 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)) # add task_id to xmodule_instance_args, so that it can be output with tracking info: if xmodule_instance_args is not None: xmodule_instance_args['task_id'] = task_id # Now that we have an entry we can try to catch failures: task_progress = None try: # Check that the task_id submitted in the InstructorTask matches the current task # that is running. request_task_id = _get_current_task().request.id if task_id != request_task_id: fmt = 'Requested task "{task_id}" did not match actual task "{actual_id}"' message = fmt.format(task_id=task_id, course_id=course_id, state_key=module_state_key, actual_id=request_task_id) TASK_LOG.error(message) raise UpdateProblemModuleStateError(message) # Now do the work: with dog_stats_api.timer( 'instructor_tasks.module.time.overall', tags=['action:{name}'.format(name=action_name)]): task_progress = _perform_module_state_update( course_id, module_state_key, student_ident, update_fcn, action_name, filter_fcn, xmodule_instance_args) # If we get here, we assume we've succeeded, so update the InstructorTask entry in anticipation. # But we do this within the try, in case creating the task_output causes an exception to be # raised. entry.task_output = InstructorTask.create_output_for_success( task_progress) entry.task_state = SUCCESS entry.save_now() except Exception: # try to write out the failure to the entry before failing _, exception, traceback = exc_info() traceback_string = format_exc( traceback) if traceback is not None else '' TASK_LOG.warning("background task (%s) failed: %s %s", task_id, exception, traceback_string) entry.task_output = InstructorTask.create_output_for_failure( exception, traceback_string) entry.task_state = FAILURE entry.save_now() raise # log and exit, returning task_progress info as task result: 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
def _update_instructor_task(instructor_task, task_result): """ Updates and possibly saves a InstructorTask entry based on a task Result. Used when updated status is requested. The `instructor_task` that is passed in is updated in-place, but is usually not saved. In general, tasks that have finished (either with success or failure) should have their entries updated by the task itself, so are not updated here. Tasks that are still running are not updated and saved while they run. The one exception to the no-save rule are tasks that are in a "revoked" state. This may mean that the task never had the opportunity to update the InstructorTask entry. Tasks that are in progress and have subtasks doing the processing do not look to the task's AsyncResult object. When subtasks are running, the InstructorTask object itself is updated with the subtasks' progress, not any AsyncResult object. In this case, the InstructorTask is not updated at all. Calculates json to store in "task_output" field of the `instructor_task`, as well as updating the task_state. For a successful task, the json contains the output of the task result. For a failed task, the json contains "exception", "message", and "traceback" keys. A revoked task just has a "message" stating it was revoked. """ # Pull values out of the result object as close to each other as possible. # If we wait and check the values later, the values for the state and result # are more likely to have changed. Pull the state out first, and # then code assuming that the result may not exactly match the state. task_id = task_result.task_id result_state = task_result.state returned_result = task_result.result result_traceback = task_result.traceback # Assume we don't always save the InstructorTask entry if we don't have to, # but that in most cases we will update the InstructorTask in-place with its # current progress. entry_needs_updating = True entry_needs_saving = False task_output = None if instructor_task.task_state == PROGRESS and len( instructor_task.subtasks) > 0: # This happens when running subtasks: the result object is marked with SUCCESS, # meaning that the subtasks have successfully been defined. However, the InstructorTask # will be marked as in PROGRESS, until the last subtask completes and marks it as SUCCESS. # We want to ignore the parent SUCCESS if subtasks are still running, and just trust the # contents of the InstructorTask. entry_needs_updating = False elif result_state in [PROGRESS, SUCCESS]: # construct a status message directly from the task result's result: # it needs to go back with the entry passed in. log.info("background task (%s), state %s: result: %s", task_id, result_state, returned_result) task_output = InstructorTask.create_output_for_success(returned_result) elif result_state == FAILURE: # on failure, the result's result contains the exception that caused the failure exception = returned_result traceback = result_traceback if result_traceback is not None else '' log.warning("background task (%s) failed: %s %s", task_id, returned_result, traceback) task_output = InstructorTask.create_output_for_failure( exception, result_traceback) elif result_state == REVOKED: # on revocation, the result's result doesn't contain anything # but we cannot rely on the worker thread to set this status, # so we set it here. entry_needs_saving = True log.warning("background task (%s) revoked.", task_id) task_output = InstructorTask.create_output_for_revoked() # save progress and state into the entry, even if it's not being saved: # when celery is run in "ALWAYS_EAGER" mode, progress needs to go back # with the entry passed in. if entry_needs_updating: instructor_task.task_state = result_state if task_output is not None: instructor_task.task_output = task_output if entry_needs_saving: instructor_task.save()
def _update_subtask_status(entry_id, current_task_id, new_subtask_status): """ Update the status of the subtask in the parent InstructorTask object tracking its progress. Uses select_for_update to lock the InstructorTask object while it is being updated. The operation is surrounded by a try/except/else that permit the manual transaction to be committed on completion, or rolled back on error. The InstructorTask's "task_output" field is updated. This is a JSON-serialized dict. Accumulates values for 'attempted', 'succeeded', 'failed', 'skipped' from `new_subtask_status` into the corresponding values in the InstructorTask's task_output. Also updates the 'duration_ms' value with the current interval since the original InstructorTask started. Note that this value is only approximate, since the subtask may be running on a different server than the original task, so is subject to clock skew. The InstructorTask's "subtasks" field is also updated. This is also a JSON-serialized dict. Keys include 'total', 'succeeded', 'retried', 'failed', which are counters for the number of subtasks. 'Total' is expected to have been set at the time the subtasks were created. The other three counters are incremented depending on the value of `status`. Once the counters for 'succeeded' and 'failed' match the 'total', the subtasks are done and the InstructorTask's "status" is changed to SUCCESS. The "subtasks" field also contains a 'status' key, that contains a dict that stores status information for each subtask. At the moment, the value for each subtask (keyed by its task_id) is the value of the SubtaskStatus.to_dict(), but could be expanded in future to store information about failure messages, progress made, etc. """ TASK_LOG.info("Preparing to update status for subtask %s for instructor task %d with status %s", current_task_id, entry_id, new_subtask_status) try: entry = InstructorTask.objects.select_for_update().get(pk=entry_id) subtask_dict = json.loads(entry.subtasks) subtask_status_info = subtask_dict['status'] if current_task_id not in subtask_status_info: # unexpected error -- raise an exception format_str = "Unexpected task_id '{}': unable to update status for subtask of instructor task '{}'" msg = format_str.format(current_task_id, entry_id) TASK_LOG.warning(msg) raise ValueError(msg) # Update status: subtask_status_info[current_task_id] = new_subtask_status.to_dict() # Update the parent task progress. # Set the estimate of duration, but only if it # increases. Clock skew between time() returned by different machines # may result in non-monotonic values for duration. task_progress = json.loads(entry.task_output) start_time = task_progress['start_time'] prev_duration = task_progress['duration_ms'] new_duration = int((time() - start_time) * 1000) task_progress['duration_ms'] = max(prev_duration, new_duration) # Update counts only when subtask is done. # In future, we can make this more responsive by updating status # between retries, by comparing counts that change from previous # retry. new_state = new_subtask_status.state if new_subtask_status is not None and new_state in READY_STATES: for statname in ['attempted', 'succeeded', 'failed', 'skipped']: task_progress[statname] += getattr(new_subtask_status, statname) # Figure out if we're actually done (i.e. this is the last task to complete). # This is easier if we just maintain a counter, rather than scanning the # entire new_subtask_status dict. if new_state == SUCCESS: subtask_dict['succeeded'] += 1 elif new_state in READY_STATES: subtask_dict['failed'] += 1 num_remaining = subtask_dict['total'] - subtask_dict['succeeded'] - subtask_dict['failed'] # If we're done with the last task, update the parent status to indicate that. # At present, we mark the task as having succeeded. In future, we should see # if there was a catastrophic failure that occurred, and figure out how to # report that here. if num_remaining <= 0: entry.task_state = SUCCESS entry.subtasks = json.dumps(subtask_dict) entry.task_output = InstructorTask.create_output_for_success(task_progress) TASK_LOG.debug("about to save....") entry.save() TASK_LOG.info("Task output updated to %s for subtask %s of instructor task %d", entry.task_output, current_task_id, entry_id) except Exception: TASK_LOG.exception("Unexpected error while updating InstructorTask.") transaction.rollback() dog_stats_api.increment('instructor_task.subtask.update_exception') raise else: TASK_LOG.debug("about to commit....") transaction.commit()
def _update_instructor_task(instructor_task, task_result): """ Updates and possibly saves a InstructorTask entry based on a task Result. Used when updated status is requested. The `instructor_task` that is passed in is updated in-place, but is usually not saved. In general, tasks that have finished (either with success or failure) should have their entries updated by the task itself, so are not updated here. Tasks that are still running are not updated and saved while they run. The one exception to the no-save rule are tasks that are in a "revoked" state. This may mean that the task never had the opportunity to update the InstructorTask entry. Tasks that are in progress and have subtasks doing the processing do not look to the task's AsyncResult object. When subtasks are running, the InstructorTask object itself is updated with the subtasks' progress, not any AsyncResult object. In this case, the InstructorTask is not updated at all. Calculates json to store in "task_output" field of the `instructor_task`, as well as updating the task_state. For a successful task, the json contains the output of the task result. For a failed task, the json contains "exception", "message", and "traceback" keys. A revoked task just has a "message" stating it was revoked. """ # Pull values out of the result object as close to each other as possible. # If we wait and check the values later, the values for the state and result # are more likely to have changed. Pull the state out first, and # then code assuming that the result may not exactly match the state. task_id = task_result.task_id result_state = task_result.state returned_result = task_result.result result_traceback = task_result.traceback # Assume we don't always save the InstructorTask entry if we don't have to, # but that in most cases we will update the InstructorTask in-place with its # current progress. entry_needs_updating = True entry_needs_saving = False task_output = None if instructor_task.task_state == PROGRESS and len(instructor_task.subtasks) > 0: # This happens when running subtasks: the result object is marked with SUCCESS, # meaning that the subtasks have successfully been defined. However, the InstructorTask # will be marked as in PROGRESS, until the last subtask completes and marks it as SUCCESS. # We want to ignore the parent SUCCESS if subtasks are still running, and just trust the # contents of the InstructorTask. entry_needs_updating = False elif result_state in [PROGRESS, SUCCESS]: # construct a status message directly from the task result's result: # it needs to go back with the entry passed in. log.info("background task (%s), state %s: result: %s", task_id, result_state, returned_result) task_output = InstructorTask.create_output_for_success(returned_result) elif result_state == FAILURE: # on failure, the result's result contains the exception that caused the failure exception = returned_result traceback = result_traceback if result_traceback is not None else '' log.warning("background task (%s) failed: %s %s", task_id, returned_result, traceback) task_output = InstructorTask.create_output_for_failure(exception, result_traceback) elif result_state == REVOKED: # on revocation, the result's result doesn't contain anything # but we cannot rely on the worker thread to set this status, # so we set it here. entry_needs_saving = True log.warning("background task (%s) revoked.", task_id) task_output = InstructorTask.create_output_for_revoked() # save progress and state into the entry, even if it's not being saved: # when celery is run in "ALWAYS_EAGER" mode, progress needs to go back # with the entry passed in. if entry_needs_updating: instructor_task.task_state = result_state if task_output is not None: instructor_task.task_output = task_output if entry_needs_saving: instructor_task.save()
def update_problem_module_state(entry_id, update_fcn, action_name, filter_fcn, xmodule_instance_args): """ Performs generic update by visiting StudentModule instances with the update_fcn provided. The `entry_id` is the primary key for the InstructorTask entry representing the task. This function updates the entry on success and failure of the _perform_module_state_update function it wraps. It is setting the entry's value for task_state based on what Celery would set it to once the task returns to Celery: FAILURE if an exception is encountered, and SUCCESS if it returns normally. Other arguments are pass-throughs to _perform_module_state_update, and documented there. If no exceptions are raised, a dict containing the task's result is returned, with the following keys: 'attempted': number of attempts made '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. Pass-through of input `action_name`. 'duration_ms': how long the task has (or had) been running. Before returning, this is also JSON-serialized and stored in the task_output column of the InstructorTask entry. If an exception is raised internally, it is caught and recorded in the InstructorTask entry. This is also a JSON-serialized dict, stored in the task_output column, containing the following keys: 'exception': type of exception object 'message': error message from exception object 'traceback': traceback information (truncated if necessary) Once the exception is caught, it is raised again and allowed to pass up to the task-running level, so that it can also set the failure modes and capture the error trace in the result object that Celery creates. """ # get the InstructorTask to be updated. If this fails, then let the exception return to Celery. # There's no point in catching it here. entry = InstructorTask.objects.get(pk=entry_id) # get inputs to use in this task from the entry: task_id = entry.task_id course_id = entry.course_id task_input = json.loads(entry.task_input) module_state_key = task_input.get('problem_url') student_ident = task_input['student'] if 'student' in task_input else None 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)) # add task_id to xmodule_instance_args, so that it can be output with tracking info: if xmodule_instance_args is not None: xmodule_instance_args['task_id'] = task_id # Now that we have an entry we can try to catch failures: task_progress = None try: # Check that the task_id submitted in the InstructorTask matches the current task # that is running. request_task_id = _get_current_task().request.id if task_id != request_task_id: fmt = 'Requested task "{task_id}" did not match actual task "{actual_id}"' message = fmt.format(task_id=task_id, course_id=course_id, state_key=module_state_key, actual_id=request_task_id) TASK_LOG.error(message) raise UpdateProblemModuleStateError(message) # Now do the work: with dog_stats_api.timer('instructor_tasks.module.time.overall', tags=['action:{name}'.format(name=action_name)]): task_progress = _perform_module_state_update(course_id, module_state_key, student_ident, update_fcn, action_name, filter_fcn, xmodule_instance_args) # If we get here, we assume we've succeeded, so update the InstructorTask entry in anticipation. # But we do this within the try, in case creating the task_output causes an exception to be # raised. entry.task_output = InstructorTask.create_output_for_success(task_progress) entry.task_state = SUCCESS entry.save_now() except Exception: # try to write out the failure to the entry before failing _, exception, traceback = exc_info() traceback_string = format_exc(traceback) if traceback is not None else '' TASK_LOG.warning("background task (%s) failed: %s %s", task_id, exception, traceback_string) entry.task_output = InstructorTask.create_output_for_failure(exception, traceback_string) entry.task_state = FAILURE entry.save_now() raise # log and exit, returning task_progress info as task result: 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
def initialize_subtask_info(entry, action_name, total_num, subtask_id_list): """ Store initial subtask information to InstructorTask object. The InstructorTask's "task_output" field is initialized. This is a JSON-serialized dict. Counters for 'attempted', 'succeeded', 'failed', 'skipped' keys are initialized to zero, as is the 'duration_ms' value. A 'start_time' is stored for later duration calculations, and the total number of "things to do" is set, so the user can be told how much needs to be done overall. The `action_name` is also stored, to help with constructing more readable task_progress messages. The InstructorTask's "subtasks" field is also initialized. This is also a JSON-serialized dict. Keys include 'total', 'succeeded', 'retried', 'failed', which are counters for the number of subtasks. 'Total' is set here to the total number, while the other three are initialized to zero. Once the counters for 'succeeded' and 'failed' match the 'total', the subtasks are done and the InstructorTask's "status" will be changed to SUCCESS. The "subtasks" field also contains a 'status' key, that contains a dict that stores status information for each subtask. The value for each subtask (keyed by its task_id) is its subtask status, as defined by SubtaskStatus.to_dict(). This information needs to be set up in the InstructorTask before any of the subtasks start running. If not, there is a chance that the subtasks could complete before the parent task is done creating subtasks. Doing so also simplifies the save() here, as it avoids the need for locking. Monitoring code should assume that if an InstructorTask has subtask information, that it should rely on the status stored in the InstructorTask object, rather than status stored in the corresponding AsyncResult. """ task_progress = { 'action_name': action_name, 'attempted': 0, 'failed': 0, 'skipped': 0, 'succeeded': 0, 'total': total_num, 'duration_ms': int(0), 'start_time': time() } entry.task_output = InstructorTask.create_output_for_success(task_progress) entry.task_state = PROGRESS # Write out the subtasks information. num_subtasks = len(subtask_id_list) # Note that may not be necessary to store initial value with all those zeroes! # Write out as a dict, so it will go more smoothly into json. subtask_status = { subtask_id: (SubtaskStatus.create(subtask_id)).to_dict() for subtask_id in subtask_id_list } subtask_dict = { 'total': num_subtasks, 'succeeded': 0, 'failed': 0, 'status': subtask_status } entry.subtasks = json.dumps(subtask_dict) # and save the entry immediately, before any subtasks actually start work: entry.save_now() return task_progress