launchpad-reviewers team mailing list archive

[Steve Kowalik <stevenk@xxxxxxxxxx>]

Steve Kowalik has proposed merging lp:~stevenk/launchpad/destroy-librarianformatter into lp:launchpad.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)
Related bugs:
  Bug #641103 in Launchpad itself: "LibrarianFormatter should die"
  https://bugs.launchpad.net/launchpad/+bug/641103
  Bug #665307 in Launchpad itself: "cronscripts/expire-bugtasks.py fails trying to put backtrace in librarian"
  https://bugs.launchpad.net/launchpad/+bug/665307

For more details, see:
https://code.launchpad.net/~stevenk/launchpad/destroy-librarianformatter/+merge/135311

Kill LibrarianFormatter and its two doctests entirely.

The new plan is that OopsHandler will log the OOPS created (at level INFO) after it has done so.

With a script raising an uncaught Exception:

2012-11-21 03:36:40 ERROR   Unhandled exception
2012-11-21 03:36:40 INFO    OOPS-432e7c3e29181f82f8352b061429d202

And with a script logging something at ERROR:

2012-11-21 03:38:22 ERROR   Causing OOPS
2012-11-21 03:38:22 INFO    OOPS-ba8ec0f55e9b71f94ce43b65eee2d6c5

I have removed the catch-all exception from cronscripts/expire-bugtasks.py since now OopsHandler will now deal with it. I have also checked the other scripts in cronscripts/*, and none of them use a catch-all exception.
-- 
https://code.launchpad.net/~stevenk/launchpad/destroy-librarianformatter/+merge/135311
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~stevenk/launchpad/destroy-librarianformatter into lp:launchpad.

=== modified file 'cronscripts/expire-bugtasks.py'
--- cronscripts/expire-bugtasks.py	2012-01-01 03:14:54 +0000
+++ cronscripts/expire-bugtasks.py	2012-11-21 04:28:21 +0000
@@ -1,10 +1,8 @@
 #!/usr/bin/python -S
 #
-# Copyright 2009 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2012 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
-# pylint: disable-msg=C0103,W0403
-
 """Expire all old, Incomplete bugs tasks that are unassigned in Malone.
 
 Only bug task for project that use Malone may be expired. The expiration
@@ -47,16 +45,9 @@
             # Avoid circular import.
             from lp.registry.interfaces.distribution import IDistributionSet
             target = getUtility(IDistributionSet).getByName('ubuntu')
-        try:
-            janitor = BugJanitor(
-                log=self.logger, target=target, limit=self.options.limit)
-            janitor.expireBugTasks(self.txn)
-        except Exception:
-            # We use a catchall here because we don't know (and don't care)
-            # about the particular error--we'll just log it to as an Oops.
-            self.logger.error(
-                'An error occured trying to expire bugtasks.', exc_info=1)
-            raise
+        janitor = BugJanitor(
+            log=self.logger, target=target, limit=self.options.limit)
+        janitor.expireBugTasks(self.txn)
 
 
 if __name__ == '__main__':

=== modified file 'lib/lp/services/scripts/base.py'
--- lib/lp/services/scripts/base.py	2012-06-29 08:40:05 +0000
+++ lib/lp/services/scripts/base.py	2012-11-21 04:28:21 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009-2011 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2012 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 __metaclass__ = type
@@ -384,8 +384,7 @@
         """
         self.lock_or_die(blocking=blocking)
         try:
-            self.run(
-                use_web_security=use_web_security, isolation=isolation)
+            self.run(use_web_security=use_web_security, isolation=isolation)
         finally:
             self.unlock(skip_delete=skip_delete)
 
@@ -413,7 +412,8 @@
         # self.name is used instead of the name argument, since it may have
         # have been overridden by command-line parameters or by
         # overriding the name property.
-        logging.getLogger().addHandler(OopsHandler(self.name))
+        oops_hdlr = OopsHandler(self.name, logger=self.logger)
+        logging.getLogger().addHandler(oops_hdlr)
 
     def get_last_activity(self):
         """Return the last activity, if any."""

=== modified file 'lib/lp/services/scripts/logger.py'
--- lib/lp/services/scripts/logger.py	2012-10-12 11:49:10 +0000
+++ lib/lp/services/scripts/logger.py	2012-11-21 04:28:21 +0000
@@ -1,8 +1,6 @@
-# Copyright 2009-2011 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2012 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
-# pylint: disable-msg=W0702
-
 """Logging setup for scripts.
 
 Don't import from this module. Import it from lp.services.scripts.
@@ -10,7 +8,7 @@
 
 __metaclass__ = type
 
-# Don't import stuff from this module. Import it from canonical.scripts
+# Don't import stuff from this module. Import it from lp.services.scripts
 __all__ = [
     'DEBUG2',
     'DEBUG3',
@@ -30,9 +28,6 @@
 
 
 from contextlib import contextmanager
-from cStringIO import StringIO
-from datetime import timedelta
-import hashlib
 import logging
 from logging.handlers import WatchedFileHandler
 from optparse import OptionParser
@@ -42,19 +37,10 @@
 import time
 from traceback import format_exception_only
 
-from zope.component import getUtility
 from zope.exceptions.log import Formatter
 
 from lp.services.config import config
-from lp.services.librarian.interfaces.client import (
-    ILibrarianClient,
-    UploadFailed,
-    )
 from lp.services.log import loglevels
-from lp.services.utils import (
-    compress_hash,
-    utc_now,
-    )
 from lp.services.webapp.errorlog import (
     globalErrorUtility,
     ScriptRequest,
@@ -75,12 +61,13 @@
 class OopsHandler(logging.Handler):
     """Handler to log to the OOPS system."""
 
-    def __init__(self, script_name, level=logging.WARN):
+    def __init__(self, script_name, level=logging.WARN, logger=None):
         logging.Handler.__init__(self, level)
         # Context for OOPS reports.
         self.request = ScriptRequest(
             [('script_name', script_name), ('path', sys.argv[0])])
         self.setFormatter(LaunchpadFormatter())
+        self.logger = logger
 
     def emit(self, record):
         """Emit a record as an OOPS."""
@@ -91,6 +78,8 @@
             msg = record.getMessage()
             with globalErrorUtility.oopsMessage(msg):
                 globalErrorUtility.raising(info, self.request)
+                if self.logger:
+                    self.logger.info(self.request.oopsid)
         except Exception:
             self.handleError(record)
 
@@ -109,58 +98,9 @@
         # Output should be UTC.
         self.converter = time.gmtime
 
-
-class LibrarianFormatter(LaunchpadFormatter):
-    """A logging.Formatter that stores tracebacks in the Librarian and emits
-    a URL rather than emitting the traceback directly.
-
-    The traceback will be emitted as a fallback if the Librarian cannot be
-    contacted.
-
-    XXX bug=641103 StuartBishop -- This class should die. Remove it and
-    replace with LaunchpadFormatter, fixing the test fallout.
-    """
-
     def formatException(self, ei):
-        """Format the exception and store it in the Librian.
-
-        Returns the URL, or the formatted exception if the Librarian is
-        not available.
-        """
-        traceback = LaunchpadFormatter.formatException(self, ei)
-        # Uncomment this line to stop exception storage in the librarian.
-        # Useful for debugging tests.
-        # return traceback
-        try:
-            librarian = getUtility(ILibrarianClient)
-        except LookupError:
-            return traceback
-
-        exception_string = ''
-        try:
-            exception_string = str(ei[1]).encode('ascii')
-        except:
-            pass
-        if not exception_string:
-            exception_string = ei[0].__name__
-
-        expiry = utc_now() + timedelta(days=90)
-        try:
-            filename = compress_hash(hashlib.sha1(traceback)) + '.txt'
-            url = librarian.remoteAddFile(
-                    filename, len(traceback), StringIO(traceback),
-                    'text/plain;charset=%s' % sys.getdefaultencoding(),
-                    expires=expiry)
-            return ' -> %s (%s)' % (url, exception_string)
-        except UploadFailed:
-            return traceback
-        except Exception:
-            # Exceptions raised by the Formatter get swallowed, but we want
-            # to know about them. Since we are already spitting out exception
-            # information, we can stuff our own problems in there too.
-            return '%s\n\nException raised in formatter:\n%s\n' % (
-                    traceback,
-                    LaunchpadFormatter.formatException(self, sys.exc_info()))
+        # We don't want the traceback, so do nothing.
+        pass
 
 
 class LogLevelNudger:
@@ -393,9 +333,8 @@
         root_logger.removeHandler(hdlr)
 
 
-def _logger(
-    level, out_stream, name=None,
-    log_file=None, log_file_level=logging.DEBUG, milliseconds=False):
+def _logger(level, out_stream, name=None, log_file=None,
+            log_file_level=logging.DEBUG, milliseconds=False):
     """Create the actual logger instance, logging at the given level
 
     if name is None, it will get args[0] without the extension (e.g. gina).
@@ -423,12 +362,7 @@
     # logs.
     root_logger.setLevel(0)
     hdlr.setLevel(level)
-    if milliseconds:
-        # Python default datefmt includes milliseconds.
-        formatter = LibrarianFormatter(datefmt=None)
-    else:
-        # Launchpad default datefmt does not include milliseconds.
-        formatter = LibrarianFormatter()
+    formatter = LaunchpadFormatter()
     hdlr.setFormatter(formatter)
     root_logger.addHandler(hdlr)
 

=== removed file 'lib/lp/services/scripts/tests/librarianformatter.txt'
--- lib/lp/services/scripts/tests/librarianformatter.txt	2011-12-28 17:03:06 +0000
+++ lib/lp/services/scripts/tests/librarianformatter.txt	1970-01-01 00:00:00 +0000
@@ -1,142 +0,0 @@
-
-The LibrarianFormatter works just like a normal logger.Formatter if there
-is no Librarian available or active
-
->>> from lp.services.scripts.logger import LibrarianFormatter
-
-This is a helper to quickly construct a Logger instance with a particular
-formatter. Each call generates a unique Logger.
-
->>> _count = 0
->>> def make_logger(formatter_class):
-...     global _count
-...     _count += 1
-...     logger = logging.getLogger('log%d' % _count)
-...     output = StringIO()
-...     handler = logging.StreamHandler(output)
-...     # Note - no timestamp so we can make valid comparisons!
-...     formatter = formatter_class(fmt='%(levelname)s %(message)s')
-...     handler.setFormatter(formatter)
-...     logger.addHandler(handler)
-...     logger.setLevel(logging.DEBUG)
-...     logger.propagate = False
-...     return logger, output
-
-Create an exception we can reuse
-
->>> try:
-...     raise RuntimeError('An Exception')
-... except RuntimeError:
-...     exception = sys.exc_info()
-
-Because no Librarian is running, output from the two loggers should be
-identical. Note the overhead involved in attempting to contact the
-Librarian is not significant.
-
->>> from lp.testing.layers import LibrarianLayer
->>> LibrarianLayer.hide()
-
->>> from lp.services.utils import utc_now
-
->>> normal_log, normal_out= make_logger(logging.Formatter)
->>> librarian_log, librarian_out = make_logger(LibrarianFormatter)
->>> import time
->>> start_time = time.time()
->>> for log in (normal_log, librarian_log):
-...     log.error('Blah!', exc_info=exception)
->>> end_time = time.time()
->>> (end_time - start_time) < 5.0
-True
-
->>> print normal_out.getvalue()
-ERROR Blah!
-Traceback (most recent call last):
-...
-RuntimeError: An Exception
-<BLANKLINE>
-
->>> print librarian_out.getvalue()
-ERROR Blah!
-Traceback (most recent call last):
-...
-RuntimeError: An Exception
-<BLANKLINE>
-
->>> normal_out.getvalue() == librarian_out.getvalue()
-True
-
-Now if we fire up the Librarian, the LibrarianFormatter should start
-storing tracebacks there instead, reducing the verbosity of spam from
-cronjobs
-
->>> LibrarianLayer.reveal()
->>> librarian_log, librarian_out = make_logger(LibrarianFormatter)
->>> librarian_log.error('Oops', exc_info=exception)
->>> print librarian_out.getvalue()
-ERROR Oops
- -> http://.../....txt (An Exception)
->>> url = librarian_out.getvalue().splitlines()[-1].split()[1:2][0]
->>> print url
-http://.../....txt
->>> print urlopen(url).read()
-Traceback (most recent call last):
-    ...
-RuntimeError: An Exception
-
-As the librarian commits to the test database in a subprocess, we need
-to force the DatabaseLayer to fully tear down and restore the database
-after this test.
-
->>> from lp.testing.layers import DatabaseLayer
->>> DatabaseLayer.force_dirty_database()
-
-We keep exceptions from expiring for about 3 months.
-
->>> match = re.search('/(\d+)/', url)
->>> alias_id = match.group(1)
->>> from lp.services.librarian.model import LibraryFileAlias
->>> transaction.abort() # To see db changes made by the librarian
->>> alias = LibraryFileAlias.get(alias_id)
->>> alias.expires > utc_now() + timedelta(days=89)
-True
-
-Note that we also need to remain informative with dud exceptions, such as
-those with a non-ASCII string representation or no string representation
-at all
-
->>> librarian_log, librarian_out = make_logger(LibrarianFormatter)
->>> class Dud(Exception):
-...     pass
->>> try:
-...     raise Dud()
-... except Dud:
-...     librarian_log.exception('Dud1')
->>> try:
-...     raise Dud(u'\N{BIOHAZARD SIGN}'.encode('utf8'))
-... except Dud:
-...     librarian_log.exception('Dud2')
->>> print librarian_out.getvalue()
-ERROR Dud1
- -> http://.../....txt (Dud)
-ERROR Dud2
- -> http://.../....txt (Dud)
-<BLANKLINE>
-
-The end result of this is to not have scripts display exceptions to
-stderr, instead reporting URLs and greatly reducing the verbosity.
-
->>> script = os.path.join(this_directory, 'raiseexception.py')
->>> import subprocess
->>> p = subprocess.Popen([sys.executable, script], stdin=subprocess.PIPE,
-...     stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
->>> (out, err) = p.communicate()
->>> p.returncode
-0
->>> print out
-Script Output
-ERROR   Oops
- -> http://.../....txt (Aargh)
-ERROR   Root oops
- -> http://.../....txt (Aargh)
-
-

=== removed file 'lib/lp/services/scripts/tests/librarianformatter_noca.txt'
--- lib/lp/services/scripts/tests/librarianformatter_noca.txt	2011-12-21 19:44:48 +0000
+++ lib/lp/services/scripts/tests/librarianformatter_noca.txt	1970-01-01 00:00:00 +0000
@@ -1,66 +0,0 @@
->>> import logging
->>> import sys
->>> from cStringIO import StringIO
-
-The LibrarianFormatter works just like a normal logger.Formatter if there
-is no Librarian available or active
-
->>> from lp.services.scripts.logger import LibrarianFormatter
-
-This is a helper to quickly construct a Logger instance with a particular
-formatter. Each call generates a unique Logger.
-
->>> _count = 0
->>> def make_logger(formatter_class):
-...     global _count
-...     _count += 1
-...     logger = logging.getLogger('log%d' % _count)
-...     output = StringIO()
-...     handler = logging.StreamHandler(output)
-...     # Note - no timestamp so we can make valid comparisons!
-...     formatter = formatter_class(fmt='%(levelname)s %(message)s')
-...     handler.setFormatter(formatter)
-...     logger.addHandler(handler)
-...     logger.setLevel(logging.DEBUG)
-...     return logger, output
-
-Now setup two identical Logger instances except for their formatter
-
->>> normal_log, normal_out = make_logger(logging.Formatter)
->>> librarian_log, librarian_out = make_logger(LibrarianFormatter)
-
-Output from the standard formatter should match the output from
-LibrianFormatter at this stage, as we have no component architecture
-loaded and no Librarian running.
-
-First, create an exception we can reuse
-
->>> try:
-...     raise RuntimeError('An Exception')
-... except RuntimeError:
-...     exception = sys.exc_info()
-...     for log in (normal_log, librarian_log):
-...         log.info('Some crap')
-...         log.error('Oops!', exc_info=exception)
-...         log.error('Error %d occurred', 42)
->>> normal_out.getvalue() == librarian_out.getvalue()
-True
->>> print normal_out.getvalue()
-INFO Some crap
-ERROR Oops!
-Traceback (most recent call last):
-  File "<doctest librarianformatter_noca.txt[...]>", line 2, in <module>
-    raise RuntimeError('An Exception')
-RuntimeError: An Exception
-ERROR Error 42 occurred
-<BLANKLINE>
->>> print librarian_out.getvalue()
-INFO Some crap
-ERROR Oops!
-Traceback (most recent call last):
-  File "<doctest librarianformatter_noca.txt[...]>", line 2, in <module>
-    raise RuntimeError('An Exception')
-RuntimeError: An Exception
-ERROR Error 42 occurred
-<BLANKLINE>
-

=== removed file 'lib/lp/services/scripts/tests/raiseexception.py'
--- lib/lp/services/scripts/tests/raiseexception.py	2011-12-21 20:23:01 +0000
+++ lib/lp/services/scripts/tests/raiseexception.py	1970-01-01 00:00:00 +0000
@@ -1,35 +0,0 @@
-# Copyright 2009 Canonical Ltd.  This software is licensed under the
-# GNU Affero General Public License version 3 (see the file LICENSE).
-
-"""This script is called from librarianformatter.txt to
-demonstrate a script using the LibrarianFormatter
-"""
-
-__metaclass__ = type
-
-import logging
-from optparse import OptionParser
-import sys
-
-from lp.services.scripts import (
-    execute_zcml_for_scripts,
-    logger,
-    logger_options,
-    )
-
-
-if __name__ == '__main__':
-    parser = OptionParser()
-    logger_options(parser)
-    (options, args) = parser.parse_args()
-    log = logger(options)
-    # Test the root logger too, because some code is using it
-    root_log = logging.getLogger()
-    execute_zcml_for_scripts()
-    print >> sys.stderr, 'Script Output'
-    try:
-        raise RuntimeError('Aargh')
-    except RuntimeError:
-        log.exception('Oops')
-        root_log.exception('Root oops')
-

=== removed file 'lib/lp/services/scripts/tests/test_librarianformatter.py'
--- lib/lp/services/scripts/tests/test_librarianformatter.py	2011-12-28 17:03:06 +0000
+++ lib/lp/services/scripts/tests/test_librarianformatter.py	1970-01-01 00:00:00 +0000
@@ -1,45 +0,0 @@
-# Copyright 2009 Canonical Ltd.  This software is licensed under the
-# GNU Affero General Public License version 3 (see the file LICENSE).
-
-"""Module docstring goes here."""
-
-__metaclass__ = type
-
-from datetime import (
-    datetime,
-    timedelta,
-    )
-import logging
-import os.path
-import re
-from StringIO import StringIO
-import sys
-import time
-from urllib2 import urlopen
-
-from pytz import utc
-import transaction
-
-from lp.testing import (
-    ANONYMOUS,
-    login,
-    logout,
-    )
-from lp.testing.layers import LaunchpadFunctionalLayer
-from lp.testing.systemdocs import LayeredDocFileSuite
-
-
-this_directory = os.path.dirname(__file__)
-
-def setUp(test):
-    # Suck this modules environment into the test environment
-    test.globs.update(globals())
-    login(ANONYMOUS)
-
-def tearDown(test):
-    logout()
-
-def test_suite():
-    return LayeredDocFileSuite(
-        'librarianformatter.txt', setUp=setUp, tearDown=tearDown,
-        layer=LaunchpadFunctionalLayer)

=== removed file 'lib/lp/services/scripts/tests/test_librarianformatter_noca.py'
--- lib/lp/services/scripts/tests/test_librarianformatter_noca.py	2011-12-28 17:03:06 +0000
+++ lib/lp/services/scripts/tests/test_librarianformatter_noca.py	1970-01-01 00:00:00 +0000
@@ -1,22 +0,0 @@
-# Copyright 2009 Canonical Ltd.  This software is licensed under the
-# GNU Affero General Public License version 3 (see the file LICENSE).
-
-"""Python harness for librarianformatter_noca.txt."""
-
-__metaclass__ = type
-
-from lp.testing import reset_logging
-from lp.testing.systemdocs import LayeredDocFileSuite
-
-
-def setUp(test):
-    # Suck this modules environment into the test environment
-    reset_logging()
-
-def tearDown(test):
-    reset_logging()
-
-def test_suite():
-    return LayeredDocFileSuite(
-        'librarianformatter_noca.txt',
-        setUp=setUp, tearDown=tearDown, stdout_logging=False)