1import sys 2import logging 3import timeit 4from functools import wraps 5from collections.abc import Mapping, Callable 6import warnings 7from logging import PercentStyle 8 9 10# default logging level used by Timer class 11TIME_LEVEL = logging.DEBUG 12 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} 20 21 22class LevelFormatter(logging.Formatter): 23 """Log formatter with level-specific formatting. 24 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. 28 29 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` 35 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 """ 55 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 77 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) 87 88 89def configLogger(**kwargs): 90 """A more sophisticated logging system configuation manager. 91 92 This is more or less the same as :py:func:`logging.basicConfig`, 93 with some additional options and defaults. 94 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"). 98 99 A number of optional keyword arguments may be specified, which can alter 100 the default behaviour. 101 102 Args: 103 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) 186 187 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 227 228 229class Timer(object): 230 """Keeps track of overall time and split/lap times. 231 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: ... 242 243 Can be used as a context manager inside with-statements. 244 245 >>> with Timer() as t: 246 ... time.sleep(0.01) 247 >>> print("%0.3f seconds" % t.elapsed) 248 0... seconds 249 250 If initialised with a logger, it can log the elapsed time automatically 251 upon exiting the with-statement. 252 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 259 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. 262 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 270 271 It can also be used as a function decorator to log the time elapsed to run 272 the decorated function. 273 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 """ 285 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" 290 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 300 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 309 310 def time(self): 311 """Return the overall time (in seconds) since the timer started.""" 312 return self._time() - self.start 313 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 320 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 337 338 def __enter__(self): 339 """Start a new lap""" 340 self.last = self._time() 341 self.elapsed = 0.0 342 return self 343 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) 358 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__ 371 372 @wraps(func) 373 def wrapper(*args, **kwds): 374 with self: 375 return func(*args, **kwds) 376 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) 382 383 def __float__(self): 384 return self.elapsed 385 386 def __int__(self): 387 return int(self.elapsed) 388 389 def __str__(self): 390 return "%.3f" % self.elapsed 391 392 393class ChannelsFilter(logging.Filter): 394 """Provides a hierarchical filter for log entries based on channel names. 395 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. 399 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 """ 419 420 def __init__(self, *names): 421 self.names = names 422 self.num = len(names) 423 self.lengths = {n: len(n) for n in names} 424 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 435 436 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 445 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 450 451 self.logger.addHandler(self) 452 self.logger.setLevel(self.level) 453 self.logger.disabled = False 454 self.logger.propagate = False 455 456 return self 457 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 463 464 return self 465 466 def emit(self, record): 467 self.records.append(record) 468 469 def assertRegex(self, regexp, msg=None): 470 import re 471 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 479 480 481class LogMixin(object): 482 """Mixin class that adds logging functionality to another class. 483 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>``. 488 489 For example: 490 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 """ 508 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 515 516 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) 520 521 522def deprecateFunction(msg, category=UserWarning): 523 """Decorator to raise a warning when a deprecated function is called.""" 524 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) 534 535 return wrapper 536 537 return decorator 538 539 540if __name__ == "__main__": 541 import doctest 542 543 sys.exit(doctest.testmod(optionflags=doctest.ELLIPSIS).failed) 544