1""" fontTools.misc.loggingTools.py -- tools for interfacing with the Python 2logging package. 3""" 4 5from __future__ import print_function, absolute_import 6from fontTools.misc.py23 import * 7import sys 8import logging 9import timeit 10from functools import wraps 11try: 12 from collections.abc import Mapping, Callable 13except ImportError: # python < 3.3 14 from collections import Mapping, Callable 15import warnings 16 17try: 18 from logging import PercentStyle 19except ImportError: 20 PercentStyle = None 21 22 23# default logging level used by Timer class 24TIME_LEVEL = logging.DEBUG 25 26# per-level format strings used by the default formatter 27# (the level name is not printed for INFO and DEBUG messages) 28DEFAULT_FORMATS = { 29 "*": "%(levelname)s: %(message)s", 30 "INFO": "%(message)s", 31 "DEBUG": "%(message)s", 32 } 33 34 35class LevelFormatter(logging.Formatter): 36 """ Formatter class which optionally takes a dict of logging levels to 37 format strings, allowing to customise the log records appearance for 38 specific levels. 39 The '*' key identifies the default format string. 40 41 >>> import sys 42 >>> handler = logging.StreamHandler(sys.stdout) 43 >>> formatter = LevelFormatter( 44 ... fmt={ 45 ... '*': '[%(levelname)s] %(message)s', 46 ... 'DEBUG': '%(name)s [%(levelname)s] %(message)s', 47 ... 'INFO': '%(message)s', 48 ... }) 49 >>> handler.setFormatter(formatter) 50 >>> log = logging.getLogger('test') 51 >>> log.setLevel(logging.DEBUG) 52 >>> log.addHandler(handler) 53 >>> log.debug('this uses a custom format string') 54 test [DEBUG] this uses a custom format string 55 >>> log.info('this also uses a custom format string') 56 this also uses a custom format string 57 >>> log.warning("this one uses the default format string") 58 [WARNING] this one uses the default format string 59 """ 60 61 def __init__(self, fmt=None, datefmt=None, style="%"): 62 if style != '%': 63 raise ValueError( 64 "only '%' percent style is supported in both python 2 and 3") 65 if fmt is None: 66 fmt = DEFAULT_FORMATS 67 if isinstance(fmt, basestring): 68 default_format = fmt 69 custom_formats = {} 70 elif isinstance(fmt, Mapping): 71 custom_formats = dict(fmt) 72 default_format = custom_formats.pop("*", None) 73 else: 74 raise TypeError('fmt must be a str or a dict of str: %r' % fmt) 75 super(LevelFormatter, self).__init__(default_format, datefmt) 76 self.default_format = self._fmt 77 self.custom_formats = {} 78 for level, fmt in custom_formats.items(): 79 level = logging._checkLevel(level) 80 self.custom_formats[level] = fmt 81 82 def format(self, record): 83 if self.custom_formats: 84 fmt = self.custom_formats.get(record.levelno, self.default_format) 85 if self._fmt != fmt: 86 self._fmt = fmt 87 # for python >= 3.2, _style needs to be set if _fmt changes 88 if PercentStyle: 89 self._style = PercentStyle(fmt) 90 return super(LevelFormatter, self).format(record) 91 92 93def configLogger(**kwargs): 94 """ Do basic configuration for the logging system. This is more or less 95 the same as logging.basicConfig with some additional options and defaults. 96 97 The default behaviour is to create a StreamHandler which writes to 98 sys.stderr, set a formatter using the DEFAULT_FORMATS strings, and add 99 the handler to the top-level library logger ("fontTools"). 100 101 A number of optional keyword arguments may be specified, which can alter 102 the default behaviour. 103 104 logger Specifies the logger name or a Logger instance to be configured. 105 (it defaults to "fontTools" logger). Unlike basicConfig, this 106 function can be called multiple times to reconfigure a logger. 107 If the logger or any of its children already exists before the 108 call is made, they will be reset before the new configuration 109 is applied. 110 filename Specifies that a FileHandler be created, using the specified 111 filename, rather than a StreamHandler. 112 filemode Specifies the mode to open the file, if filename is specified 113 (if filemode is unspecified, it defaults to 'a'). 114 format Use the specified format string for the handler. This argument 115 also accepts a dictionary of format strings keyed by level name, 116 to allow customising the records appearance for specific levels. 117 The special '*' key is for 'any other' level. 118 datefmt Use the specified date/time format. 119 level Set the logger level to the specified level. 120 stream Use the specified stream to initialize the StreamHandler. Note 121 that this argument is incompatible with 'filename' - if both 122 are present, 'stream' is ignored. 123 handlers If specified, this should be an iterable of already created 124 handlers, which will be added to the logger. Any handler 125 in the list which does not have a formatter assigned will be 126 assigned the formatter created in this function. 127 filters If specified, this should be an iterable of already created 128 filters, which will be added to the handler(s), if the latter 129 do(es) not already have filters assigned. 130 propagate All loggers have a "propagate" attribute initially set to True, 131 which determines whether to continue searching for handlers up 132 the logging hierarchy. By default, this arguments sets the 133 "propagate" attribute to False. 134 """ 135 # using kwargs to enforce keyword-only arguments in py2. 136 handlers = kwargs.pop("handlers", None) 137 if handlers is None: 138 if "stream" in kwargs and "filename" in kwargs: 139 raise ValueError("'stream' and 'filename' should not be " 140 "specified together") 141 else: 142 if "stream" in kwargs or "filename" in kwargs: 143 raise ValueError("'stream' or 'filename' should not be " 144 "specified together with 'handlers'") 145 if handlers is None: 146 filename = kwargs.pop("filename", None) 147 mode = kwargs.pop("filemode", 'a') 148 if filename: 149 h = logging.FileHandler(filename, mode) 150 else: 151 stream = kwargs.pop("stream", None) 152 h = logging.StreamHandler(stream) 153 handlers = [h] 154 # By default, the top-level library logger is configured. 155 logger = kwargs.pop("logger", "fontTools") 156 if not logger or isinstance(logger, basestring): 157 # empty "" or None means the 'root' logger 158 logger = logging.getLogger(logger) 159 # before (re)configuring, reset named logger and its children (if exist) 160 _resetExistingLoggers(parent=logger.name) 161 # use DEFAULT_FORMATS if 'format' is None 162 fs = kwargs.pop("format", None) 163 dfs = kwargs.pop("datefmt", None) 164 # XXX: '%' is the only format style supported on both py2 and 3 165 style = kwargs.pop("style", '%') 166 fmt = LevelFormatter(fs, dfs, style) 167 filters = kwargs.pop("filters", []) 168 for h in handlers: 169 if h.formatter is None: 170 h.setFormatter(fmt) 171 if not h.filters: 172 for f in filters: 173 h.addFilter(f) 174 logger.addHandler(h) 175 if logger.name != "root": 176 # stop searching up the hierarchy for handlers 177 logger.propagate = kwargs.pop("propagate", False) 178 # set a custom severity level 179 level = kwargs.pop("level", None) 180 if level is not None: 181 logger.setLevel(level) 182 if kwargs: 183 keys = ', '.join(kwargs.keys()) 184 raise ValueError('Unrecognised argument(s): %s' % keys) 185 186 187def _resetExistingLoggers(parent="root"): 188 """ Reset the logger named 'parent' and all its children to their initial 189 state, if they already exist in the current configuration. 190 """ 191 root = logging.root 192 # get sorted list of all existing loggers 193 existing = sorted(root.manager.loggerDict.keys()) 194 if parent == "root": 195 # all the existing loggers are children of 'root' 196 loggers_to_reset = [parent] + existing 197 elif parent not in existing: 198 # nothing to do 199 return 200 elif parent in existing: 201 loggers_to_reset = [parent] 202 # collect children, starting with the entry after parent name 203 i = existing.index(parent) + 1 204 prefixed = parent + "." 205 pflen = len(prefixed) 206 num_existing = len(existing) 207 while i < num_existing: 208 if existing[i][:pflen] == prefixed: 209 loggers_to_reset.append(existing[i]) 210 i += 1 211 for name in loggers_to_reset: 212 if name == "root": 213 root.setLevel(logging.WARNING) 214 for h in root.handlers[:]: 215 root.removeHandler(h) 216 for f in root.filters[:]: 217 root.removeFilters(f) 218 root.disabled = False 219 else: 220 logger = root.manager.loggerDict[name] 221 logger.level = logging.NOTSET 222 logger.handlers = [] 223 logger.filters = [] 224 logger.propagate = True 225 logger.disabled = False 226 227 228class Timer(object): 229 """ Keeps track of overall time and split/lap times. 230 231 >>> import time 232 >>> timer = Timer() 233 >>> time.sleep(0.01) 234 >>> print("First lap:", timer.split()) 235 First lap: ... 236 >>> time.sleep(0.02) 237 >>> print("Second lap:", timer.split()) 238 Second lap: ... 239 >>> print("Overall time:", timer.time()) 240 Overall time: ... 241 242 Can be used as a context manager inside with-statements. 243 244 >>> with Timer() as t: 245 ... time.sleep(0.01) 246 >>> print("%0.3f seconds" % t.elapsed) 247 0... seconds 248 249 If initialised with a logger, it can log the elapsed time automatically 250 upon exiting the with-statement. 251 252 >>> import logging 253 >>> log = logging.getLogger("fontTools") 254 >>> configLogger(level="DEBUG", format="%(message)s", stream=sys.stdout) 255 >>> with Timer(log, 'do something'): 256 ... time.sleep(0.01) 257 Took ... to do something 258 259 The same Timer instance, holding a reference to a logger, can be reused 260 in multiple with-statements, optionally with different messages or levels. 261 262 >>> timer = Timer(log) 263 >>> with timer(): 264 ... time.sleep(0.01) 265 elapsed time: ...s 266 >>> with timer('redo it', level=logging.INFO): 267 ... time.sleep(0.02) 268 Took ... to redo it 269 270 It can also be used as a function decorator to log the time elapsed to run 271 the decorated function. 272 273 >>> @timer() 274 ... def test1(): 275 ... time.sleep(0.01) 276 >>> @timer('run test 2', level=logging.INFO) 277 ... def test2(): 278 ... time.sleep(0.02) 279 >>> test1() 280 Took ... to run 'test1' 281 >>> test2() 282 Took ... to run test 2 283 """ 284 285 # timeit.default_timer choses the most accurate clock for each platform 286 _time = timeit.default_timer 287 default_msg = "elapsed time: %(time).3fs" 288 default_format = "Took %(time).3fs to %(msg)s" 289 290 def __init__(self, logger=None, msg=None, level=None, start=None): 291 self.reset(start) 292 if logger is None: 293 for arg in ('msg', 'level'): 294 if locals().get(arg) is not None: 295 raise ValueError( 296 "'%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 return wrapper 377 else: 378 msg = func_or_msg or kwargs.get("msg") 379 level = kwargs.get("level", self.level) 380 return self.__class__(self.logger, msg, level) 381 382 def __float__(self): 383 return self.elapsed 384 385 def __int__(self): 386 return int(self.elapsed) 387 388 def __str__(self): 389 return "%.3f" % self.elapsed 390 391 392class ChannelsFilter(logging.Filter): 393 """ Filter out records emitted from a list of enabled channel names, 394 including their children. It works the same as the logging.Filter class, 395 but allows to specify multiple channel names. 396 397 >>> import sys 398 >>> handler = logging.StreamHandler(sys.stdout) 399 >>> handler.setFormatter(logging.Formatter("%(message)s")) 400 >>> filter = ChannelsFilter("A.B", "C.D") 401 >>> handler.addFilter(filter) 402 >>> root = logging.getLogger() 403 >>> root.addHandler(handler) 404 >>> root.setLevel(level=logging.DEBUG) 405 >>> logging.getLogger('A.B').debug('this record passes through') 406 this record passes through 407 >>> logging.getLogger('A.B.C').debug('records from children also pass') 408 records from children also pass 409 >>> logging.getLogger('C.D').debug('this one as well') 410 this one as well 411 >>> logging.getLogger('A.B.').debug('also this one') 412 also this one 413 >>> logging.getLogger('A.F').debug('but this one does not!') 414 >>> logging.getLogger('C.DE').debug('neither this one!') 415 """ 416 417 def __init__(self, *names): 418 self.names = names 419 self.num = len(names) 420 self.lenghts = {n: len(n) for n in names} 421 422 def filter(self, record): 423 if self.num == 0: 424 return True 425 for name in self.names: 426 nlen = self.lenghts[name] 427 if name == record.name: 428 return True 429 elif (record.name.find(name, 0, nlen) == 0 430 and record.name[nlen] == "."): 431 return True 432 return False 433 434 435class CapturingLogHandler(logging.Handler): 436 def __init__(self, logger, level): 437 super(CapturingLogHandler, self).__init__(level=level) 438 self.records = [] 439 if isinstance(logger, basestring): 440 self.logger = logging.getLogger(logger) 441 else: 442 self.logger = logger 443 444 def __enter__(self): 445 self.original_disabled = self.logger.disabled 446 self.original_level = self.logger.level 447 self.original_propagate = self.logger.propagate 448 449 self.logger.addHandler(self) 450 self.logger.setLevel(self.level) 451 self.logger.disabled = False 452 self.logger.propagate = False 453 454 return self 455 456 def __exit__(self, type, value, traceback): 457 self.logger.removeHandler(self) 458 self.logger.setLevel(self.original_level) 459 self.logger.disabled = self.original_disabled 460 self.logger.propagate = self.original_propagate 461 462 return self 463 464 def emit(self, record): 465 self.records.append(record) 466 467 def assertRegex(self, regexp, msg=None): 468 import re 469 pattern = re.compile(regexp) 470 for r in self.records: 471 if pattern.search(r.getMessage()): 472 return True 473 if msg is None: 474 msg = "Pattern '%s' not found in logger records" % regexp 475 assert 0, msg 476 477 478class LogMixin(object): 479 """ Mixin class that adds logging functionality to another class. 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 For example: 485 486 >>> class BaseClass(object): 487 ... pass 488 >>> class MyClass(LogMixin, BaseClass): 489 ... pass 490 >>> a = MyClass() 491 >>> isinstance(a.log, logging.Logger) 492 True 493 >>> print(a.log.name) 494 fontTools.misc.loggingTools.MyClass 495 >>> class AnotherClass(MyClass): 496 ... pass 497 >>> b = AnotherClass() 498 >>> isinstance(b.log, logging.Logger) 499 True 500 >>> print(b.log.name) 501 fontTools.misc.loggingTools.AnotherClass 502 """ 503 504 @property 505 def log(self): 506 if not hasattr(self, "_log"): 507 name = ".".join( 508 (self.__class__.__module__, self.__class__.__name__) 509 ) 510 self._log = logging.getLogger(name) 511 return self._log 512 513 514def deprecateArgument(name, msg, category=UserWarning): 515 """ Raise a warning about deprecated function argument 'name'. """ 516 warnings.warn( 517 "%r is deprecated; %s" % (name, msg), category=category, stacklevel=3) 518 519 520def deprecateFunction(msg, category=UserWarning): 521 """ Decorator to raise a warning when a deprecated function is called. """ 522 def decorator(func): 523 @wraps(func) 524 def wrapper(*args, **kwargs): 525 warnings.warn( 526 "%r is deprecated; %s" % (func.__name__, msg), 527 category=category, stacklevel=2) 528 return func(*args, **kwargs) 529 return wrapper 530 return decorator 531 532 533class LastResortLogger(logging.Logger): 534 """ Adds support for 'lastResort' handler introduced in Python 3.2. 535 It allows to print messages to sys.stderr even when no explicit handler 536 was configured. 537 To enable it, you can do: 538 539 import logging 540 logging.lastResort = StderrHandler(logging.WARNING) 541 logging.setLoggerClass(LastResortLogger) 542 """ 543 544 def callHandlers(self, record): 545 # this is the same as Python 3.5's logging.Logger.callHandlers 546 c = self 547 found = 0 548 while c: 549 for hdlr in c.handlers: 550 found = found + 1 551 if record.levelno >= hdlr.level: 552 hdlr.handle(record) 553 if not c.propagate: 554 c = None # break out 555 else: 556 c = c.parent 557 if found == 0: 558 if logging.lastResort: 559 if record.levelno >= logging.lastResort.level: 560 logging.lastResort.handle(record) 561 elif ( 562 logging.raiseExceptions 563 and not self.manager.emittedNoHandlerWarning 564 ): 565 sys.stderr.write( 566 "No handlers could be found for logger" 567 ' "%s"\n' % self.name 568 ) 569 self.manager.emittedNoHandlerWarning = True 570 571 572class StderrHandler(logging.StreamHandler): 573 """ This class is like a StreamHandler using sys.stderr, but always uses 574 whateve sys.stderr is currently set to rather than the value of 575 sys.stderr at handler construction time. 576 """ 577 578 def __init__(self, level=logging.NOTSET): 579 """ 580 Initialize the handler. 581 """ 582 logging.Handler.__init__(self, level) 583 584 @property 585 def stream(self): 586 # the try/execept avoids failures during interpreter shutdown, when 587 # globals are set to None 588 try: 589 return sys.stderr 590 except AttributeError: 591 return __import__("sys").stderr 592 593 594if __name__ == "__main__": 595 import doctest 596 sys.exit(doctest.testmod(optionflags=doctest.ELLIPSIS).failed) 597