Created performance logging endpoint, changed CDN experiment to point to it.

common/djangoapps/performance/tests/test_logs.py

+"""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)

common/djangoapps/performance/views/__init__.py

+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)

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

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',

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 #####

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.

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;
     });

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?