From 6d11ee612192a4173fb3717ef656ee8fa870fe7e Mon Sep 17 00:00:00 2001 From: Bianca Severino Date: Wed, 3 Mar 2021 14:35:16 -0500 Subject: [PATCH] Add more detail and consistency to log messages --- CHANGELOG.rst | 5 + edx_proctoring/__init__.py | 2 +- edx_proctoring/api.py | 332 +++++++++++------- edx_proctoring/backends/rest.py | 21 +- edx_proctoring/backends/software_secure.py | 6 +- edx_proctoring/backends/tests/test_backend.py | 2 +- edx_proctoring/callbacks.py | 6 +- edx_proctoring/exceptions.py | 3 - edx_proctoring/models.py | 6 +- edx_proctoring/signals.py | 6 +- edx_proctoring/tests/test_reviews.py | 4 +- edx_proctoring/tests/test_signals.py | 47 +++ edx_proctoring/tests/test_views.py | 21 +- edx_proctoring/utils.py | 2 +- edx_proctoring/views.py | 128 ++++--- package.json | 2 +- 16 files changed, 379 insertions(+), 214 deletions(-) create mode 100644 edx_proctoring/tests/test_signals.py diff --git a/CHANGELOG.rst b/CHANGELOG.rst index 5df69bec1e4..52b90e4fd17 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -13,6 +13,11 @@ Change Log Unreleased ~~~~~~~~~~ + +[3.7.5] - 2021-03-05 +~~~~~~~~~~~~~~~~~~~~ +* Add more useful attributes to log messages, in a key=value format that is easier to extract, and reduce + duplicate exception logs. * Update private.txt file path in developer docs [3.7.4] - 2021-03-03 diff --git a/edx_proctoring/__init__.py b/edx_proctoring/__init__.py index 9695438097a..8ce693bffa8 100644 --- a/edx_proctoring/__init__.py +++ b/edx_proctoring/__init__.py @@ -3,6 +3,6 @@ """ # Be sure to update the version number in edx_proctoring/package.json -__version__ = '3.7.4' +__version__ = '3.7.5' default_app_config = 'edx_proctoring.apps.EdxProctoringConfig' # pylint: disable=invalid-name diff --git a/edx_proctoring/api.py b/edx_proctoring/api.py index 262f4d5ba7a..b4905729fbf 100644 --- a/edx_proctoring/api.py +++ b/edx_proctoring/api.py @@ -86,7 +86,11 @@ def create_exam(course_id, content_id, exam_name, time_limit_mins, due_date=None """ if ProctoredExam.get_exam_by_content_id(course_id, content_id) is not None: - raise ProctoredExamAlreadyExists + err_msg = ( + 'Attempted to create proctored exam with course_id={course_id} and content_id={content_id}, ' + 'but this exam already exists.'.format(course_id=course_id, content_id=content_id) + ) + raise ProctoredExamAlreadyExists(err_msg) proctored_exam = ProctoredExam.objects.create( course_id=course_id, @@ -103,10 +107,10 @@ def create_exam(course_id, content_id, exam_name, time_limit_mins, due_date=None ) log_msg = ( - u'Created exam ({exam_id}) with parameters: course_id={course_id}, ' - u'content_id={content_id}, exam_name={exam_name}, time_limit_mins={time_limit_mins}, ' - u'is_proctored={is_proctored}, is_practice_exam={is_practice_exam}, ' - u'external_id={external_id}, is_active={is_active}, hide_after_due={hide_after_due}'.format( + 'Created exam (exam_id={exam_id}) with parameters: course_id={course_id}, ' + 'content_id={content_id}, exam_name={exam_name}, time_limit_mins={time_limit_mins}, ' + 'is_proctored={is_proctored}, is_practice_exam={is_practice_exam}, ' + 'external_id={external_id}, is_active={is_active}, hide_after_due={hide_after_due}'.format( exam_id=proctored_exam.id, course_id=course_id, content_id=content_id, exam_name=exam_name, time_limit_mins=time_limit_mins, @@ -136,7 +140,14 @@ def create_exam_review_policy(exam_id, set_by_user_id, review_policy): """ exam_review_policy = ProctoredExamReviewPolicy.get_review_policy_for_exam(exam_id) if exam_review_policy is not None: - raise ProctoredExamReviewPolicyAlreadyExists + err_msg = ( + 'user_id={user_id} attempted to create an exam review policy for ' + 'exam_id={exam_id}, but a review policy for this exam already exists.'.format( + user_id=set_by_user_id, + exam_id=exam_id, + ) + ) + raise ProctoredExamReviewPolicyAlreadyExists(err_msg) exam_review_policy = ProctoredExamReviewPolicy.objects.create( proctored_exam_id=exam_id, @@ -145,8 +156,8 @@ def create_exam_review_policy(exam_id, set_by_user_id, review_policy): ) log_msg = ( - u'Created ProctoredExamReviewPolicy ({review_policy}) with parameters: exam_id={exam_id}, ' - u'set_by_user_id={set_by_user_id}'.format( + 'Created ProctoredExamReviewPolicy (review_policy={review_policy}) ' + 'with parameters: exam_id={exam_id}, set_by_user_id={set_by_user_id}'.format( exam_id=exam_id, review_policy=review_policy, set_by_user_id=set_by_user_id, @@ -169,8 +180,8 @@ def update_review_policy(exam_id, set_by_user_id, review_policy): Returns: review_policy_id """ log_msg = ( - u'Updating exam review policy with exam_id {exam_id} ' - u'set_by_user_id={set_by_user_id}, review_policy={review_policy} ' + 'Updating exam review policy with exam_id={exam_id} ' + 'set_by_user_id={set_by_user_id}, review_policy={review_policy} ' .format( exam_id=exam_id, set_by_user_id=set_by_user_id, review_policy=review_policy ) @@ -178,17 +189,34 @@ def update_review_policy(exam_id, set_by_user_id, review_policy): log.info(log_msg) exam_review_policy = ProctoredExamReviewPolicy.get_review_policy_for_exam(exam_id) if exam_review_policy is None: - raise ProctoredExamReviewPolicyNotFoundException + err_msg = ( + 'user_id={user_id} attempted to update exam review policy for ' + 'exam_id={exam_id}, but this exam does not have a review policy.'.format( + user_id=set_by_user_id, + exam_id=exam_id, + ) + ) + raise ProctoredExamReviewPolicyNotFoundException(err_msg) if review_policy: exam_review_policy.set_by_user_id = set_by_user_id exam_review_policy.review_policy = review_policy exam_review_policy.save() - msg = u'Updated exam review policy with {exam_id}'.format(exam_id=exam_id) + msg = ( + 'Updated exam review policy for exam_id={exam_id}, set_by_user_id={set_by_user_id}'.format( + set_by_user_id=set_by_user_id, + exam_id=exam_id, + ) + ) log.info(msg) else: exam_review_policy.delete() - msg = u'removed exam review policy with {exam_id}'.format(exam_id=exam_id) + msg = ( + 'Removed exam review policy for exam_id={exam_id}, set_by_user_id={set_by_user_id}'.format( + set_by_user_id=set_by_user_id, + exam_id=exam_id, + ) + ) log.info(msg) @@ -197,14 +225,15 @@ def remove_review_policy(exam_id): Given a exam id, remove the existing record, otherwise raise exception if not found. """ - log_msg = ( - u'removing exam review policy with exam_id {exam_id}' - .format(exam_id=exam_id) - ) + log_msg = 'Removing exam review policy for exam_id={exam_id}'.format(exam_id=exam_id) log.info(log_msg) exam_review_policy = ProctoredExamReviewPolicy.get_review_policy_for_exam(exam_id) if exam_review_policy is None: - raise ProctoredExamReviewPolicyNotFoundException + err_msg = ( + 'Attempted to remove exam remove policy for exam_id={exam_id}, but this ' + 'exam does not have a review policy.'.format(exam_id=exam_id) + ) + raise ProctoredExamReviewPolicyNotFoundException(err_msg) exam_review_policy.delete() @@ -226,7 +255,11 @@ def get_review_policy_by_exam_id(exam_id): """ exam_review_policy = ProctoredExamReviewPolicy.get_review_policy_for_exam(exam_id) if exam_review_policy is None: - raise ProctoredExamReviewPolicyNotFoundException + err_msg = ( + 'Attempted to get exam review policy for exam_id={exam_id}, but this review ' + 'policy does not exist.'.format(exam_id=exam_id) + ) + raise ProctoredExamReviewPolicyNotFoundException(err_msg) return ProctoredExamReviewPolicySerializer(exam_review_policy).data @@ -255,11 +288,11 @@ def update_exam(exam_id, exam_name=None, time_limit_mins=None, due_date=constant """ log_msg = ( - u'Updating exam_id {exam_id} with parameters ' - u'exam_name={exam_name}, time_limit_mins={time_limit_mins}, due_date={due_date}' - u'is_proctored={is_proctored}, is_practice_exam={is_practice_exam}, ' - u'external_id={external_id}, is_active={is_active}, hide_after_due={hide_after_due}, ' - u'backend={backend}'.format( + 'Updating exam_id={exam_id} with parameters ' + 'exam_name={exam_name}, time_limit_mins={time_limit_mins}, due_date={due_date}' + 'is_proctored={is_proctored}, is_practice_exam={is_practice_exam}, ' + 'external_id={external_id}, is_active={is_active}, hide_after_due={hide_after_due}, ' + 'backend={backend}'.format( exam_id=exam_id, exam_name=exam_name, time_limit_mins=time_limit_mins, due_date=due_date, is_proctored=is_proctored, is_practice_exam=is_practice_exam, external_id=external_id, is_active=is_active, hide_after_due=hide_after_due, backend=backend @@ -269,7 +302,10 @@ def update_exam(exam_id, exam_name=None, time_limit_mins=None, due_date=constant proctored_exam = ProctoredExam.get_exam_by_id(exam_id) if proctored_exam is None: - raise ProctoredExamNotFoundException + err_msg = ( + 'Attempted to update exam_id={exam_id}, but this exam does not exist.'.format(exam_id=exam_id) + ) + raise ProctoredExamNotFoundException(err_msg) if exam_name is not None: proctored_exam.exam_name = exam_name @@ -316,7 +352,10 @@ def get_exam_by_id(exam_id): """ proctored_exam = ProctoredExam.get_exam_by_id(exam_id) if proctored_exam is None: - raise ProctoredExamNotFoundException + err_msg = ( + 'Attempted to get exam_id={exam_id}, but this exam does not exist.'.format(exam_id=exam_id) + ) + raise ProctoredExamNotFoundException(err_msg) serialized_exam_object = ProctoredExamSerializer(proctored_exam) return serialized_exam_object.data @@ -340,11 +379,12 @@ def get_exam_by_content_id(course_id, content_id): """ proctored_exam = ProctoredExam.get_exam_by_content_id(course_id, content_id) if proctored_exam is None: - log.exception( - u'Cannot find the proctored exam in this course %s with content_id: %s', - course_id, content_id + err_msg = ( + 'Cannot find proctored exam in course_id={course_id} with content_id={content_id}'.format( + course_id=course_id, content_id=content_id + ) ) - raise ProctoredExamNotFoundException + raise ProctoredExamNotFoundException(err_msg) serialized_exam_object = ProctoredExamSerializer(proctored_exam) return serialized_exam_object.data @@ -356,8 +396,8 @@ def add_allowance_for_user(exam_id, user_info, key, value): """ log_msg = ( - u'Adding allowance "{key}" with value "{value}" for exam_id {exam_id} ' - u'for user {user_info} '.format( + 'Adding allowance key={key} with value={value} for exam_id={exam_id} ' + 'for user={user_info} '.format( key=key, value=value, exam_id=exam_id, user_info=user_info ) ) @@ -396,7 +436,7 @@ def remove_allowance_for_user(exam_id, user_id, key): Deletes an allowance for a user within a given exam. """ log_msg = ( - u'Removing allowance "{key}" for exam_id {exam_id} for user_id {user_id} '.format( + 'Removing allowance key={key} for exam_id={exam_id} for user_id={user_id}'.format( key=key, exam_id=exam_id, user_id=user_id ) ) @@ -516,10 +556,8 @@ def update_exam_attempt(attempt_id, **kwargs): exam_attempt_obj = ProctoredExamStudentAttempt.objects.get_exam_attempt_by_id(attempt_id) if not exam_attempt_obj: err_msg = ( - u'Attempted to access of attempt object with attempt_id {attempt_id} but ' - 'it does not exist.'.format( - attempt_id=attempt_id - ) + 'Attempted to update exam attempt with attempt_id={attempt_id} but ' + 'this attempt does not exist.'.format(attempt_id=attempt_id) ) raise StudentExamAttemptDoesNotExistsException(err_msg) @@ -533,8 +571,8 @@ def update_exam_attempt(attempt_id, **kwargs): 'time_remaining_seconds', ]: err_msg = ( - u'You cannot call into update_exam_attempt to change ' - u'field {key}'.format(key=key) + 'You cannot call into update_exam_attempt to change ' + 'field={key}. (attempt_id={attempt_id})'.format(key=key, attempt_id=attempt_id) ) raise ProctoredExamPermissionDenied(err_msg) setattr(exam_attempt_obj, key, value) @@ -629,13 +667,14 @@ def _register_proctored_exam_attempt(user_id, exam_id, exam, attempt_code, revie ) except BackendProviderSentNoAttemptID as ex: log_message = ( - u'Failed to get the attempt ID for {user_id}' - u'in {exam_id} from the backend because the backend' - u'did not provide the id in API response, even when the' - u'HTTP response status is {status}, ' - u'Response: {response}'.format( + 'Failed to get the attempt ID for user_id={user_id} ' + 'for exam_id={exam_id} in course_id={course_id} from the ' + 'backend because the backend did not provide the id in API ' + 'response, even when the HTTP response status is {status}, ' + 'Response: {response}'.format( user_id=user_id, exam_id=exam_id, + course_id=exam['course_id'], response=str(ex), status=ex.http_status ) @@ -644,12 +683,13 @@ def _register_proctored_exam_attempt(user_id, exam_id, exam, attempt_code, revie raise ex except BackendProviderCannotRegisterAttempt as ex: log_message = ( - u'Failed to create attempt for {user_id} ' - u'in {exam_id} because backend was unable ' - u'to register the attempt. Status: {status}, ' - u'Reponse: {response}'.format( + 'Failed to create attempt for user_id={user_id} ' + 'for exam_id={exam_id} in course_id={course_id} ' + 'because backend was unable to register the attempt. ' + 'Status: {status}, Response: {response}'.format( user_id=user_id, exam_id=exam_id, + course_id=exam['course_id'], response=str(ex), status=ex.http_status, ) @@ -659,9 +699,14 @@ def _register_proctored_exam_attempt(user_id, exam_id, exam, attempt_code, revie except BackendProviderOnboardingException as ex: force_status = ex.status log_msg = ( - u'Failed to create attempt for {user_id} ' - u'in {exam_id} because of onboarding failure: ' - u'{force_status}'.format(**locals()) + 'Failed to create attempt for user_id={user_id} ' + 'for exam_id={exam_id} in course_id={course_id} ' + 'because of onboarding failure: {force_status}'.format( + user_id=user_id, + exam_id=exam_id, + course_id=exam['course_id'], + force_status=force_status + ) ) log.error(log_msg) @@ -680,15 +725,19 @@ def create_exam_attempt(exam_id, user_id, taking_as_proctored=False): """ # for now the student is allowed the exam default + exam = get_exam_by_id(exam_id) + log_msg = ( - u'Creating exam attempt for exam_id {exam_id} for ' - u'user_id {user_id} with taking as proctored = {taking_as_proctored}'.format( - exam_id=exam_id, user_id=user_id, taking_as_proctored=taking_as_proctored + 'Creating exam attempt for exam_id={exam_id} for user_id={user_id} ' + 'in course_id={course_id} with taking_as_proctored={taking_as_proctored}'.format( + exam_id=exam_id, + user_id=user_id, + course_id=exam['course_id'], + taking_as_proctored=taking_as_proctored, ) ) log.info(log_msg) - exam = get_exam_by_id(exam_id) existing_attempt = ProctoredExamStudentAttempt.objects.get_current_exam_attempt(exam_id, user_id) time_remaining_seconds = None # only practice exams and exams with resume states may have multiple attempts @@ -699,9 +748,9 @@ def create_exam_attempt(exam_id, user_id, taking_as_proctored=False): mark_exam_attempt_as_resumed(existing_attempt.id) elif not existing_attempt.is_sample_attempt: err_msg = ( - 'Cannot create new exam attempt for exam_id = {exam_id} and ' - 'user_id = {user_id} because it already exists!' - ).format(exam_id=exam_id, user_id=user_id) + 'Cannot create new exam attempt for exam_id={exam_id} and ' + 'user_id={user_id} in course_id={course_id} because it already exists!' + ).format(exam_id=exam_id, user_id=user_id, course_id=exam['course_id']) raise StudentExamAttemptAlreadyExistsException(err_msg) @@ -712,14 +761,13 @@ def create_exam_attempt(exam_id, user_id, taking_as_proctored=False): force_status = None if is_exam_passed_due(exam, user=user_id) and taking_as_proctored: - log_msg = ( - u'user_id {user_id} trying to create exam atttempt for past due proctored exam {exam_id} ' - u'Do not register an exam attempt! Return None'.format( - exam_id=exam_id, user_id=user_id + err_msg = ( + 'user_id={user_id} trying to create exam attempt for past due proctored ' + 'exam_id={exam_id} in course_id={course_id}. Do not register an exam attempt!'.format( + exam_id=exam_id, user_id=user_id, course_id=exam['course_id'] ) ) - log.error(log_msg) - raise StudentExamAttemptOnPastDueProctoredExam + raise StudentExamAttemptOnPastDueProctoredExam(err_msg) if taking_as_proctored: external_id, force_status = _register_proctored_exam_attempt( @@ -743,10 +791,10 @@ def create_exam_attempt(exam_id, user_id, taking_as_proctored=False): emit_event(exam, attempt.status, attempt=_get_exam_attempt(attempt)) log_msg = ( - u'Created exam attempt ({attempt_id}) for exam_id {exam_id} for ' - u'user_id {user_id} with taking as proctored = {taking_as_proctored} ' - u'Attempt_code {attempt_code} was generated which has a ' - u'external_id of {external_id}'.format( + 'Created exam attempt_id={attempt_id} for exam_id={exam_id} for ' + 'user_id={user_id} with taking as proctored={taking_as_proctored}. ' + 'attempt_code={attempt_code} was generated which has an ' + 'external_id={external_id}'.format( attempt_id=attempt.id, exam_id=exam_id, user_id=user_id, taking_as_proctored=taking_as_proctored, attempt_code=attempt_code, @@ -770,8 +818,8 @@ def start_exam_attempt(exam_id, user_id): if not existing_attempt: err_msg = ( - u'Cannot start exam attempt for exam_id = {exam_id} ' - u'and user_id = {user_id} because it does not exist!' + 'Cannot start exam attempt for exam_id={exam_id} ' + 'and user_id={user_id} because it does not exist!' ).format(exam_id=exam_id, user_id=user_id) raise StudentExamAttemptDoesNotExistsException(err_msg) @@ -789,8 +837,8 @@ def start_exam_attempt_by_code(attempt_code): if not existing_attempt: err_msg = ( - u'Cannot start exam attempt for attempt_code = {attempt_code} ' - u'because it does not exist!' + 'Cannot start exam attempt for attempt_code={attempt_code} ' + 'because it does not exist!' ).format(attempt_code=attempt_code) raise StudentExamAttemptDoesNotExistsException(err_msg) @@ -806,8 +854,8 @@ def _start_exam_attempt(existing_attempt): if existing_attempt.started_at and existing_attempt.status == ProctoredExamStudentAttemptStatus.started: # cannot restart an attempt err_msg = ( - u'Cannot start exam attempt for exam_id = {exam_id} ' - u'and user_id = {user_id} because it has already started!' + 'Cannot start exam attempt for exam_id={exam_id} ' + 'and user_id={user_id} because it has already started!' ).format(exam_id=existing_attempt.proctored_exam.id, user_id=existing_attempt.user_id) raise StudentExamAttemptedAlreadyStarted(err_msg) @@ -929,7 +977,10 @@ def update_attempt_status(attempt_id, to_status, if exam_attempt_obj is None: if raise_if_not_found: - raise StudentExamAttemptDoesNotExistsException('Error. Trying to look up an exam that does not exist.') + raise StudentExamAttemptDoesNotExistsException( + 'Tried to look up exam by attempt_id={attempt_id}, ' + 'but this attempt does not exist.'.format(attempt_id=attempt_id) + ) return exam_id = exam_attempt_obj.proctored_exam.id @@ -938,8 +989,8 @@ def update_attempt_status(attempt_id, to_status, from_status = exam_attempt_obj.status log_msg = ( - u'Updating attempt status for exam_id {exam_id} ' - u'for user_id {user_id} from status "{from_status}" to "{to_status}"'.format( + 'Updating attempt status for exam_id={exam_id} ' + 'for user_id={user_id} from status "{from_status}" to "{to_status}"'.format( exam_id=exam_id, user_id=user_id, from_status=from_status, to_status=to_status ) ) @@ -958,13 +1009,14 @@ def update_attempt_status(attempt_id, to_status, if not is_state_transition_legal(from_status, to_status): illegal_status_transition_msg = ( - 'A status transition from {from_status} to {to_status} was attempted ' - 'on exam_id {exam_id} for user_id {user_id}. This is not ' - 'allowed!'.format( + 'A status transition from "{from_status}" to "{to_status}" was attempted ' + 'on exam_id={exam_id} for user_id={user_id}. This is not ' + 'allowed! (course_id={course_id})'.format( from_status=from_status, to_status=to_status, exam_id=exam_id, - user_id=user_id + user_id=user_id, + course_id=exam['course_id'] ) ) @@ -1012,9 +1064,9 @@ def update_attempt_status(attempt_id, to_status, credit_requirement_status = 'failed' log_msg = ( - u'Calling set_credit_requirement_status for ' - u'user_id {user_id} on {course_id} for ' - u'content_id {content_id}. Status: {status}'.format( + 'Calling set_credit_requirement_status for ' + 'user_id={user_id} on course_id={course_id} for ' + 'content_id={content_id}. status={status}'.format( user_id=exam_attempt_obj.user_id, course_id=exam['course_id'], content_id=exam_attempt_obj.proctored_exam.content_id, @@ -1083,11 +1135,11 @@ def update_attempt_status(attempt_id, to_status, if grades_service.should_override_grade_on_rejected_exam(exam['course_id']): log_msg = ( - u'Overriding exam subsection grade for ' - u'user_id {user_id} on {course_id} for ' - u'content_id {content_id}. Override ' - u'earned_all: {earned_all}, ' - u'earned_graded: {earned_graded}.'.format( + 'Overriding exam subsection grade for ' + 'user_id={user_id} on course_id={course_id} for ' + 'content_id={content_id}. Override ' + 'earned_all={earned_all}, ' + 'earned_graded={earned_graded}.'.format( user_id=exam_attempt_obj.user_id, course_id=exam['course_id'], content_id=exam_attempt_obj.proctored_exam.content_id, @@ -1112,8 +1164,8 @@ def update_attempt_status(attempt_id, to_status, certificates_service = get_runtime_service('certificates') log.info( - u'Invalidating certificate for user_id {user_id} in course {course_id} whose ' - u'grade dropped below passing threshold due to suspicious proctored exam'.format( + 'Invalidating certificate for user_id={user_id} in course_id={course_id} whose ' + 'grade dropped below passing threshold due to suspicious proctored exam'.format( user_id=exam_attempt_obj.user_id, course_id=exam['course_id'] ) @@ -1131,11 +1183,11 @@ def update_attempt_status(attempt_id, to_status, if grades_service.should_override_grade_on_rejected_exam(exam['course_id']): log_msg = ( - u'Deleting override of exam subsection grade for ' - u'user_id {user_id} on {course_id} for ' - u'content_id {content_id}. Override ' - u'earned_all: {earned_all}, ' - u'earned_graded: {earned_graded}.'.format( + 'Deleting override of exam subsection grade for ' + 'user_id={user_id} on course_id={course_id} for ' + 'content_id={content_id}. Override ' + 'earned_all={earned_all}, ' + 'earned_graded={earned_graded}.'.format( user_id=exam_attempt_obj.user_id, course_id=exam['course_id'], content_id=exam_attempt_obj.proctored_exam.content_id, @@ -1165,9 +1217,11 @@ def update_attempt_status(attempt_id, to_status, else: course_name = default_name log.info( - u"Could not find credit_state for user id %r in the course %r.", - exam_attempt_obj.user_id, - exam_attempt_obj.proctored_exam.course_id + 'While updating attempt status, could not find credit_state for ' + 'user_id={user_id} in course_id={course_id}'.format( + user_id=exam_attempt_obj.user_id, + course_id=exam_attempt_obj.proctored_exam.course_id, + ) ) email = create_proctoring_attempt_status_email( user_id, @@ -1211,7 +1265,7 @@ def update_attempt_status(attempt_id, to_status, return attempt['id'] -def create_proctoring_attempt_status_email(user_id, exam_attempt_obj, course_name, course_key): +def create_proctoring_attempt_status_email(user_id, exam_attempt_obj, course_name, course_id): """ Creates an email about change in proctoring attempt status. """ @@ -1249,7 +1303,14 @@ def create_proctoring_attempt_status_email(user_id, exam_attempt_obj, course_nam try: course_info_url = reverse('info', args=[exam_attempt_obj.proctored_exam.course_id]) except NoReverseMatch: - log.exception(u"Can't find course info url for course %s", exam_attempt_obj.proctored_exam.course_id) + log.exception( + 'Attempted to create proctoring status email for user_id={user_id} in exam_id={exam_id}, ' + 'but could not find course info url for course_id={course_id}'.format( + user_id=user_id, + exam_id=exam_attempt_obj.proctored_exam.id, + course_id=course_id, + ) + ) scheme = 'https' if getattr(settings, 'HTTPS', 'on') == 'on' else 'http' course_url = '{scheme}://{site_name}{course_info_url}'.format( @@ -1275,10 +1336,16 @@ def create_proctoring_attempt_status_email(user_id, exam_attempt_obj, course_nam instructor_service = get_runtime_service('instructor') if instructor_service: try: - proctoring_escalation_email = instructor_service.get_proctoring_escalation_email(course_key) + proctoring_escalation_email = instructor_service.get_proctoring_escalation_email(course_id) except (InvalidKeyError, ObjectDoesNotExist): log.warning( - 'Could not retrieve proctoring escalation email with course key: {}'.format(course_key) + 'While creating proctoring status email for user_id={user_id} in exam_id={exam_id}, ' + 'could not retrieve proctoring escalation email with course_id={course_id}. Using ' + 'default contact URL.'.format( + user_id=user_id, + exam_id=exam_attempt_obj.proctored_exam.id, + course_id=course_id, + ) ) if proctoring_escalation_email: @@ -1336,7 +1403,7 @@ def reset_practice_exam(exam_id, user_id, requesting_user): Resets a completed practice exam attempt back to the created state. """ log_msg = ( - 'Resetting practice exam {exam_id} for user {user_id}'.format( + 'Resetting practice exam_id={exam_id} for user_id={user_id}'.format( exam_id=exam_id, user_id=user_id, ) @@ -1345,31 +1412,35 @@ def reset_practice_exam(exam_id, user_id, requesting_user): exam_attempt_obj = ProctoredExamStudentAttempt.objects.get_current_exam_attempt(exam_id, user_id) if exam_attempt_obj is None: - raise StudentExamAttemptDoesNotExistsException('Error. Trying to look up an exam that does not exist.') + err_msg = ( + 'Tried to reset attempt in exam_id={exam_id} for user_id={user_id}, ' + 'but this attempt does not exist.'.format(exam_id=exam_id, user_id=user_id) + ) + raise StudentExamAttemptDoesNotExistsException(err_msg) exam = get_exam_by_id(exam_id) if not exam['is_practice_exam']: - msg = ( - 'Failed to reset attempt status on exam_id {exam_id} for user_id {user_id}. ' - 'Only practice exams may be reset!'.format( - exam_id=exam_id, - user_id=user_id, + err_msg = ( + 'Failed to reset attempt status on exam_id={exam_id} for user_id={user_id}. ' + 'Only practice exams may be reset! (course_id={course_id})'.format( + exam_id=exam_id, user_id=user_id, course_id=exam['course_id'] ) ) - raise ProctoredExamIllegalStatusTransition(msg) + raise ProctoredExamIllegalStatusTransition(err_msg) # prevent a reset if the exam is currently in progress or has already been verified attempt_in_progress = ProctoredExamStudentAttemptStatus.is_incomplete_status(exam_attempt_obj.status) if attempt_in_progress or exam_attempt_obj.status == ProctoredExamStudentAttemptStatus.verified: - msg = ( - 'Failed to reset attempt status on exam_id {exam_id} for user_id {user_id}. ' - 'Attempt with status {status} cannot be reset!'.format( + err_msg = ( + 'Failed to reset attempt status on exam_id={exam_id} for user_id={user_id}. ' + 'Attempt with status={status} cannot be reset! (course_id={course_id})'.format( exam_id=exam_id, user_id=user_id, status=exam_attempt_obj.status, + course_id=exam['course_id'], ) ) - raise ProctoredExamIllegalStatusTransition(msg) + raise ProctoredExamIllegalStatusTransition(err_msg) # resetting a submitted attempt that has not been reviewed will entirely remove that submission. if exam_attempt_obj.status == ProctoredExamStudentAttemptStatus.submitted: @@ -1389,15 +1460,14 @@ def remove_exam_attempt(attempt_id, requesting_user): """ log_msg = ( - u'Removing exam attempt {attempt_id}'.format(attempt_id=attempt_id) + 'Removing exam attempt_id={attempt_id}'.format(attempt_id=attempt_id) ) log.info(log_msg) existing_attempt = ProctoredExamStudentAttempt.objects.get_exam_attempt_by_id(attempt_id) if not existing_attempt: err_msg = ( - u'Cannot remove attempt for attempt_id = {attempt_id} ' - u'because it does not exist!' + 'Cannot remove attempt for attempt_id={attempt_id} because it does not exist!' ).format(attempt_id=attempt_id) raise StudentExamAttemptDoesNotExistsException(err_msg) @@ -1679,10 +1749,7 @@ def _resolve_prerequisite_links(exam, prerequisites): for prerequisite in prerequisites: jumpto_url = None if prerequisite['namespace'] in JUMPTO_SUPPORTED_NAMESPACES and prerequisite['name']: - try: - jumpto_url = reverse('jump_to', args=[exam['course_id'], prerequisite['name']]) - except NoReverseMatch: - log.exception(u"Can't find jumpto url for course %s", exam['course_id']) + jumpto_url = reverse('jump_to', args=[exam['course_id'], prerequisite['name']]) prerequisite['jumpto_url'] = jumpto_url @@ -1790,8 +1857,10 @@ def get_attempt_status_summary(user_id, course_id, content_id): except ProctoredExamNotFoundException: # this really shouldn't happen, but log it at least log.exception( - u'Cannot find the proctored exam in this course %s with content_id: %s', - course_id, content_id + 'Requested attempt status summary for user_id={user_id}, but could not find exam ' + 'in course_id={course_id} with content_id={content_id}'.format( + user_id=user_id, course_id=course_id, content_id=content_id + ) ) return None @@ -1962,7 +2031,7 @@ def _get_timed_exam_view(exam, context, exam_id, user_id, course_id): try: progress_page_url = reverse('progress', args=[course_id]) except NoReverseMatch: - log.exception(u"Can't find progress url for course %s", course_id) + log.exception("Can't find progress url for course_id={course_id}".format(course_id=course_id)) context.update({ 'total_time': total_time, @@ -2040,7 +2109,7 @@ def _get_proctored_exam_context(exam, attempt, user_id, course_id, is_practice_e try: progress_page_url = reverse('progress', args=[course_id]) except NoReverseMatch: - log.exception(u"Can't find progress url for course %s", course_id) + log.exception("Can't find progress url for course_id={course_id}".format(course_id=course_id)) provider = get_backend_provider(exam) @@ -2333,10 +2402,7 @@ def _get_proctored_exam_view(exam, context, exam_id, user_id, course_id): onboarding_exam = ProctoredExam.objects.filter(course_id=course_id, is_active=True, is_practice_exam=True).first() - try: - context['onboarding_link'] = reverse('jump_to', args=[course_id, onboarding_exam.content_id]) - except (NoReverseMatch, AttributeError): - log.exception(u"Can't find onboarding exam for %s", course_id) + context['onboarding_link'] = reverse('jump_to', args=[course_id, onboarding_exam.content_id]) elif attempt_status == ProctoredExamStudentAttemptStatus.ready_to_resume: student_view_template = 'proctored_exam/ready_to_resume.html' @@ -2485,7 +2551,7 @@ def does_backend_support_onboarding(backend): return get_backend_provider(name=backend).supports_onboarding except NotImplementedError: log.exception( - u"No proctoring backend configured for '{}'.".format(backend) + 'No proctoring backend configured for backend={backend}'.format(backend=backend) ) return False @@ -2499,8 +2565,8 @@ def get_exam_configuration_dashboard_url(course_id, content_id): exam = get_exam_by_content_id(course_id, content_id) except ProctoredExamNotFoundException: log.exception( - u'Cannot find the proctored exam in this course %s with content_id: %s', - course_id, content_id + 'Cannot find the proctored exam in course_id={course_id} with ' + 'content_id={content_id}'.format(course_id=course_id, content_id=content_id) ) return None diff --git a/edx_proctoring/backends/rest.py b/edx_proctoring/backends/rest.py index 014c8244c32..4e8d1c8f092 100644 --- a/edx_proctoring/backends/rest.py +++ b/edx_proctoring/backends/rest.py @@ -184,7 +184,11 @@ def register_exam_attempt(self, exam, context): payload['status'] = 'created' # attempt code isn't needed in this API payload.pop('attempt_code', False) - log.debug(u'Creating exam attempt for %r at %r', exam['external_id'], url) + log.debug( + 'Creating exam attempt for exam_id={exam_id} (external_id={external_id}) at {url}'.format( + exam_id=exam['id'], external_id=exam['external_id'], url=url + ) + ) response = self.session.post(url, json=payload) if response.status_code != 200: raise BackendProviderCannotRegisterAttempt(response.content, response.status_code) @@ -264,7 +268,7 @@ def on_exam_saved(self, exam): url = self.exam_url.format(exam_id=external_id) else: url = self.create_exam_url - log.info(u'Saving exam to %r', url) + log.info('Saving exam_id={exam_id} to {url}'.format(exam_id=exam['id'], url=url)) response = None try: response = self.session.post(url, json=exam) @@ -275,7 +279,11 @@ def on_exam_saved(self, exam): content = exc.response.content if hasattr(exc, 'response') else response.content else: content = None - log.exception(u'failed to save exam. %r', content) + log.exception( + 'Failed to save exam_id={exam_id} to {url}. Response: {content}'.format( + exam_id=exam['id'], url=url, content=content + ) + ) data = {} return data.get('id') @@ -304,7 +312,12 @@ def get_instructor_url(self, course_id, user, exam_id=None, attempt_id=None, sho encoded = jwt.encode(token, self.client_secret).decode('utf-8') url = self.instructor_url.format(client_id=self.client_id, jwt=encoded) - log.debug(u'Created instructor url for %r %r %r', course_id, exam_id, attempt_id) + log.debug( + 'Created instructor url for course_id={course_id} exam_id={exam_id} ' + 'attempt_id={attempt_id}'.format( + course_id=course_id, exam_id=exam_id, attempt_id=attempt_id + ) + ) return url def retire_user(self, user_id): diff --git a/edx_proctoring/backends/software_secure.py b/edx_proctoring/backends/software_secure.py index 66adca23e99..0dc6a080451 100644 --- a/edx_proctoring/backends/software_secure.py +++ b/edx_proctoring/backends/software_secure.py @@ -80,8 +80,8 @@ def register_exam_attempt(self, exam, context): if status not in [200, 201]: err_msg = ( - u'Could not register attempt_code = {attempt_code}. ' - u'HTTP Status code was {status_code} and response was {response}.'.format( + 'Could not register attempt_code={attempt_code}. ' + 'HTTP Status code was {status_code} and response was {response}.'.format( attempt_code=attempt_code, status_code=status, response=response @@ -353,7 +353,7 @@ def _sign_doc(self, body_json, method, headers, date): message = method_string + headers_str + body_str log_msg = ( - u'About to send payload to SoftwareSecure: examCode: {examCode}, courseID: {courseID}'. + 'About to send payload to SoftwareSecure: examCode={examCode}, courseID={courseID}'. format(examCode=body_json.get('examCode'), courseID=body_json.get('orgExtra').get('courseID')) ) log.info(log_msg) diff --git a/edx_proctoring/backends/tests/test_backend.py b/edx_proctoring/backends/tests/test_backend.py index bafdf58c749..60021e183ee 100644 --- a/edx_proctoring/backends/tests/test_backend.py +++ b/edx_proctoring/backends/tests/test_backend.py @@ -278,7 +278,7 @@ def test_mock_provider_exception(self, _, get_attempt_mock, logger_mock): self.assertTrue(get_attempt_mock.called) - log_format_string = (u"BLOCKING ERROR: Can't find course info url for course %s") + log_format_string = ("BLOCKING ERROR: Can't find course info url for course_id=%s") logger_mock.assert_any_call(log_format_string, '') diff --git a/edx_proctoring/callbacks.py b/edx_proctoring/callbacks.py index a898eb9c7c2..0af621defa3 100644 --- a/edx_proctoring/callbacks.py +++ b/edx_proctoring/callbacks.py @@ -26,7 +26,7 @@ def start_exam_callback(request, attempt_code): # pylint: disable=unused-argume """ attempt = get_exam_attempt_by_code(attempt_code) if not attempt: - log.warning(u"Attempt code %r cannot be found.", attempt_code) + log.warning('attempt_code={attempt_code} cannot be found.'.format(attempt_code=attempt_code)) return HttpResponse( content='You have entered an exam code that is not valid.', status=404 @@ -40,7 +40,7 @@ def start_exam_callback(request, attempt_code): # pylint: disable=unused-argume if ProctoredExamStudentAttemptStatus.is_in_progress_status(attempt_status): update_attempt_status(attempt['id'], ProctoredExamStudentAttemptStatus.submitted) else: - log.warning(u"Attempted to enter proctored exam attempt {attempt_id} when status was {attempt_status}" + log.warning('Attempted to enter proctored exam attempt_id={attempt_id} when status={attempt_status}' .format( attempt_id=attempt['id'], attempt_status=attempt_status, @@ -53,7 +53,7 @@ def start_exam_callback(request, attempt_code): # pylint: disable=unused-argume try: exam_url = reverse('jump_to', args=[course_id, content_id]) except NoReverseMatch: - log.exception(u"BLOCKING ERROR: Can't find course info url for course %s", course_id) + log.exception("BLOCKING ERROR: Can't find course info url for course_id=%s", course_id) response = HttpResponseRedirect(exam_url) response.set_signed_cookie('exam', attempt['attempt_code']) return response diff --git a/edx_proctoring/exceptions.py b/edx_proctoring/exceptions.py index 029be2b7448..651fa1e6820 100644 --- a/edx_proctoring/exceptions.py +++ b/edx_proctoring/exceptions.py @@ -21,9 +21,6 @@ class ProctoredExamNotFoundException(ProctoredBaseException): """ Raised when a look up fails. """ - def __init__(self, *args): - """ Init method of exception """ - ProctoredBaseException.__init__(self, u'The exam_id does not exist.', *args) class ProctoredExamReviewPolicyNotFoundException(ProctoredBaseException): diff --git a/edx_proctoring/models.py b/edx_proctoring/models.py index 69dacc9d2a3..79464976912 100644 --- a/edx_proctoring/models.py +++ b/edx_proctoring/models.py @@ -669,7 +669,11 @@ def add_allowance_for_user(cls, exam_id, user_info, key, value): exam = ProctoredExam.get_exam_by_id(exam_id) if exam and not exam.is_active: - raise ProctoredExamNotActiveException + err_msg = ( + 'Attempted to add an allowance for user_id={user_id} in exam_id={exam_id}, but ' + 'this exam is not active.'.format(user_id=user_id, exam_id=exam_id) + ) + raise ProctoredExamNotActiveException(err_msg) try: student_allowance = cls.objects.get(proctored_exam_id=exam_id, user_id=user_id, key=key) diff --git a/edx_proctoring/signals.py b/edx_proctoring/signals.py index 2143d2e40df..3faa32b06ee 100644 --- a/edx_proctoring/signals.py +++ b/edx_proctoring/signals.py @@ -118,7 +118,11 @@ def on_attempt_changed(sender, instance, signal, **kwargs): # pylint: disable=u if backend: result = backend.remove_exam_attempt(instance.proctored_exam.external_id, instance.external_id) if not result: - log.error(u'Failed to remove attempt %d from %s', instance.id, backend.verbose_name) + log.error( + 'Failed to remove attempt_id=%s from backend=%s', + instance.id, + instance.proctored_exam.backend, + ) models.archive_model(models.ProctoredExamStudentAttemptHistory, instance, id='attempt_id') diff --git a/edx_proctoring/tests/test_reviews.py b/edx_proctoring/tests/test_reviews.py index b088f01fae0..0fe53593388 100644 --- a/edx_proctoring/tests/test_reviews.py +++ b/edx_proctoring/tests/test_reviews.py @@ -509,8 +509,8 @@ def test_reviewed_by_is_course_or_global_staff(self, logger_mock): ) log_format_string = ( - u'User %(user)s does not have the required permissions ' - u'to submit a review for attempt_code %(attempt_code)s.' + 'user=%(user)s does not have the required permissions ' + 'to submit a review for attempt_code=%(attempt_code)s.' ) log_format_dictionary = { diff --git a/edx_proctoring/tests/test_signals.py b/edx_proctoring/tests/test_signals.py new file mode 100644 index 00000000000..c726b1e6ba3 --- /dev/null +++ b/edx_proctoring/tests/test_signals.py @@ -0,0 +1,47 @@ +""" +Tests for signals.py +""" + +from unittest.mock import patch + +from httmock import HTTMock + +from django.db.models.signals import pre_delete + +from edx_proctoring.models import ProctoredExam, ProctoredExamStudentAttempt +from edx_proctoring.signals import on_attempt_changed + +from .utils import ProctoredExamTestCase + + +class SignalTests(ProctoredExamTestCase): + """ + Tests for signals.py + """ + def setUp(self): + super().setUp() + self.backend_name = 'software_secure' + self.proctored_exam = ProctoredExam.objects.create( + course_id='x/y/z', content_id=self.content_id, exam_name=self.exam_name, + time_limit_mins=self.default_time_limit, external_id=self.external_id, + backend=self.backend_name + ) + + pre_delete.connect(on_attempt_changed, sender=ProctoredExamStudentAttempt) + + def tearDown(self): + super().tearDown() + pre_delete.disconnect() + + @patch('logging.Logger.error') + def test_backend_fails_to_delete_attempt(self, logger_mock): + attempt = ProctoredExamStudentAttempt.objects.create( + proctored_exam=self.proctored_exam, user=self.user, attempt_code='12345', + external_id='abcde' + ) + + # If there is no response from the backend, assert that it is logged correctly + with HTTMock(None): + attempt.delete_exam_attempt() + log_format_string = ('Failed to remove attempt_id=%s from backend=%s') + logger_mock.assert_any_call(log_format_string, 1, self.backend_name) diff --git a/edx_proctoring/tests/test_views.py b/edx_proctoring/tests/test_views.py index fd9793ed8b9..f992df4c7c5 100644 --- a/edx_proctoring/tests/test_views.py +++ b/edx_proctoring/tests/test_views.py @@ -281,7 +281,10 @@ def test_update_non_existing_exam(self): self.assertEqual(response.status_code, 400) response_data = json.loads(response.content.decode('utf-8')) - self.assertEqual(response_data, {'detail': 'The exam_id does not exist.'}) + self.assertEqual( + response_data['detail'], + 'Attempted to update exam_id={exam_id}, but this exam does not exist.'.format(exam_id=exam_id), + ) def test_get_exam_by_id(self): """ @@ -317,7 +320,10 @@ def test_get_exam_by_bad_id(self): ) self.assertEqual(response.status_code, 400) response_data = json.loads(response.content.decode('utf-8')) - self.assertEqual(response_data['detail'], 'The exam_id does not exist.') + self.assertEqual( + response_data['detail'], + 'Attempted to get exam_id=99999, but this exam does not exist.', + ) def test_get_exam_by_content_id(self): """ @@ -394,7 +400,11 @@ def test_get_exam_by_bad_content_id(self): ) self.assertEqual(response.status_code, 400) response_data = json.loads(response.content.decode('utf-8')) - message = 'The exam_id does not exist.' + message = ( + 'Cannot find proctored exam in course_id=c/d/e with content_id={content_id}'.format( + content_id=proctored_exam.content_id, + ) + ) self.assertEqual(response_data['detail'], message) def test_get_exam_insufficient_args(self): @@ -1869,7 +1879,8 @@ def test_restart_exam_attempt(self): response_data = json.loads(response.content.decode('utf-8')) self.assertEqual( response_data['detail'], - 'Cannot create new exam attempt for exam_id = 1 and user_id = 1 because it already exists!' + 'Cannot create new exam attempt for exam_id=1 and user_id=1 in course_id=a/b/c ' + 'because it already exists!' ) def test_stop_exam_attempt(self): @@ -2433,7 +2444,7 @@ def test_stop_unstarted_attempt(self): self.assertEqual(response.status_code, 400) response_data = json.loads(response.content.decode('utf-8')) - self.assertEqual(response_data['detail'], 'Attempted to access attempt_id 0 but it does not exist.') + self.assertEqual(response_data['detail'], 'Attempted to update attempt_id=0 but it does not exist.') def test_get_exam_attempt(self): """ diff --git a/edx_proctoring/utils.py b/edx_proctoring/utils.py index ab53d6dbfb8..dae2dfd7184 100644 --- a/edx_proctoring/utils.py +++ b/edx_proctoring/utils.py @@ -115,7 +115,7 @@ def locate_attempt_by_attempt_code(attempt_code): if not attempt_obj: # still can't find, error out err_msg = ( - u'Could not locate attempt_code: {attempt_code}'.format(attempt_code=attempt_code) + 'Could not locate attempt_code={attempt_code}'.format(attempt_code=attempt_code) ) log.error(err_msg) is_archived = None diff --git a/edx_proctoring/views.py b/edx_proctoring/views.py index e30507468cf..224d3b2c4fa 100644 --- a/edx_proctoring/views.py +++ b/edx_proctoring/views.py @@ -19,7 +19,7 @@ from django.core.exceptions import ObjectDoesNotExist from django.core.paginator import Paginator from django.shortcuts import redirect -from django.urls import NoReverseMatch, reverse +from django.urls import reverse from django.utils.decorators import method_decorator from django.utils.translation import ugettext as _ @@ -619,22 +619,19 @@ def get(self, request, attempt_id): HTTP GET Handler. Returns the status of the exam attempt. """ attempt = get_exam_attempt_by_id(attempt_id) + user_id = request.user.id if not attempt: err_msg = ( - 'Attempted to access attempt_id {attempt_id} but ' - 'it does not exist.'.format( - attempt_id=attempt_id - ) + 'Attempted to get attempt_id={attempt_id} but this attempt does not ' + 'exist.'.format(attempt_id=attempt_id) ) raise StudentExamAttemptDoesNotExistsException(err_msg) # make sure the the attempt belongs to the calling user_id - if attempt['user']['id'] != request.user.id: + if attempt['user']['id'] != user_id: err_msg = ( - 'Attempted to access attempt_id {attempt_id} but ' - 'does not have access to it.'.format( - attempt_id=attempt_id - ) + 'user_id={user_id} attempted to get attempt_id={attempt_id} but ' + 'does not have authorization.'.format(user_id=user_id, attempt_id=attempt_id) ) raise ProctoredExamPermissionDenied(err_msg) @@ -667,24 +664,26 @@ def put(self, request, attempt_id): """ attempt = get_exam_attempt_by_id(attempt_id) + user_id = request.user.id if not attempt: err_msg = ( - 'Attempted to access attempt_id {attempt_id} but ' - 'it does not exist.'.format( + 'Attempted to update attempt_id={attempt_id} but it does not exist.'.format( attempt_id=attempt_id ) ) raise StudentExamAttemptDoesNotExistsException(err_msg) course_id = attempt['proctored_exam']['id'] - user_id = request.user.id action = request.data.get('action') err_msg = ( - 'Attempted to access attempt_id {attempt_id} but ' - 'does not have access to it.'.format( - attempt_id=attempt_id + 'user_id={user_id} attempted to update attempt_id={attempt_id} in ' + 'course_id={course_id} but does not have access to it. (action={action})'.format( + user_id=user_id, + attempt_id=attempt_id, + course_id={course_id}, + action={action}, ) ) @@ -744,10 +743,17 @@ def put(self, request, attempt_id): ) else: exam_attempt_id = False - LOG.warning('Browser JS reported problem with proctoring desktop ' - 'application. Did block user: %s, for attempt: %s', - should_block_user, - attempt['id']) + LOG.warning( + 'Browser JS reported problem with proctoring desktop application. Did block user: ' + '{should_block_user}. user_id={user_id}, course_id={course_id}, exam_id={exam_id}, ' + 'attempt_id={attempt_id}'.format( + should_block_user=should_block_user, + user_id=user_id, + course_id=course_id, + exam_id=attempt['proctored_exam']['id'], + attempt_id=attempt_id, + ) + ) elif action == 'decline': exam_attempt_id = update_attempt_status( attempt_id, @@ -771,10 +777,8 @@ def delete(self, request, attempt_id): # pylint: disable=unused-argument if not attempt: err_msg = ( - 'Attempted to access attempt_id {attempt_id} but ' - 'it does not exist.'.format( - attempt_id=attempt_id - ) + 'Attempted to delete attempt_id={attempt_id} but this attempt does not ' + 'exist.'.format(attempt_id=attempt_id) ) raise StudentExamAttemptDoesNotExistsException(err_msg) @@ -856,13 +860,9 @@ def get(self, request): # pylint: disable=unused-argument critically_low_threshold_pct * float(attempt['allowed_time_limit_mins']) * 60 ) - exam_url_path = '' - try: - # resolve the LMS url, note we can't assume we're running in - # a same process as the LMS - exam_url_path = reverse('jump_to', args=[exam['course_id'], exam['content_id']]) - except NoReverseMatch: - LOG.exception(u"Can't find exam url for course %s", exam['course_id']) + # resolve the LMS url, note we can't assume we're running in + # a same process as the LMS + exam_url_path = reverse('jump_to', args=[exam['course_id'], exam['content_id']]) response_dict = { 'in_timed_exam': True, @@ -912,18 +912,24 @@ def post(self, request): start_immediately = request.data.get('start_clock', 'false').lower() == 'true' exam_id = request.data.get('exam_id', None) attempt_proctored = request.data.get('attempt_proctored', 'false').lower() == 'true' + user_id = request.user.id exam = get_exam_by_id(exam_id) # Bypassing the due date check for practice exam # because student can attempt the practice after the due date if not exam.get("is_practice_exam") and is_exam_passed_due(exam, request.user): raise ProctoredExamPermissionDenied( - 'Attempted to access expired exam with exam_id {exam_id}'.format(exam_id=exam_id) + 'user_id={user_id} attempted to create an attempt for expired exam ' + 'with exam_id={exam_id} in course_id={course_id}'.format( + user_id=user_id, + exam_id=exam_id, + course_id=exam['course_id'], + ) ) exam_attempt_id = create_exam_attempt( exam_id=exam_id, - user_id=request.user.id, + user_id=user_id, taking_as_proctored=attempt_proctored ) @@ -935,7 +941,7 @@ def post(self, request): ProctoredExamStudentAttemptStatus.declined ) elif start_immediately: - start_exam_attempt(exam_id, request.user.id) + start_exam_attempt(exam_id, user_id) data = {'exam_attempt_id': exam_attempt_id} return Response(data) @@ -1173,20 +1179,23 @@ class ProctoredExamAttemptReviewStatus(ProctoredAPIView): edx_proctoring/v1/proctored_exam/attempt/()/review_status$ Supports: - HTTP PUT: Update the is_status_acknowledge flag + HTTP PUT: Update the is_status_acknowledged flag """ def put(self, request, attempt_id): # pylint: disable=unused-argument """ - Update the is_status_acknowledge flag for the specific attempt + Update the is_status_acknowledged flag for the specific attempt """ attempt = get_exam_attempt_by_id(attempt_id) # make sure the the attempt belongs to the calling user_id if attempt and attempt['user']['id'] != request.user.id: err_msg = ( - 'Attempted to access attempt_id {attempt_id} but ' - 'does not have access to it.'.format( - attempt_id=attempt_id + 'user_id={user_id} attempted to update attempt_id={attempt_id} ' + 'review status to acknowledged in exam_id={exam_id}, but does not ' + 'have authorization.'.format( + user_id=request.user.id, + attempt_id=attempt_id, + exam_id=attempt['proctored_exam']['id'], ) ) raise ProctoredExamPermissionDenied(err_msg) @@ -1207,7 +1216,9 @@ def post(self, request, external_id): # pylint: disable=unused-argument """ attempt = get_exam_attempt_by_external_id(external_id) if not attempt: - LOG.warning(u"Attempt code %r cannot be found.", external_id) + LOG.warning( + 'Attempt cannot be found by external_id={external_id}'.format(external_id=external_id) + ) return Response(data='You have entered an exam code that is not valid.', status=404) if attempt['status'] in [ProctoredExamStudentAttemptStatus.created, ProctoredExamStudentAttemptStatus.download_software_clicked]: @@ -1237,9 +1248,9 @@ def make_review(self, attempt, data, backend=None): if review: if not constants.ALLOW_REVIEW_UPDATES: err_msg = ( - 'We already have a review submitted regarding ' - 'attempt_code {attempt_code}. We do not allow for updates!'.format( - attempt_code=attempt_code + 'We already have a review submitted regarding attempt_code={attempt_code}. ' + 'We do not allow for updates! (backend={backend})'.format( + attempt_code=attempt_code, backend=backend ) ) raise ProctoredExamReviewAlreadyExists(err_msg) @@ -1247,9 +1258,9 @@ def make_review(self, attempt, data, backend=None): # we allow updates warn_msg = ( 'We already have a review submitted from our proctoring provider regarding ' - 'attempt_code {attempt_code}. We have been configured to allow for ' - 'updates and will continue...'.format( - attempt_code=attempt_code + 'attempt_code={attempt_code}. We have been configured to allow for ' + 'updates and will continue... (backend={backend})'.format( + attempt_code=attempt_code, backend=backend ) ) LOG.warning(warn_msg) @@ -1280,8 +1291,8 @@ def make_review(self, attempt, data, backend=None): course_id = attempt['proctored_exam']['course_id'] if review.reviewed_by is not None and not is_user_course_or_global_staff(review.reviewed_by, course_id): LOG.warning( - 'User %(user)s does not have the required permissions to submit ' - 'a review for attempt_code %(attempt_code)s.', + 'user=%(user)s does not have the required permissions to submit ' + 'a review for attempt_code=%(attempt_code)s.', {'user': review.reviewed_by, 'attempt_code': attempt_code} ) @@ -1331,10 +1342,8 @@ def post(self, request, external_id): attempt = get_exam_attempt_by_external_id(external_id) if attempt is None: err_msg = ( - 'Attempted to access external exam id {external_id} but ' - 'it does not exist.'.format( - external_id=external_id - ) + 'Attempted to access exam attempt with external_id={external_id} ' + 'but it does not exist.'.format(external_id=external_id) ) raise StudentExamAttemptDoesNotExistsException(err_msg) if request.user.has_perm('edx_proctoring.can_review_attempt', attempt): @@ -1396,7 +1405,7 @@ def post(self, request): if not attempt_obj: # still can't find, error out err_msg = ( - 'Could not locate attempt_code: {attempt_code}'.format(attempt_code=attempt_code) + 'Could not locate attempt_code={attempt_code}'.format(attempt_code=attempt_code) ) raise StudentExamAttemptDoesNotExistsException(err_msg) serialized = ProctoredExamStudentAttemptSerializer(attempt_obj).data @@ -1511,11 +1520,20 @@ def post(self, request, user_id, **kwargs): # pylint: disable=unused-argument if backend_name in seen or not attempt.taking_as_proctored: continue backend_user_id = obscured_user_id(user_id, backend_name) - LOG.info('retiring user %s from %s', user_id, backend_name) + LOG.info( + 'Retiring user_id={user_id} from backend={backend}'.format( + user_id=user_id, backend=backend_name + ) + ) try: result = get_backend_provider(name=backend_name).retire_user(backend_user_id) except ProctoredBaseException: - LOG.exception('attempting to delete %s (%s) from %s', user_id, backend_user_id, backend_name) + LOG.exception( + 'Failed to delete user_id={user_id} (backend_user_id={backend_user_id}) from ' + 'backend={backend}'.format( + user_id=user_id, backend_user_id=backend_user_id, backend=backend_name + ) + ) result = False if result is not None: results[backend_name] = result diff --git a/package.json b/package.json index 27844032a2d..1f71ae6ca3e 100644 --- a/package.json +++ b/package.json @@ -2,7 +2,7 @@ "name": "@edx/edx-proctoring", "//": "Be sure to update the version number in edx_proctoring/__init__.py", "//": "Note that the version format is slightly different than that of the Python version when using prereleases.", - "version": "3.7.4", + "version": "3.7.5", "main": "edx_proctoring/static/index.js", "repository": { "type": "git",