Launchpad itself

Merge lp:~abentley/launchpad/errorlog-context into lp:launchpad

  1. errorlog-context
  2. Merge into devel
Proposed by Aaron Bentley
Status: Merged
Merged at revision: not available
Proposed branch: lp:~abentley/launchpad/errorlog-context
Merge into: lp:launchpad
Diff against target: 453 lines (+227/-113)
4 files modified
lib/canonical/launchpad/webapp/errorlog.py (+139/-96)
lib/canonical/launchpad/webapp/tests/test_errorlog.py (+47/-2)
lib/lp/services/job/runner.py (+16/-14)
lib/lp/services/job/tests/test_runner.py (+25/-1)
To merge this branch: bzr merge lp:~abentley/launchpad/errorlog-context
Reviewer Review Type Date Requested Status
Gary Poster (community) code Approve
Brad Crittenden (community) code Approve
Review via email: mp+15217@code.launchpad.net
To post a comment you must log in.
Revision history for this message
Aaron Bentley (abentley) wrote :

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

= Summary =
Provide better oops reporting for scripts using error_vars.

== Proposed fix ==
Allow callers at any level to provide error vars for oops reporting
using a with statement.

== Pre-implementation notes ==
Preimplementation was with thumper.

== Implementation details ==
ErrorReportingUtility gains an _error_vars member, which is a set. The
context manager, ErrorReportingUtilty.contextErrorVariables, updates the
set with tuples of key, value tuples, and removes entries from the set
as needed. ErrorReportingUtility.error_variables provides a flattened,
sorted version of this set. Calling "raising or handling" adds these
variables to the list of variables retrieved from the request object.

ErrorReportingUtility._makeErrorReport was extracted from _raising, to
simplify testing.

== Tests ==
bin/test -vt test_errorlog -t test_runner

== Demo and Q/A ==
None

= Launchpad lint =

Checking for conflicts. and issues in doctests and templates.
Running jslint, xmllint, pyflakes, and pylint.
Using normal rules.

Linting changed files:
  lib/canonical/launchpad/webapp/tests/test_errorlog.py
  lib/lp/services/job/tests/test_runner.py
  lib/lp/services/job/runner.py
  lib/canonical/launchpad/webapp/errorlog.py

== Pylint notices ==

lib/canonical/launchpad/webapp/tests/test_errorlog.py
    38: [F0401] Unable to import 'lazr.restful.declarations' (No module
named restful)

lib/lp/services/job/runner.py
    19: [F0401] Unable to import 'lazr.delegates' (No module named
delegates)

lib/canonical/launchpad/webapp/errorlog.py
    28: [F0401] Unable to import 'lazr.restful.utils' (No module named
restful)
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iEYEARECAAYFAksMOHYACgkQ0F+nu1YWqI3B8ACfc7khXiXxdLNgcDaSP1wcP0o7
b8EAn1KjOTOJs1zZ7y1VJcGD1GjnKlKn
=lYxf
-----END PGP SIGNATURE-----

Revision history for this message
Brad Crittenden (bac) :
review: Approve (code)
Revision history for this message
Tim Penhey (thumper) wrote :

When talking with Francis this morning, he suggested that Gary take a look at
this too.

  reviewer gary

Revision history for this message
Gary Poster (gary) wrote :

merge-conditional

I very much like the general functionality and the clean ups, not to mention the introduction of "with" to Launchpad :-) .

We spent a long time today on IRC, and finally on SIP, clarifying my misunderstandings, and coming to an agreement on what to do here.

The first thing to note is that we did try using the pre-existing Zope functionality of being able to annotate frames with extra information. This is implemented in zope.exception.exceptionformatter (implementation is in http://svn.zope.org/zope.exceptions/trunk/src/zope/exceptions/exceptionformatter.py?view=auto ) and I constructed a couple of examples, such as http://paste.ubuntu.com/327940/ . However, we discovered that it was not sufficient: Aaron had a use case of wanting to annotate the oops outside of the frames caught by the traceback. Therefore, we retreated to the original proposal.

We agreed on the following:

- The implementation of storing this information in request variables is an expedient hack. Aaron will create a bug for this, and make an XXX.

- ``contextErrorVariables`` will become ``oopsMessage`` (or something to that effect) and will take a single value that can be cast to a string. (Maybe in the future we will also support string interpolation a la the stdlib logging module. Maybe not.)

- As a temporary implementation, each OOPS message will have a key in the request variables that is clearly not something actually from the request. The value will be the message. The keys might be given names that allow them to be sorted so that the nesting is clear.

With these changes, r=gary.

Thank you, Aaron, not only for this very nice improvement but also for your patience!

Gary

review: Approve (code)

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'lib/canonical/launchpad/webapp/errorlog.py'
2--- lib/canonical/launchpad/webapp/errorlog.py 2009-10-07 18:41:52 +0000
3+++ lib/canonical/launchpad/webapp/errorlog.py 2009-11-27 19:36:19 +0000
4@@ -7,8 +7,10 @@
5
6 __metaclass__ = type
7
8+import contextlib
9 import datetime
10 import errno
11+from itertools import repeat
12 import logging
13 import os
14 import re
15@@ -236,10 +238,12 @@
16 lasterrordir = None
17 lastid = 0
18
19-
20 def __init__(self):
21 self.lastid_lock = threading.Lock()
22 self.configure()
23+ self._oops_messages = {}
24+ self._oops_message_key_iter = (
25+ index for index, _ignored in enumerate(repeat(None)))
26
27 def configure(self, section_name=None):
28 """Configure the utility using the named section form the config.
29@@ -399,113 +403,144 @@
30 return oops, filename
31
32 def raising(self, info, request=None, now=None):
33- """See IErrorReportingUtility.raising()"""
34+ """See IErrorReportingUtility.raising()
35+
36+ :param now: The datetime to use as the current time. Will be
37+ determined if not supplied. Useful for testing. Not part of
38+ IErrorReportingUtility).
39+ """
40 self._raising(info, request=request, now=now, informational=False)
41
42 def _raising(self, info, request=None, now=None, informational=False):
43 """Private method used by raising() and handling()."""
44+ entry = self._makeErrorReport(info, request, now, informational)
45+ if entry is None:
46+ return
47+ # As a side-effect, _makeErrorReport updates self.lastid.
48+ filename = self.getOopsFilename(self.lastid, entry.time)
49+ entry.write(open(filename, 'wb'))
50+ if request:
51+ request.oopsid = entry.id
52+ request.oops = entry
53+
54+ if self.copy_to_zlog:
55+ self._do_copy_to_zlog(
56+ entry.time, entry.type, entry.url, info, entry.id)
57+
58+ def _makeErrorReport(self, info, request=None, now=None,
59+ informational=False):
60+ """Return an ErrorReport for the supplied data.
61+
62+ As a side-effect, self.lastid is updated to the integer oops id.
63+ :param info: Output of sys.exc_info()
64+ :param request: The IErrorReportRequest which provides context to the
65+ info.
66+ :param now: The datetime to use as the current time. Will be
67+ determined if not supplied. Useful for testing.
68+ :param informational: If true, the report is flagged as informational
69+ only.
70+ """
71 if now is not None:
72 now = now.astimezone(UTC)
73 else:
74 now = datetime.datetime.now(UTC)
75- try:
76- tb_text = None
77-
78- strtype = str(getattr(info[0], '__name__', info[0]))
79- if strtype in self._ignored_exceptions:
80- return
81-
82- if not isinstance(info[2], basestring):
83- tb_text = ''.join(format_exception(*info,
84- **{'as_html': False}))
85+ tb_text = None
86+
87+ strtype = str(getattr(info[0], '__name__', info[0]))
88+ if strtype in self._ignored_exceptions:
89+ return
90+
91+ if not isinstance(info[2], basestring):
92+ tb_text = ''.join(format_exception(*info,
93+ **{'as_html': False}))
94+ else:
95+ tb_text = info[2]
96+ tb_text = _safestr(tb_text)
97+
98+ url = None
99+ username = None
100+ req_vars = []
101+ pageid = ''
102+
103+ if request:
104+ # XXX jamesh 2005-11-22: Temporary fix, which Steve should
105+ # undo. URL is just too HTTPRequest-specific.
106+ if safe_hasattr(request, 'URL'):
107+ url = request.URL
108+
109+ if WebServiceLayer.providedBy(request):
110+ webservice_error = getattr(
111+ info[0], '__lazr_webservice_error__', 500)
112+ if webservice_error / 100 != 5:
113+ request.oopsid = None
114+ # Return so the OOPS is not generated.
115+ return
116+
117+ missing = object()
118+ principal = getattr(request, 'principal', missing)
119+ if safe_hasattr(principal, 'getLogin'):
120+ login = principal.getLogin()
121+ elif principal is missing or principal is None:
122+ # Request has no principal.
123+ login = None
124 else:
125- tb_text = info[2]
126- tb_text = _safestr(tb_text)
127-
128- url = None
129- username = None
130- req_vars = []
131- pageid = ''
132-
133- if request:
134- # XXX jamesh 2005-11-22: Temporary fix, which Steve should
135- # undo. URL is just too HTTPRequest-specific.
136- if safe_hasattr(request, 'URL'):
137- url = request.URL
138-
139- if WebServiceLayer.providedBy(request):
140- webservice_error = getattr(
141- info[0], '__lazr_webservice_error__', 500)
142- if webservice_error / 100 != 5:
143- request.oopsid = None
144- # Return so the OOPS is not generated.
145- return
146-
147- missing = object()
148- principal = getattr(request, 'principal', missing)
149- if safe_hasattr(principal, 'getLogin'):
150- login = principal.getLogin()
151- elif principal is missing or principal is None:
152- # Request has no principal.
153- login = None
154+ # Request has an UnauthenticatedPrincipal.
155+ login = 'unauthenticated'
156+ if strtype in (
157+ self._ignored_exceptions_for_unauthenticated_users):
158+ return
159+
160+ if principal is not None and principal is not missing:
161+ username = _safestr(
162+ ', '.join([
163+ unicode(login),
164+ unicode(request.principal.id),
165+ unicode(request.principal.title),
166+ unicode(request.principal.description)]))
167+
168+ if getattr(request, '_orig_env', None):
169+ pageid = request._orig_env.get('launchpad.pageid', '')
170+
171+ for key, value in request.items():
172+ if _is_sensitive(request, key):
173+ req_vars.append((_safestr(key), '<hidden>'))
174 else:
175- # Request has an UnauthenticatedPrincipal.
176- login = 'unauthenticated'
177- if strtype in (
178- self._ignored_exceptions_for_unauthenticated_users):
179- return
180-
181- if principal is not None and principal is not missing:
182- username = _safestr(
183- ', '.join([
184- unicode(login),
185- unicode(request.principal.id),
186- unicode(request.principal.title),
187- unicode(request.principal.description)]))
188-
189- if getattr(request, '_orig_env', None):
190- pageid = request._orig_env.get('launchpad.pageid', '')
191-
192- req_vars = []
193- for key, value in request.items():
194- if _is_sensitive(request, key):
195- req_vars.append((_safestr(key), '<hidden>'))
196- else:
197- req_vars.append((_safestr(key), _safestr(value)))
198- if IXMLRPCRequest.providedBy(request):
199- args = request.getPositionalArguments()
200- req_vars.append(('xmlrpc args', _safestr(args)))
201- req_vars.sort()
202- strv = _safestr(info[1])
203-
204- strurl = _safestr(url)
205-
206- duration = get_request_duration()
207-
208- statements = sorted(
209- (start, end, _safestr(database_id), _safestr(statement))
210- for (start, end, database_id, statement)
211- in get_request_statements())
212-
213- oopsid, filename = self.newOopsId(now)
214-
215- entry = ErrorReport(oopsid, strtype, strv, now, pageid, tb_text,
216- username, strurl, duration,
217- req_vars, statements,
218- informational)
219- entry.write(open(filename, 'wb'))
220-
221- if request:
222- request.oopsid = oopsid
223- request.oops = entry
224-
225- if self.copy_to_zlog:
226- self._do_copy_to_zlog(now, strtype, strurl, info, oopsid)
227- finally:
228- info = None
229+ req_vars.append((_safestr(key), _safestr(value)))
230+ if IXMLRPCRequest.providedBy(request):
231+ args = request.getPositionalArguments()
232+ req_vars.append(('xmlrpc args', _safestr(args)))
233+ # XXX AaronBentley 2009-11-26 bug=488950: There should be separate
234+ # storage for oops messages.
235+ req_vars.extend(
236+ ('<oops-message-%d>' % key, str(message)) for key, message
237+ in self._oops_messages.iteritems())
238+ req_vars.sort()
239+ strv = _safestr(info[1])
240+
241+ strurl = _safestr(url)
242+
243+ duration = get_request_duration()
244+
245+ statements = sorted(
246+ (start, end, _safestr(database_id), _safestr(statement))
247+ for (start, end, database_id, statement)
248+ in get_request_statements())
249+
250+ oopsid, filename = self.newOopsId(now)
251+ return ErrorReport(oopsid, strtype, strv, now, pageid, tb_text,
252+ username, strurl, duration,
253+ req_vars, statements,
254+ informational)
255
256 def handling(self, info, request=None, now=None):
257- """Flag ErrorReport as informational only."""
258+ """Flag ErrorReport as informational only.
259+
260+ :param info: Output of sys.exc_info()
261+ :param request: The IErrorReportRequest which provides context to the
262+ info.
263+ :param now: The datetime to use as the current time. Will be
264+ determined if not supplied. Useful for testing.
265+ """
266 self._raising(info, request=request, now=now, informational=True)
267
268 def _do_copy_to_zlog(self, now, strtype, url, info, oopsid):
269@@ -531,6 +566,14 @@
270 logging.getLogger('SiteError').exception(
271 '%s (%s)' % (url, oopsid))
272
273+ @contextlib.contextmanager
274+ def oopsMessage(self, message):
275+ """Add an oops message to be included in oopses from this context."""
276+ key = self._oops_message_key_iter.next()
277+ self._oops_messages[key] = message
278+ yield
279+ del self._oops_messages[key]
280+
281
282 globalErrorUtility = ErrorReportingUtility()
283
284
285=== modified file 'lib/canonical/launchpad/webapp/tests/test_errorlog.py'
286--- lib/canonical/launchpad/webapp/tests/test_errorlog.py 2009-10-15 22:33:49 +0000
287+++ lib/canonical/launchpad/webapp/tests/test_errorlog.py 2009-11-27 19:36:19 +0000
288@@ -3,6 +3,7 @@
289
290 """Tests for error logging & OOPS reporting."""
291
292+from __future__ import with_statement
293 __metaclass__ = type
294
295 import datetime
296@@ -620,8 +621,8 @@
297 # raise UnprintableException()
298 self.assertEqual(
299 lines[17],
300- 'UnprintableException: <unprintable UnprintableException object>\n'
301- )
302+ 'UnprintableException:'
303+ ' <unprintable UnprintableException object>\n')
304
305 def test_raising_unauthorized_without_request(self):
306 """Unauthorized exceptions are logged when there's no request."""
307@@ -776,6 +777,50 @@
308 # raise ArbitraryException(\'xyz\')
309 self.assertEqual(lines[17], 'ArbitraryException: xyz\n')
310
311+ def test_oopsMessage(self):
312+ """oopsMessage pushes and pops the messages."""
313+ utility = ErrorReportingUtility()
314+ with utility.oopsMessage({'a':'b', 'c':'d'}):
315+ self.assertEqual(
316+ {0: {'a':'b', 'c':'d'}}, utility._oops_messages)
317+ # An additional message doesn't supplant the original message.
318+ with utility.oopsMessage(dict(e='f', a='z', c='d')):
319+ self.assertEqual({
320+ 0: {'a':'b', 'c':'d'},
321+ 1: {'a': 'z', 'e': 'f', 'c': 'd'},
322+ }, utility._oops_messages)
323+ # Messages are removed when out of context.
324+ self.assertEqual(
325+ {0: {'a':'b', 'c':'d'}},
326+ utility._oops_messages)
327+
328+ def test__makeErrorReport_includes_oops_messages(self):
329+ """The error report should include the oops messages."""
330+ utility = ErrorReportingUtility()
331+ with utility.oopsMessage(dict(a='b', c='d')):
332+ try:
333+ raise ArbitraryException('foo')
334+ except ArbitraryException:
335+ info = sys.exc_info()
336+ oops = utility._makeErrorReport(info)
337+ self.assertEqual(
338+ [('<oops-message-0>', "{'a': 'b', 'c': 'd'}")],
339+ oops.req_vars)
340+
341+ def test__makeErrorReport_combines_request_and_error_vars(self):
342+ """The oops messages should be distinct from real request vars."""
343+ utility = ErrorReportingUtility()
344+ request = ScriptRequest([('c', 'd')])
345+ with utility.oopsMessage(dict(a='b')):
346+ try:
347+ raise ArbitraryException('foo')
348+ except ArbitraryException:
349+ info = sys.exc_info()
350+ oops = utility._makeErrorReport(info, request)
351+ self.assertEqual(
352+ [('<oops-message-0>', "{'a': 'b'}"), ('c', 'd')],
353+ oops.req_vars)
354+
355
356 class TestSensitiveRequestVariables(unittest.TestCase):
357 """Test request variables that should not end up in the stored OOPS.
358
359=== modified file 'lib/lp/services/job/runner.py'
360--- lib/lp/services/job/runner.py 2009-09-24 04:38:40 +0000
361+++ lib/lp/services/job/runner.py 2009-11-27 19:36:19 +0000
362@@ -4,6 +4,7 @@
363 """Facilities for running Jobs."""
364
365
366+from __future__ import with_statement
367 __metaclass__ = type
368
369
370@@ -138,20 +139,21 @@
371 """Run all the Jobs for this JobRunner."""
372 for job in self.jobs:
373 job = IRunnableJob(job)
374- try:
375- self.runJob(job)
376- except LeaseHeld:
377- self.incomplete_jobs.append(job)
378- except job.user_error_types, e:
379- job.notifyUserError(e)
380- except Exception:
381- info = sys.exc_info()
382- request = errorlog.ScriptRequest(job.getOopsVars())
383- errorlog.globalErrorUtility.raising(info, request)
384- oops = errorlog.globalErrorUtility.getLastOopsReport()
385- job.notifyOops(oops)
386- if self.logger is not None:
387- self.logger.info('Job resulted in OOPS: %s' % oops.id)
388+ with errorlog.globalErrorUtility.oopsMessage(
389+ dict(job.getOopsVars())):
390+ try:
391+ self.runJob(job)
392+ except LeaseHeld:
393+ self.incomplete_jobs.append(job)
394+ except job.user_error_types, e:
395+ job.notifyUserError(e)
396+ except Exception:
397+ info = sys.exc_info()
398+ errorlog.globalErrorUtility.raising(info)
399+ oops = errorlog.globalErrorUtility.getLastOopsReport()
400+ job.notifyOops(oops)
401+ if self.logger is not None:
402+ self.logger.info('Job resulted in OOPS: %s' % oops.id)
403
404
405 class JobCronScript(LaunchpadCronScript):
406
407=== modified file 'lib/lp/services/job/tests/test_runner.py'
408--- lib/lp/services/job/tests/test_runner.py 2009-09-24 05:49:10 +0000
409+++ lib/lp/services/job/tests/test_runner.py 2009-11-27 19:36:19 +0000
410@@ -4,10 +4,16 @@
411 """Tests for job-running facilities."""
412
413
414+from __future__ import with_statement
415+
416+import contextlib
417+import sys
418 from unittest import TestLoader
419
420 import transaction
421 from canonical.testing import LaunchpadZopelessLayer
422+from zope.component import getUtility
423+from zope.error.interfaces import IErrorReportingUtility
424 from zope.interface import implements
425
426 from lp.testing.mail_helpers import pop_notifications
427@@ -125,7 +131,25 @@
428 reporter = errorlog.globalErrorUtility
429 oops = reporter.getLastOopsReport()
430 self.assertIn('Fake exception. Foobar, I say!', oops.tb_text)
431- self.assertEqual([('foo', 'bar')], oops.req_vars)
432+ self.assertEqual(1, len(oops.req_vars))
433+ self.assertEqual("{'foo': 'bar'}", oops.req_vars[0][1])
434+
435+ def test_oops_messages_used_when_handling(self):
436+ """Oops messages should appear even when exceptions are handled."""
437+ job_1, job_2 = self.makeTwoJobs()
438+ def handleError():
439+ reporter = errorlog.globalErrorUtility
440+ try:
441+ raise ValueError('Fake exception. Foobar, I say!')
442+ except ValueError:
443+ reporter.handling(sys.exc_info())
444+ job_1.run = handleError
445+ runner = JobRunner([job_1, job_2])
446+ runner.runAll()
447+ reporter = getUtility(IErrorReportingUtility)
448+ oops = reporter.getLastOopsReport()
449+ self.assertEqual(1, len(oops.req_vars))
450+ self.assertEqual("{'foo': 'bar'}", oops.req_vars[0][1])
451
452 def test_runAll_aborts_transaction_on_error(self):
453 """runAll should abort the transaction on oops."""