123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543 |
- 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)
|