Commit aba0fcd8 by Will Daly

Merge pull request #6894 from edx/will/better-logging-for-cert-cmds

Info-level logging for certificate management commands
parents 2bb1aafa a8df217a
"""Django management command to force certificate regeneration for one user"""
import logging
import copy
from optparse import make_option
from django.contrib.auth.models import User
from django.core.management.base import BaseCommand, CommandError
from opaque_keys import InvalidKeyError
from opaque_keys.edx.keys import CourseKey
from opaque_keys.edx.locations import SlashSeparatedCourseKey
from xmodule.course_module import CourseDescriptor
from xmodule.modulestore.django import modulestore
from certificates.queue import XQueueCertInterface
LOGGER = logging.getLogger(__name__)
class Command(BaseCommand):
help = """Put a request on the queue to recreate the certificate for a particular user in a particular course."""
......@@ -49,12 +53,32 @@ class Command(BaseCommand):
)
def handle(self, *args, **options):
# Scrub the username from the log message
cleaned_options = copy.copy(options)
if 'username' in cleaned_options:
cleaned_options['username'] = '<USERNAME>'
LOGGER.info(
(
u"Starting to create tasks to regenerate certificates "
u"with arguments %s and options %s"
),
unicode(args),
unicode(cleaned_options)
)
if options['course']:
# try to parse out the course from the serialized form
try:
course_id = CourseKey.from_string(options['course'])
except InvalidKeyError:
print("Course id {} could not be parsed as a CourseKey; falling back to SSCK.from_dep_str".format(options['course']))
LOGGER.warning(
(
u"Course id %s could not be parsed as a CourseKey; "
u"falling back to SlashSeparatedCourseKey.from_deprecated_string()"
),
options['course']
)
course_id = SlashSeparatedCourseKey.from_deprecated_string(options['course'])
else:
raise CommandError("You must specify a course")
......@@ -64,23 +88,61 @@ class Command(BaseCommand):
raise CommandError('both course id and student username are required')
student = None
print "Fetching enrollment for student {0} in {1}".format(user, course_id)
if '@' in user:
student = User.objects.get(email=user, courseenrollment__course_id=course_id)
else:
student = User.objects.get(username=user, courseenrollment__course_id=course_id)
print "Fetching course data for {0}".format(course_id)
course = modulestore().get_course(course_id, depth=2)
if not options['noop']:
LOGGER.info(
(
u"Adding task to the XQueue to generate a certificate "
u"for student %s in course '%s'."
),
student.id,
course_id
)
# Add the certificate request to the queue
xq = XQueueCertInterface()
xqueue_interface = XQueueCertInterface()
if options['insecure']:
xq.use_https = False
ret = xq.regen_cert(student, course_id, course=course,
forced_grade=options['grade_value'],
template_file=options['template_file'])
print '{0} - {1}'.format(student, ret)
xqueue_interface.use_https = False
ret = xqueue_interface.regen_cert(
student, course_id, course=course,
forced_grade=options['grade_value'],
template_file=options['template_file']
)
LOGGER.info(
(
u"Added a certificate regeneration task to the XQueue "
u"for student %s in course '%s'. "
u"The new certificate status is '%s'."
),
student.id,
unicode(course_id),
ret
)
else:
print "noop option given, skipping work queueing..."
LOGGER.info(
(
u"Skipping certificate generation for "
u"student %s in course '%s' "
u"because the noop flag is set."
),
student.id,
unicode(course_id)
)
LOGGER.info(
(
u"Finished regenerating certificates command for "
u"user %s and course '%s'."
),
student.id,
unicode(course_id)
)
......@@ -2,20 +2,22 @@
Management command to find all students that need certificates for
courses that have finished, and put their cert requests on the queue.
"""
import logging
import datetime
from pytz import UTC
from django.core.management.base import BaseCommand, CommandError
from certificates.models import certificate_status_for_student
from certificates.queue import XQueueCertInterface
from django.contrib.auth.models import User
from optparse import make_option
from django.conf import settings
from opaque_keys import InvalidKeyError
from opaque_keys.edx.keys import CourseKey
from opaque_keys.edx.locations import SlashSeparatedCourseKey
from xmodule.course_module import CourseDescriptor
from xmodule.modulestore.django import modulestore
from certificates.models import CertificateStatuses
import datetime
from pytz import UTC
LOGGER = logging.getLogger(__name__)
class Command(BaseCommand):
......@@ -59,12 +61,21 @@ class Command(BaseCommand):
def handle(self, *args, **options):
LOGGER.info(
(
u"Starting to create tasks for ungenerated certificates "
u"with arguments %s and options %s"
),
unicode(args),
unicode(options)
)
# Will only generate a certificate if the current
# status is in the unavailable state, can be set
# to something else with the force flag
if options['force']:
valid_statuses = getattr(CertificateStatuses, options['force'])
valid_statuses = [getattr(CertificateStatuses, options['force'])]
else:
valid_statuses = [CertificateStatuses.unavailable]
......@@ -77,7 +88,13 @@ class Command(BaseCommand):
try:
course = CourseKey.from_string(options['course'])
except InvalidKeyError:
print("Course id {} could not be parsed as a CourseKey; falling back to SSCK.from_dep_str".format(options['course']))
LOGGER.warning(
(
u"Course id %s could not be parsed as a CourseKey; "
u"falling back to SlashSeparatedCourseKey.from_deprecated_string()"
),
options['course']
)
course = SlashSeparatedCourseKey.from_deprecated_string(options['course'])
ended_courses = [course]
else:
......@@ -87,9 +104,9 @@ class Command(BaseCommand):
# prefetch all chapters/sequentials by saying depth=2
course = modulestore().get_course(course_key, depth=2)
print "Fetching enrolled students for {0}".format(course_key.to_deprecated_string())
enrolled_students = User.objects.filter(
courseenrollment__course_id=course_key)
courseenrollment__course_id=course_key
)
xq = XQueueCertInterface()
if options['insecure']:
......@@ -112,10 +129,61 @@ class Command(BaseCommand):
count, total, hours, minutes)
start = datetime.datetime.now(UTC)
if certificate_status_for_student(
student, course_key)['status'] in valid_statuses:
cert_status = certificate_status_for_student(student, course_key)['status']
LOGGER.info(
(
u"Student %s has certificate status '%s' "
u"in course '%s'"
),
student.id,
cert_status,
unicode(course_key)
)
if cert_status in valid_statuses:
if not options['noop']:
# Add the certificate request to the queue
ret = xq.add_cert(student, course_key, course=course)
if ret == 'generating':
print '{0} - {1}'.format(student, ret)
LOGGER.info(
(
u"Added a certificate generation task to the XQueue "
u"for student %s in course '%s'. "
u"The new certificate status is '%s'."
),
student.id,
unicode(course_key),
ret
)
else:
LOGGER.info(
(
u"Skipping certificate generation for "
u"student %s in course '%s' "
u"because the noop flag is set."
),
student.id,
unicode(course_key)
)
else:
LOGGER.info(
(
u"Skipped student %s because "
u"certificate status '%s' is not in %s"
),
student.id,
cert_status,
unicode(valid_statuses)
)
LOGGER.info(
(
u"Completed ungenerated certificates command "
u"for course '%s'"
),
unicode(course_key)
)
......@@ -19,7 +19,7 @@ import lxml.html
from lxml.etree import XMLSyntaxError, ParserError
logger = logging.getLogger(__name__)
LOGGER = logging.getLogger(__name__)
class XQueueCertInterface(object):
......@@ -101,8 +101,31 @@ class XQueueCertInterface(object):
# AWS. See note in the docstring too.
try:
certificate = GeneratedCertificate.objects.get(user=student, course_id=course_id)
LOGGER.info(
(
u"Found an existing certificate entry for student %s "
u"in course '%s' "
u"with status '%s' while regenerating certificates. "
),
student.id,
unicode(course_id),
certificate.status
)
certificate.status = status.unavailable
certificate.save()
LOGGER.info(
(
u"The certificate status for student %s "
u"in course '%s' has been changed to '%s'."
),
student.id,
unicode(course_id),
certificate.status
)
except GeneratedCertificate.DoesNotExist:
pass
......@@ -153,17 +176,30 @@ class XQueueCertInterface(object):
Returns the student's status
"""
VALID_STATUSES = [status.generating,
status.unavailable,
status.deleted,
status.error,
status.notpassing]
valid_statuses = [
status.generating,
status.unavailable,
status.deleted,
status.error,
status.notpassing
]
cert_status = certificate_status_for_student(student, course_id)['status']
new_status = cert_status
if cert_status in VALID_STATUSES:
if cert_status not in valid_statuses:
LOGGER.warning(
(
u"Cannot create certificate generation task for user %s "
u"in the course '%s'; "
u"the certificate status '%s' is not one of %s."
),
student.id,
unicode(course_id),
cert_status,
unicode(valid_statuses)
)
else:
# grade the student
# re-use the course passed in optionally so we don't have to re-fetch everything
......@@ -207,12 +243,33 @@ class XQueueCertInterface(object):
grade_contents = grade.get('grade', None)
try:
grade_contents = lxml.html.fromstring(grade_contents).text_content()
except (TypeError, XMLSyntaxError, ParserError) as e:
except (TypeError, XMLSyntaxError, ParserError) as exc:
LOGGER.info(
(
u"Could not retrieve grade for student %s "
u"in the course '%s' "
u"because an exception occurred while parsing the "
u"grade contents '%s' as HTML. "
u"The exception was: '%s'"
),
student.id,
unicode(course_id),
grade_contents,
unicode(exc)
)
# Despite blowing up the xml parser, bad values here are fine
grade_contents = None
if is_whitelisted or grade_contents is not None:
if is_whitelisted:
LOGGER.info(
u"Student %s is whitelisted in '%s'",
student.id,
unicode(course_id)
)
# check to see whether the student is on the
# the embargoed country restricted list
# otherwise, put a new certificate request
......@@ -222,6 +279,18 @@ class XQueueCertInterface(object):
new_status = status.restricted
cert.status = new_status
cert.save()
LOGGER.info(
(
u"Student %s is in the embargoed country restricted "
u"list, so their certificate status has been set to '%s' "
u"for the course '%s'. "
u"No certificate generation task was sent to the XQueue."
),
student.id,
new_status,
unicode(course_id)
)
else:
key = make_hashkey(random.random())
cert.key = key
......@@ -240,14 +309,36 @@ class XQueueCertInterface(object):
cert.status = new_status
cert.save()
self._send_to_xqueue(contents, key)
LOGGER.info(
(
u"The certificate status has been set to '%s'. "
u"Sent a certificate grading task to the XQueue "
u"with the key '%s'. "
),
key,
new_status
)
else:
cert_status = status.notpassing
cert.status = cert_status
cert.save()
LOGGER.info(
(
u"Student %s does not have a grade for '%s', "
u"so their certificate status has been set to '%s'. "
u"No certificate generation task was sent to the XQueue."
),
student.id,
unicode(course_id),
cert_status
)
return new_status
def _send_to_xqueue(self, contents, key):
"""Create a new task on the XQueue. """
if self.use_https:
proto = "https"
......@@ -261,5 +352,5 @@ class XQueueCertInterface(object):
(error, msg) = self.xqueue_interface.send_to_queue(
header=xheader, body=json.dumps(contents))
if error:
logger.critical('Unable to add a request to the queue: {} {}'.format(error, msg))
LOGGER.critical(u'Unable to add a request to the queue: %s %s', unicode(error), msg)
raise Exception('Unable to send queue message')
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment