Merge pull request #804 from edx/bseverino/improve-logging

[MST-626] Add more detail and consistency to log messages

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

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

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):

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)

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, '')
 
 

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

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):

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)

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')
 
 

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 = {

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)

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):
         """

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