Commit b5c4b638 by Adam Palay

Merge remote-tracking branch 'origin/release' into adam/merge-release-to-master

Conflicts:
	common/djangoapps/cors_csrf/helpers.py
	common/djangoapps/enrollment/views.py
	lms/djangoapps/commerce/constants.py
	lms/djangoapps/commerce/tests.py
	lms/djangoapps/commerce/views.py
parents d182b8db 7abcfddf
"""Tests that performance data is successfully logged."""
import datetime
import dateutil
import json
import mock
import unittest
import logging
from StringIO import StringIO
from django.test import TestCase
from django.test.client import RequestFactory
from performance.views import performance_log
class PerformanceTrackingTest(TestCase):
"""
Tests that performance logs correctly handle events
"""
def setUp(self):
self.request_factory = RequestFactory()
self.stream = StringIO()
self.handler = logging.StreamHandler(self.stream)
self.log = logging.getLogger()
self.log.setLevel(logging.INFO)
for handler in self.log.handlers:
self.log.removeHandler(handler)
self.log.addHandler(self.handler)
self.addCleanup(self.log.removeHandler, self.handler)
self.addCleanup(self.handler.close)
def test_empty_get(self):
request = self.request_factory.get('/performance')
pre_time = datetime.datetime.utcnow()
performance_log(request)
post_time = datetime.datetime.utcnow()
self.handler.flush()
logged_value = json.loads(self.stream.getvalue().strip())
self.assertEqual(logged_value['accept_language'], '')
self.assertEqual(logged_value['agent'], '')
self.assertEqual(logged_value['event'], '')
self.assertEqual(logged_value['event_source'], 'browser')
self.assertEqual(logged_value['expgroup'], '')
self.assertEqual(logged_value['id'], '')
self.assertEqual(logged_value['page'], '')
self.assertEqual(logged_value['referer'], '')
self.assertEqual(logged_value['value'], '')
logged_time = dateutil.parser.parse(logged_value['time']).replace(tzinfo=None)
self.assertTrue(pre_time <= logged_time)
self.assertTrue(post_time >= logged_time)
def test_empty_post(self):
request = self.request_factory.post('/performance')
pre_time = datetime.datetime.utcnow()
performance_log(request)
post_time = datetime.datetime.utcnow()
self.handler.flush()
logged_value = json.loads(self.stream.getvalue().strip())
self.assertEqual(logged_value['accept_language'], '')
self.assertEqual(logged_value['agent'], '')
self.assertEqual(logged_value['event'], '')
self.assertEqual(logged_value['event_source'], 'browser')
self.assertEqual(logged_value['expgroup'], '')
self.assertEqual(logged_value['id'], '')
self.assertEqual(logged_value['page'], '')
self.assertEqual(logged_value['referer'], '')
self.assertEqual(logged_value['value'], '')
logged_time = dateutil.parser.parse(logged_value['time']).replace(tzinfo=None)
self.assertTrue(pre_time <= logged_time)
self.assertTrue(post_time >= logged_time)
def test_populated_get(self):
request = self.request_factory.get('/performance',
{'event': "a_great_event",
'id': "12345012345",
'expgroup': "17", 'page': "atestpage",
'value': "100234"})
request.META['HTTP_ACCEPT_LANGUAGE'] = "en"
request.META['HTTP_REFERER'] = "https://www.edx.org/evilpage"
request.META['HTTP_USER_AGENT'] = "Mozilla/5.0"
request.META['REMOTE_ADDR'] = "18.19.20.21"
request.META['SERVER_NAME'] = "some-aws-server"
pre_time = datetime.datetime.utcnow()
performance_log(request)
post_time = datetime.datetime.utcnow()
self.handler.flush()
logged_value = json.loads(self.stream.getvalue().strip())
self.assertEqual(logged_value['accept_language'], 'en')
self.assertEqual(logged_value['agent'], 'Mozilla/5.0')
self.assertEqual(logged_value['event'], 'a_great_event')
self.assertEqual(logged_value['event_source'], 'browser')
self.assertEqual(logged_value['expgroup'], '17')
self.assertEqual(logged_value['host'], 'some-aws-server')
self.assertEqual(logged_value['id'], '12345012345')
self.assertEqual(logged_value['ip'], '18.19.20.21')
self.assertEqual(logged_value['page'], 'atestpage')
self.assertEqual(logged_value['referer'], 'https://www.edx.org/evilpage')
self.assertEqual(logged_value['value'], '100234')
logged_time = dateutil.parser.parse(logged_value['time']).replace(tzinfo=None)
self.assertTrue(pre_time <= logged_time)
self.assertTrue(post_time >= logged_time)
def test_populated_post(self):
request = self.request_factory.post('/performance',
{'event': "a_great_event",
'id': "12345012345",
'expgroup': "17", 'page': "atestpage",
'value': "100234"})
request.META['HTTP_ACCEPT_LANGUAGE'] = "en"
request.META['HTTP_REFERER'] = "https://www.edx.org/evilpage"
request.META['HTTP_USER_AGENT'] = "Mozilla/5.0"
request.META['REMOTE_ADDR'] = "18.19.20.21"
request.META['SERVER_NAME'] = "some-aws-server"
pre_time = datetime.datetime.utcnow()
performance_log(request)
post_time = datetime.datetime.utcnow()
self.handler.flush()
logged_value = json.loads(self.stream.getvalue().strip())
self.assertEqual(logged_value['accept_language'], 'en')
self.assertEqual(logged_value['agent'], 'Mozilla/5.0')
self.assertEqual(logged_value['event'], 'a_great_event')
self.assertEqual(logged_value['event_source'], 'browser')
self.assertEqual(logged_value['expgroup'], '17')
self.assertEqual(logged_value['host'], 'some-aws-server')
self.assertEqual(logged_value['id'], '12345012345')
self.assertEqual(logged_value['ip'], '18.19.20.21')
self.assertEqual(logged_value['page'], 'atestpage')
self.assertEqual(logged_value['referer'], 'https://www.edx.org/evilpage')
self.assertEqual(logged_value['value'], '100234')
logged_time = dateutil.parser.parse(logged_value['time']).replace(tzinfo=None)
self.assertTrue(pre_time <= logged_time)
self.assertTrue(post_time >= logged_time)
import datetime
import json
import logging
from django.http import HttpResponse
from track.utils import DateTimeJSONEncoder
perflog = logging.getLogger("perflog")
def _get_request_header(request, header_name, default=''):
"""Helper method to get header values from a request's META dict, if present."""
if request is not None and hasattr(request, 'META') and header_name in request.META:
return request.META[header_name]
else:
return default
def _get_request_value(request, value_name, default=''):
"""Helper method to get header values from a request's REQUEST dict, if present."""
if request is not None and hasattr(request, 'REQUEST') and value_name in request.REQUEST:
return request.REQUEST[value_name]
else:
return default
def performance_log(request):
"""
Log when POST call to "performance" URL is made by a user.
Request should provide "event" and "page" arguments.
"""
event = {
"ip": _get_request_header(request, 'REMOTE_ADDR'),
"referer": _get_request_header(request, 'HTTP_REFERER'),
"accept_language": _get_request_header(request, 'HTTP_ACCEPT_LANGUAGE'),
"event_source": "browser",
"event": _get_request_value(request, 'event'),
"agent": _get_request_header(request, 'HTTP_USER_AGENT'),
"page": _get_request_value(request, 'page'),
"id": _get_request_value(request, 'id'),
"expgroup": _get_request_value(request, 'expgroup'),
"value": _get_request_value(request, 'value'),
"time": datetime.datetime.utcnow(),
"host": _get_request_header(request, 'SERVER_NAME'),
}
perflog.info(json.dumps(event, cls=DateTimeJSONEncoder))
return HttpResponse(status=204)
......@@ -236,9 +236,8 @@ class VideoModule(VideoFields, VideoTranscriptsMixin, VideoStudentViewHandlers,
# CDN_VIDEO_URLS is only to be used here and will be deleted
# TODO(ali@edx.org): Delete this after the CDN experiment has completed.
html_id = self.location.html_id()
if getattr(settings, 'PERFORMANCE_GRAPHITE_URL', '') != '' and \
self.system.user_location == 'CN' and \
getattr(settings.FEATURES, 'ENABLE_VIDEO_BEACON', False) and \
if self.system.user_location == 'CN' and \
settings.FEATURES.get('ENABLE_VIDEO_BEACON', False) and \
html_id in getattr(settings, 'CDN_VIDEO_URLS', {}).keys():
cdn_urls = getattr(settings, 'CDN_VIDEO_URLS', {})[html_id]
cdn_exp_group, new_source = random.choice(zip(range(len(cdn_urls)), cdn_urls))
......@@ -254,7 +253,6 @@ class VideoModule(VideoFields, VideoTranscriptsMixin, VideoStudentViewHandlers,
'autoplay': settings.FEATURES.get('AUTOPLAY_VIDEOS', False),
'branding_info': branding_info,
'cdn_eval': cdn_eval,
'cdn_eval_endpoint': getattr(settings, 'PERFORMANCE_GRAPHITE_URL', ''),
'cdn_exp_group': cdn_exp_group,
# This won't work when we move to data that
# isn't on the filesystem
......
......@@ -79,6 +79,23 @@ class OrdersView(APIView):
if not valid:
return DetailResponse(error, status=HTTP_406_NOT_ACCEPTABLE)
# Ensure that the course has an honor mode with SKU
honor_mode = CourseMode.mode_for_course(course_key, CourseMode.HONOR)
course_id = unicode(course_key)
# If there is no honor course mode, this most likely a Prof-Ed course. Return an error so that the JS
# redirects to track selection.
if not honor_mode:
msg = Messages.NO_HONOR_MODE.format(course_id=course_id)
return DetailResponse(msg, status=HTTP_406_NOT_ACCEPTABLE)
elif not honor_mode.sku:
# If there are no course modes with SKUs, enroll the user without contacting the external API.
msg = Messages.NO_SKU_ENROLLED.format(enrollment_mode=CourseMode.HONOR, course_id=course_id,
username=user.username)
log.debug(msg)
self._enroll(course_key, user)
return DetailResponse(msg)
# Ensure that the E-Commerce API is setup properly
ecommerce_api_url = getattr(settings, 'ECOMMERCE_API_URL', None)
ecommerce_api_signing_key = getattr(settings, 'ECOMMERCE_API_SIGNING_KEY', None)
......
......@@ -30,7 +30,6 @@ class TestVideoYouTube(TestVideo):
'autoplay': settings.FEATURES.get('AUTOPLAY_VIDEOS', False),
'branding_info': None,
'cdn_eval': False,
'cdn_eval_endpoint': getattr(settings, 'PERFORMANCE_GRAPHITE_URL', ''),
'cdn_exp_group': None,
'data_dir': getattr(self, 'data_dir', None),
'display_name': u'A Name',
......@@ -97,7 +96,6 @@ class TestVideoNonYouTube(TestVideo):
'ajax_url': self.item_descriptor.xmodule_runtime.ajax_url + '/save_user_state',
'branding_info': None,
'cdn_eval': False,
'cdn_eval_endpoint': getattr(settings, 'PERFORMANCE_GRAPHITE_URL', ''),
'cdn_exp_group': None,
'data_dir': getattr(self, 'data_dir', None),
'show_captions': 'true',
......@@ -204,7 +202,6 @@ class TestGetHtmlMethod(BaseTestXmodule):
expected_context = {
'branding_info': None,
'cdn_eval': False,
'cdn_eval_endpoint': getattr(settings, 'PERFORMANCE_GRAPHITE_URL', ''),
'cdn_exp_group': None,
'data_dir': getattr(self, 'data_dir', None),
'show_captions': 'true',
......@@ -324,7 +321,6 @@ class TestGetHtmlMethod(BaseTestXmodule):
initial_context = {
'branding_info': None,
'cdn_eval': False,
'cdn_eval_endpoint': getattr(settings, 'PERFORMANCE_GRAPHITE_URL', ''),
'cdn_exp_group': None,
'data_dir': getattr(self, 'data_dir', None),
'show_captions': 'true',
......@@ -467,7 +463,6 @@ class TestGetHtmlMethod(BaseTestXmodule):
initial_context = {
'branding_info': None,
'cdn_eval': False,
'cdn_eval_endpoint': getattr(settings, 'PERFORMANCE_GRAPHITE_URL', ''),
'cdn_exp_group': None,
'data_dir': getattr(self, 'data_dir', None),
'show_captions': 'true',
......@@ -588,7 +583,6 @@ class TestGetHtmlMethod(BaseTestXmodule):
initial_context = {
'branding_info': None,
'cdn_eval': False,
'cdn_eval_endpoint': getattr(settings, 'PERFORMANCE_GRAPHITE_URL', ''),
'cdn_exp_group': None,
'data_dir': getattr(self, 'data_dir', None),
'show_captions': 'true',
......@@ -710,7 +704,6 @@ class TestGetHtmlMethod(BaseTestXmodule):
'url': 'http://www.xuetangx.com'
},
'cdn_eval': False,
'cdn_eval_endpoint': getattr(settings, 'PERFORMANCE_GRAPHITE_URL', ''),
'cdn_exp_group': None,
'data_dir': getattr(self, 'data_dir', None),
'show_captions': 'true',
......
......@@ -1938,10 +1938,13 @@ def calculate_grades_csv(request, course_id):
course_key = SlashSeparatedCourseKey.from_deprecated_string(course_id)
try:
instructor_task.api.submit_calculate_grades_csv(request, course_key)
success_status = _("Your grade report is being generated! You can view the status of the generation task in the 'Pending Instructor Tasks' section.")
success_status = _("Your grade report is being generated! "
"You can view the status of the generation task in the 'Pending Instructor Tasks' section.")
return JsonResponse({"status": success_status})
except AlreadyRunningError:
already_running_status = _("A grade report generation task is already in progress. Check the 'Pending Instructor Tasks' table for the status of the task. When completed, the report will be available for download in the table below.")
already_running_status = _("A grade report generation task is already in progress. "
"Check the 'Pending Instructor Tasks' table for the status of the task. "
"When completed, the report will be available for download in the table below.")
return JsonResponse({
"status": already_running_status
})
......
......@@ -19,10 +19,14 @@ a problem URL and optionally a student. These are used to set up the initial va
of the query for traversing StudentModule objects.
"""
import logging
from functools import partial
from django.conf import settings
from django.utils.translation import ugettext_noop
from celery import task
from functools import partial
from bulk_email.tasks import perform_delegate_email_batches
from instructor_task.tasks_helper import (
run_main_task,
BaseInstructorTask,
......@@ -34,7 +38,9 @@ from instructor_task.tasks_helper import (
upload_students_csv,
cohort_students_and_upload
)
from bulk_email.tasks import perform_delegate_email_batches
TASK_LOG = logging.getLogger('edx.celery.task')
@task(base=BaseInstructorTask) # pylint: disable=not-callable
......@@ -140,6 +146,11 @@ def calculate_grades_csv(entry_id, xmodule_instance_args):
"""
# Translators: This is a past-tense verb that is inserted into task progress messages as {action}.
action_name = ugettext_noop('graded')
TASK_LOG.info(
u"Task: %s, InstructorTask ID: %s, Task type: %s, Preparing for task execution",
xmodule_instance_args.get('task_id'), entry_id, action_name
)
task_fn = partial(upload_grades_csv, xmodule_instance_args)
return run_main_task(entry_id, task_fn, action_name)
......
......@@ -226,39 +226,40 @@ def run_main_task(entry_id, task_fcn, action_name):
"""
# get the InstructorTask to be updated. If this fails, then let the exception return to Celery.
# Get the InstructorTask to be updated. If this fails then let the exception return to Celery.
# There's no point in catching it here.
entry = InstructorTask.objects.get(pk=entry_id)
entry.task_state = PROGRESS
entry.save_now()
# get inputs to use in this task from the entry:
# Get inputs to use in this task from the entry
task_id = entry.task_id
course_id = entry.course_id
task_input = json.loads(entry.task_input)
# construct log message:
fmt = u'task "{task_id}": course "{course_id}" input "{task_input}"'
task_info_string = fmt.format(task_id=task_id, course_id=course_id, task_input=task_input)
TASK_LOG.info('Starting update (nothing %s yet): %s', action_name, task_info_string)
# Construct log message
fmt = u'Task: {task_id}, InstructorTask ID: {entry_id}, Course: {course_id}, Input: {task_input}'
task_info_string = fmt.format(task_id=task_id, entry_id=entry_id, course_id=course_id, task_input=task_input)
TASK_LOG.info(u'%s, Starting update (nothing %s yet)', task_info_string, action_name)
# Check that the task_id submitted in the InstructorTask matches the current task
# that is running.
request_task_id = _get_current_task().request.id
if task_id != request_task_id:
fmt = u'Requested task did not match actual task "{actual_id}": {task_info}'
message = fmt.format(actual_id=request_task_id, task_info=task_info_string)
fmt = u'{task_info}, Requested task did not match actual task "{actual_id}"'
message = fmt.format(task_info=task_info_string, actual_id=request_task_id)
TASK_LOG.error(message)
raise ValueError(message)
# Now do the work:
# Now do the work
with dog_stats_api.timer('instructor_tasks.time.overall', tags=[u'action:{name}'.format(name=action_name)]):
task_progress = task_fcn(entry_id, course_id, task_input, action_name)
# Release any queries that the connection has been hanging onto:
# Release any queries that the connection has been hanging onto
reset_queries()
# log and exit, returning task_progress info as task result:
TASK_LOG.info('Finishing %s: final: %s', task_info_string, task_progress)
# Log and exit, returning task_progress info as task result
TASK_LOG.info(u'%s, Task type: %s, Finishing task: %s', task_info_string, action_name, task_progress)
return task_progress
......@@ -567,6 +568,15 @@ def upload_grades_csv(_xmodule_instance_args, _entry_id, course_id, _task_input,
enrolled_students = CourseEnrollment.users_enrolled_in(course_id)
task_progress = TaskProgress(action_name, enrolled_students.count(), start_time)
fmt = u'Task: {task_id}, InstructorTask ID: {entry_id}, Course: {course_id}, Input: {task_input}'
task_info_string = fmt.format(
task_id=_xmodule_instance_args.get('task_id') if _xmodule_instance_args is not None else None,
entry_id=_entry_id,
course_id=course_id,
task_input=_task_input
)
TASK_LOG.info(u'%s, Task type: %s, Starting task execution', task_info_string, action_name)
course = get_course_by_id(course_id)
cohorts_header = ['Cohort Name'] if course.is_cohorted else []
......@@ -578,12 +588,34 @@ def upload_grades_csv(_xmodule_instance_args, _entry_id, course_id, _task_input,
rows = []
err_rows = [["id", "username", "error_msg"]]
current_step = {'step': 'Calculating Grades'}
total_enrolled_students = enrolled_students.count()
student_counter = 0
TASK_LOG.info(
u'%s, Task type: %s, Current step: %s, Starting grade calculation for total students: %s',
task_info_string,
action_name,
current_step,
total_enrolled_students
)
for student, gradeset, err_msg in iterate_grades_for(course_id, enrolled_students):
# Periodically update task status (this is a cache write)
if task_progress.attempted % status_interval == 0:
task_progress.update_task_state(extra_meta=current_step)
task_progress.attempted += 1
# Now add a log entry after certain intervals to get a hint that task is in progress
student_counter += 1
if student_counter % 1000 == 0:
TASK_LOG.info(
u'%s, Task type: %s, Current step: %s, Grade calculation in-progress for students: %s/%s',
task_info_string,
action_name,
current_step,
student_counter,
total_enrolled_students
)
if gradeset:
# We were able to successfully grade this student for this course.
task_progress.succeeded += 1
......@@ -625,9 +657,19 @@ def upload_grades_csv(_xmodule_instance_args, _entry_id, course_id, _task_input,
task_progress.failed += 1
err_rows.append([student.id, student.username, err_msg])
TASK_LOG.info(
u'%s, Task type: %s, Current step: %s, Grade calculation completed for students: %s/%s',
task_info_string,
action_name,
current_step,
student_counter,
total_enrolled_students
)
# By this point, we've got the rows we're going to stuff into our CSV files.
current_step = {'step': 'Uploading CSVs'}
task_progress.update_task_state(extra_meta=current_step)
TASK_LOG.info(u'%s, Task type: %s, Current step: %s', task_info_string, action_name, current_step)
# Perform the actual upload
upload_csv_to_report_store(rows, 'grade_report', course_id, start_date)
......@@ -637,6 +679,7 @@ def upload_grades_csv(_xmodule_instance_args, _entry_id, course_id, _task_input,
upload_csv_to_report_store(err_rows, 'grade_report_err', course_id, start_date)
# One last update before we close out...
TASK_LOG.info(u'%s, Task type: %s, Finalizing grade task', task_info_string, action_name)
return task_progress.update_task_state(extra_meta=current_step)
......
......@@ -554,7 +554,6 @@ FACEBOOK_APP_ID = AUTH_TOKENS.get("FACEBOOK_APP_ID")
XBLOCK_SETTINGS = ENV_TOKENS.get('XBLOCK_SETTINGS', {})
##### CDN EXPERIMENT/MONITORING FLAGS #####
PERFORMANCE_GRAPHITE_URL = ENV_TOKENS.get('PERFORMANCE_GRAPHITE_URL', PERFORMANCE_GRAPHITE_URL)
CDN_VIDEO_URLS = ENV_TOKENS.get('CDN_VIDEO_URLS', CDN_VIDEO_URLS)
##### ECOMMERCE API CONFIGURATION SETTINGS #####
......
......@@ -565,7 +565,7 @@ TRACKING_BACKENDS = {
# We're already logging events, and we don't want to capture user
# names/passwords. Heartbeat events are likely not interesting.
TRACKING_IGNORE_URL_PATTERNS = [r'^/event', r'^/login', r'^/heartbeat', r'^/segmentio/event']
TRACKING_IGNORE_URL_PATTERNS = [r'^/event', r'^/login', r'^/heartbeat', r'^/segmentio/event', r'^/performance']
EVENT_TRACKING_ENABLED = True
EVENT_TRACKING_BACKENDS = {
......@@ -2153,7 +2153,6 @@ SEARCH_ENGINE = None
SEARCH_RESULT_PROCESSOR = "lms.lib.courseware_search.lms_result_processor.LmsSearchResultProcessor"
##### CDN EXPERIMENT/MONITORING FLAGS #####
PERFORMANCE_GRAPHITE_URL = ''
CDN_VIDEO_URLS = {}
# The configuration visibility of account fields.
......
......@@ -154,19 +154,17 @@
</div>
% if cdn_eval:
<script>
function sendMetricToGraphite(metricName, value) {
var url = "${cdn_eval_endpoint}";
var request = new XMLHttpRequest();
request.open("POST", url, true); // send asynchronously
request.send(metricName + " " + value);
};
function sendPerformanceBeacon(id, expgroup, value) {
var data = {event: "canplaythrough", id: id, expgroup: expgroup, value: value, page: "html5vid"};
$.ajax({method: "POST", url: "/performance", data: data});
}
var cdnStartTime, beaconSent = false;
function initializeCDNExperiment() {
cdnStartTime = Date.now();
$("#video_${id}").bind("html5:canplaythrough", null, function() {
if (!beaconSent) {
timeElapsed = Date.now() - cdnStartTime;
sendMetricToGraphite("videocdnexp.${id}.${cdn_exp_group}.loadtime", timeElapsed);
sendPerformanceBeacon("${id}", ${cdn_exp_group}, timeElapsed);
}
beaconSent = true;
});
......
......@@ -32,6 +32,7 @@ urlpatterns = (
url(r'^email_confirm/(?P<key>[^/]*)$', 'student.views.confirm_email_change'),
url(r'^change_name$', 'student.views.change_name_request', name="change_name"),
url(r'^event$', 'track.views.user_track'),
url(r'^performance$', 'performance.views.performance_log'),
url(r'^segmentio/event$', 'track.views.segmentio.segmentio_event'),
url(r'^t/(?P<template>[^/]*)$', 'static_template_view.views.index'), # TODO: Is this used anymore? What is STATIC_GRAB?
......
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