Merge pull request #1371 from edx/gprice/cs-request-logging

Log all comments service requests

lms/djangoapps/django_comment_client/base/tests.py

@@ -12,7 +12,7 @@ from util.testing import UrlResetMixin
 
 from courseware.tests.modulestore_config import TEST_DATA_MIXED_MODULESTORE
 from nose.tools import assert_true, assert_equal  # pylint: disable=E0611
-from mock import patch
+from mock import patch, ANY
 
 log = logging.getLogger(__name__)
 
@@ -97,6 +97,7 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
                 'commentable_id': u'i4x-MITx-999-course-Robot_Super_Course',
                 'anonymous': False, 'course_id': u'MITx/999/Robot_Super_Course',
             },
+            params={'request_id': ANY},
             headers={'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
             timeout=5
         )
@@ -132,7 +133,8 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
             (
                 ('get', 'http://localhost:4567/api/v1/threads/518d4237b023791dca00000d'),
                 {
-                    'params': {'mark_as_read': True},
+                    'data': None,
+                    'params': {'mark_as_read': True, 'request_id': ANY},
                     'headers': {'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
                     'timeout': 5
                 }
@@ -141,6 +143,7 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
                 ('put', 'http://localhost:4567/api/v1/threads/518d4237b023791dca00000d/abuse_flag'),
                 {
                     'data': {'user_id': '1'},
+                    'params': {'request_id': ANY},
                     'headers': {'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
                     'timeout': 5
                 }
@@ -148,7 +151,8 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
             (
                 ('get', 'http://localhost:4567/api/v1/threads/518d4237b023791dca00000d'),
                 {
-                    'params': {'mark_as_read': True},
+                    'data': None,
+                    'params': {'mark_as_read': True, 'request_id': ANY},
                     'headers': {'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
                     'timeout': 5
                 }
@@ -189,7 +193,8 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
             (
                 ('get', 'http://localhost:4567/api/v1/threads/518d4237b023791dca00000d'),
                 {
-                    'params': {'mark_as_read': True},
+                    'data': None,
+                    'params': {'mark_as_read': True, 'request_id': ANY},
                     'headers': {'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
                     'timeout': 5
                 }
@@ -198,6 +203,7 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
                 ('put', 'http://localhost:4567/api/v1/threads/518d4237b023791dca00000d/abuse_unflag'),
                 {
                     'data': {'user_id': '1'},
+                    'params': {'request_id': ANY},
                     'headers': {'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
                     'timeout': 5
                 }
@@ -205,7 +211,8 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
             (
                 ('get', 'http://localhost:4567/api/v1/threads/518d4237b023791dca00000d'),
                 {
-                    'params': {'mark_as_read': True},
+                    'data': None,
+                    'params': {'mark_as_read': True, 'request_id': ANY},
                     'headers': {'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
                     'timeout': 5
                 }
@@ -242,7 +249,8 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
             (
                 ('get', 'http://localhost:4567/api/v1/comments/518d4237b023791dca00000d'),
                 {
-                    'params': {},
+                    'data': None,
+                    'params': {'request_id': ANY},
                     'headers': {'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
                     'timeout': 5
                 }
@@ -251,6 +259,7 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
                 ('put', 'http://localhost:4567/api/v1/comments/518d4237b023791dca00000d/abuse_flag'),
                 {
                     'data': {'user_id': '1'},
+                    'params': {'request_id': ANY},
                     'headers': {'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
                     'timeout': 5
                 }
@@ -258,7 +267,8 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
             (
                 ('get', 'http://localhost:4567/api/v1/comments/518d4237b023791dca00000d'),
                 {
-                    'params': {},
+                    'data': None,
+                    'params': {'request_id': ANY},
                     'headers': {'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
                     'timeout': 5
                 }
@@ -295,7 +305,8 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
             (
                 ('get', 'http://localhost:4567/api/v1/comments/518d4237b023791dca00000d'),
                 {
-                    'params': {},
+                    'data': None,
+                    'params': {'request_id': ANY},
                     'headers': {'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
                     'timeout': 5
                 }
@@ -304,6 +315,7 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
                 ('put', 'http://localhost:4567/api/v1/comments/518d4237b023791dca00000d/abuse_unflag'),
                 {
                     'data': {'user_id': '1'},
+                    'params': {'request_id': ANY},
                     'headers': {'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
                     'timeout': 5
                 }
@@ -311,7 +323,8 @@ class ViewsTestCase(UrlResetMixin, ModuleStoreTestCase):
             (
                 ('get', 'http://localhost:4567/api/v1/comments/518d4237b023791dca00000d'),
                 {
-                    'params': {},
+                    'data': None,
+                    'params': {'request_id': ANY},
                     'headers': {'X-Edx-Api-Key': 'PUT_YOUR_API_KEY_HERE'},
                     'timeout': 5
                 }

lms/lib/comment_client/utils.py

+from contextlib import contextmanager
 from dogapi import dog_stats_api
 import json
 import logging
 import requests
 import settings
+from time import time
+from uuid import uuid4
 
 log = logging.getLogger(__name__)
 
@@ -28,16 +31,46 @@ def merge_dict(dic1, dic2):
     return dict(dic1.items() + dic2.items())
 
 
+@contextmanager
+def request_timer(request_id, method, url):
+    start = time()
+    yield
+    end = time()
+    duration = end - start
+    dog_stats_api.histogram('comment_client.request.time', duration, end)
+    log.info(
+        "comment_client_request_log: request_id={request_id}, method={method}, "
+        "url={url}, duration={duration}".format(
+            request_id=request_id,
+            method=method,
+            url=url,
+            duration=duration
+        )
+    )
+
+
 def perform_request(method, url, data_or_params=None, *args, **kwargs):
     if data_or_params is None:
         data_or_params = {}
     headers = {'X-Edx-Api-Key': settings.API_KEY}
+    request_id = uuid4()
+    request_id_dict = {'request_id': request_id}
     try:
-        with dog_stats_api.timer('comment_client.request.time'):
-            if method in ['post', 'put', 'patch']:
-                response = requests.request(method, url, data=data_or_params, headers=headers, timeout=5)
-            else:
-                response = requests.request(method, url, params=data_or_params, headers=headers, timeout=5)
+        if method in ['post', 'put', 'patch']:
+            data = data_or_params
+            params = request_id_dict
+        else:
+            data = None
+            params = merge_dict(data_or_params, request_id_dict)
+        with request_timer(request_id, method, url):
+            response = requests.request(
+                method,
+                url,
+                data=data,
+                params=params,
+                headers=headers,
+                timeout=5
+            )
     except Exception as err:
         log.exception("Trying to call {method} on {url} with params {params}".format(
             method=method, url=url, params=data_or_params))