diff --git a/common/djangoapps/performance/__init__.py b/common/djangoapps/performance/__init__.py new file mode 100644 index 0000000000000000000000000000000000000000..e69de29bb2d1d6434b8b29ae775ad8c2e48c5391 diff --git a/common/djangoapps/performance/tests/__init__.py b/common/djangoapps/performance/tests/__init__.py new file mode 100644 index 0000000000000000000000000000000000000000..e69de29bb2d1d6434b8b29ae775ad8c2e48c5391 diff --git a/common/djangoapps/performance/tests/test_logs.py b/common/djangoapps/performance/tests/test_logs.py new file mode 100644 index 0000000000000000000000000000000000000000..04c795e724488865f8db05d5091cc09980581e3e --- /dev/null +++ b/common/djangoapps/performance/tests/test_logs.py @@ -0,0 +1,133 @@ +"""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) diff --git a/common/djangoapps/performance/views/__init__.py b/common/djangoapps/performance/views/__init__.py new file mode 100644 index 0000000000000000000000000000000000000000..805e2d96cbd80d94bb8b65286faa4835e4604189 --- /dev/null +++ b/common/djangoapps/performance/views/__init__.py @@ -0,0 +1,52 @@ +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) diff --git a/common/lib/xmodule/xmodule/video_module/video_module.py b/common/lib/xmodule/xmodule/video_module/video_module.py index 46272814a696c043c7bbac2f3ecd664a9ebb3a7f..85aee1fc659ae5b435c58499a0f7469e891b8eae 100644 --- a/common/lib/xmodule/xmodule/video_module/video_module.py +++ b/common/lib/xmodule/xmodule/video_module/video_module.py @@ -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 diff --git a/lms/djangoapps/courseware/tests/test_video_mongo.py b/lms/djangoapps/courseware/tests/test_video_mongo.py index d1a59ef78ab3349d7aaf02428ba1e3532922377b..8734ef24e22b18cbed29ed52d9f190a7c19d8f77 100644 --- a/lms/djangoapps/courseware/tests/test_video_mongo.py +++ b/lms/djangoapps/courseware/tests/test_video_mongo.py @@ -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', diff --git a/lms/envs/aws.py b/lms/envs/aws.py index b0a2580ea097d9bb50983ce90a1b8be8e4efbaa4..38bb7b7e7cc853f71d0379c0b02ffb56552ffa9c 100644 --- a/lms/envs/aws.py +++ b/lms/envs/aws.py @@ -556,7 +556,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 ##### diff --git a/lms/envs/common.py b/lms/envs/common.py index 14d998b0606e11de48a3d7d39a80b68b51eca1c5..80b97bff69a3c042fc68f9b68a3259718a541781 100644 --- a/lms/envs/common.py +++ b/lms/envs/common.py @@ -558,7 +558,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 = { @@ -2075,7 +2075,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. diff --git a/lms/templates/video.html b/lms/templates/video.html index 1ad97ee6f08562c2197a8bccf5fc53cd0d3fb3ce..64534e4aa6ee696fb8bc38d9a5671ab5cc72bf4e 100644 --- a/lms/templates/video.html +++ b/lms/templates/video.html @@ -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; }); diff --git a/lms/urls.py b/lms/urls.py index 844e0d249dd5489b9807ca4efb5daef0189115ce..09da3933454aa4df9eed32cf2ac1f73f86099a23 100644 --- a/lms/urls.py +++ b/lms/urls.py @@ -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?