Launchpad itself

Merge lp:~lifeless/launchpad/oops into lp:launchpad

  1. oops
  2. Merge into devel
Proposed by Robert Collins
Status: Merged
Approved by: Michael Hudson-Doyle
Approved revision: no longer in the source branch.
Merged at revision: 11508
Proposed branch: lp:~lifeless/launchpad/oops
Merge into: lp:launchpad
Diff against target: 370 lines (+122/-28)
9 files modified
lib/canonical/launchpad/doc/librarian.txt (+19/-0)
lib/canonical/launchpad/webapp/errorlog.py (+5/-1)
lib/canonical/librarian/client.py (+26/-7)
lib/canonical/librarian/ftests/test_client.py (+3/-2)
lib/lp/services/mail/sendmail.py (+20/-6)
lib/lp/services/mail/tests/test_sendmail.py (+0/-4)
lib/lp/services/memcache/client.py (+26/-1)
lib/lp/services/memcache/tests/test_memcache_client.py (+19/-6)
lib/lp/testing/tests/test_testcase.py (+4/-1)
To merge this branch: bzr merge lp:~lifeless/launchpad/oops
Reviewer Review Type Date Requested Status
Graham Binns (community) release-critical Approve
Michael Hudson-Doyle Approve
Review via email: mp+34600@code.launchpad.net

Commit message

Record more data in the request timeline: email sending, librarian client downloads, and memcache get/sets.

Description of the change

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.

To post a comment you must log in.
Revision history for this message
Michael Hudson-Doyle (mwhudson) wrote :

This all looks fine. I like the new API! And I'm sure the information will be really useful.

I worry a bit about tests that don't have a participation when they try to access the database, but well you'll find out about that :-) I think the scripts should all be fine (execute_zcml_for_scripts() calls login(ANONYMOUS) iirc).

review: Approve
Revision history for this message
Robert Collins (lifeless) wrote :

Thanks Michael, due to the black hole of webapp.adapter, things work fine now - fixing that is long term and the rabbit hole I went down week before last. So as it doesn't /really/ use a participation, its all good; when we fix it to use one, it will be all good in a better way.

And yes, login() sets up a participation, so it will be fine for them, in future, when we migrae the underlying API.

Revision history for this message
Graham Binns (gmb) :
review: Approve (release-critical)

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'lib/canonical/launchpad/doc/librarian.txt'
2--- lib/canonical/launchpad/doc/librarian.txt 2009-11-24 15:36:44 +0000
3+++ lib/canonical/launchpad/doc/librarian.txt 2010-09-04 20:19:45 +0000
4@@ -183,6 +183,25 @@
5 >>> re.search(r'^http://localhost:58000/\d+/text.txt$', url) is not None
6 True
7
8+Librarian reads are logged in the request timeline.
9+
10+ >>> from canonical.lazr.utils import get_current_browser_request
11+ >>> from lp.services.timeline.requesttimeline import get_request_timeline
12+ >>> request = get_current_browser_request()
13+ >>> timeline = get_request_timeline(request)
14+ >>> f = client.getFileByAlias(aid)
15+ >>> action = timeline.actions[-1]
16+ >>> action.category
17+ 'librarian-connection'
18+ >>> action.detail.endswith('/text.txt')
19+ True
20+ >>> _unused = f.read()
21+ >>> action = timeline.actions[-1]
22+ >>> action.category
23+ 'librarian-read'
24+ >>> action.detail.endswith('/text.txt')
25+ True
26+
27 At this level we can also reverse the transactional semantics by using the
28 remoteAddFile instead of the addFile method. In this case, the database
29 rows are added by the Librarian, which means that the file is downloadable
30
31=== modified file 'lib/canonical/launchpad/webapp/errorlog.py'
32--- lib/canonical/launchpad/webapp/errorlog.py 2010-09-03 11:09:57 +0000
33+++ lib/canonical/launchpad/webapp/errorlog.py 2010-09-04 20:19:45 +0000
34@@ -85,6 +85,9 @@
35 'representation of an object')
36 value = '<unprintable %s object>' % (
37 str(type(obj).__name__))
38+ # Some str() calls return unicode objects.
39+ if isinstance(value, unicode):
40+ return _safestr(value)
41 # encode non-ASCII characters
42 value = value.replace('\\', '\\\\')
43 value = re.sub(r'[\x80-\xff]',
44@@ -163,6 +166,7 @@
45 return '<ErrorReport %s %s: %s>' % (self.id, self.type, self.value)
46
47 def get_chunks(self):
48+ """Returns a list of bytestrings making up the oops disk content."""
49 chunks = []
50 chunks.append('Oops-Id: %s\n' % _normalise_whitespace(self.id))
51 chunks.append(
52@@ -171,7 +175,7 @@
53 'Exception-Value: %s\n' % _normalise_whitespace(self.value))
54 chunks.append('Date: %s\n' % self.time.isoformat())
55 chunks.append('Page-Id: %s\n' % _normalise_whitespace(self.pageid))
56- chunks.append('Branch: %s\n' % self.branch_nick)
57+ chunks.append('Branch: %s\n' % _safestr(self.branch_nick))
58 chunks.append('Revision: %s\n' % self.revno)
59 chunks.append('User: %s\n' % _normalise_whitespace(self.username))
60 chunks.append('URL: %s\n' % _normalise_whitespace(self.url))
61
62=== modified file 'lib/canonical/librarian/client.py'
63--- lib/canonical/librarian/client.py 2010-08-17 21:05:47 +0000
64+++ lib/canonical/librarian/client.py 2010-09-04 20:19:45 +0000
65@@ -33,6 +33,8 @@
66 from canonical.librarian.interfaces import (
67 DownloadFailed, ILibrarianClient, IRestrictedLibrarianClient,
68 LIBRARIAN_SERVER_DEFAULT_TIMEOUT, LibrarianServerError, UploadFailed)
69+from canonical.lazr.utils import get_current_browser_request
70+from lp.services.timeline.requesttimeline import get_request_timeline
71
72
73 def url_path_quote(filename):
74@@ -246,16 +248,23 @@
75
76
77 class _File:
78- """A wrapper around a file like object that has security assertions"""
79+ """A File wrapper which uses the timeline and has security assertions."""
80
81- def __init__(self, file):
82+ def __init__(self, file, url):
83 self.file = file
84+ self.url = url
85
86 def read(self, chunksize=None):
87- if chunksize is None:
88- return self.file.read()
89- else:
90- return self.file.read(chunksize)
91+ request = get_current_browser_request()
92+ timeline = get_request_timeline(request)
93+ action = timeline.start("librarian-read", self.url)
94+ try:
95+ if chunksize is None:
96+ return self.file.read()
97+ else:
98+ return self.file.read(chunksize)
99+ finally:
100+ action.finish()
101
102 def close(self):
103 return self.file.close()
104@@ -345,9 +354,19 @@
105 # File has been deleted
106 return None
107 try_until = time.time() + timeout
108+ request = get_current_browser_request()
109+ timeline = get_request_timeline(request)
110+ action = timeline.start("librarian-connection", url)
111+ try:
112+ return self._connect_read(url, try_until, aliasID)
113+ finally:
114+ action.finish()
115+
116+ def _connect_read(self, url, try_until, aliasID):
117+ """Helper for getFileByAlias."""
118 while 1:
119 try:
120- return _File(urllib2.urlopen(url))
121+ return _File(urllib2.urlopen(url), url)
122 except urllib2.URLError, error:
123 # 404 errors indicate a data inconsistency: more than one
124 # attempt to open the file is pointless.
125
126=== modified file 'lib/canonical/librarian/ftests/test_client.py'
127--- lib/canonical/librarian/ftests/test_client.py 2009-11-24 15:36:44 +0000
128+++ lib/canonical/librarian/ftests/test_client.py 2010-09-04 20:19:45 +0000
129@@ -32,7 +32,7 @@
130
131
132 def make_mock_file(error, max_raise):
133- """Return a surrogate for clinet._File.
134+ """Return a surrogate for client._File.
135
136 The surrogate function raises error when called for the first
137 max_raise times.
138@@ -44,7 +44,7 @@
139 'num_calls': 0,
140 }
141
142- def mock_file(url):
143+ def mock_file(url_file, url):
144 if file_status['num_calls'] < file_status['max_raise']:
145 file_status['num_calls'] += 1
146 raise file_status['error']
147@@ -52,6 +52,7 @@
148
149 return mock_file
150
151+
152 class LibrarianClientTestCase(unittest.TestCase):
153 layer = LaunchpadFunctionalLayer
154
155
156=== modified file 'lib/lp/services/mail/sendmail.py'
157--- lib/lp/services/mail/sendmail.py 2010-08-20 20:31:18 +0000
158+++ lib/lp/services/mail/sendmail.py 2010-09-04 20:19:45 +0000
159@@ -1,8 +1,7 @@
160 # Copyright 2009 Canonical Ltd. This software is licensed under the
161 # GNU Affero General Public License version 3 (see the file LICENSE).
162
163-"""
164-The One True Way to send mail from the Launchpad application.
165+"""The One True Way to send mail from the Launchpad application.
166
167 Uses zope.sendmail.interfaces.IMailer, so you can subscribe to
168 IMailSentEvent or IMailErrorEvent to record status.
169@@ -24,7 +23,6 @@
170 'sendmail',
171 'simple_sendmail',
172 'simple_sendmail_from_person',
173- 'raw_sendmail',
174 'validate_message',
175 ]
176
177@@ -45,6 +43,7 @@
178 import hashlib
179 from smtplib import SMTP
180
181+from lazr.restful.utils import get_current_browser_request
182 from zope.app import zapi
183 from zope.security.proxy import isinstance as zisinstance
184 from zope.sendmail.interfaces import IMailDelivery
185@@ -54,6 +53,7 @@
186 from canonical.launchpad.helpers import is_ascii_only
187 from canonical.lp import isZopeless
188 from lp.services.mail.stub import TestMailer
189+from lp.services.timeline.requesttimeline import get_request_timeline
190
191 # email package by default ends up encoding UTF-8 messages using base64,
192 # which sucks as they look like spam to stupid spam filters. We define
193@@ -414,10 +414,12 @@
194 message['X-Launchpad-Hash'] = hash.hexdigest()
195
196 raw_message = message.as_string()
197+ message_detail = message['Subject']
198 if isZopeless():
199 # Zopeless email sending is not unit tested, and won't be.
200 # The zopeless specific stuff is pretty simple though so this
201 # should be fine.
202+ # TODO: Store a timeline action for zopeless mail.
203
204 if config.instance_name == 'testrunner':
205 # when running in the testing environment, store emails
206@@ -443,14 +445,17 @@
207 # The "MAIL FROM" is set to the bounce address, to behave in a way
208 # similar to mailing list software.
209 return raw_sendmail(
210- config.canonical.bounce_address, to_addrs, raw_message)
211+ config.canonical.bounce_address,
212+ to_addrs,
213+ raw_message,
214+ message_detail)
215
216
217 def get_msgid():
218 return make_msgid('launchpad')
219
220
221-def raw_sendmail(from_addr, to_addrs, raw_message):
222+def raw_sendmail(from_addr, to_addrs, raw_message, message_detail):
223 """Send a raw RFC8222 email message.
224
225 All headers and encoding should already be done, as the message is
226@@ -461,12 +466,21 @@
227
228 Returns the message-id.
229
230+ :param message_detail: Information about the message to include in the
231+ request timeline.
232 """
233+ # Note that raw_sendail has no tests, unit or otherwise.
234 assert not isinstance(to_addrs, basestring), 'to_addrs must be a sequence'
235 assert isinstance(raw_message, str), 'Not a plain string'
236 assert raw_message.decode('ascii'), 'Not ASCII - badly encoded message'
237 mailer = zapi.getUtility(IMailDelivery, 'Mail')
238- return mailer.send(from_addr, to_addrs, raw_message)
239+ request = get_current_browser_request()
240+ timeline = get_request_timeline(request)
241+ action = timeline.start("sendmail", message_detail)
242+ try:
243+ return mailer.send(from_addr, to_addrs, raw_message)
244+ finally:
245+ action.finish()
246
247
248 if __name__ == '__main__':
249
250=== modified file 'lib/lp/services/mail/tests/test_sendmail.py'
251--- lib/lp/services/mail/tests/test_sendmail.py 2010-08-20 20:31:18 +0000
252+++ lib/lp/services/mail/tests/test_sendmail.py 2010-09-04 20:19:45 +0000
253@@ -243,7 +243,3 @@
254 suite.addTest(DocTestSuite('lp.services.mail.sendmail'))
255 suite.addTests(unittest.TestLoader().loadTestsFromName(__name__))
256 return suite
257-
258-
259-if __name__ == '__main__':
260- unittest.main(defaultTest='test_suite')
261
262=== modified file 'lib/lp/services/memcache/client.py'
263--- lib/lp/services/memcache/client.py 2010-08-20 20:31:18 +0000
264+++ lib/lp/services/memcache/client.py 2010-09-04 20:19:45 +0000
265@@ -8,9 +8,11 @@
266
267 import re
268
269+from lazr.restful.utils import get_current_browser_request
270 import memcache
271
272 from canonical.config import config
273+from lp.services.timeline.requesttimeline import get_request_timeline
274
275
276 def memcache_client_factory():
277@@ -20,4 +22,27 @@
278 r'\((.+?),(\d+)\)', config.memcache.servers)]
279 assert len(servers) > 0, "Invalid memcached server list %r" % (
280 config.memcache.addresses,)
281- return memcache.Client(servers)
282+ return TimelineRecordingClient(servers)
283+
284+
285+class TimelineRecordingClient(memcache.Client):
286+
287+ def __get_timeline_action(self, suffix, key):
288+ request = get_current_browser_request()
289+ timeline = get_request_timeline(request)
290+ return timeline.start("memcache-%s" % suffix, key)
291+
292+ def get(self, key):
293+ action = self.__get_timeline_action("get", key)
294+ try:
295+ return memcache.Client.get(self, key)
296+ finally:
297+ action.finish()
298+
299+ def set(self, key, value, time=0, min_compress_len=0):
300+ action = self.__get_timeline_action("set", key)
301+ try:
302+ return memcache.Client.set(self, key, value, time=time,
303+ min_compress_len=min_compress_len)
304+ finally:
305+ action.finish()
306
307=== modified file 'lib/lp/services/memcache/tests/test_memcache_client.py'
308--- lib/lp/services/memcache/tests/test_memcache_client.py 2010-01-07 06:47:46 +0000
309+++ lib/lp/services/memcache/tests/test_memcache_client.py 2010-09-04 20:19:45 +0000
310@@ -5,16 +5,17 @@
311
312 __metaclass__ = type
313
314-import unittest
315-
316+from lazr.restful.utils import get_current_browser_request
317 from zope.component import getUtility
318
319 from canonical.testing.layers import LaunchpadZopelessLayer
320 from lp.services.memcache.interfaces import IMemcacheClient
321+from lp.services.timeline.requesttimeline import get_request_timeline
322 from lp.testing import TestCase
323
324
325 class MemcacheClientTestCase(TestCase):
326+
327 layer = LaunchpadZopelessLayer
328
329 def setUp(self):
330@@ -36,7 +37,19 @@
331 self.client.MemcachedKeyCharacterError,
332 self.client.set, 'key with spaces', 'some value')
333
334-
335-def test_suite():
336- return unittest.TestLoader().loadTestsFromName(__name__)
337-
338+ def test_set_recorded_to_timeline(self):
339+ request = get_current_browser_request()
340+ timeline = get_request_timeline(request)
341+ self.client.set('foo', 'bar')
342+ action = timeline.actions[-1]
343+ self.assertEqual('memcache-set', action.category)
344+ self.assertEqual('foo', action.detail)
345+
346+ def test_get_recorded_to_timeline(self):
347+ request = get_current_browser_request()
348+ timeline = get_request_timeline(request)
349+ self.client.set('foo', 'bar')
350+ self.client.get('foo')
351+ action = timeline.actions[-1]
352+ self.assertEqual('memcache-get', action.category)
353+ self.assertEqual('foo', action.detail)
354
355=== modified file 'lib/lp/testing/tests/test_testcase.py'
356--- lib/lp/testing/tests/test_testcase.py 2010-08-20 20:31:18 +0000
357+++ lib/lp/testing/tests/test_testcase.py 2010-09-04 20:19:45 +0000
358@@ -91,8 +91,11 @@
359 # getLastOopsReport does, and doing so changes whether the
360 # timezone is in the timestamp.
361 content = StringIO()
362- content.writelines(self.getDetails()['oops-0'].iter_text())
363+ content.writelines(self.getDetails()['oops-0'].iter_bytes())
364 content.seek(0)
365+ # Safety net: ensure that no autocasts have occured even on Python 2.6
366+ # which is slightly better.
367+ self.assertIsInstance(content.getvalue(), str)
368 from_details = errorlog.ErrorReport.read(content)
369 self.assertEqual(
370 oops.get_chunks(),