qutebrowser/qutebrowser/utils/log.py

# vim: ft=python fileencoding=utf-8 sts=4 sw=4 et:

# Copyright 2014 Florian Bruhin (The Compiler) <mail@qutebrowser.org>
#
# This file is part of qutebrowser.
#
# qutebrowser is free software: you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation, either version 3 of the License, or
# (at your option) any later version.
#
# qutebrowser is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with qutebrowser.  If not, see <http://www.gnu.org/licenses/>.

"""Loggers and utilities related to logging."""

import re
import os
import sys
import html
import logging
from contextlib import contextmanager
from logging import getLogger
from collections import deque

from PyQt5.QtCore import (QtDebugMsg, QtWarningMsg, QtCriticalMsg, QtFatalMsg,
                          qInstallMessageHandler)
# Optional imports
try:
    # pylint: disable=import-error
    from colorlog import ColoredFormatter
except ImportError:
    ColoredFormatter = None
try:
    # pylint: disable=import-error
    import colorama
except ImportError:
    colorama = None

# Log formats to use.
SIMPLE_FMT = '{levelname}: {message}'
EXTENDED_FMT = ('{asctime:8} {levelname:8} {name:10} {module}:{funcName}:'
                '{lineno} {message}')
SIMPLE_FMT_COLORED = '%(log_color)s%(levelname)s%(reset)s: %(message)s'
EXTENDED_FMT_COLORED = ('%(green)s%(asctime)-8s%(reset)s %(log_color)s'
                        '%(levelname)-8s%(reset)s %(cyan)s%(name)-10s '
                        '%(module)s:%(funcName)s:%(lineno)s%(reset)s '
                        '%(log_color)s%(message)s%(reset)s')
EXTENDED_FMT_HTML = ('<tr><td><pre>%(green)s%(asctime)-8s%(reset)s</pre></td>'
                     '<td><pre>%(log_color)s%(levelname)-8s%(reset)s</pre>'
                     '</td><td></pre>%(cyan)s%(name)-10s</pre></td>'
                     '<td><pre>%(module)s:%(funcName)s:%(lineno)s%(reset)s'
                     '</pre></td><td><pre>%(log_color)s%(message)s%(reset)s'
                     '</pre></td></tr>')
DATEFMT = '%H:%M:%S'
LOG_COLORS = {
    'DEBUG': 'white',
    'INFO': 'green',
    'WARNING': 'yellow',
    'ERROR': 'red',
    'CRITICAL': 'red',
}


# The different loggers used.

statusbar = getLogger('statusbar')
completion = getLogger('completion')
destroy = getLogger('destroy')
modes = getLogger('modes')
webview = getLogger('webview')
mouse = getLogger('mouse')
misc = getLogger('misc')
url = getLogger('url')
procs = getLogger('procs')
commands = getLogger('commands')
init = getLogger('init')
signals = getLogger('signals')
hints = getLogger('hints')
keyboard = getLogger('keyboard')
downloads = getLogger('downloads')
js = getLogger('js')  # Javascript console messages
qt = getLogger('qt')  # Warnings produced by Qt
style = getLogger('style')
rfc6266 = getLogger('rfc6266')


ram_handler = None


def init_log(args):
    """Init loggers based on the argparse namespace passed."""
    level = 'DEBUG' if args.debug else args.loglevel.upper()
    try:
        numeric_level = getattr(logging, level)
    except AttributeError:
        raise ValueError("Invalid log level: {}".format(args.loglevel))

    console, ram = _init_handlers(numeric_level, args.color, args.loglines)
    root = getLogger()
    if console is not None:
        if args.logfilter is not None and numeric_level < logging.DEBUG:
            console.addFilter(LogFilter(args.logfilter.split(',')))
            console.addFilter(LeplFilter())
        root.addHandler(console)
    if ram is not None:
        root.addHandler(ram)
        ram.addFilter(LeplFilter())
    root.setLevel(logging.NOTSET)
    logging.captureWarnings(True)
    qInstallMessageHandler(qt_message_handler)


@contextmanager
def disable_qt_msghandler():
    """Contextmanager which temporarely disables the Qt message handler."""
    old_handler = qInstallMessageHandler(None)
    yield
    qInstallMessageHandler(old_handler)


def fix_rfc2622():
    """Fix the rfc6266 logger.

    In rfc2622 <= v0.04, a NullHandler class is added as handler, instead of an
    object, which causes an exception later.

    This was fixed in [1], but since v0.05 is not out yet, we work around the
    issue by deleting the wrong handler.

    This should be executed after init_log is done and rfc6266 is imported, but
    before using it.

    [1]: https://github.com/g2p/rfc6266/commit/cad58963ed13f5e1068fcc9e4326123b6b2bdcf8
    """
    rfc6266.removeHandler(logging.NullHandler)


def _init_handlers(level, color, ram_capacity):
    """Init log handlers.

    Args:
        level: The numeric logging level.
        color: Whether to use color if available.
    """
    global ram_handler
    console_fmt, ram_fmt, html_fmt, use_colorama = _init_formatters(
        level, color)

    if sys.stderr is None:
        console_handler = None
    else:
        if use_colorama:
            stream = colorama.AnsiToWin32(sys.stderr)
        else:
            stream = sys.stderr
        console_handler = logging.StreamHandler(stream)
        console_handler.setLevel(level)
        console_handler.setFormatter(console_fmt)

    if ram_capacity == 0:
        ram_handler = None
    else:
        ram_handler = RAMHandler(capacity=ram_capacity)
        ram_handler.setLevel(logging.NOTSET)
        ram_handler.setFormatter(ram_fmt)
        ram_handler.html_formatter = html_fmt

    return console_handler, ram_handler


def _init_formatters(level, color):
    """Init log formatters.

    Args:
        level: The numeric logging level.
        color: Whether to use color if available.

    Return:
        A (console_formatter, ram_formatter, use_colorama) tuple.
        console_formatter/ram_formatter: logging.Formatter instances.
        use_colorama: Whether to use colorama.
    """
    if level <= logging.DEBUG:
        console_fmt = EXTENDED_FMT
        console_fmt_colored = EXTENDED_FMT_COLORED
    else:
        console_fmt = SIMPLE_FMT
        console_fmt_colored = SIMPLE_FMT_COLORED
    ram_formatter = logging.Formatter(EXTENDED_FMT, DATEFMT, '{')
    html_formatter = HTMLFormatter(EXTENDED_FMT_HTML, DATEFMT,
                                   log_colors=LOG_COLORS)
    if sys.stderr is None:
        return None, ram_formatter, html_formatter, False
    use_colorama = False
    if (ColoredFormatter is not None and (os.name == 'posix' or colorama) and
            sys.stderr.isatty() and color):
        console_formatter = ColoredFormatter(console_fmt_colored, DATEFMT,
                                             log_colors=LOG_COLORS)
        if colorama:
            use_colorama = True
    else:
        console_formatter = logging.Formatter(console_fmt, DATEFMT, '{')
    return console_formatter, ram_formatter, html_formatter, use_colorama


def qt_message_handler(msg_type, context, msg):
    """Qt message handler to redirect qWarning etc. to the logging system.

    Args:
        QtMsgType msg_type: The level of the message.
        QMessageLogContext context: The source code location of the message.
        msg: The message text.
    """
    # Mapping from Qt logging levels to the matching logging module levels.
    # Note we map critical to ERROR as it's actually "just" an error, and fatal
    # to critical.
    qt_to_logging = {
        QtDebugMsg: logging.DEBUG,
        QtWarningMsg: logging.WARNING,
        QtCriticalMsg: logging.ERROR,
        QtFatalMsg: logging.CRITICAL,
    }
    # Change levels of some well-known messages to debug so they don't get
    # shown to the user.
    # suppressed_msgs is a list of regexes matching the message texts to hide.
    suppressed_msgs = ("libpng warning: iCCP: Not recognizing known sRGB "
                       "profile that has been edited",
                       "OpenType support missing for script [0-9]*")
    if any(re.match(pattern, msg.strip()) for pattern in suppressed_msgs):
        level = logging.DEBUG
    else:
        level = qt_to_logging[msg_type]
    # We get something like "void qt_png_warning(png_structp, png_const_charp)"
    # from Qt, but only want "qt_png_warning".
    match = re.match(r'.*( |::)(\w*)\(.*\)', context.function)
    if match is not None:
        func = match.group(2)
    else:
        func = context.function
    name = 'qt' if context.category == 'default' else 'qt-' + context.category
    if msg.splitlines()[0] == ('This application failed to start because it '
                               'could not find or load the Qt platform plugin '
                               '"xcb".'):
        # Handle this message specially.
        msg += ("\n\nOn Archlinux, this should fix the problem:\n"
                "    pacman -S libxkbcommon-x11")
        try:
            import faulthandler
        except ImportError:
            pass
        else:
            faulthandler.disable()
    record = qt.makeRecord(name, level, context.file, context.line, msg, None,
                           None, func)
    qt.handle(record)


class LogFilter(logging.Filter):

    """Filter to filter log records based on the commandline argument.

    The default Filter only supports one name to show - we support a
    comma-separated list instead.

    Attributes:
        names: A list of names that should be logged.
    """

    def __init__(self, names):
        super().__init__()
        self.names = names

    def filter(self, record):
        """Determine if the specified record is to be logged."""
        if self.names is None:
            return True
        if record.levelno > logging.DEBUG:
            # More important than DEBUG, so we won't filter at all
            return True
        for name in self.names:
            if record.name == name:
                return True
            elif not record.name.startswith(name):
                continue
            elif record.name[len(name)] == '.':
                return True
        return False


class LeplFilter(logging.Filter):

    """Filter to filter debug log records by the lepl library."""

    def filter(self, record):
        """Determine if the specified record is to be logged."""
        if (record.levelno == logging.INFO and
                record.name == 'lepl.lexer.rewriters.AddLexer'):
            # Special useless info message triggered by rfc6266
            return False
        if record.levelno > logging.DEBUG:
            # More important than DEBUG, so we won't filter at all
            return True
        return not record.name.startswith('lepl.')


class RAMHandler(logging.Handler):

    """Logging handler which keeps the messages in a deque in RAM.

    Loosly based on logging.BufferingHandler which is unsuitable because it
    uses a simple list rather than a deque.

    Attributes:
        data: A deque containing the logging records.
    """

    def __init__(self, capacity):
        super().__init__()
        self.html_formatter = None
        if capacity != -1:
            self.data = deque(maxlen=capacity)
        else:
            self.data = deque()

    def emit(self, record):
        self.data.append(record)

    def dump_log(self, html=False):
        """Dump the complete formatted log data as as string."""
        if html:
            fmt = self.html_formatter.format
            lines = ['<table>']
        else:
            fmt = self.format
            lines = []
        self.acquire()
        try:
            records = list(self.data)
        finally:
            self.release()
        for record in records:
            lines.append(fmt(record))
        if html:
            lines.append('</table>')
        return '\n'.join(lines)


class HTMLFormatter(logging.Formatter):

    """Formatter for HTML-colored log messages, similiar to colorlog."""

    def __init__(self, fmt, datefmt, log_colors):
        """Constructor.

        Args:
            fmt: The format string to use.
            datefmt: The date format to use.
            log_colors: The colors to use for logging levels.
        """
        super().__init__(fmt, datefmt)
        self._log_colors = log_colors
        self._colordict = {}
        # We could solve this nicer by using CSS, but for this simple case this
        # works.
        for color in ['black', 'red', 'green', 'yellow', 'blue', 'purple',
                      'cyan', 'white']:
            self._colordict[color] = '<font color="{}">'.format(color)
        self._colordict['reset'] = '</font>'

    def format(self, record):
        record.__dict__.update(self._colordict)
        if record.levelname in self._log_colors:
            color = self._log_colors[record.levelname]
            record.log_color = self._colordict[color]
        else:
            record.log_color = ''
        for field in ['msg', 'filename', 'funcName', 'levelname', 'module',
                      'name', 'pathname', 'processName', 'threadName']:
            data = str(getattr(record, field))
            setattr(record, field, html.escape(data))
        message = super().format(record)
        if not message.endswith(self._colordict['reset']):
            message += self._colordict['reset']
        return message

    def formatTime(self, record, datefmt=None):
        out = super().formatTime(record, datefmt)
        return html.escape(out)