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

[James Westby]

Add entries to the request timeline when creating or verifying a captcha.

These http requests made during a request can take time, so record them
in the timeline. That way if there is a slow request involving one you
can see how long it took.

Hi,

This makes it so that timing information about recaptcha requests
will show up in oopses. The v1 api that makes these requests sometimes
times out, and the oops has no information about what is happening during
the 10s. This will make it such that you will see how long the request
to recaptcha took.

I didn't instrument the captcha verification in the v1 api as it wasn't
easy, and it is deprecated. If we see slowness in those requests we
can revisit that.

Thanks,

James

[Ricardo Kirkner (ricardokirkner)]

LGTM, but if you allow for nitpicking... we have certain conventions for import grouping and ordering; this is

1. group imports by origin (stdlib, 3rd party, app)
2. within each group, subgroup by 'import ... ' then 'from ... import ...'
3. within each subgroup, order asciibetically

l. 109 should go before l. 107
l. 298-299: according to the convention, l. 298 should come after the 'import ..' statements, and l.299 shoudl go into a different group
l. 347-348: these should go into a second group
l. 501: this should go after the 'import ..' lines

review: Approve

[Ubuntu One Auto Pilot (otto-pilot)]

There are additional revisions which have not been approved in review. Please seek review and approval of these new revisions.

=== modified file 'src/api/v10/handlers.py'
--- src/api/v10/handlers.py	2013-08-16 15:16:58 +0000
+++ src/api/v10/handlers.py	2013-08-26 13:12:23 +0000
@@ -38,6 +38,9 @@
     application_token_created,
     application_token_invalidated,
 )
+from identityprovider.timeline import (
+    get_request_timing_function,
+)
 
 from oauth_backend.models import Token
 
@@ -163,12 +166,13 @@
 
     @named_operation
     def new(self, request):
+        timer = get_request_timing_function(request)
         try:
-            return Captcha.new().serialize()
+            return Captcha.new(timer=timer).serialize()
         except NewCaptchaError as e:
             logger.exception("Failed to connect to reCaptcha server")
             # TODO: Some better return here?
-            return e.dummy
+            return e.dummy.serialize()
 
 
 class RegistrationHandler(LazrRestfulHandler):

=== modified file 'src/api/v10/tests/test_handlers.py'
--- src/api/v10/tests/test_handlers.py	2013-08-20 17:47:58 +0000
+++ src/api/v10/tests/test_handlers.py	2013-08-26 13:12:23 +0000
@@ -6,10 +6,14 @@
 from django.utils.http import urlencode
 from django.core.urlresolvers import reverse
 
-from mock import patch
+from mock import (
+    Mock,
+    patch,
+)
 from lazr.restfulclient.errors import HTTPError
 
 from gargoyle import gargoyle
+from timeline import Timeline
 
 from identityprovider.tests.utils import SSOBaseTestCase
 from identityprovider.models import (
@@ -17,6 +21,9 @@
     APIUser,
     EmailAddress,
 )
+from identityprovider.models.captcha import (
+    Captcha,
+)
 from identityprovider.models.const import (
     AccountStatus,
     EmailStatus,
@@ -29,7 +36,10 @@
 from identityprovider.tests.utils import authorization_header_from_token
 from identityprovider.validators import PASSWORD_POLICY_ERROR
 
-from api.v10.handlers import AuthenticationHandler
+from api.v10.handlers import (
+    AuthenticationHandler,
+    CaptchaHandler,
+)
 from api.v10.tests.utils import (
     AnonAPITestCase,
     MockRequest,
@@ -548,3 +558,26 @@
         self.assertContains(response, email.email)
         updatedemail = EmailAddress.objects.get(email=email.email)
         self.assertEqual(EmailStatus.VALIDATED, updatedemail.status)
+
+
+class CaptchasTestCase(SSOBaseTestCase):
+
+    url = reverse('api-10-captchas')
+
+    @patch.object(Captcha, '_open')
+    def test_returns_dummy(self, mock_open):
+        resp = self.client.post(self.url, {'ws.op': 'new'},
+                                HTTP_ACCEPT='application/json')
+        self.assertEqual(None, json.loads(resp.content)['image_url'])
+
+    @patch.object(Captcha, '_open')
+    def test_puts_entry_in_timeline(self, mock_open):
+        handler = CaptchaHandler()
+        request = Mock()
+        timeline = Timeline()
+        request.META = {'timeline.timeline': timeline}
+        handler.new(request)
+        self.assertEqual(1, len(timeline.actions))
+        self.assertEqual('captcha-new', timeline.actions[0].category)
+        self.assertEqual(mock_open.call_args[0][0],
+                         timeline.actions[0].detail)

=== modified file 'src/api/v20/handlers.py'
--- src/api/v20/handlers.py	2013-08-20 17:47:58 +0000
+++ src/api/v20/handlers.py	2013-08-26 13:12:23 +0000
@@ -43,8 +43,9 @@
     AccountStatus,
     TokenType,
 )
+from identityprovider.store import SSODataStore
+from identityprovider.timeline import get_request_timing_function
 from identityprovider.utils import redirection_url_for_token
-from identityprovider.store import SSODataStore
 from webui.decorators import limitlogin
 
 
@@ -164,8 +165,9 @@
                 gargoyle.is_active('CAPTCHA')):
             extra = {}
             if data.get('create_captcha', True):
+                timer = get_request_timing_function(request)
                 try:
-                    extra = Captcha.new().serialize()
+                    extra = Captcha.new(timer=timer).serialize()
                 except Exception:
                     logger.exception('failed to create reCaptcha')
             return errors.CAPTCHA_REQUIRED(**extra)
@@ -175,8 +177,10 @@
             captcha = Captcha(captcha_id)
             verified = False
             try:
+                timer = get_request_timing_function(request)
                 verified = captcha.verify(
-                    captcha_solution, remote_addr, data['email'])
+                    captcha_solution, remote_addr, data['email'],
+                    timer=timer)
             except VerifyCaptchaError as e:
                 # only expose HTTP error codes to client
                 code = e.response.code if e.response.code > 200 else None

=== modified file 'src/api/v20/tests/test_handlers.py'
--- src/api/v20/tests/test_handlers.py	2013-08-20 18:02:58 +0000
+++ src/api/v20/tests/test_handlers.py	2013-08-26 13:12:23 +0000
@@ -1,20 +1,22 @@
 import json
-
+from StringIO import StringIO
 from urllib import urlencode
 
 from django.core import mail
 from django.core.serializers.json import DjangoJSONEncoder
 from django.core.urlresolvers import NoReverseMatch, reverse
 from gargoyle.testutils import switches
-from mock import ANY, patch
+from mock import ANY, Mock, patch
 from oauth_backend.models import Token
 from oauth.oauth import OAuthRequest
+from timeline import Timeline
 
 from identityprovider.models import (
     Account,
     AuthToken,
     EmailAddress,
 )
+from identityprovider.models.captcha import Captcha, CaptchaResponse
 from identityprovider.models.const import (
     AccountStatus,
     EmailStatus,
@@ -812,3 +814,43 @@
             url=url, token=self.token, method='DELETE')
 
         self.assertEqual(response.status_code, 404)
+
+
+class AccountRegistrationHandlerTests(BaseTestCase):
+
+    @patch.object(Captcha, '_open')
+    @switches(CAPTCHA=True)
+    def test_timeline_for_captcha_generation(self, mock_open):
+        handler = handlers.AccountRegistrationHandler()
+        request = Mock()
+        timeline = Timeline()
+        request.META = {
+            'timeline.timeline': timeline,
+            'CONTENT_TYPE': 'application/json',
+        }
+        request.data = dict(create_captcha=True)
+        handler.create(request)
+        self.assertEqual(1, len(timeline.actions))
+        self.assertEqual('captcha-new', timeline.actions[0].category)
+        self.assertEqual(mock_open.call_args[0][0],
+                         timeline.actions[0].detail)
+
+    @patch.object(Captcha, '_open')
+    @switches(CAPTCHA=True)
+    def test_timeline_for_captcha_verification(self, mock_open):
+        mock_open.response = CaptchaResponse(500, StringIO(''))
+        handler = handlers.AccountRegistrationHandler()
+        request = Mock()
+        timeline = Timeline()
+        request.META = {
+            'timeline.timeline': timeline,
+            'CONTENT_TYPE': 'application/json',
+        }
+        request.environ = {'REMOTE_ADDR': '127.0.0.1'}
+        request.data = dict(captcha_id='captcha-id',
+                            captcha_solution='captcha_solution',
+                            email='[e-mail]')
+        with patch_settings(DISABLE_CAPTCHA_VERIFICATION=False):
+            handler.create(request)
+        self.assertEqual(1, len(timeline.actions))
+        self.assertEqual('captcha-verify', timeline.actions[0].category)

=== modified file 'src/api/v20/tests/test_registration.py'
--- src/api/v20/tests/test_registration.py	2013-08-08 20:17:55 +0000
+++ src/api/v20/tests/test_registration.py	2013-08-26 13:12:23 +0000
@@ -1,4 +1,5 @@
 from mock import (
+    ANY,
     patch,
     call as mock_call,
 )
@@ -177,7 +178,7 @@
 
         self.assertEqual(response.status_code, 201)
         expected_calls = mock_call('999').verify(
-            'foo bar', '127.0.0.1', self.data['email']).call_list()
+            'foo bar', '127.0.0.1', self.data['email'], timer=ANY).call_list()
         self.assertEqual(mock_captcha.mock_calls, expected_calls)
 
         self.assertIn('openid', json_body)
@@ -197,7 +198,7 @@
         response, json_body = call(self.handler.create, self.url, self.data)
         self.assertEqual(response.status_code, 403)
         expected_calls = mock_call('999').verify(
-            'foo bar', '127.0.0.1', self.data['email']).call_list()
+            'foo bar', '127.0.0.1', self.data['email'], timer=ANY).call_list()
         self.assertEqual(mock_captcha.mock_calls, expected_calls)
 
         self.assertEqual(json_body['code'], "CAPTCHA_FAILURE")

=== modified file 'src/identityprovider/models/captcha.py'
--- src/identityprovider/models/captcha.py	2013-05-21 13:57:39 +0000
+++ src/identityprovider/models/captcha.py	2013-08-26 13:12:23 +0000
@@ -9,6 +9,8 @@
 
 from django.conf import settings
 
+from identityprovider.timeline import maybe_contextmanager
+
 
 class CaptchaError(Exception):
     """All instances of CaptchaError have a traceback member."""
@@ -122,15 +124,16 @@
         }
 
     @classmethod
-    def new(cls):
+    def new(cls, timer=None):
         cls._setup_opener()
         url = (settings.CAPTCHA_API_URL +
                '/challenge?k=%s' % settings.CAPTCHA_PUBLIC_KEY)
-        response = cls._open(url)
-        if response.is_error:
-            raise NewCaptchaError(response.traceback, cls(None, None))
+        with maybe_contextmanager(timer, 'captcha-new', url):
+            response = cls._open(url)
+            if response.is_error:
+                raise NewCaptchaError(response.traceback, cls(None, None))
 
-        data = response.data()
+            data = response.data()
         m = re.search(r"challenge\s*:\s*'(.+?)'", data, re.M | re.S)
         if m:
             captcha_id = m.group(1)
@@ -173,7 +176,7 @@
 
         return CaptchaResponse(response.code, response, None)
 
-    def verify(self, captcha_solution, remote_ip, email):
+    def verify(self, captcha_solution, remote_ip, email, timer=None):
         if self._verified is not None:
             return self._verified
 
@@ -194,7 +197,9 @@
             'response': captcha_solution,
         })
         request = urllib2.Request(settings.CAPTCHA_VERIFY_URL, request_data)
-        self.response = self._open(request)
+        with maybe_contextmanager(timer, 'captcha-verify',
+                                  settings.CAPTCHA_VERIFY_URL):
+            self.response = self._open(request)
 
         if not self.response.is_error:
             response_data = self.response.data()

=== modified file 'src/identityprovider/tests/test_models_captcha.py'
--- src/identityprovider/tests/test_models_captcha.py	2013-03-01 20:26:19 +0000
+++ src/identityprovider/tests/test_models_captcha.py	2013-08-26 13:12:23 +0000
@@ -3,21 +3,21 @@
 
 import unittest
 import urllib2
+from contextlib import contextmanager
+from cStringIO import StringIO
 
+from django.conf import settings
 from mock import (
     Mock,
     patch,
 )
 
-from cStringIO import StringIO
-
 from identityprovider.models.captcha import (
     Captcha,
     CaptchaResponse,
     NewCaptchaError,
     VerifyCaptchaError,
 )
-
 from identityprovider.tests.utils import patch_settings
 
 
@@ -66,6 +66,20 @@
 
         self.assertRaises(urllib2.URLError, Captcha.new)
 
+    @patch.object(Captcha, '_open')
+    def test_new_captcha_uses_timer(self, mock_open):
+        passed_info = []
+
+        @contextmanager
+        def timer_fn(category, detail):
+            passed_info.append((category, detail))
+            yield
+        mock_open.return_value = CaptchaResponse(200, StringIO(''))
+        Captcha.new(timer=timer_fn)
+        self.assertEqual(1, len(passed_info))
+        self.assertEqual('captcha-new', passed_info[0][0])
+        self.assertEqual(mock_open.call_args[0][0], passed_info[0][1])
+
 
 class CaptchaVerifyTestCase(unittest.TestCase):
 
@@ -157,3 +171,16 @@
         self.assertRaises(
             VerifyCaptchaError, c.verify, None, 'localhost', ''
         )
+
+    @patch.object(Captcha, '_open')
+    def test_verify_uses_timer(self, mock_open):
+        passed_info = []
+
+        @contextmanager
+        def timer_fn(category, detail):
+            passed_info.append((category, detail))
+            yield
+        c = Captcha(None)
+        c.verify(None, 'localhost', '', timer=timer_fn)
+        self.assertEqual('captcha-verify', passed_info[0][0])
+        self.assertEqual(settings.CAPTCHA_VERIFY_URL, passed_info[0][1])

=== added file 'src/identityprovider/tests/test_timeline.py'
--- src/identityprovider/tests/test_timeline.py	1970-01-01 00:00:00 +0000
+++ src/identityprovider/tests/test_timeline.py	2013-08-26 13:12:23 +0000
@@ -0,0 +1,72 @@
+from contextlib import contextmanager
+from unittest import TestCase
+
+from mock import Mock
+from timeline import Timeline
+
+from identityprovider.timeline import (
+    get_request_timeline,
+    get_timing_function,
+    maybe_contextmanager,
+)
+
+
+class GetRequestTimelineTests(TestCase):
+
+    def test_no_timeline(self):
+        request = Mock()
+        request.META = dict()
+        self.assertEqual(None, get_request_timeline(request))
+
+    def test_timeline(self):
+        request = Mock()
+        timeline = object()
+        request.META = {'timeline.timeline': timeline}
+        self.assertEqual(timeline, get_request_timeline(request))
+
+
+class GetTimingFunctionTests(TestCase):
+
+    def test_no_timeline(self):
+        timer_fn = get_timing_function(None)
+        with timer_fn('category', 'detail'):
+            # No crash
+            pass
+
+    def test_timeline(self):
+        timeline = Timeline()
+        timer_fn = get_timing_function(timeline)
+        with timer_fn('category', 'detail'):
+            pass
+        self.assertEqual(1, len(timeline.actions))
+        self.assertEqual('category', timeline.actions[0].category)
+        self.assertEqual('detail', timeline.actions[0].detail)
+
+
+class MaybeContextManagerTests(TestCase):
+
+    def test_None(self):
+        with maybe_contextmanager(None, 'a'):
+            # no crash
+            pass
+
+    def test_passes_args(self):
+        passed_args = []
+        passed_kwargs = []
+
+        @contextmanager
+        def cm(*args, **kwargs):
+            passed_args.append(args)
+            passed_kwargs.append(kwargs)
+            yield
+        with maybe_contextmanager(cm, 'a', b='c'):
+            pass
+        self.assertEqual([('a',)], passed_args)
+        self.assertEqual([dict(b='c')], passed_kwargs)
+
+    def test_yields_value(self):
+        @contextmanager
+        def cm(*args, **kwargs):
+            yield 'the value'
+        with maybe_contextmanager(cm) as the_value:
+            self.assertEqual('the value', the_value)

=== added file 'src/identityprovider/timeline.py'
--- src/identityprovider/timeline.py	1970-01-01 00:00:00 +0000
+++ src/identityprovider/timeline.py	2013-08-26 13:12:23 +0000
@@ -0,0 +1,71 @@
+from contextlib import contextmanager
+
+
+def get_request_timeline(request):
+    """Get the timeline for a request, if any.
+
+    :return: a Timeline instance if the request has one, or None if not.
+    """
+    return request.META.get('timeline.timeline', None)
+
+
+def get_timing_function(timeline):
+    """Get a context manager that will put timing info in to a timeline.
+
+    Given
+
+      timer_fn = get_timing_function(timeline, detail_fn)
+
+      def request(method, url):
+          with timer_fn('http-{}'.format(method), url):
+              <..make request..>
+
+    calling request('GET', 'http://google.com/') will lead to an action
+    being inserted in to the timeline with
+
+       start: time at which "with timer_fn(..." was exectuted.
+       duration: duration until the with block was left, i.e. duration of
+            the request.
+       category: 'http-GET'
+       detail: 'http://google.com/'
+
+    :param timeline: the Timeline instance in which to create the action,
+        or None to take no timing information.
+    :return: a context manager that can be called with info about the
+        operation, and will record an action on the timeline for the duration
+        between __enter__ and __exit__.
+    """
+    @contextmanager
+    def timer_fn(category, detail):
+        if not timeline:
+            yield
+        else:
+            action = timeline.start(category, detail)
+            yield
+            action.finish()
+    return timer_fn
+
+
+def get_request_timing_function(request):
+    return get_timing_function(get_request_timeline(request))
+
+
+@contextmanager
+def maybe_contextmanager(cm, *args, **kwargs):
+    """Allow an optional context manager to be used.
+
+    When you take an optional context manager as an argument, it can be
+    tricky to use it, as you can't do "with None:".
+
+    This function allows for you to call
+
+        with maybe_contextmanager(cm, args, ...):
+            pass
+
+    and it will work whether cm is a contextmanager or None.
+    """
+    if cm is None:
+        yield
+    else:
+        with cm(*args, **kwargs) as info:
+            yield info

=== modified file 'src/webui/tests/test_views_ui.py'
--- src/webui/tests/test_views_ui.py	2013-08-12 14:33:47 +0000
+++ src/webui/tests/test_views_ui.py	2013-08-26 13:12:23 +0000
@@ -6,24 +6,22 @@
 import re
 import urllib
 import urllib2
-
 from functools import partial
+from StringIO import StringIO
+from unittest import skipUnless
 from urlparse import urlsplit
 
-from mock import patch, Mock
-from pyquery import PyQuery
-from unittest import skipUnless
-
 from django.conf import settings
 from django.contrib.sessions.models import Session
 from django.core import mail
 from django.core.urlresolvers import reverse
 from django.http import QueryDict, HttpResponse
-
+from gargoyle import gargoyle
 from gargoyle.testutils import switches
-from gargoyle import gargoyle
-
+from mock import patch, Mock
 from openid.message import IDENTIFIER_SELECT
+from pyquery import PyQuery
+from timeline import Timeline
 from u1testutils.logging import LogHandlerTestCase
 
 from identityprovider import signed
@@ -41,7 +39,7 @@
     twofactor,
 )
 from identityprovider.models.authtoken import create_token
-from identityprovider.models.captcha import Captcha
+from identityprovider.models.captcha import Captcha, CaptchaResponse
 from identityprovider.models.const import AccountStatus, EmailStatus, TokenType
 from identityprovider.readonly import ReadOnlyManager
 from identityprovider.tests import DEFAULT_USER_PASSWORD
@@ -52,7 +50,6 @@
 )
 from identityprovider.utils import validate_launchpad_password
 from identityprovider.views import server
-
 from webui import decorators
 from webui.views import ui
 
@@ -138,6 +135,22 @@
         return r
 
 
+class VerifyCaptureResponseTests(SSOBaseTestCase):
+
+    @patch.object(Captcha, '_open')
+    def test_uses_timeline_from_request(self, mock_open):
+        mock_open.return_value = CaptchaResponse(200, StringIO('true\na'))
+        request = Mock()
+        timeline = Timeline()
+        request.META = {'timeline.timeline': timeline}
+        request.POST = {'recaptcha_challenge_field': 'captcha-id'}
+        request.environ = {'REMOTE_ADDR': '127.0.0.1'}
+        with patch.multiple(settings, DISABLE_CAPTCHA_VERIFICATION=False):
+            ui._verify_captcha_response(None, request, None)
+        self.assertEqual(1, len(timeline.actions))
+        self.assertEqual('captcha-verify', timeline.actions[0].category)
+
+
 class SpanishUIViewsTestCase(BaseTestCase):
 
     def setUp(self):

=== modified file 'src/webui/views/ui.py'
--- src/webui/views/ui.py	2013-08-21 15:13:22 +0000
+++ src/webui/views/ui.py	2013-08-26 13:12:23 +0000
@@ -74,6 +74,7 @@
     redirection_url_for_token,
 )
 from identityprovider.stats import stats
+from identityprovider.timeline import get_request_timing_function
 from identityprovider.views.utils import (
     get_rpconfig,
     get_rpconfig_from_request,
@@ -679,7 +680,9 @@
     email = request.POST.get('email', '')
     ip_addr = request.environ["REMOTE_ADDR"]
     try:
-        verified = captcha.verify(captcha_solution, ip_addr, email)
+        timer_fn = get_request_timing_function(request)
+        verified = captcha.verify(captcha_solution, ip_addr, email,
+                                  timer=timer_fn)
         if verified:
             return None
     except VerifyCaptchaError: