From 4e733c6e1f11d1c30b6a023cc925e98e9d07bf9d Mon Sep 17 00:00:00 2001 From: Omar Al-Ithawi Date: Tue, 3 Feb 2015 13:01:22 +0200 Subject: [PATCH 1/3] Unicode fixes for log messages and other things --- .../management/commands/assigngroups.py | 8 +- common/djangoapps/student/models.py | 43 ++++----- common/djangoapps/student/views.py | 18 ++-- lms/djangoapps/certificates/views.py | 3 +- lms/djangoapps/courseware/grades.py | 5 +- .../management/commands/regrade_partial.py | 88 ++++++++++++++----- .../management/commands/remove_input_state.py | 2 +- lms/djangoapps/instructor/views/api.py | 12 ++- lms/djangoapps/instructor/views/legacy.py | 10 ++- lms/djangoapps/lms_migration/migrate.py | 6 +- lms/djangoapps/shoppingcart/models.py | 30 +++++-- lms/djangoapps/shoppingcart/views.py | 18 ++-- lms/djangoapps/verify_student/views.py | 2 +- 13 files changed, 162 insertions(+), 83 deletions(-) diff --git a/common/djangoapps/student/management/commands/assigngroups.py b/common/djangoapps/student/management/commands/assigngroups.py index 3c6df5b3ba..166e5cab16 100644 --- a/common/djangoapps/student/management/commands/assigngroups.py +++ b/common/djangoapps/student/management/commands/assigngroups.py @@ -82,9 +82,11 @@ class Command(BaseCommand): v = random.uniform(0, 1) group = group_from_value(groups, v) group_objects[group].users.add(user) - f.write("Assigned user {name} ({id}) to {group}\n".format(name=user.username, - id=user.id, - group=group)) + f.write(u"Assigned user {name} ({id}) to {group}\n".format( + name=user.username, + id=user.id, + group=group + ).encode('utf-8')) ## Save groups for group in group_objects: diff --git a/common/djangoapps/student/models.py b/common/djangoapps/student/models.py index 0159587a24..fc036399a9 100644 --- a/common/djangoapps/student/models.py +++ b/common/djangoapps/student/models.py @@ -889,7 +889,12 @@ class CourseEnrollment(models.Model): except: # pylint: disable=bare-except if event_name and self.course_id: - log.exception('Unable to emit event %s for user %s and course %s', event_name, self.user.username, self.course_id) + log.exception( + u'Unable to emit event %s for user %s and course %s', + event_name, + self.user.username, # pylint: disable=no-member + self.course_id, + ) @classmethod def enroll(cls, user, course_key, mode="honor", check_access=False): @@ -930,10 +935,9 @@ class CourseEnrollment(models.Model): course = modulestore().get_course(course_key) except ItemNotFoundError: log.warning( - "User {0} failed to enroll in non-existent course {1}".format( - user.username, - course_key.to_deprecated_string() - ) + u"User %s failed to enroll in non-existent course %s", + user.username, + course_key.to_deprecated_string(), ) raise NonExistentCourseError @@ -942,27 +946,24 @@ class CourseEnrollment(models.Model): raise NonExistentCourseError if CourseEnrollment.is_enrollment_closed(user, course): log.warning( - "User {0} failed to enroll in course {1} because enrollment is closed".format( - user.username, - course_key.to_deprecated_string() - ) + u"User %s failed to enroll in course %s because enrollment is closed", + user.username, + course_key.to_deprecated_string() ) raise EnrollmentClosedError if CourseEnrollment.is_course_full(course): log.warning( - "User {0} failed to enroll in full course {1}".format( - user.username, - course_key.to_deprecated_string() - ) + u"User %s failed to enroll in full course %s", + user.username, + course_key.to_deprecated_string(), ) raise CourseFullError if CourseEnrollment.is_enrolled(user, course_key): log.warning( - "User {0} attempted to enroll in {1}, but they were already enrolled".format( - user.username, - course_key.to_deprecated_string() - ) + u"User %s attempted to enroll in %s, but they were already enrolled", + user.username, + course_key.to_deprecated_string() ) if check_access: raise AlreadyEnrolledError @@ -1029,8 +1030,8 @@ class CourseEnrollment(models.Model): record.update_enrollment(is_active=False, skip_refund=skip_refund) except cls.DoesNotExist: - err_msg = u"Tried to unenroll student {} from {} but they were not enrolled" - log.error(err_msg.format(user, course_id)) + err_msg = u"Tried to unenroll student %s from %s but they were not enrolled" + log.error(err_msg, user, course_id) @classmethod def unenroll_by_email(cls, email, course_id): @@ -1046,8 +1047,8 @@ 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 {} from course {}, but user not found" - log.error(err_msg.format(email, course_id)) + err_msg = u"Tried to unenroll email %s from course %s, but user not found" + log.error(err_msg, user, course_id) @classmethod def is_enrolled(cls, user, course_key): diff --git a/common/djangoapps/student/views.py b/common/djangoapps/student/views.py index 774cf23168..792dd3c454 100644 --- a/common/djangoapps/student/views.py +++ b/common/djangoapps/student/views.py @@ -338,7 +338,7 @@ def _cert_info(user, course, cert_status): if status == 'ready': if 'download_url' not in cert_status: - log.warning("User %s has a downloadable cert for %s, but no download url", + log.warning(u"User %s has a downloadable cert for %s, but no download url", user.username, course.id) return default_info else: @@ -841,13 +841,11 @@ def change_enrollment(request, check_access=True): try: course_id = SlashSeparatedCourseKey.from_deprecated_string(request.POST.get("course_id")) except InvalidKeyError: - log.warning( - "User {username} tried to {action} with invalid course id: {course_id}".format( - username=user.username, - action=action, - course_id=request.POST.get("course_id") - ) - ) + 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"), + }) return HttpResponseBadRequest(_("Invalid course id")) if action == "enroll": @@ -1248,11 +1246,11 @@ def disable_account_ajax(request): if account_action == 'disable': user_account.account_status = UserStanding.ACCOUNT_DISABLED context['message'] = _("Successfully disabled {}'s account").format(username) - log.info("{} disabled {}'s account".format(request.user, username)) + log.info(u"%s disabled %s's account", request.user, username) elif account_action == 'reenable': user_account.account_status = UserStanding.ACCOUNT_ENABLED context['message'] = _("Successfully reenabled {}'s account").format(username) - log.info("{} reenabled {}'s account".format(request.user, username)) + log.info(u"%s reenabled %s's account", request.user, username) else: context['message'] = _("Unexpected account status") return JsonResponse(context, status=400) diff --git a/lms/djangoapps/certificates/views.py b/lms/djangoapps/certificates/views.py index e2d5f49f5f..13d341dc1a 100644 --- a/lms/djangoapps/certificates/views.py +++ b/lms/djangoapps/certificates/views.py @@ -36,7 +36,8 @@ def request_certificate(request): status = certificate_status_for_student(student, course_key)['status'] if status in [CertificateStatuses.unavailable, CertificateStatuses.notpassing, CertificateStatuses.error]: - logger.info('Grading and certification requested for user {} in course {} via /request_certificate call'.format(username, course_key)) + log_msg = u'Grading and certification requested for user %s in course %s via /request_certificate call' + logger.info(log_msg, username, course_key) status = xqci.add_cert(student, course_key, course=course) return HttpResponse(json.dumps({'add_status': status}), mimetype='application/json') return HttpResponse(json.dumps({'add_status': 'ERRORANONYMOUSUSER'}), mimetype='application/json') diff --git a/lms/djangoapps/courseware/grades.py b/lms/djangoapps/courseware/grades.py index bd8cb577f2..3db3cb8f35 100644 --- a/lms/djangoapps/courseware/grades.py +++ b/lms/djangoapps/courseware/grades.py @@ -89,8 +89,9 @@ def answer_distributions(course_key): raw_answers = state_dict.get("student_answers", {}) except ValueError: log.error( - "Answer Distribution: Could not parse module state for " + - "StudentModule id={}, course={}".format(module.id, course_key) + u"Answer Distribution: Could not parse module state for StudentModule id=%s, course=%s", + module.id, + course_key, ) continue diff --git a/lms/djangoapps/courseware/management/commands/regrade_partial.py b/lms/djangoapps/courseware/management/commands/regrade_partial.py index c24f84ddfc..1cbcd52b87 100644 --- a/lms/djangoapps/courseware/management/commands/regrade_partial.py +++ b/lms/djangoapps/courseware/management/commands/regrade_partial.py @@ -52,9 +52,13 @@ class Command(BaseCommand): module_state = module.state if module_state is None: # not likely, since we filter on it. But in general... - LOG.info("No state found for {type} module {id} for student {student} in course {course_id}" - .format(type=module.module_type, id=module.module_state_key, - student=module.student.username, course_id=module.course_id)) + LOG.info( + u"No state found for %(type)s module %(id)s for student %(student)s in course %(course_id)s", + module.module_type, + module.module_state_key, + module.student.username, + module.course_id, + ) return state_dict = json.loads(module_state) @@ -66,15 +70,31 @@ class Command(BaseCommand): if (not student_answers) or len(student_answers) == 0: # we should not have a grade here: if module.grade != 0: - LOG.error("No answer found but grade {grade} exists for {type} module {id} for student {student} " - "in course {course_id}".format(grade=module.grade, - type=module.module_type, id=module.module_state_key, - student=module.student.username, course_id=module.course_id)) + log_msg = ( + u"No answer found but grade %(grade)s exists for %(type)s module %(id)s for student %(student)s " + + u"in course %(course_id)s" + ) + + LOG.error(log_msg, { + "grade": module.grade, + "type": module.module_type, + "id": module.module_state_key, + "student": module.student.username, + "course_id": module.course_id, + }) else: - LOG.debug("No answer and no grade found for {type} module {id} for student {student} " - "in course {course_id}".format(grade=module.grade, - type=module.module_type, id=module.module_state_key, - student=module.student.username, course_id=module.course_id)) + log_msg = ( + u"No answer and no grade found for %(type)s module %(id)s for student %(student)s " + + u"in course %(course_id)s" + ) + + LOG.debug(log_msg, { + "grade": module.grade, + "type": module.module_type, + "id": module.module_state_key, + "student": module.student.username, + "course_id": module.course_id, + }) return # load into a CorrectMap, as done in LoncapaProblem.__init__(): @@ -90,24 +110,48 @@ class Command(BaseCommand): if module.grade == correct: # nothing to change - LOG.debug("Grade matches for {type} module {id} for student {student} in course {course_id}" - .format(type=module.module_type, id=module.module_state_key, - student=module.student.username, course_id=module.course_id)) + log_msg = u"Grade matches for %(type)s module %(id)s for student %(student)s in course %(course_id)s" + LOG.debug(log_msg, { + "type": module.module_type, + "id": module.module_state_key, + "student": module.student.username, + "course_id": module.course_id, + }) elif save_changes: # make the change - LOG.info("Grade changing from {0} to {1} for {type} module {id} for student {student} " - "in course {course_id}".format(module.grade, correct, - type=module.module_type, id=module.module_state_key, - student=module.student.username, course_id=module.course_id)) + log_msg = ( + u"Grade changing from %(grade)s to %(correct)s for %(type)s module " + + u"%(id)s for student %(student)s in course %(course_id)s" + ) + + LOG.debug(log_msg, { + "grade": module.grade, + "correct": correct, + "type": module.module_type, + "id": module.module_state_key, + "student": module.student.username, + "course_id": module.course_id, + }) + module.grade = correct module.save() self.num_changed += 1 else: # don't make the change, but log that the change would be made - LOG.info("Grade would change from {0} to {1} for {type} module {id} for student {student} " - "in course {course_id}".format(module.grade, correct, - type=module.module_type, id=module.module_state_key, - student=module.student.username, course_id=module.course_id)) + log_msg = ( + u"Grade would change from %(grade)s to %(correct)s for %(type)s module %(id)s for student " + + u"%(student)s in course %(course_id)s" + ) + + LOG.debug(log_msg, { + "grade": module.grade, + "correct": correct, + "type": module.module_type, + "id": module.module_state_key, + "student": module.student.username, + "course_id": module.course_id, + }) + self.num_changed += 1 def handle(self, **options): diff --git a/lms/djangoapps/courseware/management/commands/remove_input_state.py b/lms/djangoapps/courseware/management/commands/remove_input_state.py index e45d08e351..3e86d213a9 100644 --- a/lms/djangoapps/courseware/management/commands/remove_input_state.py +++ b/lms/djangoapps/courseware/management/commands/remove_input_state.py @@ -68,7 +68,7 @@ class Command(BaseCommand): try: module = StudentModule.objects.get(id=student_module_id) except StudentModule.DoesNotExist: - LOG.error("Unable to find student module with id = {0}: skipping... ".format(student_module_id)) + LOG.error(u"Unable to find student module with id = %s: skipping... ", student_module_id) continue self.remove_studentmodule_input_state(module, save_changes) diff --git a/lms/djangoapps/instructor/views/api.py b/lms/djangoapps/instructor/views/api.py index 8c97f1e899..73d544030e 100644 --- a/lms/djangoapps/instructor/views/api.py +++ b/lms/djangoapps/instructor/views/api.py @@ -353,12 +353,20 @@ def register_and_enroll_students(request, course_id): # pylint: disable=too-man 'username': username, 'email': email, 'response': warning_message}) log.warning('email {email} already exist'.format(email=email)) else: - log.info("user already exists with username '{username}' and email '{email}'".format(email=email, username=username)) + log.info( + u"user already exists with username '%s' and email '%s'", + email=email, + username=username, + ) # make sure user is enrolled in course if not CourseEnrollment.is_enrolled(user, course_id): CourseEnrollment.enroll(user, course_id) - log.info('user {username} enrolled in the course {course}'.format(username=username, course=course.id)) + log.info( + u'user %s enrolled in the course %s', + username=username, + course=course.id, + ) enroll_email(course_id=course_id, student_email=email, auto_enroll=True, email_students=True, email_params=email_params) else: # This email does not yet exist, so we need to create a new account diff --git a/lms/djangoapps/instructor/views/legacy.py b/lms/djangoapps/instructor/views/legacy.py index 4bb65e5849..09ecfe05d3 100644 --- a/lms/djangoapps/instructor/views/legacy.py +++ b/lms/djangoapps/instructor/views/legacy.py @@ -252,9 +252,11 @@ def instructor_dashboard(request, course_id): try: ddata.append([student.email, student.grades[aidx]]) except IndexError: - log.debug('No grade for assignment {idx} ({name}) for student {email}'.format( - idx=aidx, name=aname, email=student.email) - ) + log.debug(u'No grade for assignment %(idx)s (%(name)s) for student %(email)s', { + "idx": aidx, + "name": aname, + "email": student.email, + }) datatable['data'] = ddata datatable['title'] = _('Grades for assignment "{name}"').format(name=aname) @@ -749,7 +751,7 @@ def get_student_grade_summary_data(request, course, get_grades=True, get_raw_sco if get_grades: gradeset = student_grades(student, request, course, keep_raw_scores=get_raw_scores, use_offline=use_offline) - log.debug('student={0}, gradeset={1}'.format(student, gradeset)) + log.debug(u'student=%s, gradeset=%s', student, gradeset) with gtab.add_row(student.id) as add_grade: if get_raw_scores: # TODO (ichuang) encode Score as dict instead of as list, so score[0] -> score['earned'] diff --git a/lms/djangoapps/lms_migration/migrate.py b/lms/djangoapps/lms_migration/migrate.py index ee6f715fb6..eb33a14773 100644 --- a/lms/djangoapps/lms_migration/migrate.py +++ b/lms/djangoapps/lms_migration/migrate.py @@ -69,11 +69,11 @@ def manage_modulestores(request, reload_dir=None, commit_id=None): html += '

IP address: %s

' % ip html += '

User: %s

' % request.user html += '

My pid: %s

' % os.getpid() - log.debug('request from ip=%s, user=%s' % (ip, request.user)) + log.debug(u'request from ip=%s, user=%s', ip, request.user) if not (ip in ALLOWED_IPS or 'any' in ALLOWED_IPS): if request.user and request.user.is_staff: - log.debug('request allowed because user=%s is staff' % request.user) + log.debug(u'request allowed because user=%s is staff', request.user) else: html += 'Permission denied' html += "" @@ -185,7 +185,7 @@ def gitreload(request, reload_dir=None): if not (ip in ALLOWED_IPS or 'any' in ALLOWED_IPS): if request.user and request.user.is_staff: - log.debug('request allowed because user=%s is staff' % request.user) + log.debug(u'request allowed because user=%s is staff', request.user) else: html += 'Permission denied' html += "" diff --git a/lms/djangoapps/shoppingcart/models.py b/lms/djangoapps/shoppingcart/models.py index 8c6bda7860..29ed866986 100644 --- a/lms/djangoapps/shoppingcart/models.py +++ b/lms/djangoapps/shoppingcart/models.py @@ -927,7 +927,7 @@ class CouponRedemption(models.Model): coupon_redemption = cls.objects.filter(user=user, order=cart) if coupon_redemption: coupon_redemption.delete() - log.info('Coupon redemption entry removed for user {0} for order {1}'.format(user, cart.id)) + log.info(u'Coupon redemption entry removed for user %s for order %s', user, cart.id) @classmethod def get_discount_price(cls, percentage_discount, value): @@ -946,8 +946,11 @@ class CouponRedemption(models.Model): coupon_redemptions = cls.objects.filter(order=order, user=order.user) for coupon_redemption in coupon_redemptions: if coupon_redemption.coupon.code != coupon.code or coupon_redemption.coupon.id == coupon.id: - log.exception("Coupon redemption already exist for user '{0}' against order id '{1}'" - .format(order.user.username, order.id)) + log.exception( + u"Coupon redemption already exist for user '%s' against order id '%s'", + order.user.username, + order.id, + ) raise MultipleCouponsNotAllowedException for item in cart_items: @@ -959,8 +962,11 @@ class CouponRedemption(models.Model): item.list_price = item.unit_cost item.unit_cost = discount_price item.save() - log.info("Discount generated for user {0} against order id '{1}' " - .format(order.user.username, order.id)) + log.info( + u"Discount generated for user %s against order id '%s'", + order.user.username, + order.id, + ) is_redemption_applied = True return is_redemption_applied @@ -1018,8 +1024,12 @@ class PaidCourseRegistration(OrderItem): raise CourseDoesNotExistException if cls.contained_in_order(order, course_id): - log.warning("User {} tried to add PaidCourseRegistration for course {}, already in cart id {}" - .format(order.user.email, course_id, order.id)) + log.warning( + u"User %s tried to add PaidCourseRegistration for course %s, already in cart id %s", + order.user.email, + course_id, + order.id, + ) raise ItemAlreadyInCartException if CourseEnrollment.is_enrolled(user=order.user, course_key=course_id): @@ -1319,7 +1329,11 @@ class CertificateItem(OrderItem): try: target_cert = target_certs[0] except IndexError: - log.error("Matching CertificateItem not found while trying to refund. User %s, Course %s", course_enrollment.user, course_enrollment.course_id) + log.error( + u"Matching CertificateItem not found while trying to refund. User %s, Course %s", + course_enrollment.user, + course_enrollment.course_id, + ) return target_cert.status = 'refunded' target_cert.refund_requested_time = datetime.now(pytz.utc) diff --git a/lms/djangoapps/shoppingcart/views.py b/lms/djangoapps/shoppingcart/views.py index a19541d05c..00ce713cf2 100644 --- a/lms/djangoapps/shoppingcart/views.py +++ b/lms/djangoapps/shoppingcart/views.py @@ -200,8 +200,10 @@ def clear_cart(request): coupon_redemption = CouponRedemption.objects.filter(user=request.user, order=cart.id) if coupon_redemption: coupon_redemption.delete() - log.info('Coupon redemption entry removed for user {user} for order {order_id}'.format(user=request.user, - order_id=cart.id)) + log.info(u'Coupon redemption entry removed for user %(user)s for order %(order_id)s', { + "user": request.user, + "order_id": cart.id, + }) return HttpResponse('Cleared') @@ -224,7 +226,10 @@ def remove_item(request): if item.user == request.user: order_item_course_id = getattr(item, 'course_id') item.delete() - log.info('order item {item_id} removed for user {user}'.format(item_id=item_id, user=request.user)) + log.info(u'order item %(item_id)s removed for user %(user)s', { + "item_id": item_id, + "user": request.user, + }) remove_code_redemption(order_item_course_id, item_id, item, request.user) item.order.update_order_type() @@ -244,8 +249,11 @@ def remove_code_redemption(order_item_course_id, item_id, item, user): order=item.order_id ) coupon_redemption.delete() - log.info('Coupon "{code}" redemption entry removed for user "{user}" for order item "{item_id}"' - .format(code=coupon_redemption.coupon.code, user=user, item_id=item_id)) + log.info(u'Coupon "%(code)s" redemption entry removed for user "%(user)s" for order item "%(item_id)s"', { + "code": coupon_redemption.coupon.code, + "user": user, + "item_id": item_id, + }) except CouponRedemption.DoesNotExist: log.debug('Code redemption does not exist for order item id={item_id}.'.format(item_id=item_id)) diff --git a/lms/djangoapps/verify_student/views.py b/lms/djangoapps/verify_student/views.py index 2ac8704551..9b40f00488 100644 --- a/lms/djangoapps/verify_student/views.py +++ b/lms/djangoapps/verify_student/views.py @@ -929,7 +929,7 @@ def midcourse_reverify_dash(request): try: course_enrollment_pairs.append((modulestore().get_course(enrollment.course_id), enrollment)) except ItemNotFoundError: - log.error("User {0} enrolled in non-existent course {1}".format(user.username, enrollment.course_id)) + log.error(u"User %s enrolled in non-existent course %s", user.username, enrollment.course_id) statuses = ["approved", "pending", "must_reverify", "denied"] From 0f45724c9afd98716c7c7526d895b458300c1c98 Mon Sep 17 00:00:00 2001 From: Sarina Canelake Date: Tue, 3 Feb 2015 12:34:19 -0500 Subject: [PATCH 2/3] Convert shopping cart to use unicode lazy logging Conflicts: lms/djangoapps/shoppingcart/views.py --- .../shoppingcart/tests/test_views.py | 44 ++++++++++---- lms/djangoapps/shoppingcart/views.py | 59 ++++++++++--------- 2 files changed, 66 insertions(+), 37 deletions(-) diff --git a/lms/djangoapps/shoppingcart/tests/test_views.py b/lms/djangoapps/shoppingcart/tests/test_views.py index a729f18e05..82d621ee88 100644 --- a/lms/djangoapps/shoppingcart/tests/test_views.py +++ b/lms/djangoapps/shoppingcart/tests/test_views.py @@ -584,7 +584,9 @@ class ShoppingCartViewsTests(ModuleStoreTestCase): resp = self.client.post(reverse('shoppingcart.views.remove_item', args=[]), {'id': reg_item.id}) debug_log.assert_called_with( - 'Code redemption does not exist for order item id={0}.'.format(reg_item.id)) + 'Code redemption does not exist for order item id=%s.', + str(reg_item.id) + ) self.assertEqual(resp.status_code, 200) self.assertEquals(self.cart.orderitem_set.count(), 0) @@ -604,7 +606,11 @@ class ShoppingCartViewsTests(ModuleStoreTestCase): self.assertEqual(resp.status_code, 200) self.assertEquals(self.cart.orderitem_set.count(), 0) info_log.assert_called_with( - 'Coupon "{0}" redemption entry removed for user "{1}" for order item "{2}"'.format(self.coupon_code, self.user, reg_item.id)) + 'Coupon "%s" redemption entry removed for user "%s" for order item "%s"', + self.coupon_code, + self.user, + str(reg_item.id) + ) @patch('shoppingcart.views.log.info') def test_reset_redemption_for_coupon(self, info_log): @@ -619,7 +625,10 @@ class ShoppingCartViewsTests(ModuleStoreTestCase): self.assertEqual(resp.status_code, 200) info_log.assert_called_with( - 'Coupon redemption entry removed for user {0} for order {1}'.format(self.user, reg_item.id)) + 'Coupon redemption entry removed for user %s for order %s', + self.user, + reg_item.id + ) @patch('shoppingcart.views.log.info') def test_coupon_discount_for_multiple_courses_in_cart(self, info_log): @@ -648,7 +657,11 @@ class ShoppingCartViewsTests(ModuleStoreTestCase): self.assertEqual(resp.status_code, 200) self.assertEquals(self.cart.orderitem_set.count(), 1) info_log.assert_called_with( - 'Coupon "{0}" redemption entry removed for user "{1}" for order item "{2}"'.format(self.coupon_code, self.user, reg_item.id)) + 'Coupon "%s" redemption entry removed for user "%s" for order item "%s"', + self.coupon_code, + self.user, + str(reg_item.id) + ) @patch('shoppingcart.views.log.info') def test_delete_certificate_item(self, info_log): @@ -664,7 +677,10 @@ class ShoppingCartViewsTests(ModuleStoreTestCase): self.assertEqual(resp.status_code, 200) self.assertEquals(self.cart.orderitem_set.count(), 1) info_log.assert_called_with( - 'order item {0} removed for user {1}'.format(cert_item.id, self.user)) + 'order item %s removed for user %s', + str(cert_item.id), + self.user + ) @patch('shoppingcart.views.log.info') def test_remove_coupon_redemption_on_clear_cart(self, info_log): @@ -682,7 +698,10 @@ class ShoppingCartViewsTests(ModuleStoreTestCase): self.assertEquals(self.cart.orderitem_set.count(), 0) info_log.assert_called_with( - 'Coupon redemption entry removed for user {0} for order {1}'.format(self.user, reg_item.id)) + 'Coupon redemption entry removed for user %s for order %s', + self.user, + reg_item.id + ) def test_add_course_to_cart_already_registered(self): CourseEnrollment.enroll(self.user, self.course_key) @@ -773,13 +792,18 @@ class ShoppingCartViewsTests(ModuleStoreTestCase): {'id': cert_item.id}) self.assertEqual(resp2.status_code, 200) exception_log.assert_called_with( - 'Cannot remove cart OrderItem id={0}. DoesNotExist or item is already purchased'.format(cert_item.id)) + 'Cannot remove cart OrderItem id=%s. DoesNotExist or item is already purchased', str(cert_item.id) + ) - resp3 = self.client.post(reverse('shoppingcart.views.remove_item', args=[]), - {'id': -1}) + resp3 = self.client.post( + reverse('shoppingcart.views.remove_item', args=[]), + {'id': -1} + ) self.assertEqual(resp3.status_code, 200) exception_log.assert_called_with( - 'Cannot remove cart OrderItem id={0}. DoesNotExist or item is already purchased'.format(-1)) + 'Cannot remove cart OrderItem id=%s. DoesNotExist or item is already purchased', + '-1' + ) @patch('shoppingcart.views.process_postpay_callback', postpay_mock) def test_postpay_callback_success(self): diff --git a/lms/djangoapps/shoppingcart/views.py b/lms/djangoapps/shoppingcart/views.py index 00ce713cf2..f21a452819 100644 --- a/lms/djangoapps/shoppingcart/views.py +++ b/lms/djangoapps/shoppingcart/views.py @@ -81,7 +81,7 @@ def add_course_to_cart(request, course_id): assert isinstance(course_id, basestring) if not request.user.is_authenticated(): - log.info("Anon user trying to add course {} to cart".format(course_id)) + log.info(u"Anon user trying to add course %s to cart", course_id) return HttpResponseForbidden(_('You must be logged-in to add to a shopping cart')) cart = Order.get_cart_for_user(request.user) course_key = SlashSeparatedCourseKey.from_deprecated_string(course_id) @@ -131,7 +131,7 @@ def update_user_cart(request): try: item = OrderItem.objects.get(id=item_id, status='cart') except OrderItem.DoesNotExist: - log.exception('Cart OrderItem id={item_id} DoesNotExist'.format(item_id=item_id)) + log.exception(u'Cart OrderItem id=%s DoesNotExist', item_id) return HttpResponseNotFound('Order item does not exist.') item.qty = qty @@ -200,10 +200,11 @@ def clear_cart(request): coupon_redemption = CouponRedemption.objects.filter(user=request.user, order=cart.id) if coupon_redemption: coupon_redemption.delete() - log.info(u'Coupon redemption entry removed for user %(user)s for order %(order_id)s', { - "user": request.user, - "order_id": cart.id, - }) + log.info( + u'Coupon redemption entry removed for user %s for order %s', + request.user, + cart.id, + ) return HttpResponse('Cleared') @@ -219,17 +220,20 @@ def remove_item(request): items = OrderItem.objects.filter(id=item_id, status='cart').select_subclasses() if not len(items): - log.exception('Cannot remove cart OrderItem id={item_id}. DoesNotExist or item is already purchased'.format( - item_id=item_id)) + log.exception( + u'Cannot remove cart OrderItem id=%s. DoesNotExist or item is already purchased', + item_id + ) else: item = items[0] if item.user == request.user: order_item_course_id = getattr(item, 'course_id') item.delete() - log.info(u'order item %(item_id)s removed for user %(user)s', { - "item_id": item_id, - "user": request.user, - }) + log.info( + u'order item %s removed for user %s', + item_id, + request.user, + ) remove_code_redemption(order_item_course_id, item_id, item, request.user) item.order.update_order_type() @@ -249,13 +253,14 @@ def remove_code_redemption(order_item_course_id, item_id, item, user): order=item.order_id ) coupon_redemption.delete() - log.info(u'Coupon "%(code)s" redemption entry removed for user "%(user)s" for order item "%(item_id)s"', { - "code": coupon_redemption.coupon.code, - "user": user, - "item_id": item_id, - }) + log.info( + u'Coupon "%s" redemption entry removed for user "%s" for order item "%s"', + coupon_redemption.coupon.code, + user, + item_id, + ) except CouponRedemption.DoesNotExist: - log.debug('Code redemption does not exist for order item id={item_id}.'.format(item_id=item_id)) + log.debug(u'Code redemption does not exist for order item id=%s.', item_id) @login_required @@ -318,7 +323,7 @@ def get_reg_code_validity(registration_code, request, limiter): reg_code_already_redeemed = True if not reg_code_is_valid: - #tick the rate limiter counter + # tick the rate limiter counter AUDIT_LOG.info("Redemption of a non existing RegistrationCode {code}".format(code=registration_code)) limiter.tick_bad_request_counter(request) raise Http404() @@ -439,7 +444,7 @@ def use_registration_code(course_reg, user): and redirects the user to the Registration code redemption page. """ if RegistrationCodeRedemption.is_registration_code_redeemed(course_reg): - log.warning("Registration code '{registration_code}' already used".format(registration_code=course_reg.code)) + log.warning(u"Registration code '%s' already used", course_reg.code) return HttpResponseBadRequest( _("Oops! The code '{registration_code}' you entered is either invalid or expired").format( registration_code=course_reg.code @@ -449,8 +454,7 @@ def use_registration_code(course_reg, user): cart = Order.get_cart_for_user(user) cart_items = cart.find_item_by_course_id(course_reg.course_id) except ItemNotFoundInCartException: - log.warning("Course item does not exist against registration code '{registration_code}'".format( - registration_code=course_reg.code)) + log.warning(u"Course item does not exist against registration code '%s'", course_reg.code) return HttpResponseNotFound( _("Code '{registration_code}' is not valid for any course in the shopping cart.").format( registration_code=course_reg.code @@ -489,7 +493,7 @@ def use_coupon_code(coupons, user): return HttpResponseBadRequest(_("Only one coupon redemption is allowed against an order")) if not is_redemption_applied: - log.warning("Discount does not exist against code '{code}'.".format(code=coupons[0].code)) + log.warning(u"Discount does not exist against code '%s'.", coupons[0].code) return HttpResponseNotFound(_("Discount does not exist against code '{code}'.").format(code=coupons[0].code)) return HttpResponse( @@ -568,10 +572,11 @@ def donate(request): # Course ID may be None if this is a donation to the entire organization Donation.add_to_order(cart, amount, course_id=course_id) except InvalidCartItem as ex: - log.exception(( - u"Could not create donation item for " - u"amount '{amount}' and course ID '{course_id}'" - ).format(amount=amount, course_id=course_id)) + log.exception( + u"Could not create donation item for amount '%s' and course ID '%s'", + amount, + course_id + ) return HttpResponseBadRequest(unicode(ex)) # Start the purchase. From 01064fcc79d0dafb3b115961c53950d9ea1d1ad8 Mon Sep 17 00:00:00 2001 From: Sarina Canelake Date: Tue, 3 Feb 2015 12:52:47 -0500 Subject: [PATCH 3/3] Fix logging calls to use unicode, and lazy logging --- common/djangoapps/student/models.py | 27 ++++--- common/djangoapps/student/views.py | 76 ++++++++++++------- .../management/commands/regrade_partial.py | 2 +- lms/djangoapps/instructor/tests/test_api.py | 16 +++- lms/djangoapps/instructor/views/api.py | 26 +++---- 5 files changed, 92 insertions(+), 55 deletions(-) diff --git a/common/djangoapps/student/models.py b/common/djangoapps/student/models.py index fc036399a9..227a97dd48 100644 --- a/common/djangoapps/student/models.py +++ b/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): diff --git a/common/djangoapps/student/views.py b/common/djangoapps/student/views.py index 792dd3c454..8a76fefcf5 100644 --- a/common/djangoapps/student/views.py +++ b/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}) diff --git a/lms/djangoapps/courseware/management/commands/regrade_partial.py b/lms/djangoapps/courseware/management/commands/regrade_partial.py index 1cbcd52b87..6198a4759e 100644 --- a/lms/djangoapps/courseware/management/commands/regrade_partial.py +++ b/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, diff --git a/lms/djangoapps/instructor/tests/test_api.py b/lms/djangoapps/instructor/tests/test_api.py index e2cf283537..6fbb93adc1 100644 --- a/lms/djangoapps/instructor/tests/test_api.py +++ b/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): """ diff --git a/lms/djangoapps/instructor/views/api.py b/lms/djangoapps/instructor/views/api.py index 73d544030e..b8de74244c 100644 --- a/lms/djangoapps/instructor/views/api.py +++ b/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),