path: root/contrib/python/fonttools/fontTools/misc/loggingTools.py

import sys
import logging
import timeit
from functools import wraps
from collections.abc import Mapping, Callable
import warnings
from logging import PercentStyle


# default logging level used by Timer class
TIME_LEVEL = logging.DEBUG

# per-level format strings used by the default formatter
# (the level name is not printed for INFO and DEBUG messages)
DEFAULT_FORMATS = {
    "*": "%(levelname)s: %(message)s",
    "INFO": "%(message)s",
    "DEBUG": "%(message)s",
}


class LevelFormatter(logging.Formatter):
    """Log formatter with level-specific formatting.

    Formatter class which optionally takes a dict of logging levels to
    format strings, allowing to customise the log records appearance for
    specific levels.


    Attributes:
            fmt: A dictionary mapping logging levels to format strings.
                    The ``*`` key identifies the default format string.
            datefmt: As per py:class:`logging.Formatter`
            style: As per py:class:`logging.Formatter`

    >>> import sys
    >>> handler = logging.StreamHandler(sys.stdout)
    >>> formatter = LevelFormatter(
    ...     fmt={
    ...         '*':     '[%(levelname)s] %(message)s',
    ...         'DEBUG': '%(name)s [%(levelname)s] %(message)s',
    ...         'INFO':  '%(message)s',
    ...     })
    >>> handler.setFormatter(formatter)
    >>> log = logging.getLogger('test')
    >>> log.setLevel(logging.DEBUG)
    >>> log.addHandler(handler)
    >>> log.debug('this uses a custom format string')
    test [DEBUG] this uses a custom format string
    >>> log.info('this also uses a custom format string')
    this also uses a custom format string
    >>> log.warning("this one uses the default format string")
    [WARNING] this one uses the default format string
    """

    def __init__(self, fmt=None, datefmt=None, style="%"):
        if style != "%":
            raise ValueError(
                "only '%' percent style is supported in both python 2 and 3"
            )
        if fmt is None:
            fmt = DEFAULT_FORMATS
        if isinstance(fmt, str):
            default_format = fmt
            custom_formats = {}
        elif isinstance(fmt, Mapping):
            custom_formats = dict(fmt)
            default_format = custom_formats.pop("*", None)
        else:
            raise TypeError("fmt must be a str or a dict of str: %r" % fmt)
        super(LevelFormatter, self).__init__(default_format, datefmt)
        self.default_format = self._fmt
        self.custom_formats = {}
        for level, fmt in custom_formats.items():
            level = logging._checkLevel(level)
            self.custom_formats[level] = fmt

    def format(self, record):
        if self.custom_formats:
            fmt = self.custom_formats.get(record.levelno, self.default_format)
            if self._fmt != fmt:
                self._fmt = fmt
                # for python >= 3.2, _style needs to be set if _fmt changes
                if PercentStyle:
                    self._style = PercentStyle(fmt)
        return super(LevelFormatter, self).format(record)


def configLogger(**kwargs):
    """A more sophisticated logging system configuation manager.

    This is more or less the same as :py:func:`logging.basicConfig`,
    with some additional options and defaults.

    The default behaviour is to create a ``StreamHandler`` which writes to
    sys.stderr, set a formatter using the ``DEFAULT_FORMATS`` strings, and add
    the handler to the top-level library logger ("fontTools").

    A number of optional keyword arguments may be specified, which can alter
    the default behaviour.

    Args:

            logger: Specifies the logger name or a Logger instance to be
                    configured. (Defaults to "fontTools" logger). Unlike ``basicConfig``,
                    this function can be called multiple times to reconfigure a logger.
                    If the logger or any of its children already exists before the call is
                    made, they will be reset before the new configuration is applied.
            filename: Specifies that a ``FileHandler`` be created, using the
                    specified filename, rather than a ``StreamHandler``.
            filemode: Specifies the mode to open the file, if filename is
                    specified. (If filemode is unspecified, it defaults to ``a``).
            format: Use the specified format string for the handler. This
                    argument also accepts a dictionary of format strings keyed by
                    level name, to allow customising the records appearance for
                    specific levels. The special ``'*'`` key is for 'any other' level.
            datefmt: Use the specified date/time format.
            level: Set the logger level to the specified level.
            stream: Use the specified stream to initialize the StreamHandler. Note
                    that this argument is incompatible with ``filename`` - if both
                    are present, ``stream`` is ignored.
            handlers: If specified, this should be an iterable of already created
                    handlers, which will be added to the logger. Any handler in the
                    list which does not have a formatter assigned will be assigned the
                    formatter created in this function.
            filters: If specified, this should be an iterable of already created
                    filters. If the ``handlers`` do not already have filters assigned,
                    these filters will be added to them.
            propagate: All loggers have a ``propagate`` attribute which determines
                    whether to continue searching for handlers up the logging hierarchy.
                    If not provided, the "propagate" attribute will be set to ``False``.
    """
    # using kwargs to enforce keyword-only arguments in py2.
    handlers = kwargs.pop("handlers", None)
    if handlers is None:
        if "stream" in kwargs and "filename" in kwargs:
            raise ValueError(
                "'stream' and 'filename' should not be " "specified together"
            )
    else:
        if "stream" in kwargs or "filename" in kwargs:
            raise ValueError(
                "'stream' or 'filename' should not be "
                "specified together with 'handlers'"
            )
    if handlers is None:
        filename = kwargs.pop("filename", None)
        mode = kwargs.pop("filemode", "a")
        if filename:
            h = logging.FileHandler(filename, mode)
        else:
            stream = kwargs.pop("stream", None)
            h = logging.StreamHandler(stream)
        handlers = [h]
    # By default, the top-level library logger is configured.
    logger = kwargs.pop("logger", "fontTools")
    if not logger or isinstance(logger, str):
        # empty "" or None means the 'root' logger
        logger = logging.getLogger(logger)
    # before (re)configuring, reset named logger and its children (if exist)
    _resetExistingLoggers(parent=logger.name)
    # use DEFAULT_FORMATS if 'format' is None
    fs = kwargs.pop("format", None)
    dfs = kwargs.pop("datefmt", None)
    # XXX: '%' is the only format style supported on both py2 and 3
    style = kwargs.pop("style", "%")
    fmt = LevelFormatter(fs, dfs, style)
    filters = kwargs.pop("filters", [])
    for h in handlers:
        if h.formatter is None:
            h.setFormatter(fmt)
        if not h.filters:
            for f in filters:
                h.addFilter(f)
        logger.addHandler(h)
    if logger.name != "root":
        # stop searching up the hierarchy for handlers
        logger.propagate = kwargs.pop("propagate", False)
    # set a custom severity level
    level = kwargs.pop("level", None)
    if level is not None:
        logger.setLevel(level)
    if kwargs:
        keys = ", ".join(kwargs.keys())
        raise ValueError("Unrecognised argument(s): %s" % keys)


def _resetExistingLoggers(parent="root"):
    """Reset the logger named 'parent' and all its children to their initial
    state, if they already exist in the current configuration.
    """
    root = logging.root
    # get sorted list of all existing loggers
    existing = sorted(root.manager.loggerDict.keys())
    if parent == "root":
        # all the existing loggers are children of 'root'
        loggers_to_reset = [parent] + existing
    elif parent not in existing:
        # nothing to do
        return
    elif parent in existing:
        loggers_to_reset = [parent]
        # collect children, starting with the entry after parent name
        i = existing.index(parent) + 1
        prefixed = parent + "."
        pflen = len(prefixed)
        num_existing = len(existing)
        while i < num_existing:
            if existing[i][:pflen] == prefixed:
                loggers_to_reset.append(existing[i])
            i += 1
    for name in loggers_to_reset:
        if name == "root":
            root.setLevel(logging.WARNING)
            for h in root.handlers[:]:
                root.removeHandler(h)
            for f in root.filters[:]:
                root.removeFilters(f)
            root.disabled = False
        else:
            logger = root.manager.loggerDict[name]
            logger.level = logging.NOTSET
            logger.handlers = []
            logger.filters = []
            logger.propagate = True
            logger.disabled = False


class Timer(object):
    """Keeps track of overall time and split/lap times.

    >>> import time
    >>> timer = Timer()
    >>> time.sleep(0.01)
    >>> print("First lap:", timer.split())
    First lap: ...
    >>> time.sleep(0.02)
    >>> print("Second lap:", timer.split())
    Second lap: ...
    >>> print("Overall time:", timer.time())
    Overall time: ...

    Can be used as a context manager inside with-statements.

    >>> with Timer() as t:
    ...     time.sleep(0.01)
    >>> print("%0.3f seconds" % t.elapsed)
    0... seconds

    If initialised with a logger, it can log the elapsed time automatically
    upon exiting the with-statement.

    >>> import logging
    >>> log = logging.getLogger("my-fancy-timer-logger")
    >>> configLogger(logger=log, level="DEBUG", format="%(message)s", stream=sys.stdout)
    >>> with Timer(log, 'do something'):
    ...     time.sleep(0.01)
    Took ... to do something

    The same Timer instance, holding a reference to a logger, can be reused
    in multiple with-statements, optionally with different messages or levels.

    >>> timer = Timer(log)
    >>> with timer():
    ...     time.sleep(0.01)
    elapsed time: ...s
    >>> with timer('redo it', level=logging.INFO):
    ...     time.sleep(0.02)
    Took ... to redo it

    It can also be used as a function decorator to log the time elapsed to run
    the decorated function.

    >>> @timer()
    ... def test1():
    ...    time.sleep(0.01)
    >>> @timer('run test 2', level=logging.INFO)
    ... def test2():
    ...    time.sleep(0.02)
    >>> test1()
    Took ... to run 'test1'
    >>> test2()
    Took ... to run test 2
    """

    # timeit.default_timer choses the most accurate clock for each platform
    _time = timeit.default_timer
    default_msg = "elapsed time: %(time).3fs"
    default_format = "Took %(time).3fs to %(msg)s"

    def __init__(self, logger=None, msg=None, level=None, start=None):
        self.reset(start)
        if logger is None:
            for arg in ("msg", "level"):
                if locals().get(arg) is not None:
                    raise ValueError("'%s' can't be specified without a 'logger'" % arg)
        self.logger = logger
        self.level = level if level is not None else TIME_LEVEL
        self.msg = msg

    def reset(self, start=None):
        """Reset timer to 'start_time' or the current time."""
        if start is None:
            self.start = self._time()
        else:
            self.start = start
        self.last = self.start
        self.elapsed = 0.0

    def time(self):
        """Return the overall time (in seconds) since the timer started."""
        return self._time() - self.start

    def split(self):
        """Split and return the lap time (in seconds) in between splits."""
        current = self._time()
        self.elapsed = current - self.last
        self.last = current
        return self.elapsed

    def formatTime(self, msg, time):
        """Format 'time' value in 'msg' and return formatted string.
        If 'msg' contains a '%(time)' format string, try to use that.
        Otherwise, use the predefined 'default_format'.
        If 'msg' is empty or None, fall back to 'default_msg'.
        """
        if not msg:
            msg = self.default_msg
        if msg.find("%(time)") < 0:
            msg = self.default_format % {"msg": msg, "time": time}
        else:
            try:
                msg = msg % {"time": time}
            except (KeyError, ValueError):
                pass  # skip if the format string is malformed
        return msg

    def __enter__(self):
        """Start a new lap"""
        self.last = self._time()
        self.elapsed = 0.0
        return self

    def __exit__(self, exc_type, exc_value, traceback):
        """End the current lap. If timer has a logger, log the time elapsed,
        using the format string in self.msg (or the default one).
        """
        time = self.split()
        if self.logger is None or exc_type:
            # if there's no logger attached, or if any exception occurred in
            # the with-statement, exit without logging the time
            return
        message = self.formatTime(self.msg, time)
        # Allow log handlers to see the individual parts to facilitate things
        # like a server accumulating aggregate stats.
        msg_parts = {"msg": self.msg, "time": time}
        self.logger.log(self.level, message, msg_parts)

    def __call__(self, func_or_msg=None, **kwargs):
        """If the first argument is a function, return a decorator which runs
        the wrapped function inside Timer's context manager.
        Otherwise, treat the first argument as a 'msg' string and return an updated
        Timer instance, referencing the same logger.
        A 'level' keyword can also be passed to override self.level.
        """
        if isinstance(func_or_msg, Callable):
            func = func_or_msg
            # use the function name when no explicit 'msg' is provided
            if not self.msg:
                self.msg = "run '%s'" % func.__name__

            @wraps(func)
            def wrapper(*args, **kwds):
                with self:
                    return func(*args, **kwds)

            return wrapper
        else:
            msg = func_or_msg or kwargs.get("msg")
            level = kwargs.get("level", self.level)
            return self.__class__(self.logger, msg, level)

    def __float__(self):
        return self.elapsed

    def __int__(self):
        return int(self.elapsed)

    def __str__(self):
        return "%.3f" % self.elapsed


class ChannelsFilter(logging.Filter):
    """Provides a hierarchical filter for log entries based on channel names.

    Filters out records emitted from a list of enabled channel names,
    including their children. It works the same as the ``logging.Filter``
    class, but allows the user to specify multiple channel names.

    >>> import sys
    >>> handler = logging.StreamHandler(sys.stdout)
    >>> handler.setFormatter(logging.Formatter("%(message)s"))
    >>> filter = ChannelsFilter("A.B", "C.D")
    >>> handler.addFilter(filter)
    >>> root = logging.getLogger()
    >>> root.addHandler(handler)
    >>> root.setLevel(level=logging.DEBUG)
    >>> logging.getLogger('A.B').debug('this record passes through')
    this record passes through
    >>> logging.getLogger('A.B.C').debug('records from children also pass')
    records from children also pass
    >>> logging.getLogger('C.D').debug('this one as well')
    this one as well
    >>> logging.getLogger('A.B.').debug('also this one')
    also this one
    >>> logging.getLogger('A.F').debug('but this one does not!')
    >>> logging.getLogger('C.DE').debug('neither this one!')
    """

    def __init__(self, *names):
        self.names = names
        self.num = len(names)
        self.lengths = {n: len(n) for n in names}

    def filter(self, record):
        if self.num == 0:
            return True
        for name in self.names:
            nlen = self.lengths[name]
            if name == record.name:
                return True
            elif record.name.find(name, 0, nlen) == 0 and record.name[nlen] == ".":
                return True
        return False


class CapturingLogHandler(logging.Handler):
    def __init__(self, logger, level):
        super(CapturingLogHandler, self).__init__(level=level)
        self.records = []
        if isinstance(logger, str):
            self.logger = logging.getLogger(logger)
        else:
            self.logger = logger

    def __enter__(self):
        self.original_disabled = self.logger.disabled
        self.original_level = self.logger.level
        self.original_propagate = self.logger.propagate

        self.logger.addHandler(self)
        self.logger.setLevel(self.level)
        self.logger.disabled = False
        self.logger.propagate = False

        return self

    def __exit__(self, type, value, traceback):
        self.logger.removeHandler(self)
        self.logger.setLevel(self.original_level)
        self.logger.disabled = self.original_disabled
        self.logger.propagate = self.original_propagate

        return self

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

    def assertRegex(self, regexp, msg=None):
        import re

        pattern = re.compile(regexp)
        for r in self.records:
            if pattern.search(r.getMessage()):
                return True
        if msg is None:
            msg = "Pattern '%s' not found in logger records" % regexp
        assert 0, msg


class LogMixin(object):
    """Mixin class that adds logging functionality to another class.

    You can define a new class that subclasses from ``LogMixin`` as well as
    other base classes through multiple inheritance.
    All instances of that class will have a ``log`` property that returns
    a ``logging.Logger`` named after their respective ``<module>.<class>``.

    For example:

    >>> class BaseClass(object):
    ...     pass
    >>> class MyClass(LogMixin, BaseClass):
    ...     pass
    >>> a = MyClass()
    >>> isinstance(a.log, logging.Logger)
    True
    >>> print(a.log.name)
    fontTools.misc.loggingTools.MyClass
    >>> class AnotherClass(MyClass):
    ...     pass
    >>> b = AnotherClass()
    >>> isinstance(b.log, logging.Logger)
    True
    >>> print(b.log.name)
    fontTools.misc.loggingTools.AnotherClass
    """

    @property
    def log(self):
        if not hasattr(self, "_log"):
            name = ".".join((self.__class__.__module__, self.__class__.__name__))
            self._log = logging.getLogger(name)
        return self._log


def deprecateArgument(name, msg, category=UserWarning):
    """Raise a warning about deprecated function argument 'name'."""
    warnings.warn("%r is deprecated; %s" % (name, msg), category=category, stacklevel=3)


def deprecateFunction(msg, category=UserWarning):
    """Decorator to raise a warning when a deprecated function is called."""

    def decorator(func):
        @wraps(func)
        def wrapper(*args, **kwargs):
            warnings.warn(
                "%r is deprecated; %s" % (func.__name__, msg),
                category=category,
                stacklevel=2,
            )
            return func(*args, **kwargs)

        return wrapper

    return decorator


if __name__ == "__main__":
    import doctest

    sys.exit(doctest.testmod(optionflags=doctest.ELLIPSIS).failed)