Merge lp:~allenap/launchpad/use-zope-tb-formatter into lp:launchpad

[Gavin Panella]

[r=jtv][bug=715659] Use zope.exceptions to format logged exceptions so that __traceback_info__ is reported.

This branch does two things:

- Adds a new function, traceback_info(), that injects a
  __traceback_info__ local variable into the calling frame. From
  its docstring:

    This is more aesthetically pleasing that assigning to
    __traceback_info__, but it more importantly avoids spurious
    lint warnings about unused local variables, and helps to
    avoid typos.

- Uses zope.exceptions to format logged exceptions, which means that
  the traceback info will be included.

The OOPS tools already use zope.exceptions to format exceptions so
this extra info should show up in OOPS reports soon.

[Jeroen T. Vermeulen (jtv)]

Awesome. I had to struggle to come up with a nit to pick.

What I came up with was pitiful:

213 + # The local variable __traceback_info__ is set by `traceback_info`.

Text may be improved if the passive voice is avoided.

Jeroen

review: Approve

=== modified file 'lib/canonical/launchpad/scripts/logger.py'
--- lib/canonical/launchpad/scripts/logger.py	2010-12-20 20:36:16 +0000
+++ lib/canonical/launchpad/scripts/logger.py	2011-02-09 11:03:45 +0000
@@ -15,13 +15,19 @@
 
 # Don't import stuff from this module. Import it from canonical.scripts
 __all__ = [
+    'DEBUG2',
+    'DEBUG3',
+    'DEBUG4',
+    'DEBUG5',
+    'DEBUG6',
+    'DEBUG7',
+    'DEBUG8',
+    'DEBUG9',
+    'LaunchpadFormatter',
     'log',
     'logger',
     'logger_options',
     'OopsHandler',
-    'LaunchpadFormatter',
-    'DEBUG2', 'DEBUG3', 'DEBUG4', 'DEBUG5',
-    'DEBUG6', 'DEBUG7', 'DEBUG8', 'DEBUG9',
     ]
 
 
@@ -38,10 +44,11 @@
 import re
 import sys
 import time
-import traceback
+from traceback import format_exception_only
 
 from pytz import utc
 from zope.component import getUtility
+from zope.exceptions.log import Formatter
 
 from canonical.base import base
 from canonical.config import config
@@ -55,7 +62,6 @@
     )
 from lp.services.log import loglevels
 
-
 # Reexport our custom loglevels for old callsites. These callsites
 # should be importing the symbols from lp.services.log.loglevels
 DEBUG2 = loglevels.DEBUG2
@@ -91,7 +97,7 @@
             self.handleError(record)
 
 
-class LaunchpadFormatter(logging.Formatter):
+class LaunchpadFormatter(Formatter):
     """logging.Formatter encoding our preferred output format."""
 
     def __init__(self, fmt=None, datefmt=None):
@@ -124,7 +130,7 @@
         Returns the URL, or the formatted exception if the Librarian is
         not available.
         """
-        traceback = logging.Formatter.formatException(self, ei)
+        traceback = LaunchpadFormatter.formatException(self, ei)
         # Uncomment this line to stop exception storage in the librarian.
         # Useful for debugging tests.
         # return traceback
@@ -158,7 +164,7 @@
             # information, we can stuff our own problems in there too.
             return '%s\n\nException raised in formatter:\n%s\n' % (
                     traceback,
-                    logging.Formatter.formatException(self, sys.exc_info()))
+                    LaunchpadFormatter.formatException(self, sys.exc_info()))
 
 
 def logger_options(parser, default=logging.INFO):
@@ -408,7 +414,7 @@
     def shortException(self, msg, *args):
         """Like Logger.exception, but does not print a traceback."""
         exctype, value = sys.exc_info()[:2]
-        report = ''.join(traceback.format_exception_only(exctype, value))
+        report = ''.join(format_exception_only(exctype, value))
         # _log.error interpolates msg, so we need to escape % chars
         msg += '\n' + report.rstrip('\n').replace('%', '%%')
         self._log.error(msg, *args)

=== modified file 'lib/canonical/launchpad/scripts/tests/test_logger.py'
--- lib/canonical/launchpad/scripts/tests/test_logger.py	2010-10-04 19:50:45 +0000
+++ lib/canonical/launchpad/scripts/tests/test_logger.py	2011-02-09 11:03:45 +0000
@@ -6,13 +6,55 @@
 __metaclass__ = type
 __all__ = []
 
+import doctest
+from sys import exc_info
 import unittest
 
+from testtools.matchers import DocTestMatches
+
+from canonical.launchpad.scripts.logger import LaunchpadFormatter
 from canonical.launchpad.testing.systemdocs import LayeredDocFileSuite
 from canonical.testing.layers import BaseLayer
+from lp.services.utils import traceback_info
+from lp.testing import TestCase
+
+
+DOCTEST_FLAGS = (
+    doctest.ELLIPSIS |
+    doctest.NORMALIZE_WHITESPACE |
+    doctest.REPORT_NDIFF)
+
+
+class TestLaunchpadFormatter(TestCase):
+    """Tests of `LaunchpadFormatter`."""
+
+    def test_traceback_info(self):
+        # LaunchpadFormatter inherits from zope.exceptions.log.Formatter, so
+        # __traceback_info__ annotations are included in formatted exceptions.
+
+        traceback_info("Captain Kirk")
+
+        try:
+            0/0
+        except ZeroDivisionError:
+            info = exc_info()
+
+        self.assertThat(
+            LaunchpadFormatter().formatException(info),
+            DocTestMatches(
+                flags=DOCTEST_FLAGS, example="""
+                    Traceback (most recent call last):
+                    ...
+                    __traceback_info__: Captain Kirk
+                    ZeroDivisionError: ...
+                    """))
 
 
 def test_suite():
-    return unittest.TestSuite([
+    suite = unittest.TestSuite()
+    suite.addTest(
         LayeredDocFileSuite(
-            'test_logger.txt', layer=BaseLayer),])
+            'test_logger.txt', layer=BaseLayer))
+    suite.addTest(
+        unittest.TestLoader().loadTestsFromName(__name__))
+    return suite

=== modified file 'lib/lp/services/tests/test_utils.py'
--- lib/lp/services/tests/test_utils.py	2011-01-26 22:07:08 +0000
+++ lib/lp/services/tests/test_utils.py	2011-02-09 11:03:45 +0000
@@ -14,6 +14,7 @@
     decorate_with,
     docstring_dedent,
     iter_split,
+    traceback_info,
     )
 from lp.testing import TestCase
 
@@ -42,35 +43,35 @@
         # The same iterator can be used multiple times.
         iterator = CachingIterator(itertools.count())
         self.assertEqual(
-            [0,1,2,3,4], list(itertools.islice(iterator, 0, 5)))
+            [0, 1, 2, 3, 4], list(itertools.islice(iterator, 0, 5)))
         self.assertEqual(
-            [0,1,2,3,4], list(itertools.islice(iterator, 0, 5)))
+            [0, 1, 2, 3, 4], list(itertools.islice(iterator, 0, 5)))
 
     def test_more_values(self):
         # If a subsequent call to iter causes more values to be fetched, they
         # are also cached.
         iterator = CachingIterator(itertools.count())
         self.assertEqual(
-            [0,1,2], list(itertools.islice(iterator, 0, 3)))
+            [0, 1, 2], list(itertools.islice(iterator, 0, 3)))
         self.assertEqual(
-            [0,1,2,3,4], list(itertools.islice(iterator, 0, 5)))
+            [0, 1, 2, 3, 4], list(itertools.islice(iterator, 0, 5)))
 
     def test_limited_iterator(self):
         # Make sure that StopIteration is handled correctly.
-        iterator = CachingIterator(iter([0,1,2,3,4]))
+        iterator = CachingIterator(iter([0, 1, 2, 3, 4]))
         self.assertEqual(
-            [0,1,2], list(itertools.islice(iterator, 0, 3)))
-        self.assertEqual([0,1,2,3,4], list(iterator))
+            [0, 1, 2], list(itertools.islice(iterator, 0, 3)))
+        self.assertEqual([0, 1, 2, 3, 4], list(iterator))
 
     def test_parallel_iteration(self):
         # There can be parallel iterators over the CachingIterator.
-        ci = CachingIterator(iter([0,1,2,3,4]))
+        ci = CachingIterator(iter([0, 1, 2, 3, 4]))
         i1 = iter(ci)
         i2 = iter(ci)
         self.assertEqual(0, i1.next())
         self.assertEqual(0, i2.next())
-        self.assertEqual([1,2,3,4], list(i2))
-        self.assertEqual([1,2,3,4], list(i1))
+        self.assertEqual([1, 2, 3, 4], list(i2))
+        self.assertEqual([1, 2, 3, 4], list(i1))
 
 
 class TestDecorateWith(TestCase):
@@ -155,5 +156,17 @@
         result = 'This is a multiline docstring.\n\nThis is the second line.'
         self.assertEqual(docstring_dedent(docstring), result)
 
+
+class TestTracebackInfo(TestCase):
+    """Tests of `traceback_info`."""
+
+    def test(self):
+        # `traceback_info` sets the local variable __traceback_info__ in the
+        # caller's frame.
+        self.assertEqual(None, locals().get("__traceback_info__"))
+        traceback_info("Pugwash")
+        self.assertEqual("Pugwash", locals().get("__traceback_info__"))
+
+
 def test_suite():
     return unittest.TestLoader().loadTestsFromName(__name__)

=== modified file 'lib/lp/services/utils.py'
--- lib/lp/services/utils.py	2011-02-08 15:08:01 +0000
+++ lib/lp/services/utils.py	2011-02-09 11:03:45 +0000
@@ -15,10 +15,12 @@
     'iter_split',
     'synchronize',
     'text_delta',
+    'traceback_info',
     'value_string',
     ]
 
 from itertools import tee
+import sys
 from textwrap import dedent
 
 from lazr.enum import BaseItem
@@ -150,3 +152,13 @@
     # Make sure there is at least one newline so the split works.
     first, rest = (s+'\n').split('\n', 1)
     return (first + '\n' + dedent(rest)).strip()
+
+
+def traceback_info(info):
+    """Set `__traceback_info__` in the caller's locals.
+
+    This is more aesthetically pleasing that assigning to __traceback_info__,
+    but it more importantly avoids spurious lint warnings about unused local
+    variables, and helps to avoid typos.
+    """
+    sys._getframe(1).f_locals["__traceback_info__"] = info