loggingTools.py 19 KB

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