William Grant has proposed merging lp:~wgrant/launchpad/bug-766742 into 
lp:launchpad.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)
Related bugs:
  Bug #766742 in Launchpad itself: "RootObject:+login timeouts - no visibility 
into cause"
  https://bugs.launchpad.net/launchpad/+bug/766742

For more details, see:
https://code.launchpad.net/~wgrant/launchpad/bug-766742/+merge/58643

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.
-- 
https://code.launchpad.net/~wgrant/launchpad/bug-766742/+merge/58643
Your team Launchpad code reviewers is requested to review the proposed merge of 
lp:~wgrant/launchpad/bug-766742 into lp:launchpad.
=== 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 09:27:32 +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,14 @@
         allowUnauthenticatedSession(self.request)
         consumer = self._getConsumer()
         openid_vhost = config.launchpad.openid_provider_vhost
+
+        timeline_action = get_request_timeline(self.request).start(
+            "openid-association-begin",
+            allvhosts.configs[openid_vhost].rooturl,
+            allow_nested=True)
         self.openid_request = consumer.begin(
             allvhosts.configs[openid_vhost].rooturl)
+        timeline_action.finish()
         self.openid_request.addExtension(
             sreg.SRegRequest(optional=['email', 'fullname']))
 
@@ -283,7 +290,10 @@
         params = self._gather_params(self.request)
         requested_url = self._get_requested_url(self.request)
         consumer = self._getConsumer()
+        timeline_action = get_request_timeline(self.request).start(
+            "openid-association-complete", None, allow_nested=True)
         self.openid_response = consumer.complete(params, requested_url)
+        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 09:27:32 +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, None)
+        self.assertEqual(stop.category, 'openid-association-complete-stop')
+        self.assertEqual(stop.detail, None)
+
     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

_______________________________________________
Mailing list: https://launchpad.net/~launchpad-reviewers
Post to     : [email protected]
Unsubscribe : https://launchpad.net/~launchpad-reviewers
More help   : https://help.launchpad.net/ListHelp

Reply via email to