launchpad-reviewers team mailing list archive
-
launchpad-reviewers team
-
Mailing list archive
-
Message #01118
[Merge] lp:~stub/launchpad/cronscripts into lp:launchpad/devel
Stuart Bishop has proposed merging lp:~stub/launchpad/cronscripts into lp:launchpad/devel.
Requested reviews:
Launchpad code reviewers (launchpad-reviewers)
Related bugs:
#605822 Cronscripts should have top-level exception handler
https://bugs.launchpad.net/bugs/605822
#607391 upgrade robustness for cronscripts
https://bugs.launchpad.net/bugs/607391
Make cronscripts better.
Log unhandled exceptions, and generate OOPS reports for WARN, ERROR and CRITICAL log messages.
--
https://code.launchpad.net/~stub/launchpad/cronscripts/+merge/36005
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~stub/launchpad/cronscripts into lp:launchpad/devel.
=== modified file 'lib/canonical/launchpad/scripts/logger.py'
--- lib/canonical/launchpad/scripts/logger.py 2010-08-20 20:31:18 +0000
+++ lib/canonical/launchpad/scripts/logger.py 2010-09-20 12:08:52 +0000
@@ -21,8 +21,10 @@
'BufferLogger',
'FakeLogger',
'QuietFakeLogger',
+ 'OopsHandler',
+ 'LaunchpadFormatter',
'DEBUG2', 'DEBUG3', 'DEBUG4', 'DEBUG5',
- 'DEBUG6', 'DEBUG7', 'DEBUG8', 'DEBUG9'
+ 'DEBUG6', 'DEBUG7', 'DEBUG8', 'DEBUG9',
]
@@ -44,6 +46,10 @@
from canonical.base import base
from canonical.config import config
+from canonical.launchpad.webapp.errorlog import (
+ globalErrorUtility,
+ ScriptRequest,
+ )
from canonical.librarian.interfaces import (
ILibrarianClient,
UploadFailed,
@@ -72,6 +78,7 @@
class FakeLogger:
"""Emulates a proper logger, just printing everything out the given file.
"""
+
def __init__(self, output_file=None):
"""The default output_file is sys.stdout."""
self.output_file = output_file
@@ -123,12 +130,14 @@
Does not print any message. Messages can be retrieved from
logger.output_file, which is a StringIO instance.
"""
+
def __init__(self):
self.output_file = StringIO()
class BufferLogger(FakeLogger):
"""A logger that logs to a StringIO object."""
+
def __init__(self):
self.buffer = StringIO()
@@ -142,13 +151,54 @@
self.log(line)
-class LibrarianFormatter(logging.Formatter):
+class OopsHandler(logging.Handler):
+ """Handler to log to the OOPS system."""
+
+ def __init__(self, name, level=logging.WARN):
+ logging.Handler.__init__(self, level)
+ # Context for OOPS reports.
+ self.request = ScriptRequest(
+ [('name', name), ('path', sys.argv[0])])
+ self.setFormatter(LaunchpadFormatter())
+
+ def emit(self, record):
+ """Emit a record as an OOPS."""
+ try:
+ msg = record.getMessage()
+ # Warnings and less are informational OOPS reports.
+ informational = (record.levelno <= logging.WARN)
+ with globalErrorUtility.oopsMessage(msg):
+ globalErrorUtility._raising(
+ sys.exc_info(), self.request, informational=informational)
+ except Exception, error:
+ self.handleError(record)
+
+
+class LaunchpadFormatter(logging.Formatter):
+ """logging.Formatter encoding our preferred output format."""
+
+ def __init__(self):
+ if config.instance_name == 'testrunner':
+ # Don't output timestamps in the test environment
+ fmt = '%(levelname)-7s %(message)s'
+ else:
+ fmt = '%(asctime)s %(levelname)-7s %(message)s'
+ datefmt = "%Y-%m-%d %H:%M:%S"
+ logging.Formatter.__init__(self, fmt, datefmt)
+ self.converter = time.gmtime # Output should be UTC
+
+
+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.
@@ -174,14 +224,12 @@
expiry = datetime.now().replace(tzinfo=utc) + timedelta(days=90)
try:
- filename = base(
- long(hashlib.sha1(traceback).hexdigest(),16), 62
- ) + '.txt'
+ filename = base(long(
+ hashlib.sha1(traceback).hexdigest(), 16), 62) + '.txt'
url = librarian.remoteAddFile(
filename, len(traceback), StringIO(traceback),
'text/plain;charset=%s' % sys.getdefaultencoding(),
- expires=expiry
- )
+ expires=expiry)
return ' -> %s (%s)' % (url, exception_string)
except UploadFailed:
return traceback
@@ -191,8 +239,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())
- )
+ logging.Formatter.formatException(self, sys.exc_info()))
def logger_options(parser, default=logging.INFO):
@@ -271,16 +318,13 @@
parser.add_option(
"-v", "--verbose", dest="loglevel", default=default,
action="callback", callback=dec_loglevel,
- help="Increase verbosity. May be specified multiple times."
- )
+ help="Increase verbosity. May be specified multiple times.")
parser.add_option(
"-q", "--quiet", action="callback", callback=inc_loglevel,
- help="Decrease verbosity. May be specified multiple times."
- )
+ help="Decrease verbosity. May be specified multiple times.")
parser.add_option(
"--log-file", action="store", type="string",
- help="Send log to the given file, rather than stderr."
- )
+ help="Send log to the given file, rather than stderr.")
# Set the global log
log._log = _logger(default, out_stream=sys.stderr)
@@ -351,24 +395,18 @@
# both command line tools and cron jobs (command line tools often end
# up being run from inside cron, so this is a good thing).
hdlr = logging.StreamHandler(strm=out_stream)
- if config.instance_name == 'testrunner':
- # Don't output timestamps in the test environment
- fmt = '%(levelname)-7s %(message)s'
- else:
- fmt = '%(asctime)s %(levelname)-7s %(message)s'
- formatter = LibrarianFormatter(
- fmt=fmt,
- datefmt="%Y-%m-%d %H:%M:%S",
- )
- formatter.converter = time.gmtime # Output should be UTC
+ # We set the level on the handler rather than the logger, so other
+ # handlers with different levels can be added for things like debug
+ # logs.
+ root_logger.setLevel(0)
+ hdlr.setLevel(level)
+ formatter = LaunchpadFormatter()
hdlr.setFormatter(formatter)
root_logger.addHandler(hdlr)
# Create our logger
logger = logging.getLogger(name)
- logger.setLevel(level)
-
# Set the global log
log._log = logger
@@ -406,5 +444,3 @@
log = _LogWrapper(logging.getLogger())
-
-
=== modified file 'lib/canonical/launchpad/webapp/errorlog.py'
--- lib/canonical/launchpad/webapp/errorlog.py 2010-09-15 22:09:12 +0000
+++ lib/canonical/launchpad/webapp/errorlog.py 2010-09-20 12:08:52 +0000
@@ -31,7 +31,6 @@
from canonical.launchpad.layers import WebServiceLayer
from canonical.launchpad.webapp.adapter import (
get_request_duration,
- get_request_start_time,
soft_timeout_expired,
)
from canonical.launchpad.webapp.interfaces import (
@@ -457,7 +456,7 @@
duration = get_request_duration()
# In principle the timeline is per-request, but see bug=623199 -
# at this point the request is optional, but get_request_timeline
- # does not care; when it starts caring, we will always have a
+ # does not care; when it starts caring, we will always have a
# request object (or some annotations containing object).
# RBC 20100901
timeline = get_request_timeline(request)
@@ -517,8 +516,10 @@
"""Add an oops message to be included in oopses from this context."""
key = self._oops_message_key_iter.next()
self._oops_messages[key] = message
- yield
- del self._oops_messages[key]
+ try:
+ yield
+ finally:
+ del self._oops_messages[key]
globalErrorUtility = ErrorReportingUtility()
=== modified file 'lib/lp/services/scripts/base.py'
--- lib/lp/services/scripts/base.py 2010-09-17 04:45:30 +0000
+++ lib/lp/services/scripts/base.py 2010-09-20 12:08:52 +0000
@@ -29,15 +29,19 @@
from canonical.database.sqlbase import ISOLATION_LEVEL_DEFAULT
from canonical.launchpad import scripts
from canonical.launchpad.interfaces import IScriptActivitySet
+from canonical.launchpad.scripts.logger import LaunchpadFormatter, OopsHandler
+from canonical.launchpad.webapp.errorlog import globalErrorUtility
from canonical.launchpad.webapp.interaction import (
ANONYMOUS,
setupInteractionByEmail,
)
from canonical.lp import initZopeless
+from lp.services.log.uniquefileallocator import UniqueFileAllocator
+
LOCK_PATH = "/var/lock/"
-UTC = pytz.timezone('UTC')
+UTC = pytz.UTC
class LaunchpadScriptFailure(Exception):
@@ -67,6 +71,35 @@
exit_status = 1
+def log_unhandled_exception_and_exit(func):
+ """Decorator that logs unhandled exceptions via the logging module.
+
+ Exceptions are reraised except at the top level. ie. exceptions are
+ only propagated to the outermost decorated method. At the top level,
+ an exception causes the script to terminate.
+
+ Only for methods of `LaunchpadScript` and subclasses. Not thread safe,
+ which is fine as the decorated LaunchpadScript methods are only
+ invoked from the main thread.
+ """
+
+ def log_unhandled_exceptions_func(self, *args, **kw):
+ try:
+ self._log_unhandled_exceptions_level += 1
+ return func(self, *args, **kw)
+ except:
+ if self._log_unhandled_exceptions_level == 1:
+ # self.logger is setup in LaunchpadScript.__init__() so
+ # we can use it.
+ self.logger.exception("Unhandled exception")
+ sys.exit(42)
+ else:
+ raise
+ finally:
+ self._log_unhandled_exceptions_level -= 1
+ return log_unhandled_exceptions_func
+
+
class LaunchpadScript:
"""A base class for runnable scripts and cronscripts.
@@ -102,6 +135,9 @@
lockfilepath = None
loglevel = logging.INFO
+ # State for the log_unhandled_exceptions decorator.
+ _log_unhandled_exceptions_level = 0
+
def __init__(self, name=None, dbuser=None, test_args=None):
"""Construct new LaunchpadScript.
@@ -170,6 +206,7 @@
#
# Convenience or death
#
+ @log_unhandled_exception_and_exit
def login(self, user):
"""Super-convenience method that avoids the import."""
setupInteractionByEmail(user)
@@ -196,6 +233,7 @@
"""
self.lock = GlobalLock(self.lockfilepath, logger=self.logger)
+ @log_unhandled_exception_and_exit
def lock_or_die(self, blocking=False):
"""Attempt to lock, and sys.exit(1) if the lock's already taken.
@@ -209,6 +247,7 @@
self.logger.debug('Lockfile %s in use' % self.lockfilepath)
sys.exit(1)
+ @log_unhandled_exception_and_exit
def lock_or_quit(self, blocking=False):
"""Attempt to lock, and sys.exit(0) if the lock's already taken.
@@ -223,6 +262,7 @@
self.logger.info('Lockfile %s in use' % self.lockfilepath)
sys.exit(0)
+ @log_unhandled_exception_and_exit
def unlock(self, skip_delete=False):
"""Release the lock. Do this before going home.
@@ -232,6 +272,7 @@
"""
self.lock.release(skip_delete=skip_delete)
+ @log_unhandled_exception_and_exit
def run(self, use_web_security=False, implicit_begin=True,
isolation=ISOLATION_LEVEL_DEFAULT):
"""Actually run the script, executing zcml and initZopeless."""
@@ -277,6 +318,7 @@
#
# Make things happen
#
+ @log_unhandled_exception_and_exit
def lock_and_run(self, blocking=False, skip_delete=False,
use_web_security=False, implicit_begin=True,
isolation=ISOLATION_LEVEL_DEFAULT):
@@ -306,11 +348,25 @@
"""
super(LaunchpadCronScript, self).__init__(name, dbuser, test_args)
+ name = self.name
+
+ # Customize the globalErrorUtility for script OOPS reporting.
+ # Scripts might choose to override this by calling
+ # globalErrorUtility.configure().
+ globalErrorUtility.copy_to_zlog = False
+ globalErrorUtility.log_namer = UniqueFileAllocator(
+ output_root=config.error_reports.error_dir,
+ log_type="OOPS", log_subtype=self.name)
+
+ # WARN and higher log messages should generate OOPS reports.
+ self.logger.addHandler(OopsHandler(name))
+
enabled = cronscript_enabled(
- config.canonical.cron_control_url, self.name, self.logger)
+ config.canonical.cron_control_url, name, self.logger)
if not enabled:
sys.exit(0)
+ @log_unhandled_exception_and_exit
def record_activity(self, date_started, date_completed):
"""Record the successful completion of the script."""
self.txn.begin()
@@ -332,6 +388,7 @@
control_fp = urlopen(control_url, timeout=5)
else:
control_fp = urlopen(control_url)
+ # Yuck. API makes it hard to catch 'does not exist'.
except HTTPError, error:
if error.code == 404:
log.debug("Cronscript control file not found at %s", control_url)
@@ -344,7 +401,7 @@
return True
log.exception("Error loading %s" % control_url)
return True
- except:
+ except Exception:
log.exception("Error loading %s" % control_url)
return True
=== added file 'lib/lp/services/scripts/doc/launchpad-scripts.txt'
--- lib/lp/services/scripts/doc/launchpad-scripts.txt 1970-01-01 00:00:00 +0000
+++ lib/lp/services/scripts/doc/launchpad-scripts.txt 2010-09-20 12:08:52 +0000
@@ -0,0 +1,39 @@
+Launchpad Scripts
+=================
+
+Launchpad scripts are built using the LaunchpadScript class in
+lp.services.scripts.base. This, along with the LaunchpadCronScript
+specialization, implement common behavior for all Launchpad command
+line scripts.
+
+ >>> from lp.services.scripts.base import (
+ ... LaunchpadScript, LaunchpadCronScript)
+
+
+Scripts report their executution using the standard Python logging
+module, with command line arguments and logging setup provided by
+LaunchpadScript. Unhandled exceptions from scripts are automatically
+sent to the Python logging system. Cronscripts (scripts using
+LaunchpadCronScript) also log warnings and and errors as OOPS reports.
+
+ >>> import os.path, subprocess, sys
+ >>> from canonical.config import config
+ >>> cronscript_crash_path = os.path.join(
+ ... config.root, 'lib', 'lp', 'services', 'scripts', 'tests',
+ ... 'cronscript-crash.py')
+ >>> p = subprocess.Popen(
+ ... [sys.executable, cronscript_crash_path, '-vq'],
+ ... stdout=subprocess.PIPE, stderr=subprocess.STDOUT,
+ ... stdin=subprocess.PIPE)
+ >>> print p.communicate()[0]
+ INFO Creating lockfile: ...
+ WARNING This is a warning
+ INFO New OOPS detected
+ CRITICAL This is critical
+ INFO New OOPS detected
+ ERROR Unhandled exception
+ ...
+ NotImplementedError: Whoops
+ >>> p.returncode
+ 42
+
=== added symlink 'lib/lp/services/scripts/tests/_pythonpath.py'
=== target is u'../../../../../_pythonpath.py'
=== added file 'lib/lp/services/scripts/tests/cronscript-crash.py'
--- lib/lp/services/scripts/tests/cronscript-crash.py 1970-01-01 00:00:00 +0000
+++ lib/lp/services/scripts/tests/cronscript-crash.py 2010-09-20 12:08:52 +0000
@@ -0,0 +1,43 @@
+#!/usr/bin/python -S
+# Copyright 2010 Canonical Ltd. This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Cronscript that raises an unhandled exception."""
+
+__metaclass__ = type
+__all__ = []
+
+import _pythonpath
+
+from lp.services.scripts.base import LaunchpadCronScript
+
+from canonical.launchpad.webapp.errorlog import globalErrorUtility
+
+
+class CrashScript(LaunchpadCronScript):
+
+ def main(self):
+ self.logger.debug("This is debug level")
+
+ initial_oops = globalErrorUtility.getLastOopsReport().id
+
+ self.logger.warn("This is a warning")
+
+ first_oops = globalErrorUtility.getLastOopsReport().id
+
+ if first_oops != initial_oops:
+ self.logger.info("New OOPS detected")
+
+ self.logger.critical("This is critical")
+
+ second_oops = globalErrorUtility.getLastOopsReport().id
+
+ if second_oops != first_oops:
+ self.logger.info("New OOPS detected")
+
+ raise NotImplementedError("Whoops")
+
+
+if __name__ == "__main__":
+ script = CrashScript("crash")
+ script.lock_and_run()
=== modified file 'lib/lp/services/scripts/tests/test_doc.py'
--- lib/lp/services/scripts/tests/test_doc.py 2010-08-20 20:31:18 +0000
+++ lib/lp/services/scripts/tests/test_doc.py 2010-09-20 12:08:52 +0000
@@ -12,7 +12,7 @@
setUp,
tearDown,
)
-from canonical.testing import LaunchpadZopelessLayer
+from canonical.testing import DatabaseLayer, LaunchpadZopelessLayer
from lp.services.testing import build_test_suite
@@ -22,9 +22,14 @@
'script-monitoring.txt': LayeredDocFileSuite(
'../doc/script-monitoring.txt',
setUp=setUp, tearDown=tearDown,
- layer=LaunchpadZopelessLayer
+ layer=LaunchpadZopelessLayer,
+ ),
+ 'launchpad-scripts.txt': LayeredDocFileSuite(
+ '../doc/launchpad-scripts.txt',
+ layer=DatabaseLayer,
),
}
+
def test_suite():
return build_test_suite(here, special)
