launchpad-reviewers team mailing list archive

[William Grant <me@xxxxxxxxxxxxxxxxxx>]

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