Shortcuts on this page
r m x toggle line displays
j k next/prev highlighted chunk
0 (zero) top of page
1 (one) first highlighted chunk
1import sys
2import logging
3import timeit
4from functools import wraps
5from collections.abc import Mapping, Callable
6import warnings
7from logging import PercentStyle
10# default logging level used by Timer class
11TIME_LEVEL = logging.DEBUG
13# per-level format strings used by the default formatter
14# (the level name is not printed for INFO and DEBUG messages)
15DEFAULT_FORMATS = {
16 "*": "%(levelname)s: %(message)s",
17 "INFO": "%(message)s",
18 "DEBUG": "%(message)s",
19}
22class LevelFormatter(logging.Formatter):
23 """Log formatter with level-specific formatting.
25 Formatter class which optionally takes a dict of logging levels to
26 format strings, allowing to customise the log records appearance for
27 specific levels.
30 Attributes:
31 fmt: A dictionary mapping logging levels to format strings.
32 The ``*`` key identifies the default format string.
33 datefmt: As per py:class:`logging.Formatter`
34 style: As per py:class:`logging.Formatter`
36 >>> import sys
37 >>> handler = logging.StreamHandler(sys.stdout)
38 >>> formatter = LevelFormatter(
39 ... fmt={
40 ... '*': '[%(levelname)s] %(message)s',
41 ... 'DEBUG': '%(name)s [%(levelname)s] %(message)s',
42 ... 'INFO': '%(message)s',
43 ... })
44 >>> handler.setFormatter(formatter)
45 >>> log = logging.getLogger('test')
46 >>> log.setLevel(logging.DEBUG)
47 >>> log.addHandler(handler)
48 >>> log.debug('this uses a custom format string')
49 test [DEBUG] this uses a custom format string
50 >>> log.info('this also uses a custom format string')
51 this also uses a custom format string
52 >>> log.warning("this one uses the default format string")
53 [WARNING] this one uses the default format string
54 """
56 def __init__(self, fmt=None, datefmt=None, style="%"):
57 if style != "%":
58 raise ValueError(
59 "only '%' percent style is supported in both python 2 and 3"
60 )
61 if fmt is None:
62 fmt = DEFAULT_FORMATS
63 if isinstance(fmt, str):
64 default_format = fmt
65 custom_formats = {}
66 elif isinstance(fmt, Mapping):
67 custom_formats = dict(fmt)
68 default_format = custom_formats.pop("*", None)
69 else:
70 raise TypeError("fmt must be a str or a dict of str: %r" % fmt)
71 super(LevelFormatter, self).__init__(default_format, datefmt)
72 self.default_format = self._fmt
73 self.custom_formats = {}
74 for level, fmt in custom_formats.items():
75 level = logging._checkLevel(level)
76 self.custom_formats[level] = fmt
78 def format(self, record):
79 if self.custom_formats:
80 fmt = self.custom_formats.get(record.levelno, self.default_format)
81 if self._fmt != fmt:
82 self._fmt = fmt
83 # for python >= 3.2, _style needs to be set if _fmt changes
84 if PercentStyle:
85 self._style = PercentStyle(fmt)
86 return super(LevelFormatter, self).format(record)
89def configLogger(**kwargs):
90 """A more sophisticated logging system configuation manager.
92 This is more or less the same as :py:func:`logging.basicConfig`,
93 with some additional options and defaults.
95 The default behaviour is to create a ``StreamHandler`` which writes to
96 sys.stderr, set a formatter using the ``DEFAULT_FORMATS`` strings, and add
97 the handler to the top-level library logger ("fontTools").
99 A number of optional keyword arguments may be specified, which can alter
100 the default behaviour.
102 Args:
104 logger: Specifies the logger name or a Logger instance to be
105 configured. (Defaults to "fontTools" logger). Unlike ``basicConfig``,
106 this function can be called multiple times to reconfigure a logger.
107 If the logger or any of its children already exists before the call is
108 made, they will be reset before the new configuration is applied.
109 filename: Specifies that a ``FileHandler`` be created, using the
110 specified filename, rather than a ``StreamHandler``.
111 filemode: Specifies the mode to open the file, if filename is
112 specified. (If filemode is unspecified, it defaults to ``a``).
113 format: Use the specified format string for the handler. This
114 argument also accepts a dictionary of format strings keyed by
115 level name, to allow customising the records appearance for
116 specific levels. The special ``'*'`` key is for 'any other' level.
117 datefmt: Use the specified date/time format.
118 level: Set the logger level to the specified level.
119 stream: Use the specified stream to initialize the StreamHandler. Note
120 that this argument is incompatible with ``filename`` - if both
121 are present, ``stream`` is ignored.
122 handlers: If specified, this should be an iterable of already created
123 handlers, which will be added to the logger. Any handler in the
124 list which does not have a formatter assigned will be assigned the
125 formatter created in this function.
126 filters: If specified, this should be an iterable of already created
127 filters. If the ``handlers`` do not already have filters assigned,
128 these filters will be added to them.
129 propagate: All loggers have a ``propagate`` attribute which determines
130 whether to continue searching for handlers up the logging hierarchy.
131 If not provided, the "propagate" attribute will be set to ``False``.
132 """
133 # using kwargs to enforce keyword-only arguments in py2.
134 handlers = kwargs.pop("handlers", None)
135 if handlers is None:
136 if "stream" in kwargs and "filename" in kwargs:
137 raise ValueError(
138 "'stream' and 'filename' should not be " "specified together"
139 )
140 else:
141 if "stream" in kwargs or "filename" in kwargs:
142 raise ValueError(
143 "'stream' or 'filename' should not be "
144 "specified together with 'handlers'"
145 )
146 if handlers is None:
147 filename = kwargs.pop("filename", None)
148 mode = kwargs.pop("filemode", "a")
149 if filename:
150 h = logging.FileHandler(filename, mode)
151 else:
152 stream = kwargs.pop("stream", None)
153 h = logging.StreamHandler(stream)
154 handlers = [h]
155 # By default, the top-level library logger is configured.
156 logger = kwargs.pop("logger", "fontTools")
157 if not logger or isinstance(logger, str):
158 # empty "" or None means the 'root' logger
159 logger = logging.getLogger(logger)
160 # before (re)configuring, reset named logger and its children (if exist)
161 _resetExistingLoggers(parent=logger.name)
162 # use DEFAULT_FORMATS if 'format' is None
163 fs = kwargs.pop("format", None)
164 dfs = kwargs.pop("datefmt", None)
165 # XXX: '%' is the only format style supported on both py2 and 3
166 style = kwargs.pop("style", "%")
167 fmt = LevelFormatter(fs, dfs, style)
168 filters = kwargs.pop("filters", [])
169 for h in handlers:
170 if h.formatter is None:
171 h.setFormatter(fmt)
172 if not h.filters:
173 for f in filters:
174 h.addFilter(f)
175 logger.addHandler(h)
176 if logger.name != "root":
177 # stop searching up the hierarchy for handlers
178 logger.propagate = kwargs.pop("propagate", False)
179 # set a custom severity level
180 level = kwargs.pop("level", None)
181 if level is not None:
182 logger.setLevel(level)
183 if kwargs:
184 keys = ", ".join(kwargs.keys())
185 raise ValueError("Unrecognised argument(s): %s" % keys)
188def _resetExistingLoggers(parent="root"):
189 """Reset the logger named 'parent' and all its children to their initial
190 state, if they already exist in the current configuration.
191 """
192 root = logging.root
193 # get sorted list of all existing loggers
194 existing = sorted(root.manager.loggerDict.keys())
195 if parent == "root":
196 # all the existing loggers are children of 'root'
197 loggers_to_reset = [parent] + existing
198 elif parent not in existing:
199 # nothing to do
200 return
201 elif parent in existing:
202 loggers_to_reset = [parent]
203 # collect children, starting with the entry after parent name
204 i = existing.index(parent) + 1
205 prefixed = parent + "."
206 pflen = len(prefixed)
207 num_existing = len(existing)
208 while i < num_existing:
209 if existing[i][:pflen] == prefixed:
210 loggers_to_reset.append(existing[i])
211 i += 1
212 for name in loggers_to_reset:
213 if name == "root":
214 root.setLevel(logging.WARNING)
215 for h in root.handlers[:]:
216 root.removeHandler(h)
217 for f in root.filters[:]:
218 root.removeFilters(f)
219 root.disabled = False
220 else:
221 logger = root.manager.loggerDict[name]
222 logger.level = logging.NOTSET
223 logger.handlers = []
224 logger.filters = []
225 logger.propagate = True
226 logger.disabled = False
229class Timer(object):
230 """Keeps track of overall time and split/lap times.
232 >>> import time
233 >>> timer = Timer()
234 >>> time.sleep(0.01)
235 >>> print("First lap:", timer.split())
236 First lap: ...
237 >>> time.sleep(0.02)
238 >>> print("Second lap:", timer.split())
239 Second lap: ...
240 >>> print("Overall time:", timer.time())
241 Overall time: ...
243 Can be used as a context manager inside with-statements.
245 >>> with Timer() as t:
246 ... time.sleep(0.01)
247 >>> print("%0.3f seconds" % t.elapsed)
248 0... seconds
250 If initialised with a logger, it can log the elapsed time automatically
251 upon exiting the with-statement.
253 >>> import logging
254 >>> log = logging.getLogger("my-fancy-timer-logger")
255 >>> configLogger(logger=log, level="DEBUG", format="%(message)s", stream=sys.stdout)
256 >>> with Timer(log, 'do something'):
257 ... time.sleep(0.01)
258 Took ... to do something
260 The same Timer instance, holding a reference to a logger, can be reused
261 in multiple with-statements, optionally with different messages or levels.
263 >>> timer = Timer(log)
264 >>> with timer():
265 ... time.sleep(0.01)
266 elapsed time: ...s
267 >>> with timer('redo it', level=logging.INFO):
268 ... time.sleep(0.02)
269 Took ... to redo it
271 It can also be used as a function decorator to log the time elapsed to run
272 the decorated function.
274 >>> @timer()
275 ... def test1():
276 ... time.sleep(0.01)
277 >>> @timer('run test 2', level=logging.INFO)
278 ... def test2():
279 ... time.sleep(0.02)
280 >>> test1()
281 Took ... to run 'test1'
282 >>> test2()
283 Took ... to run test 2
284 """
286 # timeit.default_timer choses the most accurate clock for each platform
287 _time = timeit.default_timer
288 default_msg = "elapsed time: %(time).3fs"
289 default_format = "Took %(time).3fs to %(msg)s"
291 def __init__(self, logger=None, msg=None, level=None, start=None):
292 self.reset(start)
293 if logger is None:
294 for arg in ("msg", "level"):
295 if locals().get(arg) is not None:
296 raise ValueError("'%s' can't be specified without a 'logger'" % arg)
297 self.logger = logger
298 self.level = level if level is not None else TIME_LEVEL
299 self.msg = msg
301 def reset(self, start=None):
302 """Reset timer to 'start_time' or the current time."""
303 if start is None:
304 self.start = self._time()
305 else:
306 self.start = start
307 self.last = self.start
308 self.elapsed = 0.0
310 def time(self):
311 """Return the overall time (in seconds) since the timer started."""
312 return self._time() - self.start
314 def split(self):
315 """Split and return the lap time (in seconds) in between splits."""
316 current = self._time()
317 self.elapsed = current - self.last
318 self.last = current
319 return self.elapsed
321 def formatTime(self, msg, time):
322 """Format 'time' value in 'msg' and return formatted string.
323 If 'msg' contains a '%(time)' format string, try to use that.
324 Otherwise, use the predefined 'default_format'.
325 If 'msg' is empty or None, fall back to 'default_msg'.
326 """
327 if not msg:
328 msg = self.default_msg
329 if msg.find("%(time)") < 0:
330 msg = self.default_format % {"msg": msg, "time": time}
331 else:
332 try:
333 msg = msg % {"time": time}
334 except (KeyError, ValueError):
335 pass # skip if the format string is malformed
336 return msg
338 def __enter__(self):
339 """Start a new lap"""
340 self.last = self._time()
341 self.elapsed = 0.0
342 return self
344 def __exit__(self, exc_type, exc_value, traceback):
345 """End the current lap. If timer has a logger, log the time elapsed,
346 using the format string in self.msg (or the default one).
347 """
348 time = self.split()
349 if self.logger is None or exc_type:
350 # if there's no logger attached, or if any exception occurred in
351 # the with-statement, exit without logging the time
352 return
353 message = self.formatTime(self.msg, time)
354 # Allow log handlers to see the individual parts to facilitate things
355 # like a server accumulating aggregate stats.
356 msg_parts = {"msg": self.msg, "time": time}
357 self.logger.log(self.level, message, msg_parts)
359 def __call__(self, func_or_msg=None, **kwargs):
360 """If the first argument is a function, return a decorator which runs
361 the wrapped function inside Timer's context manager.
362 Otherwise, treat the first argument as a 'msg' string and return an updated
363 Timer instance, referencing the same logger.
364 A 'level' keyword can also be passed to override self.level.
365 """
366 if isinstance(func_or_msg, Callable):
367 func = func_or_msg
368 # use the function name when no explicit 'msg' is provided
369 if not self.msg:
370 self.msg = "run '%s'" % func.__name__
372 @wraps(func)
373 def wrapper(*args, **kwds):
374 with self:
375 return func(*args, **kwds)
377 return wrapper
378 else:
379 msg = func_or_msg or kwargs.get("msg")
380 level = kwargs.get("level", self.level)
381 return self.__class__(self.logger, msg, level)
383 def __float__(self):
384 return self.elapsed
386 def __int__(self):
387 return int(self.elapsed)
389 def __str__(self):
390 return "%.3f" % self.elapsed
393class ChannelsFilter(logging.Filter):
394 """Provides a hierarchical filter for log entries based on channel names.
396 Filters out records emitted from a list of enabled channel names,
397 including their children. It works the same as the ``logging.Filter``
398 class, but allows the user to specify multiple channel names.
400 >>> import sys
401 >>> handler = logging.StreamHandler(sys.stdout)
402 >>> handler.setFormatter(logging.Formatter("%(message)s"))
403 >>> filter = ChannelsFilter("A.B", "C.D")
404 >>> handler.addFilter(filter)
405 >>> root = logging.getLogger()
406 >>> root.addHandler(handler)
407 >>> root.setLevel(level=logging.DEBUG)
408 >>> logging.getLogger('A.B').debug('this record passes through')
409 this record passes through
410 >>> logging.getLogger('A.B.C').debug('records from children also pass')
411 records from children also pass
412 >>> logging.getLogger('C.D').debug('this one as well')
413 this one as well
414 >>> logging.getLogger('A.B.').debug('also this one')
415 also this one
416 >>> logging.getLogger('A.F').debug('but this one does not!')
417 >>> logging.getLogger('C.DE').debug('neither this one!')
418 """
420 def __init__(self, *names):
421 self.names = names
422 self.num = len(names)
423 self.lengths = {n: len(n) for n in names}
425 def filter(self, record):
426 if self.num == 0:
427 return True
428 for name in self.names:
429 nlen = self.lengths[name]
430 if name == record.name:
431 return True
432 elif record.name.find(name, 0, nlen) == 0 and record.name[nlen] == ".":
433 return True
434 return False
437class CapturingLogHandler(logging.Handler):
438 def __init__(self, logger, level):
439 super(CapturingLogHandler, self).__init__(level=level)
440 self.records = []
441 if isinstance(logger, str):
442 self.logger = logging.getLogger(logger)
443 else:
444 self.logger = logger
446 def __enter__(self):
447 self.original_disabled = self.logger.disabled
448 self.original_level = self.logger.level
449 self.original_propagate = self.logger.propagate
451 self.logger.addHandler(self)
452 self.logger.setLevel(self.level)
453 self.logger.disabled = False
454 self.logger.propagate = False
456 return self
458 def __exit__(self, type, value, traceback):
459 self.logger.removeHandler(self)
460 self.logger.setLevel(self.original_level)
461 self.logger.disabled = self.original_disabled
462 self.logger.propagate = self.original_propagate
464 return self
466 def emit(self, record):
467 self.records.append(record)
469 def assertRegex(self, regexp, msg=None):
470 import re
472 pattern = re.compile(regexp)
473 for r in self.records:
474 if pattern.search(r.getMessage()):
475 return True
476 if msg is None:
477 msg = "Pattern '%s' not found in logger records" % regexp
478 assert 0, msg
481class LogMixin(object):
482 """Mixin class that adds logging functionality to another class.
484 You can define a new class that subclasses from ``LogMixin`` as well as
485 other base classes through multiple inheritance.
486 All instances of that class will have a ``log`` property that returns
487 a ``logging.Logger`` named after their respective ``<module>.<class>``.
489 For example:
491 >>> class BaseClass(object):
492 ... pass
493 >>> class MyClass(LogMixin, BaseClass):
494 ... pass
495 >>> a = MyClass()
496 >>> isinstance(a.log, logging.Logger)
497 True
498 >>> print(a.log.name)
499 fontTools.misc.loggingTools.MyClass
500 >>> class AnotherClass(MyClass):
501 ... pass
502 >>> b = AnotherClass()
503 >>> isinstance(b.log, logging.Logger)
504 True
505 >>> print(b.log.name)
506 fontTools.misc.loggingTools.AnotherClass
507 """
509 @property
510 def log(self):
511 if not hasattr(self, "_log"):
512 name = ".".join((self.__class__.__module__, self.__class__.__name__))
513 self._log = logging.getLogger(name)
514 return self._log
517def deprecateArgument(name, msg, category=UserWarning):
518 """Raise a warning about deprecated function argument 'name'."""
519 warnings.warn("%r is deprecated; %s" % (name, msg), category=category, stacklevel=3)
522def deprecateFunction(msg, category=UserWarning):
523 """Decorator to raise a warning when a deprecated function is called."""
525 def decorator(func):
526 @wraps(func)
527 def wrapper(*args, **kwargs):
528 warnings.warn(
529 "%r is deprecated; %s" % (func.__name__, msg),
530 category=category,
531 stacklevel=2,
532 )
533 return func(*args, **kwargs)
535 return wrapper
537 return decorator
540if __name__ == "__main__":
541 import doctest
543 sys.exit(doctest.testmod(optionflags=doctest.ELLIPSIS).failed)