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 ``.``. 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)