160a9cb238
since we use pytest-randomly to randomize the test execution, depending on when this specific test is executed, it may have the side effect of configuring the global logging configuration, causing other tests that capture logging messages to fail. E.g. see https://travis-ci.org/fonttools/fonttools/jobs/545680550
536 lines
17 KiB
Python
536 lines
17 KiB
Python
""" fontTools.misc.loggingTools.py -- tools for interfacing with the Python
|
|
logging package.
|
|
"""
|
|
|
|
from __future__ import print_function, absolute_import
|
|
from fontTools.misc.py23 import *
|
|
import sys
|
|
import logging
|
|
import timeit
|
|
from functools import wraps
|
|
try:
|
|
from collections.abc import Mapping, Callable
|
|
except ImportError: # python < 3.3
|
|
from collections import Mapping, Callable
|
|
import warnings
|
|
|
|
try:
|
|
from logging import PercentStyle
|
|
except ImportError:
|
|
PercentStyle = None
|
|
|
|
|
|
# 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.lenghts = {n: len(n) for n in names}
|
|
|
|
def filter(self, record):
|
|
if self.num == 0:
|
|
return True
|
|
for name in self.names:
|
|
nlen = self.lenghts[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)
|