Fix logging calls to use unicode, and lazy logging

common/djangoapps/student/models.py

@@ -122,13 +122,12 @@ def anonymous_id_for_user(user, course_id, save=True):
         )
         if anonymous_user_id.anonymous_user_id != digest:
             log.error(
-                "Stored anonymous user id {stored!r} for user {user!r} "
-                "in course {course!r} doesn't match computed id {digest!r}".format(
-                    user=user,
-                    course=course_id,
-                    stored=anonymous_user_id.anonymous_user_id,
-                    digest=digest
-                )
+                u"Stored anonymous user id %r for user %r "
+                u"in course %r doesn't match computed id %r",
+                user,
+                course_id,
+                anonymous_user_id.anonymous_user_id,
+                digest
             )
     except IntegrityError:
         # Another thread has already created this entry, so
@@ -1030,8 +1029,11 @@ class CourseEnrollment(models.Model):
             record.update_enrollment(is_active=False, skip_refund=skip_refund)
 
         except cls.DoesNotExist:
-            err_msg = u"Tried to unenroll student %s from %s but they were not enrolled"
-            log.error(err_msg, user, course_id)
+            log.error(
+                u"Tried to unenroll student %s from %s but they were not enrolled",
+                user,
+                course_id
+            )
 
     @classmethod
     def unenroll_by_email(cls, email, course_id):
@@ -1047,8 +1049,11 @@ class CourseEnrollment(models.Model):
             user = User.objects.get(email=email)
             return cls.unenroll(user, course_id)
         except User.DoesNotExist:
-            err_msg = u"Tried to unenroll email %s from course %s, but user not found"
-            log.error(err_msg, user, course_id)
+            log.error(
+                u"Tried to unenroll email %s from course %s, but user not found",
+                email,
+                course_id
+            )
 
     @classmethod
     def is_enrolled(cls, user, course_key):

common/djangoapps/student/views.py

@@ -285,9 +285,12 @@ def get_course_enrollment_pairs(user, course_org_filter, org_filter_out_set):
 
                 yield (course, enrollment)
             else:
-                log.error("User {0} enrolled in {2} course {1}".format(
-                    user.username, enrollment.course_id, "broken" if course else "non-existent"
-                ))
+                log.error(
+                    u"User %s enrolled in %s course %s",
+                    user.username,
+                    "broken" if course else "non-existent",
+                    enrollment.course_id
+                )
 
 
 def _cert_info(user, course, cert_status):
@@ -338,8 +341,11 @@ def _cert_info(user, course, cert_status):
 
     if status == 'ready':
         if 'download_url' not in cert_status:
-            log.warning(u"User %s has a downloadable cert for %s, but no download url",
-                        user.username, course.id)
+            log.warning(
+                u"User %s has a downloadable cert for %s, but no download url",
+                user.username,
+                course.id
+            )
             return default_info
         else:
             status_dict['download_url'] = cert_status['download_url']
@@ -470,7 +476,12 @@ def is_course_blocked(request, redeemed_registration_codes, course_key):
                 blocked = True
                 # disabling email notifications for unpaid registration courses
                 Optout.objects.get_or_create(user=request.user, course_id=course_key)
-                log.info(u"User {0} ({1}) opted out of receiving emails from course {2}".format(request.user.username, request.user.email, course_key))
+                log.info(
+                    u"User %s (%s) opted out of receiving emails from course %s",
+                    request.user.username,
+                    request.user.email,
+                    course_key
+                )
                 track.views.server_track(request, "change-email1-settings", {"receive_emails": "no", "course": course_key.to_deprecated_string()}, page='dashboard')
                 break
 
@@ -771,10 +782,9 @@ def try_change_enrollment(request):
             # There isn't really a way to display the results to the user, so we just log it
             # We expect the enrollment to be a success, and will show up on the dashboard anyway
             log.info(
-                "Attempted to automatically enroll after login. Response code: {0}; response body: {1}".format(
-                    enrollment_response.status_code,
-                    enrollment_response.content
-                )
+                u"Attempted to automatically enroll after login. Response code: %s; response body: %s",
+                enrollment_response.status_code,
+                enrollment_response.content
             )
             # Hack: since change_enrollment delivers its redirect_url in the content
             # of its response, we check here that only the 200 codes with content
@@ -782,7 +792,7 @@ def try_change_enrollment(request):
             if enrollment_response.status_code == 200 and enrollment_response.content != '':
                 return enrollment_response.content
         except Exception as exc:  # pylint: disable=broad-except
-            log.exception("Exception automatically enrolling after login: %s", exc)
+            log.exception(u"Exception automatically enrolling after login: %s", exc)
 
 
 def _update_email_opt_in(request, username, org):
@@ -841,19 +851,23 @@ def change_enrollment(request, check_access=True):
     try:
         course_id = SlashSeparatedCourseKey.from_deprecated_string(request.POST.get("course_id"))
     except InvalidKeyError:
-        log.warning(u"User %(username)s tried to %(action)s with invalid course id: %(course_id)s", {
-            "username": user.username,
-            "action": action,
-            "course_id": request.POST.get("course_id"),
-        })
+        log.warning(
+            u"User %s tried to %s with invalid course id: %s",
+            user.username,
+            action,
+            request.POST.get("course_id"),
+        )
         return HttpResponseBadRequest(_("Invalid course id"))
 
     if action == "enroll":
         # Make sure the course exists
         # We don't do this check on unenroll, or a bad course id can't be unenrolled from
         if not modulestore().has_course(course_id):
-            log.warning("User {0} tried to enroll in non-existent course {1}"
-                        .format(user.username, course_id))
+            log.warning(
+                u"User %s tried to enroll in non-existent course %s",
+                user.username,
+                course_id
+            )
             return HttpResponseBadRequest(_("Course id is invalid"))
 
         # Record the user's email opt-in preference
@@ -1008,7 +1022,7 @@ def login_user(request, error=""):  # pylint: disable-msg=too-many-statements,un
                 })  # TODO: this should be status code 301  # pylint: disable=fixme
         except ExternalAuthMap.DoesNotExist:
             # This is actually the common case, logging in user without external linked login
-            AUDIT_LOG.info("User %s w/o external auth attempting login", user)
+            AUDIT_LOG.info(u"User %s w/o external auth attempting login", user)
 
     # see if account has been locked out due to excessive login failures
     user_found_by_email_lookup = user
@@ -1617,7 +1631,7 @@ def create_account(request, post_override=None):  # pylint: disable-msg=too-many
             else:
                 user.email_user(subject, message, from_address)
         except Exception:  # pylint: disable=broad-except
-            log.error('Unable to send activation email to user from "{from_address}"'.format(from_address=from_address), exc_info=True)
+            log.error(u'Unable to send activation email to user from "%s"', from_address, exc_info=True)
             js['value'] = _('Could not send activation e-mail.')
             # What is the correct status code to use here? I think it's 500, because
             # the problem is on the server's end -- but also, the account was created.
@@ -1640,8 +1654,8 @@ def create_account(request, post_override=None):  # pylint: disable-msg=too-many
         eamap.user = new_user
         eamap.dtsignup = datetime.datetime.now(UTC)
         eamap.save()
-        AUDIT_LOG.info("User registered with external_auth %s", post_vars['username'])
-        AUDIT_LOG.info('Updated ExternalAuthMap for %s to be %s', post_vars['username'], eamap)
+        AUDIT_LOG.info(u"User registered with external_auth %s", post_vars['username'])
+        AUDIT_LOG.info(u'Updated ExternalAuthMap for %s to be %s', post_vars['username'], eamap)
 
         if settings.FEATURES.get('BYPASS_ACTIVATION_EMAIL_FOR_EXTAUTH'):
             log.info('bypassing activation email')
@@ -1949,7 +1963,7 @@ def reactivation_email_for_user(user):
     try:
         user.email_user(subject, message, settings.DEFAULT_FROM_EMAIL)
     except Exception:  # pylint: disable=broad-except
-        log.error('Unable to send reactivation email from "{from_address}"'.format(from_address=settings.DEFAULT_FROM_EMAIL), exc_info=True)
+        log.error(u'Unable to send reactivation email from "%s"', settings.DEFAULT_FROM_EMAIL, exc_info=True)
         return JsonResponse({
             "success": False,
             "error": _('Unable to send reactivation email')
@@ -2026,7 +2040,7 @@ def change_email_request(request):
     try:
         send_mail(subject, message, from_address, [pec.new_email])
     except Exception:  # pylint: disable=broad-except
-        log.error('Unable to send email activation link to user from "{from_address}"'.format(from_address=from_address), exc_info=True)
+        log.error(u'Unable to send email activation link to user from "%s"', from_address, exc_info=True)
         return JsonResponse({
             "success": False,
             "error": _('Unable to send email activation link. Please try again later.')
@@ -2226,11 +2240,21 @@ def change_email_settings(request):
         optout_object = Optout.objects.filter(user=user, course_id=course_key)
         if optout_object:
             optout_object.delete()
-        log.info(u"User {0} ({1}) opted in to receive emails from course {2}".format(user.username, user.email, course_id))
+        log.info(
+            u"User %s (%s) opted in to receive emails from course %s",
+            user.username,
+            user.email,
+            course_id
+        )
         track.views.server_track(request, "change-email-settings", {"receive_emails": "yes", "course": course_id}, page='dashboard')
     else:
         Optout.objects.get_or_create(user=user, course_id=course_key)
-        log.info(u"User {0} ({1}) opted out of receiving emails from course {2}".format(user.username, user.email, course_id))
+        log.info(
+            u"User %s (%s) opted out of receiving emails from course %s",
+            user.username,
+            user.email,
+            course_id
+        )
         track.views.server_track(request, "change-email-settings", {"receive_emails": "no", "course": course_id}, page='dashboard')
 
     return JsonResponse({"success": True})

lms/djangoapps/courseware/management/commands/regrade_partial.py

@@ -53,7 +53,7 @@ class Command(BaseCommand):
         if module_state is None:
             # not likely, since we filter on it.  But in general...
             LOG.info(
-                u"No state found for %(type)s module %(id)s for student %(student)s in course %(course_id)s",
+                u"No state found for %s module %s for student %s in course %s",
                 module.module_type,
                 module.module_state_key,
                 module.student.username,

lms/djangoapps/instructor/tests/test_api.py

@@ -334,7 +334,7 @@ class TestInstructorAPIBulkAccountCreationAndEnrollment(ModuleStoreTestCase, Log
         self.assertEquals(len(data['general_errors']), 0)
 
         # test the log for email that's send to new created user.
-        info_log.assert_called_with('email sent to new created user at test_student@example.com')
+        info_log.assert_called_with('email sent to new created user at %s', 'test_student@example.com')
 
     @patch('instructor.views.api.log.info')
     def test_account_creation_and_enrollment_with_csv_with_blank_lines(self, info_log):
@@ -351,7 +351,7 @@ class TestInstructorAPIBulkAccountCreationAndEnrollment(ModuleStoreTestCase, Log
         self.assertEquals(len(data['general_errors']), 0)
 
         # test the log for email that's send to new created user.
-        info_log.assert_called_with('email sent to new created user at test_student@example.com')
+        info_log.assert_called_with('email sent to new created user at %s', 'test_student@example.com')
 
     @patch('instructor.views.api.log.info')
     def test_email_and_username_already_exist(self, info_log):
@@ -370,7 +370,11 @@ class TestInstructorAPIBulkAccountCreationAndEnrollment(ModuleStoreTestCase, Log
         self.assertEquals(len(data['general_errors']), 0)
 
         # test the log for email that's send to new created user.
-        info_log.assert_called_with("user already exists with username '{username}' and email '{email}'".format(username='test_student_1', email='test_student@example.com'))
+        info_log.assert_called_with(
+            u"user already exists with username '%s' and email '%s'",
+            'test_student_1',
+            'test_student@example.com'
+        )
 
     def test_file_upload_type_not_csv(self):
         """
@@ -434,7 +438,11 @@ class TestInstructorAPIBulkAccountCreationAndEnrollment(ModuleStoreTestCase, Log
         uploaded_file = SimpleUploadedFile("temp.csv", csv_content)
         response = self.client.post(self.url, {'students_list': uploaded_file})
         self.assertEqual(response.status_code, 200)
-        info_log.assert_called_with('user {username} enrolled in the course {course}'.format(username='NotEnrolledStudent', course=self.course.id))
+        info_log.assert_called_with(
+            u'user %s enrolled in the course %s',
+            u'NotEnrolledStudent',
+            self.course.id
+        )
 
     def test_user_with_already_existing_email_in_csv(self):
         """

lms/djangoapps/instructor/views/api.py

@@ -350,13 +350,14 @@ def register_and_enroll_students(request, course_id):  # pylint: disable=too-man
                         ).format(email=email, username=username)
 
                         warnings.append({
-                            'username': username, 'email': email, 'response': warning_message})
-                        log.warning('email {email} already exist'.format(email=email))
+                            'username': username, 'email': email, 'response': warning_message
+                        })
+                        log.warning(u'email %s already exist', email)
                     else:
                         log.info(
                             u"user already exists with username '%s' and email '%s'",
-                            email=email,
-                            username=username,
+                            username,
+                            email
                         )
 
                     # make sure user is enrolled in course
@@ -364,8 +365,8 @@ def register_and_enroll_students(request, course_id):  # pylint: disable=too-man
                         CourseEnrollment.enroll(user, course_id)
                         log.info(
                             u'user %s enrolled in the course %s',
-                            username=username,
-                            course=course.id,
+                            username,
+                            course.id,
                         )
                         enroll_email(course_id=course_id, student_email=email, auto_enroll=True, email_students=True, email_params=email_params)
                 else:
@@ -390,7 +391,7 @@ def register_and_enroll_students(request, course_id):  # pylint: disable=too-man
                         email_params['password'] = password
                         email_params['platform_name'] = microsite.get_value('platform_name', settings.PLATFORM_NAME)
                         send_mail_to_student(email, email_params)
-                        log.info('email sent to new created user at {email}'.format(email=email))
+                        log.info(u'email sent to new created user at %s', email)
 
     else:
         general_errors.append({
@@ -544,7 +545,7 @@ def students_update_enrollment(request, course_id):
         except Exception as exc:  # pylint: disable=broad-except
             # catch and log any exceptions
             # so that one error doesn't cause a 500.
-            log.exception("Error while #{}ing student")
+            log.exception(u"Error while #{}ing student")
             log.exception(exc)
             results.append({
                 'identifier': identifier,
@@ -618,7 +619,7 @@ def bulk_beta_modify_access(request, course_id):
         # catch and log any unexpected exceptions
         # so that one error doesn't cause a 500.
         except Exception as exc:  # pylint: disable=broad-except
-            log.exception("Error while #{}ing student")
+            log.exception(u"Error while #{}ing student")
             log.exception(exc)
             error = True
         else:
@@ -1942,7 +1943,7 @@ def proxy_legacy_analytics(request, course_id):
     try:
         res = requests.get(url)
     except Exception:  # pylint: disable=broad-except
-        log.exception("Error requesting from analytics server at %s", url)
+        log.exception(u"Error requesting from analytics server at %s", url)
         return HttpResponse("Error requesting from analytics server.", status=500)
 
     if res.status_code is 200:
@@ -1957,9 +1958,8 @@ def proxy_legacy_analytics(request, course_id):
     else:
         # 500 on all other unexpected status codes.
         log.error(
-            "Error fetching {}, code: {}, msg: {}".format(
-                url, res.status_code, res.content
-            )
+            u"Error fetching %s, code: %s, msg: %s",
+            url, res.status_code, res.content
         )
         return HttpResponse(
             "Error from analytics server ({}).".format(res.status_code),