Merge lp:~james-w/canonical-identity-provider/api-client-timeline into lp:canonical-identity-provider/release

[James Westby]

Record an action in the timeline when using ssoclient.

If a request uses ssoclient to hit the sso api, this will record
an action in the timeline so that we can see it in oopses.

Hi,

We are seeing +new_account view take a long time sometimes. One of the things
it does is use ssoclient to hit the sso api. That may be taking some time,
so record timeline actions for it so we can see it in any oopses.

Thanks,

James

[Ricardo Kirkner (ricardokirkner)]

LGTM

review: Approve

[Ubuntu One Auto Pilot (otto-pilot)]

The attempt to merge lp:~james-w/canonical-identity-provider/api-client-timeline into lp:canonical-identity-provider failed. Below is the output from the failed tests.

Updating download cache at dir /mnt/tarmac/cache/canonical-identity-provider/isd-download-cache
Using saved parent location: bzr+ssh://bazaar.launchpad.net/~canonical-isd-hackers/+junk/download-cache/
No revisions or tags to pull.
[localhost] local: which virtualenv
[localhost] local: /usr/bin/python /usr/bin/virtualenv --distribute --clear --system-site-packages .env
Not deleting .env/bin
New python executable in .env/bin/python
Installing distribute.............................................................................................................................................................................................done.
Installing pip...............done.
[localhost] local: dpkg -l libpq-dev 2> /dev/null | grep '^ii' | wc -l
[localhost] local: dpkg -l libxml2-dev 2> /dev/null | grep '^ii' | wc -l
[localhost] local: dpkg -l libxslt1-dev 2> /dev/null | grep '^ii' | wc -l
[localhost] local: dpkg -l memcached 2> /dev/null | grep '^ii' | wc -l
[localhost] local: dpkg -l postgresql-plpython-9.1 2> /dev/null | grep '^ii' | wc -l
[localhost] local: dpkg -l python-dev 2> /dev/null | grep '^ii' | wc -l
[localhost] local: dpkg -l python-m2crypto 2> /dev/null | grep '^ii' | wc -l
[localhost] local: dpkg -l swig 2> /dev/null | grep '^ii' | wc -l
[localhost] local: dpkg -l config-manager 2> /dev/null | grep '^ii' | wc -l
[localhost] local: dpkg -l python-egenix-mx-base-dev 2> /dev/null | grep '^ii' | wc -l
[localhost] local: /usr/lib/config-manager/cm.py update /tmp/tmpeR8fJY
[localhost] local: . /mnt/tarmac/cache/canonical-identity-provider/merges/trunk/.env/bin/activate && make install PACKAGES="-r /mnt/tarmac/cache/canonical-identity-provider/merges/trunk/requirements.txt"
pip install --find-links=file:///mnt/tarmac/cache/canonical-identity-provider/isd-download-cache --no-index pip==dev
Ignoring indexes: http://pypi.python.org/simple/
Downloading/unpacking pip==dev
  Running setup.py egg_info for package pip

    warning: no files found matching '*.html' under directory 'docs'
    warning: no previously-included files matching '*.txt' found under directory 'docs/_build'
    no previously-included directories found matching 'docs/_build/_sources'
Installing collected packages: pip
  Found existing installation: pip 1.1
    Uninstalling pip:
      Successfully uninstalled pip
  Running setup.py install for pip

    warning: no files found matching '*.html' under directory 'docs'
    warning: no previously-included files matching '*.txt' found under directory 'docs/_build'
    no previously-included directories found matching 'docs/_build/_sources'
    Installing pip script to /mnt/tarmac/cache/canonical-identity-provider/merges/trunk/.env/bin
    Installing pip-2.7 script to /mnt/tarmac/cache/canonical-identity-provider/merges/trunk/.env/bin
Successfully installed pip
Cleaning up...
pip install --find-links=. --no-index -r /mnt/tarmac/cache/canonical-identity-provider/merges/trunk/requirements.txt
Ignoring indexes: http://pypi.python.org/simple/
Downloading/un...

=== modified file 'src/identityprovider/apiutils.py'
--- src/identityprovider/apiutils.py	2013-02-13 21:54:09 +0000
+++ src/identityprovider/apiutils.py	2013-09-04 14:56:55 +0000
@@ -13,11 +13,39 @@
 from requests.utils import get_encoding_from_headers
 
 from ssoclient.v2 import V2ApiClient
+from ssoclient.v2.http import ApiSession
+
+from identityprovider.timeline import (
+    maybe_contextmanager,
+    get_request_timing_function,
+)
+
+
+class TimelineRecordingApiSession(ApiSession):
+
+    def __init__(self, endpoint, timer=None):
+        super(TimelineRecordingApiSession, self).__init__(endpoint)
+        self.timer = timer
+
+    def request(self, method, url, **kwargs):
+        category = 'ssoclient-{}'.format(method)
+        with maybe_contextmanager(self.timer, category, url,
+                                  allow_nested=True):
+            return super(TimelineRecordingApiSession, self).request(
+                method, url, **kwargs)
+
+
+class TimelineRecordingApiClient(V2ApiClient):
+
+    def __init__(self, endpoint, timer=None):
+        self.session = TimelineRecordingApiSession(endpoint, timer=timer)
 
 
 def get_api_client(request):
     # TODO: configure caching, auth
-    api = V2ApiClient(settings.API_HOST + settings.API_URL)
+    timer = get_request_timing_function(request)
+    api = TimelineRecordingApiClient(settings.API_HOST + settings.API_URL,
+                                     timer=timer)
     if (settings.API_USE_INTERNAL
             or request.META['SERVER_NAME'] == "testserver"):
         api.session.mount('http://', DjangoWSGIAdapter(request))

=== modified file 'src/identityprovider/tests/test_apiutils.py'
--- src/identityprovider/tests/test_apiutils.py	2013-05-16 16:39:41 +0000
+++ src/identityprovider/tests/test_apiutils.py	2013-09-04 14:56:55 +0000
@@ -1,10 +1,13 @@
 import json
+from contextlib import contextmanager
 
 import requests
 from django.conf.urls import patterns, url
 from django.http import HttpResponse
 from django.test.client import RequestFactory
 from django.views.decorators.csrf import csrf_exempt
+from mock import patch
+from timeline import Timeline
 
 from identityprovider.tests.utils import (
     SSOBaseTestCase,
@@ -15,6 +18,8 @@
 from identityprovider.apiutils import (
     get_api_client,
     DjangoWSGIAdapter,
+    TimelineRecordingApiClient,
+    TimelineRecordingApiSession,
 )
 
 
@@ -40,6 +45,56 @@
         api = get_api_client(request)
         self.assert_django_adapters(api, request)
 
+    def test_returns_timeline_recording_client(self):
+        request = RequestFactory().post('/')
+        api = get_api_client(request)
+        self.assertIsInstance(api, TimelineRecordingApiClient)
+
+    @patch('requests.Session.request')
+    def test_makes_timer_function_from_request(self, mock_request):
+        timeline = Timeline()
+        request = RequestFactory().post(
+            '/', **{'timeline.timeline': timeline})
+        api = get_api_client(request)
+        api.session.post('/accounts')
+        # 2 because we use allow_nested, as the request may be routed
+        # internally if API_USE_INTERNAL is set.
+        self.assertEqual(2, len(timeline.actions))
+        self.assertEqual('ssoclient-POST-start', timeline.actions[0].category)
+        self.assertEqual('/accounts', timeline.actions[0].detail)
+
+
+class TimelineRecordingApiClientTests(SSOBaseUnittestTestCase):
+
+    def test_session_is_timeline_recording(self):
+        api = TimelineRecordingApiClient('localhost')
+        self.assertIsInstance(api.session, TimelineRecordingApiSession)
+
+    def test_passes_timer_to_session(self):
+        timer = object()
+        api = TimelineRecordingApiClient('localhost', timer=timer)
+        self.assertEqual(timer, api.session.timer)
+
+
+class TimelineRecordingApiSessionTests(SSOBaseUnittestTestCase):
+
+    @patch('requests.Session.request')
+    def test_uses_timer(self, mock_request):
+        expected_response = object()
+        mock_request.return_value = expected_response
+        called_args = []
+
+        @contextmanager
+        def timer_fn(category, detail, allow_nested=False):
+            called_args.append((category, detail, allow_nested))
+            yield
+        endpoint = 'http://localhost/'
+        session = TimelineRecordingApiSession(endpoint, timer=timer_fn)
+        path = 'test'
+        response = session.request('GET', path)
+        self.assertEqual(expected_response, response)
+        self.assertEqual([('ssoclient-GET', path, True)], called_args)
+
 
 @csrf_exempt
 def testview(request):

=== modified file 'src/identityprovider/tests/test_timeline.py'
--- src/identityprovider/tests/test_timeline.py	2013-08-26 12:49:37 +0000
+++ src/identityprovider/tests/test_timeline.py	2013-09-04 14:56:55 +0000
@@ -41,6 +41,18 @@
         self.assertEqual(1, len(timeline.actions))
         self.assertEqual('category', timeline.actions[0].category)
         self.assertEqual('detail', timeline.actions[0].detail)
+        self.assertNotEqual(None, timeline.actions[0].duration)
+
+    def test_finishes_action_even_with_exception(self):
+        timeline = Timeline()
+        timer_fn = get_timing_function(timeline)
+
+        def do_test():
+            with timer_fn('category', 'detail'):
+                1/0
+        self.assertRaises(ZeroDivisionError, do_test)
+        self.assertEqual(1, len(timeline.actions))
+        self.assertNotEqual(None, timeline.actions[0].duration)
 
 
 class MaybeContextManagerTests(TestCase):

=== modified file 'src/identityprovider/timeline.py'
--- src/identityprovider/timeline.py	2013-08-24 01:12:57 +0000
+++ src/identityprovider/timeline.py	2013-09-04 14:56:55 +0000
@@ -14,7 +14,7 @@
 
     Given
 
-      timer_fn = get_timing_function(timeline, detail_fn)
+      timer_fn = get_timing_function(timeline)
 
       def request(method, url):
           with timer_fn('http-{}'.format(method), url):
@@ -36,13 +36,16 @@
         between __enter__ and __exit__.
     """
     @contextmanager
-    def timer_fn(category, detail):
+    def timer_fn(category, detail, allow_nested=False):
         if not timeline:
             yield
         else:
-            action = timeline.start(category, detail)
-            yield
-            action.finish()
+            action = timeline.start(category, detail,
+                                    allow_nested=allow_nested)
+            try:
+                yield
+            finally:
+                action.finish()
     return timer_fn