Merge pull request #6327 from edx/sanchez/logging-verified-split

Adding a number of logging messages for verification process.

lms/djangoapps/shoppingcart/models.py

@@ -1000,8 +1000,9 @@ class PaidCourseRegistration(OrderItem):
         would in fact be quite silly since there's a clear back door.
         """
         if not modulestore().has_course(self.course_id):
-            raise PurchasedCallbackException(
-                "The customer purchased Course {0}, but that course doesn't exist!".format(self.course_id))
+            msg = u"The customer purchased Course {0}, but that course doesn't exist!".format(self.course_id)
+            log.error(msg)
+            raise PurchasedCallbackException(msg)
 
         CourseEnrollment.enroll(user=self.user, course_key=self.course_id, mode=self.mode)
 
@@ -1144,8 +1145,9 @@ class CourseRegCodeItem(OrderItem):
         be redeemed by users
         """
         if not modulestore().has_course(self.course_id):
-            raise PurchasedCallbackException(
-                "The customer purchased Course {0}, but that course doesn't exist!".format(self.course_id))
+            msg = u"The customer purchased Course {0}, but that course doesn't exist!".format(self.course_id)
+            log.error(msg)
+            raise PurchasedCallbackException(msg)
         total_registration_codes = int(self.qty)
 
         # we need to import here because of a circular dependency
@@ -1306,7 +1308,9 @@ class CertificateItem(OrderItem):
         if mode in valid_modes:
             mode_info = valid_modes[mode]
         else:
-            raise InvalidCartItem(_("Mode {mode} does not exist for {course_id}").format(mode=mode, course_id=course_id))
+            msg = u"Mode {mode} does not exist for {course_id}".format(mode=mode, course_id=course_id)
+            log.error(msg)
+            raise InvalidCartItem(_(msg))
         item, _created = cls.objects.get_or_create(
             order=order,
             user=order.user,
@@ -1577,10 +1581,9 @@ class Donation(OrderItem):
         if course_id is not None:
             course = modulestore().get_course(course_id)
             if course is None:
-                err = _(
-                    u"Could not find a course with the ID '{course_id}'"
-                ).format(course_id=course_id)
-                raise CourseDoesNotExistException(err)
+                msg = u"Could not find a course with the ID '{course_id}'".format(course_id=course_id)
+                log.error(msg)
+                raise CourseDoesNotExistException(_(msg))
 
             return _(u"Donation for {course}").format(course=course.display_name)
 

lms/djangoapps/verify_student/models.py

@@ -451,6 +451,9 @@ class PhotoVerification(StatusModel):
         if self.status == "approved":
             return
 
+        log.info(u"Verification for user '{user_id}' approved by '{reviewer}'.".format(
+            user_id=self.user, reviewer=user_id
+        ))
         self.error_msg = ""  # reset, in case this attempt was denied before
         self.error_code = ""  # reset, in case this attempt was denied before
         self.reviewing_user = user_id
@@ -494,6 +497,9 @@ class PhotoVerification(StatusModel):
             lets you amend the error message in case there were additional
             details to be made.
         """
+        log.info(u"Verification for user '{user_id}' denied by '{reviewer}'.".format(
+            user_id=self.user, reviewer=reviewing_user
+        ))
         self.error_msg = error_msg
         self.error_code = error_code
         self.reviewing_user = reviewing_user
@@ -610,6 +616,9 @@ class SoftwareSecurePhotoVerification(PhotoVerification):
                 if attempt.status != "approved":
                     return False
             except Exception:  # pylint: disable=broad-except
+                log.exception(
+                    u"An error occurred while checking re-verification for user '{user_id}'".format(user_id=user)
+                )
                 return False
 
         return True

lms/djangoapps/verify_student/views.py

@@ -424,13 +424,23 @@ class PayAndVerifyView(View):
 
         # Verify that the course exists and has a verified mode
         if course is None:
+            log.warn(u"No course specified for verification flow request.")
             raise Http404
 
         # Verify that the course has a verified mode
         course_mode = CourseMode.verified_mode_for_course(course_key)
         if course_mode is None:
+            log.warn(
+                u"No verified course mode found for course '{course_id}' for verification flow request"
+                .format(course_id=course_id)
+            )
             raise Http404
 
+        log.info(
+            u"Entering verified workflow for user '{user}', course '{course_id}', with current step '{current_step}'."
+            .format(user=request.user, course_id=course_id, current_step=current_step)
+        )
+
         # Check whether the user has verified, paid, and enrolled.
         # A user is considered "paid" if he or she has an enrollment
         # with a paid course mode (such as "verified").
@@ -762,6 +772,7 @@ def create_order(request):
             b64_face_image = request.POST['face_image'].split(",")[1]
             b64_photo_id_image = request.POST['photo_id_image'].split(",")[1]
         except IndexError:
+            log.error(u"Invalid image data during photo verification.")
             context = {
                 'success': False,
             }
@@ -791,6 +802,7 @@ def create_order(request):
 
     # make sure this course has a verified mode
     if not current_mode:
+        log.warn(u"Verification requested for course {course_id} without a verified mode.".format(course_id=course_id))
         return HttpResponseBadRequest(_("This course doesn't support verified certificates"))
 
     if current_mode.slug == 'professional':