Merge lp:~wgrant/launchpad/bug-766742 into lp:launchpad

[William Grant]

[r=jcsackett][bug=766742] OpenID actions on +login and +openid-callback now appear in the request timeline.

RootObject:+login has been frequently timing out lately, with a 10s gap between SQL statements that probably surround an OpenID HTTP request to SSO. This branch logs the start and end of the OpenID operations at both ends of authentication, so we can get a better idea of where the slowness lies.

[Robert Collins (lifeless)]

you need some try:finally's around.

I think you need "" rather than None for the detail, for oops-tools to be happy.

[j.c.sackett (jcsackett)]

Looks fine.

review: Approve

=== modified file 'lib/canonical/launchpad/webapp/login.py'
--- lib/canonical/launchpad/webapp/login.py	2010-12-16 15:42:22 +0000
+++ lib/canonical/launchpad/webapp/login.py	2011-04-21 10:03:59 +0000
@@ -62,6 +62,7 @@
     PersonCreationRationale,
     )
 from lp.services.propertycache import cachedproperty
+from lp.services.timeline.requesttimeline import get_request_timeline
 
 
 class UnauthorizedView(SystemErrorView):
@@ -195,8 +196,16 @@
         allowUnauthenticatedSession(self.request)
         consumer = self._getConsumer()
         openid_vhost = config.launchpad.openid_provider_vhost
-        self.openid_request = consumer.begin(
-            allvhosts.configs[openid_vhost].rooturl)
+
+        timeline_action = get_request_timeline(self.request).start(
+            "openid-association-begin",
+            allvhosts.configs[openid_vhost].rooturl,
+            allow_nested=True)
+        try:
+            self.openid_request = consumer.begin(
+                allvhosts.configs[openid_vhost].rooturl)
+        finally:
+            timeline_action.finish()
         self.openid_request.addExtension(
             sreg.SRegRequest(optional=['email', 'fullname']))
 
@@ -283,7 +292,12 @@
         params = self._gather_params(self.request)
         requested_url = self._get_requested_url(self.request)
         consumer = self._getConsumer()
-        self.openid_response = consumer.complete(params, requested_url)
+        timeline_action = get_request_timeline(self.request).start(
+            "openid-association-complete", '', allow_nested=True)
+        try:
+            self.openid_response = consumer.complete(params, requested_url)
+        finally:
+            timeline_action.finish()
 
     def login(self, account):
         loginsource = getUtility(IPlacelessLoginSource)

=== modified file 'lib/canonical/launchpad/webapp/tests/test_login.py'
--- lib/canonical/launchpad/webapp/tests/test_login.py	2010-12-08 17:22:23 +0000
+++ lib/canonical/launchpad/webapp/tests/test_login.py	2011-04-21 10:03:59 +0000
@@ -62,6 +62,7 @@
     )
 from lp.registry.interfaces.person import IPerson
 from lp.services.openid.model.openididentifier import OpenIdIdentifier
+from lp.services.timeline.requesttimeline import get_request_timeline
 from lp.testing import (
     logout,
     TestCaseWithFactory,
@@ -468,6 +469,19 @@
                 AssertionError,
                 getUtility(IAccountSet).getByOpenIDIdentifier, u'foo')
 
+    def test_logs_to_timeline(self):
+        # Completing an OpenID association *can* make an HTTP request to the
+        # OP, so it's a potentially long action. It is logged to the
+        # request timeline.
+        account = self.factory.makeAccount('Test account')
+        with SRegResponse_fromSuccessResponse_stubbed():
+            view, html = self._createViewWithResponse(account)
+        start, stop = get_request_timeline(view.request).actions[-2:]
+        self.assertEqual(start.category, 'openid-association-complete-start')
+        self.assertEqual(start.detail, '')
+        self.assertEqual(stop.category, 'openid-association-complete-stop')
+        self.assertEqual(stop.detail, '')
+
     def assertLastWriteIsSet(self, request):
         last_write = ISession(request)['lp.dbpolicy']['last_write']
         self.assertTrue(datetime.utcnow() - last_write < timedelta(minutes=1))
@@ -640,6 +654,22 @@
         self.assertEquals(['email', 'fullname'],
                           sorted(sreg_extension.allRequestedFields()))
 
+    def test_logs_to_timeline(self):
+        # Beginning an OpenID association makes an HTTP request to the
+        # OP, so it's a potentially long action. It is logged to the
+        # request timeline.
+        request = LaunchpadTestRequest()
+        # This is a hack to make the request.getURL(1) call issued by the view
+        # not raise an IndexError.
+        request._app_names = ['foo']
+        view = StubbedOpenIDLogin(object(), request)
+        view()
+        start, stop = get_request_timeline(request).actions[-2:]
+        self.assertEqual(start.category, 'openid-association-begin-start')
+        self.assertEqual(start.detail, 'http://testopenid.dev/')
+        self.assertEqual(stop.category, 'openid-association-begin-stop')
+        self.assertEqual(stop.detail, 'http://testopenid.dev/')
+
 
 class TestOpenIDRealm(TestCaseWithFactory):
     # The realm (aka trust_root) specified by the RP is "designed to give the