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)