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