~launchpad-pqm/launchpad/devel

# Copyright 2009-2011 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.
"""

__metaclass__ = type

# Don't import stuff from this module. Import it from canonical.scripts
__all__ = [
    'DEBUG2',
    'DEBUG3',
    'DEBUG4',
    'DEBUG5',
    'DEBUG6',
    'DEBUG7',
    'DEBUG8',
    'DEBUG9',
    'dummy_logger_options',
    'LaunchpadFormatter',
    'log',
    'logger',
    'logger_options',
    'OopsHandler',
    ]


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
import os.path
import re
import sys
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,
    )

# Reexport our custom loglevels for old callsites. These callsites
# should be importing the symbols from lp.services.log.loglevels
DEBUG2 = loglevels.DEBUG2
DEBUG3 = loglevels.DEBUG3
DEBUG4 = loglevels.DEBUG4
DEBUG5 = loglevels.DEBUG5
DEBUG6 = loglevels.DEBUG6
DEBUG7 = loglevels.DEBUG7
DEBUG8 = loglevels.DEBUG8
DEBUG9 = loglevels.DEBUG9


class OopsHandler(logging.Handler):
    """Handler to log to the OOPS system."""

    def __init__(self, script_name, level=logging.WARN):
        logging.Handler.__init__(self, level)
        # Context for OOPS reports.
        self.request = ScriptRequest(
            [('script_name', script_name), ('path', sys.argv[0])])
        self.setFormatter(LaunchpadFormatter())

    def emit(self, record):
        """Emit a record as an OOPS."""
        try:
            info = record.exc_info
            if info is None:
                info = sys.exc_info()
            msg = record.getMessage()
            with globalErrorUtility.oopsMessage(msg):
                globalErrorUtility.raising(info, self.request)
        except Exception:
            self.handleError(record)


class LaunchpadFormatter(Formatter):
    """logging.Formatter encoding our preferred output format."""

    def __init__(self, fmt=None, datefmt=None):
        if fmt is None:
            if config.isTestRunner():
                # Don't output timestamps in the test environment
                fmt = '%(levelname)-7s %(message)s'
            else:
                fmt = '%(asctime)s %(levelname)-7s %(message)s'
        if datefmt is None:
            datefmt = "%Y-%m-%d %H:%M:%S"
        logging.Formatter.__init__(self, fmt, datefmt)
        # 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()))


class LogLevelNudger:
    """Callable to adjust the global log level.

    Use instances as callbacks for `optparse`.
    """

    def __init__(self, default, increment=True):
        """Initialize nudger to increment or decrement log level.

        :param default: Default starting level.
        :param increment: Whether to increase the log level (as when
            handling the --verbose option).  If not, will decrease
            instead (as with the --quiet option).
        """
        self.default = default
        self.increment = increment

    def getIncrement(self, current_level):
        """Figure out how much to increment the log level.

        Increment is negative when decreasing log level, of course.
        """
        if self.increment:
            if current_level < 10:
                return 1
            else:
                return 10
        else:
            if current_level <= 10:
                return -1
            else:
                return -10

    def __call__(self, option, opt_str, value, parser):
        """Callback for `optparse` to handle --verbose or --quiet option."""
        current_level = getattr(parser.values, 'loglevel', self.default)
        increment = self.getIncrement(current_level)
        parser.values.loglevel = current_level + increment
        parser.values.verbose = (parser.values.loglevel < self.default)
        # Reset the global log.
        log._log = _logger(parser.values.loglevel, out_stream=sys.stderr)


def define_verbosity_options(parser, default, verbose_callback,
                             quiet_callback):
    """Define the -v and -q options on `parser`."""
    # Only one of these specifies dest and default.  That's because
    # that's enough to make the parser create the option value; there's
    # no need for the other option to specify them as well.
    parser.add_option(
        "-v", "--verbose", dest="loglevel", default=default,
        action="callback", callback=verbose_callback,
        help="Increase stderr verbosity. May be specified multiple times.")
    parser.add_option(
        "-q", "--quiet", action="callback", callback=quiet_callback,
        help="Decrease stderr verbosity. May be specified multiple times.")


def do_nothing(*args, **kwargs):
    """Do absolutely nothing."""


def dummy_logger_options(parser):
    """Add dummy --verbose and --quiet options to `parser`."""
    define_verbosity_options(parser, None, do_nothing, do_nothing)


def logger_options(parser, default=logging.INFO):
    """Add the --verbose and --quiet options to an optparse.OptionParser.

    The requested loglevel will end up in the option's loglevel attribute.
    Note that loglevel is not clamped to any particular range.

    >>> from optparse import OptionParser
    >>> parser = OptionParser()
    >>> logger_options(parser)
    >>> options, args = parser.parse_args(['-v', '-v', '-q', '-qqqqqqq'])
    >>> options.loglevel > logging.CRITICAL
    True
    >>> options.verbose
    False

    >>> parser = OptionParser()
    >>> logger_options(parser)
    >>> options, args = parser.parse_args([])
    >>> options.loglevel == logging.INFO
    True
    >>> options.verbose
    False

    >>> from optparse import OptionParser
    >>> parser = OptionParser()
    >>> logger_options(parser, logging.WARNING)
    >>> options, args = parser.parse_args(['-v'])
    >>> options.loglevel == logging.INFO
    True
    >>> options.verbose
    True

    Cleanup:
    >>> from lp.testing import reset_logging
    >>> reset_logging()

    As part of the options parsing, the 'log' global variable is updated.
    This can be used by code too lazy to pass it around as a variable.
    """

    # Raise an exception if the constants have changed. If they change we
    # will need to fix the arithmetic
    assert logging.DEBUG == 10
    assert logging.INFO == 20
    assert logging.WARNING == 30
    assert logging.ERROR == 40
    assert logging.CRITICAL == 50

    # Undocumented use of the optparse module
    parser.defaults['verbose'] = False

    define_verbosity_options(
        parser, default,
        LogLevelNudger(default, False), LogLevelNudger(default, True))

    debug_levels = ', '.join([
        v for k, v in sorted(logging._levelNames.items(), reverse=True)
            if isinstance(k, int)])

    def log_file(option, opt_str, value, parser):
        try:
            level, path = value.split(':', 1)
        except ValueError:
            level, path = logging.INFO, value

        if isinstance(level, int):
            pass
        elif level.upper() not in logging._levelNames:
            parser.error(
                "'%s' is not a valid logging level. Must be one of %s" % (
                    level, debug_levels))
        else:
            level = logging._levelNames[level.upper()]

        if not path:
            parser.error("Path to log file not specified")

        path = os.path.abspath(path)
        try:
            open(path, 'a')
        except Exception:
            parser.error("Unable to open log file %s" % path)

        parser.values.log_file = path
        parser.values.log_file_level = level

        # Reset the global log.
        log._log = _logger(parser.values.loglevel, out_stream=sys.stderr)

    parser.add_option(
        "--log-file", type="string", action="callback", callback=log_file,
        metavar="LVL:FILE", default=None,
        help="Send log messages to FILE. LVL is one of %s" % debug_levels)
    parser.set_default('log_file_level', None)

    # Set the global log
    log._log = _logger(default, out_stream=sys.stderr)


def logger(options=None, name=None):
    """Return a logging instance with standard setup.

    options should be the options as returned by an option parser that
    has been initilized with logger_options(parser)

    >>> from optparse import OptionParser
    >>> parser = OptionParser()
    >>> logger_options(parser)
    >>> options, args = parser.parse_args(['-v', '-v', '-q', '-q', '-q'])
    >>> log = logger(options)
    >>> log.debug('Not shown - too quiet')

    Cleanup:

    >>> from lp.testing import reset_logging
    >>> reset_logging()
    """
    if options is None:
        parser = OptionParser()
        logger_options(parser)
        options, args = parser.parse_args()

    log_file = getattr(options, 'log_file', None)
    log_file_level = getattr(options, 'log_file_level', None)

    return _logger(
        options.loglevel, out_stream=sys.stderr, name=name,
        log_file=log_file, log_file_level=log_file_level)


def reset_root_logger():
    root_logger = logging.getLogger()
    for hdlr in root_logger.handlers[:]:
        hdlr.flush()
        try:
            hdlr.close()
        except KeyError:
            pass
        root_logger.removeHandler(hdlr)


def _logger(
    level, out_stream, name=None,
    log_file=None, log_file_level=logging.DEBUG):
    """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).
    'out_stream must be passed, the recommended value is sys.stderr'
    """
    if name is None:
        # Determine the logger name from the script name
        name = sys.argv[0]
        name = re.sub('.py[oc]?$', '', name)

    # We install our custom handlers and formatters on the root logger.
    # This means that if the root logger is used, we still get correct
    # formatting. The root logger should probably not be used.
    root_logger = logging.getLogger()

    # reset state of root logger
    reset_root_logger()

    # Make it print output in a standard format, suitable for
    # 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(out_stream)
    # 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 = LibrarianFormatter()
    hdlr.setFormatter(formatter)
    root_logger.addHandler(hdlr)

    # Add an optional aditional log file.
    if log_file is not None:
        handler = WatchedFileHandler(log_file, encoding="UTF8")
        handler.setFormatter(formatter)
        handler.setLevel(log_file_level)
        root_logger.addHandler(handler)

    # Create our logger
    logger = logging.getLogger(name)

    # Set the global log
    log._log = logger

    # Inform the user the extra log file is in operation.
    if log_file is not None:
        log.info(
            "Logging %s and higher messages to %s" % (
                logging.getLevelName(log_file_level), log_file))

    return logger


class _LogWrapper:
    """Changes the logger instance.

    Other modules will do 'from lp.services.scripts import log'.
    This wrapper allows us to change the logger instance these other modules
    use, by replacing the _log attribute. This is done each call to logger()
    """

    def __init__(self, log):
        self._log = log

    def __getattr__(self, key):
        return getattr(self._log, key)

    def __setattr__(self, key, value):
        if key == '_log':
            self.__dict__['_log'] = value
            return value
        else:
            return setattr(self._log, key, value)

    @contextmanager
    def use(self, log):
        """Temporarily use a different `log`."""
        self._log, log = log, self._log
        try:
            yield
        finally:
            self._log = log

    def shortException(self, msg, *args):
        """Like Logger.exception, but does not print a traceback."""
        exctype, value = sys.exc_info()[:2]
        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)


log = _LogWrapper(logging.getLogger())