Lib/fontTools/misc/loggingTools.py

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)