launchpad-reviewers team mailing list archive

[Robert Collins <robertc@xxxxxxxxxxxxxxxxx>]

Robert Collins has proposed merging lp:~lifeless/launchpad/oops into lp:launchpad/devel.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)
Related bugs:
  #627940 of the blocking calls made only database statements are recorded in OOPS
  https://bugs.launchpad.net/bugs/627940


Record several blocking activities in the request timeline:
 - sending email
 - downloading from the librarian
 - set and get on memcache

This will shed some light on 'high python time oopses' that may be doing blocking actions.

Implementation wise, the librarian and memcache parts are tested. The Right Place to hook in - raw_sendmail - isn't tested at all in Launchpad, and I'm not sure how to test it either and its dealing with the internals of Utilities.

I think that this is either going to work well or blow up very very quickly though, so I'm fairly comfortable landing it and seeing how much of staging it demolishes.

I'm running it through ec2 test to catch advance issues now.

This will need an RC stamp to actually land, but given the huge increase in visibility I hope it adds, that should be a no-bwainer.
-- 
https://code.launchpad.net/~lifeless/launchpad/oops/+merge/34600
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~lifeless/launchpad/oops into lp:launchpad/devel.

=== modified file 'lib/canonical/launchpad/doc/librarian.txt'
--- lib/canonical/launchpad/doc/librarian.txt	2009-11-24 15:36:44 +0000
+++ lib/canonical/launchpad/doc/librarian.txt	2010-09-04 06:02:42 +0000
@@ -183,6 +183,25 @@
     >>> re.search(r'^http://localhost:58000/\d+/text.txt$', url) is not None
     True
 
+Librarian reads are logged in the request timeline.
+
+    >>> from canonical.lazr.utils import get_current_browser_request
+    >>> from lp.services.timeline.requesttimeline import get_request_timeline
+    >>> request = get_current_browser_request()
+    >>> timeline = get_request_timeline(request)
+    >>> f = client.getFileByAlias(aid)
+    >>> action = timeline.actions[-1]
+    >>> action.category
+    'librarian-connection'
+    >>> action.detail.endswith('/text.txt')
+    True
+    >>> _unused = f.read()
+    >>> action = timeline.actions[-1]
+    >>> action.category
+    'librarian-read'
+    >>> action.detail.endswith('/text.txt')
+    True
+
 At this level we can also reverse the transactional semantics by using the
 remoteAddFile instead of the addFile method. In this case, the database
 rows are added by the Librarian, which means that the file is downloadable

=== modified file 'lib/canonical/librarian/client.py'
--- lib/canonical/librarian/client.py	2010-08-17 21:05:47 +0000
+++ lib/canonical/librarian/client.py	2010-09-04 06:02:42 +0000
@@ -33,6 +33,8 @@
 from canonical.librarian.interfaces import (
     DownloadFailed, ILibrarianClient, IRestrictedLibrarianClient,
     LIBRARIAN_SERVER_DEFAULT_TIMEOUT, LibrarianServerError, UploadFailed)
+from canonical.lazr.utils import get_current_browser_request
+from lp.services.timeline.requesttimeline import get_request_timeline
 
 
 def url_path_quote(filename):
@@ -246,16 +248,23 @@
 
 
 class _File:
-    """A wrapper around a file like object that has security assertions"""
+    """A File wrapper which uses the timeline and has security assertions."""
 
-    def __init__(self, file):
+    def __init__(self, file, url):
         self.file = file
+        self.url = url
 
     def read(self, chunksize=None):
-        if chunksize is None:
-            return self.file.read()
-        else:
-            return self.file.read(chunksize)
+        request = get_current_browser_request()
+        timeline = get_request_timeline(request)
+        action = timeline.start("librarian-read", self.url)
+        try:
+            if chunksize is None:
+                return self.file.read()
+            else:
+                return self.file.read(chunksize)
+        finally:
+            action.finish()
 
     def close(self):
         return self.file.close()
@@ -345,9 +354,19 @@
             # File has been deleted
             return None
         try_until = time.time() + timeout
+        request = get_current_browser_request()
+        timeline = get_request_timeline(request)
+        action = timeline.start("librarian-connection", url)
+        try:
+            return self._connect_read(url, try_until, aliasID)
+        finally:
+            action.finish()
+
+    def _connect_read(self, url, try_until, aliasID):
+        """Helper for getFileByAlias."""
         while 1:
             try:
-                return _File(urllib2.urlopen(url))
+                return _File(urllib2.urlopen(url), url)
             except urllib2.URLError, error:
                 # 404 errors indicate a data inconsistency: more than one
                 # attempt to open the file is pointless.

=== modified file 'lib/lp/services/mail/sendmail.py'
--- lib/lp/services/mail/sendmail.py	2010-08-20 20:31:18 +0000
+++ lib/lp/services/mail/sendmail.py	2010-09-04 06:02:42 +0000
@@ -1,8 +1,7 @@
 # Copyright 2009 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
-"""
-The One True Way to send mail from the Launchpad application.
+"""The One True Way to send mail from the Launchpad application.
 
 Uses zope.sendmail.interfaces.IMailer, so you can subscribe to
 IMailSentEvent or IMailErrorEvent to record status.
@@ -24,7 +23,6 @@
     'sendmail',
     'simple_sendmail',
     'simple_sendmail_from_person',
-    'raw_sendmail',
     'validate_message',
     ]
 
@@ -45,6 +43,7 @@
 import hashlib
 from smtplib import SMTP
 
+from lazr.restful.utils import get_current_browser_request
 from zope.app import zapi
 from zope.security.proxy import isinstance as zisinstance
 from zope.sendmail.interfaces import IMailDelivery
@@ -54,6 +53,7 @@
 from canonical.launchpad.helpers import is_ascii_only
 from canonical.lp import isZopeless
 from lp.services.mail.stub import TestMailer
+from lp.services.timeline.requesttimeline import get_request_timeline
 
 # email package by default ends up encoding UTF-8 messages using base64,
 # which sucks as they look like spam to stupid spam filters. We define
@@ -414,10 +414,12 @@
     message['X-Launchpad-Hash'] = hash.hexdigest()
 
     raw_message = message.as_string()
+    message_detail = message['Subject']
     if isZopeless():
         # Zopeless email sending is not unit tested, and won't be.
         # The zopeless specific stuff is pretty simple though so this
         # should be fine.
+        # TODO: Store a timeline action for zopeless mail.
 
         if config.instance_name == 'testrunner':
             # when running in the testing environment, store emails
@@ -443,14 +445,17 @@
         # The "MAIL FROM" is set to the bounce address, to behave in a way
         # similar to mailing list software.
         return raw_sendmail(
-            config.canonical.bounce_address, to_addrs, raw_message)
+            config.canonical.bounce_address,
+            to_addrs,
+            raw_message,
+            message_detail)
 
 
 def get_msgid():
     return make_msgid('launchpad')
 
 
-def raw_sendmail(from_addr, to_addrs, raw_message):
+def raw_sendmail(from_addr, to_addrs, raw_message, message_detail):
     """Send a raw RFC8222 email message.
 
     All headers and encoding should already be done, as the message is
@@ -461,12 +466,21 @@
 
     Returns the message-id.
 
+    :param message_detail: Information about the message to include in the
+        request timeline.
     """
+    # Note that raw_sendail has no tests, unit or otherwise.
     assert not isinstance(to_addrs, basestring), 'to_addrs must be a sequence'
     assert isinstance(raw_message, str), 'Not a plain string'
     assert raw_message.decode('ascii'), 'Not ASCII - badly encoded message'
     mailer = zapi.getUtility(IMailDelivery, 'Mail')
-    return mailer.send(from_addr, to_addrs, raw_message)
+    request = get_current_browser_request()
+    timeline = get_request_timeline(request)
+    action = timeline.start("sendmail", message_detail)
+    try:
+        return mailer.send(from_addr, to_addrs, raw_message)
+    finally:
+        action.finish()
 
 
 if __name__ == '__main__':

=== modified file 'lib/lp/services/mail/tests/test_sendmail.py'
--- lib/lp/services/mail/tests/test_sendmail.py	2010-08-20 20:31:18 +0000
+++ lib/lp/services/mail/tests/test_sendmail.py	2010-09-04 06:02:42 +0000
@@ -243,7 +243,3 @@
     suite.addTest(DocTestSuite('lp.services.mail.sendmail'))
     suite.addTests(unittest.TestLoader().loadTestsFromName(__name__))
     return suite
-
-
-if __name__ == '__main__':
-    unittest.main(defaultTest='test_suite')

=== modified file 'lib/lp/services/memcache/client.py'
--- lib/lp/services/memcache/client.py	2010-08-20 20:31:18 +0000
+++ lib/lp/services/memcache/client.py	2010-09-04 06:02:42 +0000
@@ -8,9 +8,11 @@
 
 import re
 
+from lazr.restful.utils import get_current_browser_request
 import memcache
 
 from canonical.config import config
+from lp.services.timeline.requesttimeline import get_request_timeline
 
 
 def memcache_client_factory():
@@ -20,4 +22,27 @@
             r'\((.+?),(\d+)\)', config.memcache.servers)]
     assert len(servers) > 0, "Invalid memcached server list %r" % (
         config.memcache.addresses,)
-    return memcache.Client(servers)
+    return TimelineRecordingClient(servers)
+
+
+class TimelineRecordingClient(memcache.Client):
+
+    def __get_timeline_action(self, suffix, key):
+        request = get_current_browser_request()
+        timeline = get_request_timeline(request)
+        return timeline.start("memcache-%s" % suffix, key)
+
+    def get(self, key):
+        action = self.__get_timeline_action("get", key)
+        try:
+            return memcache.Client.get(self, key)
+        finally:
+            action.finish()
+
+    def set(self, key, value, time=0, min_compress_len=0):
+        action = self.__get_timeline_action("set", key)
+        try:
+            return memcache.Client.set(self, key, value, time=time,
+                min_compress_len=min_compress_len)
+        finally:
+            action.finish()

=== modified file 'lib/lp/services/memcache/tests/test_memcache_client.py'
--- lib/lp/services/memcache/tests/test_memcache_client.py	2010-01-07 06:47:46 +0000
+++ lib/lp/services/memcache/tests/test_memcache_client.py	2010-09-04 06:02:42 +0000
@@ -5,16 +5,17 @@
 
 __metaclass__ = type
 
-import unittest
-
+from lazr.restful.utils import get_current_browser_request
 from zope.component import getUtility
 
 from canonical.testing.layers import LaunchpadZopelessLayer
 from lp.services.memcache.interfaces import IMemcacheClient
+from lp.services.timeline.requesttimeline import get_request_timeline
 from lp.testing import TestCase
 
 
 class MemcacheClientTestCase(TestCase):
+
     layer = LaunchpadZopelessLayer
 
     def setUp(self):
@@ -36,7 +37,19 @@
             self.client.MemcachedKeyCharacterError,
             self.client.set, 'key with spaces', 'some value')
 
-
-def test_suite():
-    return unittest.TestLoader().loadTestsFromName(__name__)
-
+    def test_set_recorded_to_timeline(self):
+        request = get_current_browser_request()
+        timeline = get_request_timeline(request)
+        self.client.set('foo', 'bar')
+        action = timeline.actions[-1]
+        self.assertEqual('memcache-set', action.category)
+        self.assertEqual('foo', action.detail)
+
+    def test_get_recorded_to_timeline(self):
+        request = get_current_browser_request()
+        timeline = get_request_timeline(request)
+        self.client.set('foo', 'bar')
+        self.client.get('foo')
+        action = timeline.actions[-1]
+        self.assertEqual('memcache-get', action.category)
+        self.assertEqual('foo', action.detail)