| """ fontTools.misc.loggingTools.py -- tools for interfacing with the Python |
| logging package. |
| """ |
| |
| from fontTools.misc.py23 import * |
| 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): |
| """ Formatter class which optionally takes a dict of logging levels to |
| format strings, allowing to customise the log records appearance for |
| specific levels. |
| The '*' key identifies the default format string. |
| |
| >>> 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, basestring): |
| 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): |
| """ Do basic configuration for the logging system. This is more or less |
| the same as 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. |
| |
| logger Specifies the logger name or a Logger instance to be configured. |
| (it 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, which will be added to the handler(s), if the latter |
| do(es) not already have filters assigned. |
| propagate All loggers have a "propagate" attribute initially set to True, |
| which determines whether to continue searching for handlers up |
| the logging hierarchy. By default, this arguments sets the |
| "propagate" attribute 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, basestring): |
| # 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): |
| """ Filter out records emitted from a list of enabled channel names, |
| including their children. It works the same as the logging.Filter class, |
| but allows 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, basestring): |
| 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) |