diff --git a/Lib/fontTools/__init__.py b/Lib/fontTools/__init__.py index 761983d7c..743471efc 100644 --- a/Lib/fontTools/__init__.py +++ b/Lib/fontTools/__init__.py @@ -1,4 +1,16 @@ from __future__ import print_function, division, absolute_import from fontTools.misc.py23 import * +import logging +from fontTools.misc.loggingTools import Logger, configLogger + +# set the logging.Logger class to one which supports the "last resort" handler, +# to be used when the client doesn't explicitly configure logging. +# It prints the bare message to sys.stderr, only for events of severity WARNING +# or greater. +logging.setLoggerClass(Logger) + +log = logging.getLogger(__name__) version = "3.0" + +__all__ = ["version", "log", "configLogger"] diff --git a/Lib/fontTools/cffLib.py b/Lib/fontTools/cffLib.py index a63b4d02c..1d3fd3a74 100644 --- a/Lib/fontTools/cffLib.py +++ b/Lib/fontTools/cffLib.py @@ -6,8 +6,12 @@ from fontTools.misc import sstruct from fontTools.misc import psCharStrings from fontTools.misc.textTools import safeEval import struct +import logging -DEBUG = 0 + +# mute cffLib debug messages when running ttx in verbose mode +DEBUG = logging.DEBUG - 1 +log = logging.getLogger(__name__) cffHeaderFormat = """ @@ -132,8 +136,7 @@ class CFFWriter(object): lastPosList = None count = 1 while True: - if DEBUG: - print("CFFWriter.toFile() iteration:", count) + log.log(DEBUG, "CFFWriter.toFile() iteration: %d", count) count = count + 1 pos = 0 posList = [pos] @@ -149,8 +152,7 @@ class CFFWriter(object): if posList == lastPosList: break lastPosList = posList - if DEBUG: - print("CFFWriter.toFile() writing to file.") + log.log(DEBUG, "CFFWriter.toFile() writing to file.") begin = file.tell() posList = [0] for item in self.data: @@ -308,16 +310,14 @@ class Index(object): name = self.__class__.__name__ if file is None: return - if DEBUG: - print("loading %s at %s" % (name, file.tell())) + log.log(DEBUG, "loading %s at %s", name, file.tell()) self.file = file count = readCard16(file) if count == 0: return self.items = [None] * count offSize = readCard8(file) - if DEBUG: - print(" index count: %s offSize: %s" % (count, offSize)) + log.log(DEBUG, " index count: %s offSize: %s", count, offSize) assert offSize <= 4, "offSize too large: %s" % offSize self.offsets = offsets = [] pad = b'\0' * (4 - offSize) @@ -328,8 +328,7 @@ class Index(object): offsets.append(int(offset)) self.offsetBase = file.tell() - 1 file.seek(self.offsetBase + offsets[-1]) # pretend we've read the whole lot - if DEBUG: - print(" end of %s at %s" % (name, file.tell())) + log.log(DEBUG, " end of %s at %s", name, file.tell()) def __len__(self): return len(self.items) @@ -784,8 +783,7 @@ class CharsetConverter(object): numGlyphs = parent.numGlyphs file = parent.file file.seek(value) - if DEBUG: - print("loading charset at %s" % value) + log.log(DEBUG, "loading charset at %s", value) format = readCard8(file) if format == 0: charset = parseCharset0(numGlyphs, file, parent.strings, isCID) @@ -794,8 +792,7 @@ class CharsetConverter(object): else: raise NotImplementedError assert len(charset) == numGlyphs - if DEBUG: - print(" charset end at %s" % file.tell()) + log.log(DEBUG, " charset end at %s", file.tell()) else: # offset == 0 -> no charset data. if isCID or "CharStrings" not in parent.rawDict: assert value == 0 # We get here only when processing fontDicts from the FDArray of CFF-CID fonts. Only the real topDict references the chrset. @@ -964,8 +961,7 @@ class EncodingConverter(SimpleConverter): assert value > 1 file = parent.file file.seek(value) - if DEBUG: - print("loading Encoding at %s" % value) + log.log(DEBUG, "loading Encoding at %s", value) fmt = readCard8(file) haveSupplement = fmt & 0x80 if haveSupplement: @@ -1335,9 +1331,7 @@ class DictCompiler(object): return len(self.compile("getDataLength")) def compile(self, reason): - if DEBUG: - print("-- compiling %s for %s" % (self.__class__.__name__, reason)) - print("in baseDict: ", self) + log.log(DEBUG, "-- compiling %s for %s", self.__class__.__name__, reason) rawDict = self.rawDict data = [] for name in self.dictObj.order: @@ -1468,16 +1462,15 @@ class BaseDict(object): def __init__(self, strings=None, file=None, offset=None): self.rawDict = {} - if DEBUG: - print("loading %s at %s" % (self.__class__.__name__, offset)) + if offset is not None: + log.log(DEBUG, "loading %s at %s", self.__class__.__name__, offset) self.file = file self.offset = offset self.strings = strings self.skipNames = [] def decompile(self, data): - if DEBUG: - print(" length %s is %s" % (self.__class__.__name__, len(data))) + log.log(DEBUG, " length %s is %d", self.__class__.__name__, len(data)) dec = self.decompilerClass(self.strings) dec.decompile(data) self.rawDict = dec.getDict() @@ -1558,7 +1551,7 @@ class TopDict(BaseDict): try: charString.decompile() except: - print("Error in charstring ", i) + log.error("Error in charstring %s", i) import sys typ, value = sys.exc_info()[0:2] raise typ(value) diff --git a/Lib/fontTools/merge.py b/Lib/fontTools/merge.py index 1e4bc074d..7b0a7ade5 100644 --- a/Lib/fontTools/merge.py +++ b/Lib/fontTools/merge.py @@ -11,10 +11,16 @@ from fontTools.misc.timeTools import timestampNow from fontTools import ttLib, cffLib from fontTools.ttLib.tables import otTables, _h_e_a_d from fontTools.ttLib.tables.DefaultTable import DefaultTable +from fontTools.misc.loggingTools import Timer from functools import reduce import sys import time import operator +import logging + + +log = logging.getLogger(__name__) +timer = Timer(logger=logging.getLogger(__name__+".timer"), level=logging.INFO) def _add_method(*clazzes, **kwargs): @@ -144,7 +150,7 @@ def mergeBits(bitmap): @_add_method(DefaultTable, allowDefaultTable=True) def merge(self, m, tables): if not hasattr(self, 'mergeMap'): - m.log("Don't know how to merge '%s'." % self.tableTag) + log.info("Don't know how to merge '%s'.", self.tableTag) return NotImplemented logic = self.mergeMap @@ -650,6 +656,9 @@ class Options(object): def __init__(self, **kwargs): + self.verbose = False + self.timing = False + self.set(**kwargs) def set(self, **kwargs): @@ -721,15 +730,12 @@ class Options(object): class Merger(object): - def __init__(self, options=None, log=None): + def __init__(self, options=None): - if not log: - log = Logger() if not options: options = Options() self.options = options - self.log = log def merge(self, fontfiles): @@ -766,19 +772,18 @@ class Merger(object): allTags = ['cmap'] + list(allTags) for tag in allTags: + with timer("merge '%s'" % tag): + tables = [font.get(tag, NotImplemented) for font in fonts] - tables = [font.get(tag, NotImplemented) for font in fonts] + clazz = ttLib.getTableClass(tag) + table = clazz(tag).merge(self, tables) + # XXX Clean this up and use: table = mergeObjects(tables) - clazz = ttLib.getTableClass(tag) - table = clazz(tag).merge(self, tables) - # XXX Clean this up and use: table = mergeObjects(tables) - - if table is not NotImplemented and table is not False: - mega[tag] = table - self.log("Merged '%s'." % tag) - else: - self.log("Dropped '%s'." % tag) - self.log.lapse("merge '%s'" % tag) + if table is not NotImplemented and table is not False: + mega[tag] = table + log.info("Merged '%s'.", tag) + else: + log.info("Dropped '%s'.", tag) del self.duplicateGlyphsPerFont @@ -874,64 +879,19 @@ class Merger(object): # TODO FeatureParams nameIDs -class Logger(object): - - def __init__(self, verbose=False, xml=False, timing=False): - self.verbose = verbose - self.xml = xml - self.timing = timing - self.last_time = self.start_time = time.time() - - def parse_opts(self, argv): - argv = argv[:] - for v in ['verbose', 'xml', 'timing']: - if "--"+v in argv: - setattr(self, v, True) - argv.remove("--"+v) - return argv - - def __call__(self, *things): - if not self.verbose: - return - print(' '.join(str(x) for x in things)) - - def lapse(self, *things): - if not self.timing: - return - new_time = time.time() - print("Took %0.3fs to %s" %(new_time - self.last_time, - ' '.join(str(x) for x in things))) - self.last_time = new_time - - def font(self, font, file=sys.stdout): - if not self.xml: - return - from fontTools.misc import xmlWriter - writer = xmlWriter.XMLWriter(file) - font.disassembleInstructions = False # Work around ttLib bug - for tag in font.keys(): - writer.begintag(tag) - writer.newline() - font[tag].toXML(writer, font) - writer.endtag(tag) - writer.newline() - - __all__ = [ 'Options', 'Merger', - 'Logger', 'main' ] +@timer("make one with everything (TOTAL TIME)") def main(args=None): + from fontTools import configLogger if args is None: args = sys.argv[1:] - log = Logger() - args = log.parse_opts(args) - options = Options() args = options.parse_opts(args) @@ -939,14 +899,18 @@ def main(args=None): print("usage: pyftmerge font...", file=sys.stderr) sys.exit(1) - merger = Merger(options=options, log=log) + configLogger(level=logging.INFO if options.verbose else logging.WARNING) + if options.timing: + timer.logger.setLevel(logging.DEBUG) + else: + timer.logger.disabled = True + + merger = Merger(options=options) font = merger.merge(args) outfile = 'merged.ttf' - font.save(outfile) - log.lapse("compile and save font") + with timer("compile and save font"): + font.save(outfile) - log.last_time = log.start_time - log.lapse("make one with everything(TOTAL TIME)") if __name__ == "__main__": main() diff --git a/Lib/fontTools/misc/loggingTools.py b/Lib/fontTools/misc/loggingTools.py new file mode 100644 index 000000000..04a435d02 --- /dev/null +++ b/Lib/fontTools/misc/loggingTools.py @@ -0,0 +1,502 @@ +""" fontTools.misc.loggingTools.py -- tools for interfacing with the Python +logging package. +""" + +from __future__ import print_function, absolute_import +from fontTools.misc.py23 import basestring +import sys +import logging +import timeit +from functools import wraps +import collections +import warnings + +try: + from logging import PercentStyle +except ImportError: + PercentStyle = None + + +# default logging level used by Timer class +TIME_LEVEL = logging.DEBUG + +# per-level format strings used by the default formatter +# (the level name is not printed for INFO and DEBUG messages) +DEFAULT_FORMATS = { + "*": "%(levelname)s: %(message)s", + "INFO": "%(message)s", + "DEBUG": "%(message)s", + } + + +class LevelFormatter(logging.Formatter): + """ Formatter class which optionally takes a dict of logging levels to + format strings, allowing to customise the log records appearance for + specific levels. + The '*' key identifies the default format string. + + >>> import sys + >>> handler = logging.StreamHandler(sys.stdout) + >>> formatter = LevelFormatter( + ... fmt={ + ... '*': '[%(levelname)s] %(message)s', + ... 'DEBUG': '%(name)s [%(levelname)s] %(message)s', + ... 'INFO': '%(message)s', + ... }) + >>> handler.setFormatter(formatter) + >>> log = logging.getLogger('test') + >>> log.setLevel(logging.DEBUG) + >>> log.addHandler(handler) + >>> log.debug('this uses a custom format string') + test [DEBUG] this uses a custom format string + >>> log.info('this also uses a custom format string') + this also uses a custom format string + >>> log.warning("this one uses the default format string") + [WARNING] this one uses the default format string + """ + + def __init__(self, fmt=None, datefmt=None, style="%"): + if style != '%': + raise ValueError( + "only '%' percent style is supported in both python 2 and 3") + if fmt is None: + fmt = DEFAULT_FORMATS + if isinstance(fmt, basestring): + default_format = fmt + custom_formats = {} + elif isinstance(fmt, collections.Mapping): + custom_formats = dict(fmt) + default_format = custom_formats.pop("*", None) + else: + raise TypeError('fmt must be a str or a dict of str: %r' % fmt) + super(LevelFormatter, self).__init__(default_format, datefmt) + self.default_format = self._fmt + self.custom_formats = {} + for level, fmt in custom_formats.items(): + level = logging._checkLevel(level) + self.custom_formats[level] = fmt + + def format(self, record): + if self.custom_formats: + fmt = self.custom_formats.get(record.levelno, self.default_format) + if self._fmt != fmt: + self._fmt = fmt + # for python >= 3.2, _style needs to be set if _fmt changes + if PercentStyle: + self._style = PercentStyle(fmt) + return super(LevelFormatter, self).format(record) + + +class _StderrHandler(logging.StreamHandler): + """ This class is like a StreamHandler using sys.stderr, but always uses + whatever sys.stderr is currently set to rather than the value of + sys.stderr at handler construction time. + """ + def __init__(self, level=logging.NOTSET): + """ + Initialize the handler. + """ + logging.Handler.__init__(self, level) + + @property + def stream(self): + return sys.stderr + + +if not hasattr(logging, 'lastResort'): + # for Python pre-3.2, set a "last resort" handler used when clients don't + # explicitly configure logging + logging.lastResort = _StderrHandler(logging.WARNING) + + +class Logger(logging.Logger): + """ Add support for 'lastResort' handler introduced in Python 3.2. + You can set logging.lastResort to None, if you wish to obtain the pre-3.2 + behaviour. Also see: + https://docs.python.org/3.5/howto/logging.html#what-happens-if-no-configuration-is-provided + """ + + def callHandlers(self, record): + # this is the same as Python 3.5's logging.Logger.callHandlers + c = self + found = 0 + while c: + for hdlr in c.handlers: + found = found + 1 + if record.levelno >= hdlr.level: + hdlr.handle(record) + if not c.propagate: + c = None # break out + else: + c = c.parent + if (found == 0): + if logging.lastResort: + if record.levelno >= logging.lastResort.level: + logging.lastResort.handle(record) + elif logging.raiseExceptions and not self.manager.emittedNoHandlerWarning: + sys.stderr.write("No handlers could be found for logger" + " \"%s\"\n" % self.name) + self.manager.emittedNoHandlerWarning = True + + +def configLogger(**kwargs): + """ Do basic configuration for the logging system. This is more or less + the same as logging.basicConfig with some additional options and defaults. + + The default behaviour is to create a StreamHandler which writes to + sys.stderr, set a formatter using the DEFAULT_FORMATS strings, and add + the handler to the top-level library logger ("fontTools"). + + A number of optional keyword arguments may be specified, which can alter + the default behaviour. + + logger Specifies the logger name or a Logger instance to be configured. + (it defaults to "fontTools" logger). Unlike basicConfig, this + function can be called multiple times to reconfigure a logger. + If the logger or any of its children already exists before the + call is made, they will be reset before the new configuration + is applied. + filename Specifies that a FileHandler be created, using the specified + filename, rather than a StreamHandler. + filemode Specifies the mode to open the file, if filename is specified + (if filemode is unspecified, it defaults to 'a'). + format Use the specified format string for the handler. This argument + also accepts a dictionary of format strings keyed by level name, + to allow customising the records appearance for specific levels. + The special '*' key is for 'any other' level. + datefmt Use the specified date/time format. + level Set the logger level to the specified level. + stream Use the specified stream to initialize the StreamHandler. Note + that this argument is incompatible with 'filename' - if both + are present, 'stream' is ignored. + handlers If specified, this should be an iterable of already created + handlers, which will be added to the logger. Any handler + in the list which does not have a formatter assigned will be + assigned the formatter created in this function. + filters If specified, this should be an iterable of already created + filters, which will be added to the handler(s), if the latter + do(es) not already have filters assigned. + propagate All loggers have a "propagate" attribute initially set to True, + which determines whether to continue searching for handlers up + the logging hierarchy. By default, this arguments sets the + "propagate" attribute to False. + """ + # using kwargs to enforce keyword-only arguments in py2. + handlers = kwargs.pop("handlers", None) + if handlers is None: + if "stream" in kwargs and "filename" in kwargs: + raise ValueError("'stream' and 'filename' should not be " + "specified together") + else: + if "stream" in kwargs or "filename" in kwargs: + raise ValueError("'stream' or 'filename' should not be " + "specified together with 'handlers'") + if handlers is None: + filename = kwargs.pop("filename", None) + mode = kwargs.pop("filemode", 'a') + if filename: + h = logging.FileHandler(filename, mode) + else: + stream = kwargs.pop("stream", None) + h = logging.StreamHandler(stream) + handlers = [h] + # By default, the top-level library logger is configured. + logger = kwargs.pop("logger", "fontTools") + if not logger or isinstance(logger, basestring): + # empty "" or None means the 'root' logger + logger = logging.getLogger(logger) + # before (re)configuring, reset named logger and its children (if exist) + _resetExistingLoggers(parent=logger.name) + # use DEFAULT_FORMATS if 'format' is None + fs = kwargs.pop("format", None) + dfs = kwargs.pop("datefmt", None) + # XXX: '%' is the only format style supported on both py2 and 3 + style = kwargs.pop("style", '%') + fmt = LevelFormatter(fs, dfs, style) + filters = kwargs.pop("filters", []) + for h in handlers: + if h.formatter is None: + h.setFormatter(fmt) + if not h.filters: + for f in filters: + h.addFilter(f) + logger.addHandler(h) + if logger.name != "root": + # stop searching up the hierarchy for handlers + logger.propagate = kwargs.pop("propagate", False) + # set a custom severity level + level = kwargs.pop("level", None) + if level is not None: + logger.setLevel(level) + if kwargs: + keys = ', '.join(kwargs.keys()) + raise ValueError('Unrecognised argument(s): %s' % keys) + + +def _resetExistingLoggers(parent="root"): + """ Reset the logger named 'parent' and all its children to their initial + state, if they already exist in the current configuration. + """ + root = logging.root + # get sorted list of all existing loggers + existing = sorted(root.manager.loggerDict.keys()) + if parent == "root": + # all the existing loggers are children of 'root' + loggers_to_reset = [parent] + existing + elif parent not in existing: + # nothing to do + return + elif parent in existing: + loggers_to_reset = [parent] + # collect children, starting with the entry after parent name + i = existing.index(parent) + 1 + prefixed = parent + "." + pflen = len(prefixed) + num_existing = len(existing) + while i < num_existing: + if existing[i][:pflen] == prefixed: + loggers_to_reset.append(existing[i]) + i += 1 + for name in loggers_to_reset: + if name == "root": + root.setLevel(logging.WARNING) + for h in root.handlers[:]: + root.removeHandler(h) + for f in root.filters[:]: + root.removeFilters(f) + root.disabled = False + else: + logger = root.manager.loggerDict[name] + logger.level = logging.NOTSET + logger.handlers = [] + logger.filters = [] + logger.propagate = True + logger.disabled = False + + +class Timer(object): + """ Keeps track of overall time and split/lap times. + + >>> import time + >>> timer = Timer() + >>> time.sleep(0.01) + >>> print("First lap:", timer.split()) + First lap: 0.0... + >>> time.sleep(0.02) + >>> print("Second lap:", timer.split()) + Second lap: 0.0... + >>> print("Overall time:", timer.time()) + Overall time: 0.0... + + Can be used as a context manager inside with-statements. + + >>> with Timer() as t: + ... time.sleep(0.01) + >>> print("%0.3f seconds" % t.elapsed) + 0.0... seconds + + If initialised with a logger, it can log the elapsed time automatically + upon exiting the with-statement. + + >>> import logging + >>> log = logging.getLogger("fontTools") + >>> configLogger(level="DEBUG", format="%(message)s", stream=sys.stdout) + >>> with Timer(log, 'do something'): + ... time.sleep(0.01) + Took ... to do something + + The same Timer instance, holding a reference to a logger, can be reused + in multiple with-statements, optionally with different messages or levels. + + >>> timer = Timer(log) + >>> with timer(): + ... time.sleep(0.01) + elapsed time: 0.01...s + >>> with timer('redo it', level=logging.INFO): + ... time.sleep(0.02) + Took ... to redo it + + It can also be used as a function decorator to log the time elapsed to run + the decorated function. + + >>> @timer() + ... def test1(): + ... time.sleep(0.01) + >>> @timer('run test 2', level=logging.INFO) + ... def test2(): + ... time.sleep(0.02) + >>> test1() + Took 0.01... to run 'test1' + >>> test2() + Took ... to run test 2 + """ + + # timeit.default_timer choses the most accurate clock for each platform + _time = timeit.default_timer + default_msg = "elapsed time: %(time).3fs" + default_format = "Took %(time).3fs to %(msg)s" + + def __init__(self, logger=None, msg=None, level=None, start=None): + self.reset(start) + if logger is None: + for arg in ('msg', 'level'): + if locals().get(arg) is not None: + raise ValueError( + "'%s' can't be specified without a 'logger'" % arg) + self.logger = logger + self.level = level if level is not None else TIME_LEVEL + self.msg = msg + + def reset(self, start=None): + """ Reset timer to 'start_time' or the current time. """ + if start is None: + self.start = self._time() + else: + self.start = start + self.last = self.start + self.elapsed = 0.0 + + def time(self): + """ Return the overall time (in seconds) since the timer started. """ + return self._time() - self.start + + def split(self): + """ Split and return the lap time (in seconds) in between splits. """ + current = self._time() + self.elapsed = current - self.last + self.last = current + return self.elapsed + + def formatTime(self, msg, time): + """ Format 'time' value in 'msg' and return formatted string. + If 'msg' contains a '%(time)' format string, try to use that. + Otherwise, use the predefined 'default_format'. + If 'msg' is empty or None, fall back to 'default_msg'. + """ + if not msg: + msg = self.default_msg + if msg.find("%(time)") < 0: + msg = self.default_format % {"msg": msg, "time": time} + else: + try: + msg = msg % {"time": time} + except (KeyError, ValueError): + pass # skip if the format string is malformed + return msg + + def __enter__(self): + """ Start a new lap """ + self.last = self._time() + self.elapsed = 0.0 + return self + + def __exit__(self, exc_type, exc_value, traceback): + """ End the current lap. If timer has a logger, log the time elapsed, + using the format string in self.msg (or the default one). + """ + time = self.split() + if self.logger is None or exc_type: + # if there's no logger attached, or if any exception occurred in + # the with-statement, exit without logging the time + return + message = self.formatTime(self.msg, time) + self.logger.log(self.level, message) + + def __call__(self, func_or_msg=None, **kwargs): + """ If the first argument is a function, return a decorator which runs + the wrapped function inside Timer's context manager. + Otherwise, treat the first argument as a 'msg' string and return an updated + Timer instance, referencing the same logger. + A 'level' keyword can also be passed to override self.level. + """ + if isinstance(func_or_msg, collections.Callable): + func = func_or_msg + # use the function name when no explicit 'msg' is provided + if not self.msg: + self.msg = "run '%s'" % func.__name__ + + @wraps(func) + def wrapper(*args, **kwds): + with self: + return func(*args, **kwds) + return wrapper + else: + msg = func_or_msg or kwargs.get("msg") + level = kwargs.get("level", self.level) + return self.__class__(self.logger, msg, level) + + def __float__(self): + return self.elapsed + + def __int__(self): + return int(self.elapsed) + + def __str__(self): + return "%.3f" % self.elapsed + + +class ChannelsFilter(logging.Filter): + """ Filter out records emitted from a list of enabled channel names, + including their children. It works the same as the logging.Filter class, + but allows to specify multiple channel names. + + >>> import sys + >>> handler = logging.StreamHandler(sys.stdout) + >>> handler.setFormatter(logging.Formatter("%(message)s")) + >>> filter = ChannelsFilter("A.B", "C.D") + >>> handler.addFilter(filter) + >>> root = logging.getLogger() + >>> root.addHandler(handler) + >>> root.setLevel(level=logging.DEBUG) + >>> logging.getLogger('A.B').debug('this record passes through') + this record passes through + >>> logging.getLogger('A.B.C').debug('records from children also pass') + records from children also pass + >>> logging.getLogger('C.D').debug('this one as well') + this one as well + >>> logging.getLogger('A.B.').debug('also this one') + also this one + >>> logging.getLogger('A.F').debug('but this one does not!') + >>> logging.getLogger('C.DE').debug('neither this one!') + """ + + def __init__(self, *names): + self.names = names + self.num = len(names) + self.lenghts = {n: len(n) for n in names} + + def filter(self, record): + if self.num == 0: + return True + for name in self.names: + nlen = self.lenghts[name] + if name == record.name: + return True + elif (record.name.find(name, 0, nlen) == 0 + and record.name[nlen] == "."): + return True + return False + + +def deprecateArgument(name, msg, category=UserWarning): + """ Raise a warning about deprecated function argument 'name'. """ + warnings.warn( + "%r is deprecated; %s" % (name, msg), category=category, stacklevel=3) + + +def deprecateFunction(msg, category=UserWarning): + """ Decorator to raise a warning when a deprecated function is called. """ + def decorator(func): + @wraps(func) + def wrapper(*args, **kwargs): + warnings.warn( + "%r is deprecated; %s" % (func.__name__, msg), + category=category, stacklevel=2) + return func(*args, **kwargs) + return wrapper + return decorator + + +if __name__ == "__main__": + import doctest + sys.exit(doctest.testmod(optionflags=doctest.ELLIPSIS).failed) diff --git a/Lib/fontTools/misc/psCharStrings.py b/Lib/fontTools/misc/psCharStrings.py index ffe8b69d2..094e8296f 100644 --- a/Lib/fontTools/misc/psCharStrings.py +++ b/Lib/fontTools/misc/psCharStrings.py @@ -5,9 +5,10 @@ CFF dictionary data and Type1/Type2 CharStrings. from __future__ import print_function, division, absolute_import from fontTools.misc.py23 import * import struct +import logging -DEBUG = 0 +log = logging.getLogger(__name__) def read_operator(self, b0, data, index): @@ -315,7 +316,7 @@ class T2CharString(ByteCodeBase): try: bytecode = bytesjoin(bytecode) except TypeError: - print(bytecode) + log.error(bytecode) raise self.setBytecode(bytecode) diff --git a/Lib/fontTools/misc/psLib.py b/Lib/fontTools/misc/psLib.py index 21da56296..dffe561cf 100644 --- a/Lib/fontTools/misc/psLib.py +++ b/Lib/fontTools/misc/psLib.py @@ -5,8 +5,11 @@ from .psOperators import * import re import collections from string import whitespace +import logging +log = logging.getLogger(__name__) + ps_special = b'()<>[]{}%' # / is one too, but we take care of that one differently skipwhiteRE = re.compile(bytesjoin([b"[", whitespace, b"]*"])) @@ -189,14 +192,18 @@ class PSInterpreter(PSOperators): handle_object(object) tokenizer.close() self.tokenizer = None - finally: + except: if self.tokenizer is not None: - if 0: - print('ps error:\n- - - - - - -') - print(self.tokenizer.buf[self.tokenizer.pos-50:self.tokenizer.pos]) - print('>>>') - print(self.tokenizer.buf[self.tokenizer.pos:self.tokenizer.pos+50]) - print('- - - - - - -') + log.debug( + 'ps error:\n' + '- - - - - - -\n' + '%s\n' + '>>>\n' + '%s\n' + '- - - - - - -', + self.tokenizer.buf[self.tokenizer.pos-50:self.tokenizer.pos], + self.tokenizer.buf[self.tokenizer.pos:self.tokenizer.pos+50]) + raise def handle_object(self, object): if not (self.proclevel or object.literal or object.type == 'proceduretype'): diff --git a/Lib/fontTools/misc/xmlReader.py b/Lib/fontTools/misc/xmlReader.py index f8b43b751..ec8927d14 100644 --- a/Lib/fontTools/misc/xmlReader.py +++ b/Lib/fontTools/misc/xmlReader.py @@ -4,8 +4,11 @@ from fontTools import ttLib from fontTools.misc.textTools import safeEval from fontTools.ttLib.tables.DefaultTable import DefaultTable import os +import logging +log = logging.getLogger(__name__) + class TTXParseError(Exception): pass BUFSIZE = 0x4000 @@ -13,7 +16,7 @@ BUFSIZE = 0x4000 class XMLReader(object): - def __init__(self, fileOrPath, ttFont, progress=None, quiet=False): + def __init__(self, fileOrPath, ttFont, progress=None, quiet=None): if fileOrPath == '-': fileOrPath = sys.stdin if not hasattr(fileOrPath, "read"): @@ -25,7 +28,10 @@ class XMLReader(object): self._closeStream = False self.ttFont = ttFont self.progress = progress - self.quiet = quiet + if quiet is not None: + from fontTools.misc.loggingTools import deprecateArgument + deprecateArgument("quiet", "configure logging instead") + self.quiet = quiet self.root = None self.contentStack = [] self.stackSize = 0 @@ -83,7 +89,7 @@ class XMLReader(object): # else fall back to using the current working directory dirname = os.getcwd() subFile = os.path.join(dirname, subFile) - subReader = XMLReader(subFile, self.ttFont, self.progress, self.quiet) + subReader = XMLReader(subFile, self.ttFont, self.progress) subReader.read() self.contentStack.append([]) return @@ -91,11 +97,7 @@ class XMLReader(object): msg = "Parsing '%s' table..." % tag if self.progress: self.progress.setLabel(msg) - elif self.ttFont.verbose: - ttLib.debugmsg(msg) - else: - if not self.quiet: - print(msg) + log.info(msg) if tag == "GlyphOrder": tableClass = ttLib.GlyphOrder elif "ERROR" in attrs or ('raw' in attrs and safeEval(attrs['raw'])): diff --git a/Lib/fontTools/mtiLib/__init__.py b/Lib/fontTools/mtiLib/__init__.py index 8100d25e9..e548c5232 100644 --- a/Lib/fontTools/mtiLib/__init__.py +++ b/Lib/fontTools/mtiLib/__init__.py @@ -15,15 +15,16 @@ from fontTools.ttLib.tables.otBase import ValueRecord, valueRecordFormatDict from fontTools.otlLib import builder as otl from contextlib import contextmanager from operator import setitem +import logging class MtiLibError(Exception): pass class ReferenceNotFoundError(MtiLibError): pass class FeatureNotFoundError(ReferenceNotFoundError): pass class LookupNotFoundError(ReferenceNotFoundError): pass -def debug(*args): - #print(*args) - pass + +log = logging.getLogger(__name__) + def makeGlyph(s): if s[:2] == 'U ': @@ -79,18 +80,18 @@ class DeferredMapping(dict): self._deferredMappings = [] def addDeferredMapping(self, setter, sym, e): - debug("Adding deferred mapping for symbol '%s'" % sym, type(e).__name__) + log.debug("Adding deferred mapping for symbol '%s' %s", sym, type(e).__name__) self._deferredMappings.append((setter,sym, e)) def applyDeferredMappings(self): for setter,sym,e in self._deferredMappings: - debug("Applying deferred mapping for symbol '%s'" % sym, type(e).__name__) + log.debug("Applying deferred mapping for symbol '%s' %s", sym, type(e).__name__) try: mapped = self[sym] except KeyError: raise e setter(mapped) - debug("Set to %s" % mapped) + log.debug("Set to %s", mapped) self._deferredMappings = [] @@ -100,7 +101,7 @@ def parseScriptList(lines, featureMap=None): with lines.between('script table'): for line in lines: scriptTag, langSysTag, defaultFeature, features = line - debug("Adding script", scriptTag, "language-system", langSysTag) + log.debug("Adding script %s language-system %s", scriptTag, langSysTag) langSys = ot.LangSys() langSys.LookupOrder = None @@ -676,7 +677,7 @@ def parseContext(self, lines, font, Type, lookupMap=None): typ = lines.peek()[0].split()[0].lower() if typ == 'glyph': self.Format = 1 - debug("Parsing %s format %s" % (Type, self.Format)) + log.debug("Parsing %s format %s", Type, self.Format) c = ContextHelper(Type, self.Format) rules = [] for line in lines: @@ -690,7 +691,7 @@ def parseContext(self, lines, font, Type, lookupMap=None): bucketizeRules(self, c, rules, self.Coverage.glyphs) elif typ.endswith('class'): self.Format = 2 - debug("Parsing %s format %s" % (Type, self.Format)) + log.debug("Parsing %s format %s", Type, self.Format) c = ContextHelper(Type, self.Format) classDefs = [None] * c.DataLen while lines.peek()[0].endswith("class definition begin"): @@ -720,7 +721,7 @@ def parseContext(self, lines, font, Type, lookupMap=None): bucketizeRules(self, c, rules, range(max(firstClasses) + 1)) elif typ.endswith('coverage'): self.Format = 3 - debug("Parsing %s format %s" % (Type, self.Format)) + log.debug("Parsing %s format %s", Type, self.Format) c = ContextHelper(Type, self.Format) coverages = tuple([] for i in range(c.DataLen)) while lines.peek()[0].endswith("coverage definition begin"): @@ -782,7 +783,7 @@ def parseReverseChainedSubst(self, lines, font, _lookupMap=None): def parseLookup(lines, tableTag, font, lookupMap=None): line = lines.expect('lookup') _, name, typ = line - debug("Parsing lookup type %s %s" % (typ, name)) + log.debug("Parsing lookup type %s %s", typ, name) lookup = ot.Lookup() with lines.until('lookup end'): @@ -838,7 +839,7 @@ def parseGSUBGPOS(lines, font, tableTag): lookupMap = DeferredMapping() featureMap = DeferredMapping() assert tableTag in ('GSUB', 'GPOS') - debug("Parsing", tableTag) + log.debug("Parsing %s", tableTag) self = getattr(ot, tableTag)() self.Version = 1.0 fields = { @@ -933,7 +934,7 @@ def parseMarkFilteringSets(lines, font): return makeMarkFilteringSets(sets, font) def parseGDEF(lines, font): - debug("Parsing GDEF") + log.debug("Parsing GDEF") self = ot.GDEF() fields = { 'class definition begin': @@ -954,7 +955,7 @@ def parseGDEF(lines, font): while lines.peek() is not None: typ = lines.peek()[0].lower() if typ not in fields: - debug ('Skipping', line) + log.debug('Skipping %s', typ) next(lines) continue attr,parser = fields[typ] @@ -964,7 +965,7 @@ def parseGDEF(lines, font): return self def parseTable(lines, font, tableTag=None): - debug("Parsing table") + log.debug("Parsing table") line = lines.peek() if line[0].split()[0] == 'FontDame': next(lines) @@ -1103,13 +1104,18 @@ class MockFont(object): return self._glyphOrder def main(args): + from fontTools import configLogger + # configure the library logger (for >= WARNING) + configLogger() + # comment this out to enable debug messages from mtiLib's logger + # log.setLevel(logging.DEBUG) font = MockFont() tableTag = None if args[0].startswith('-t'): tableTag = args[0][2:] del args[0] for f in args: - debug("Processing", f) + log.debug("Processing %s", f) table = build(open(f, 'rt', encoding="utf-8"), font, tableTag=tableTag) blob = table.compile(font) # Make sure it compiles decompiled = table.__class__() diff --git a/Lib/fontTools/subset/__init__.py b/Lib/fontTools/subset/__init__.py index c16c0645c..ab8298fca 100644 --- a/Lib/fontTools/subset/__init__.py +++ b/Lib/fontTools/subset/__init__.py @@ -8,10 +8,12 @@ from fontTools import ttLib from fontTools.ttLib.tables import otTables from fontTools.misc import psCharStrings from fontTools.pens.boundsPen import BoundsPen +from fontTools.misc.loggingTools import Timer import sys import struct -import time import array +import logging +from types import MethodType __usage__ = "pyftsubset font-file [glyph...] [--option=value]..." @@ -316,6 +318,22 @@ Example: """ +log = logging.getLogger(__name__) + +def _log_glyphs(self, glyphs, font=None): + self.info("Glyph names: %s", sorted(glyphs)) + if font: + reverseGlyphMap = font.getReverseGlyphMap() + self.info("Glyph IDs: %s", sorted(reverseGlyphMap[g] for g in glyphs)) + +# bind "glyphs" function to 'log' object +log.glyphs = MethodType(_log_glyphs, log) + +# I use a different timing channel so I can configure it separately from the +# main module's logger +timer = Timer(logger=logging.getLogger(__name__+".timer")) + + def _add_method(*clazzes): """Returns a decorator function that adds a new method to one or more classes.""" @@ -2409,6 +2427,9 @@ class Options(object): self.canonical_order = False # Order tables as recommended self.flavor = None # May be 'woff' or 'woff2' self.desubroutinize = False # Desubroutinize CFF CharStrings + self.verbose = False + self.timing = False + self.xml = False self.set(**kwargs) @@ -2494,15 +2515,12 @@ class Subsetter(object): class MissingGlyphsSubsettingError(SubsettingError): pass class MissingUnicodesSubsettingError(SubsettingError): pass - def __init__(self, options=None, log=None): + def __init__(self, options=None): - if not log: - log = Logger() if not options: options = Options() self.options = options - self.log = log self.unicodes_requested = set() self.glyph_names_requested = set() self.glyph_ids_requested = set() @@ -2524,23 +2542,23 @@ class Subsetter(object): if(tag.strip() in self.options.drop_tables or (tag.strip() in self.options.hinting_tables and not self.options.hinting) or (tag == 'kern' and (not self.options.legacy_kern and 'GPOS' in font))): - self.log(tag, "dropped") + log.info("%s dropped", tag) del font[tag] continue clazz = ttLib.getTableClass(tag) if hasattr(clazz, 'prune_pre_subset'): - table = font[tag] - self.log.lapse("load '%s'" % tag) - retain = table.prune_pre_subset(self.options) - self.log.lapse("prune '%s'" % tag) + with timer("load '%s'" % tag): + table = font[tag] + with timer("prune '%s'" % tag): + retain = table.prune_pre_subset(self.options) if not retain: - self.log(tag, "pruned to empty; dropped") + log.info("%s pruned to empty; dropped", tag) del font[tag] continue else: - self.log(tag, "pruned") + log.info("%s pruned", tag) def _closure_glyphs(self, font): @@ -2558,7 +2576,7 @@ class Subsetter(object): self.glyphs_missing.update(i for i in self.glyph_ids_requested if i >= len(glyph_order)) if self.glyphs_missing: - self.log("Missing requested glyphs: %s" % self.glyphs_missing) + log.info("Missing requested glyphs: %s", self.glyphs_missing) if not self.options.ignore_missing_glyphs: raise self.MissingGlyphsSubsettingError(self.glyphs_missing) @@ -2566,13 +2584,13 @@ class Subsetter(object): self.unicodes_missing = set() if 'cmap' in font: - font['cmap'].closure_glyphs(self) - self.glyphs.intersection_update(realGlyphs) - self.log.lapse("close glyph list over 'cmap'") + with timer("close glyph list over 'cmap'"): + font['cmap'].closure_glyphs(self) + self.glyphs.intersection_update(realGlyphs) self.glyphs_cmaped = frozenset(self.glyphs) if self.unicodes_missing: missing = ["U+%04X" % u for u in self.unicodes_missing] - self.log("Missing glyphs for requested Unicodes: %s" % missing) + log.info("Missing glyphs for requested Unicodes: %s", missing) if not self.options.ignore_missing_unicodes: raise self.MissingUnicodesSubsettingError(missing) del missing @@ -2580,67 +2598,67 @@ class Subsetter(object): if self.options.notdef_glyph: if 'glyf' in font: self.glyphs.add(font.getGlyphName(0)) - self.log("Added gid0 to subset") + log.info("Added gid0 to subset") else: self.glyphs.add('.notdef') - self.log("Added .notdef to subset") + log.info("Added .notdef to subset") if self.options.recommended_glyphs: if 'glyf' in font: for i in range(min(4, len(font.getGlyphOrder()))): self.glyphs.add(font.getGlyphName(i)) - self.log("Added first four glyphs to subset") + log.info("Added first four glyphs to subset") if 'GSUB' in font: - self.log("Closing glyph list over 'GSUB': %d glyphs before" % - len(self.glyphs)) - self.log.glyphs(self.glyphs, font=font) - font['GSUB'].closure_glyphs(self) - self.glyphs.intersection_update(realGlyphs) - self.log("Closed glyph list over 'GSUB': %d glyphs after" % - len(self.glyphs)) - self.log.glyphs(self.glyphs, font=font) - self.log.lapse("close glyph list over 'GSUB'") + with timer("close glyph list over 'GSUB'"): + log.info("Closing glyph list over 'GSUB': %d glyphs before", + len(self.glyphs)) + log.glyphs(self.glyphs, font=font) + font['GSUB'].closure_glyphs(self) + self.glyphs.intersection_update(realGlyphs) + log.info("Closed glyph list over 'GSUB': %d glyphs after", + len(self.glyphs)) + log.glyphs(self.glyphs, font=font) self.glyphs_gsubed = frozenset(self.glyphs) if 'MATH' in font: - self.log("Closing glyph list over 'MATH': %d glyphs before" % - len(self.glyphs)) - self.log.glyphs(self.glyphs, font=font) - font['MATH'].closure_glyphs(self) - self.glyphs.intersection_update(realGlyphs) - self.log("Closed glyph list over 'MATH': %d glyphs after" % - len(self.glyphs)) - self.log.glyphs(self.glyphs, font=font) - self.log.lapse("close glyph list over 'MATH'") + with timer("close glyph list over 'MATH'"): + log.info("Closing glyph list over 'MATH': %d glyphs before", + len(self.glyphs)) + log.glyphs(self.glyphs, font=font) + font['MATH'].closure_glyphs(self) + self.glyphs.intersection_update(realGlyphs) + log.info("Closed glyph list over 'MATH': %d glyphs after", + len(self.glyphs)) + log.glyphs(self.glyphs, font=font) self.glyphs_mathed = frozenset(self.glyphs) if 'COLR' in font: - self.log("Closing glyph list over 'COLR': %d glyphs before" % - len(self.glyphs)) - self.log.glyphs(self.glyphs, font=font) - font['COLR'].closure_glyphs(self) - self.glyphs.intersection_update(realGlyphs) - self.log("Closed glyph list over 'COLR': %d glyphs after" % - len(self.glyphs)) - self.log.glyphs(self.glyphs, font=font) - self.log.lapse("close glyph list over 'COLR'") + with timer("close glyph list over 'COLR'"): + log.info("Closing glyph list over 'COLR': %d glyphs before", + len(self.glyphs)) + log.glyphs(self.glyphs, font=font) + font['COLR'].closure_glyphs(self) + self.glyphs.intersection_update(realGlyphs) + log.info("Closed glyph list over 'COLR': %d glyphs after", + len(self.glyphs)) + log.glyphs(self.glyphs, font=font) self.glyphs_colred = frozenset(self.glyphs) if 'glyf' in font: - self.log("Closing glyph list over 'glyf': %d glyphs before" % - len(self.glyphs)) - self.log.glyphs(self.glyphs, font=font) - font['glyf'].closure_glyphs(self) - self.glyphs.intersection_update(realGlyphs) - self.log("Closed glyph list over 'glyf': %d glyphs after" % - len(self.glyphs)) - self.log.glyphs(self.glyphs, font=font) - self.log.lapse("close glyph list over 'glyf'") + with timer("close glyph list over 'glyf'"): + log.info("Closing glyph list over 'glyf': %d glyphs before", + len(self.glyphs)) + log.glyphs(self.glyphs, font=font) + font['glyf'].closure_glyphs(self) + self.glyphs.intersection_update(realGlyphs) + log.info("Closed glyph list over 'glyf': %d glyphs after", + len(self.glyphs)) + log.glyphs(self.glyphs, font=font) self.glyphs_glyfed = frozenset(self.glyphs) self.glyphs_all = frozenset(self.glyphs) - self.log("Retaining %d glyphs: " % len(self.glyphs_all)) + log.info("Retaining %d glyphs", len(self.glyphs_all)) del self.glyphs @@ -2650,27 +2668,27 @@ class Subsetter(object): clazz = ttLib.getTableClass(tag) if tag.strip() in self.options.no_subset_tables: - self.log(tag, "subsetting not needed") + log.info("%s subsetting not needed", tag) elif hasattr(clazz, 'subset_glyphs'): - table = font[tag] - self.glyphs = self.glyphs_all - retain = table.subset_glyphs(self) - del self.glyphs - self.log.lapse("subset '%s'" % tag) + with timer("subset '%s'" % tag): + table = font[tag] + self.glyphs = self.glyphs_all + retain = table.subset_glyphs(self) + del self.glyphs if not retain: - self.log(tag, "subsetted to empty; dropped") + log.info("%s subsetted to empty; dropped", tag) del font[tag] else: - self.log(tag, "subsetted") + log.info("%s subsetted", tag) else: - self.log(tag, "NOT subset; don't know how to subset; dropped") + log.info("%s NOT subset; don't know how to subset; dropped", tag) del font[tag] - glyphOrder = font.getGlyphOrder() - glyphOrder = [g for g in glyphOrder if g in self.glyphs_all] - font.setGlyphOrder(glyphOrder) - font._buildReverseGlyphOrderDict() - self.log.lapse("subset GlyphOrder") + with timer("subset GlyphOrder"): + glyphOrder = font.getGlyphOrder() + glyphOrder = [g for g in glyphOrder if g in self.glyphs_all] + font.setGlyphOrder(glyphOrder) + font._buildReverseGlyphOrderDict() def _prune_post_subset(self, font): for tag in font.keys(): @@ -2679,17 +2697,17 @@ class Subsetter(object): old_uniranges = font[tag].getUnicodeRanges() new_uniranges = font[tag].recalcUnicodeRanges(font, pruneOnly=True) if old_uniranges != new_uniranges: - self.log(tag, "Unicode ranges pruned: %s" % sorted(new_uniranges)) + log.info("%s Unicode ranges pruned: %s", tag, sorted(new_uniranges)) clazz = ttLib.getTableClass(tag) if hasattr(clazz, 'prune_post_subset'): - table = font[tag] - retain = table.prune_post_subset(self.options) - self.log.lapse("prune '%s'" % tag) + with timer("prune '%s'" % tag): + table = font[tag] + retain = table.prune_post_subset(self.options) if not retain: - self.log(tag, "pruned to empty; dropped") + log.info("%s pruned to empty; dropped", tag) del font[tag] else: - self.log(tag, "pruned") + log.info("%s pruned", tag) def subset(self, font): @@ -2699,56 +2717,7 @@ class Subsetter(object): self._prune_post_subset(font) -class Logger(object): - - def __init__(self, verbose=False, xml=False, timing=False): - self.verbose = verbose - self.xml = xml - self.timing = timing - self.last_time = self.start_time = time.time() - - def parse_opts(self, argv): - argv = argv[:] - for v in ['verbose', 'xml', 'timing']: - if "--"+v in argv: - setattr(self, v, True) - argv.remove("--"+v) - return argv - - def __call__(self, *things): - if not self.verbose: - return - print(' '.join(str(x) for x in things)) - - def lapse(self, *things): - if not self.timing: - return - new_time = time.time() - print("Took %0.3fs to %s" %(new_time - self.last_time, - ' '.join(str(x) for x in things))) - self.last_time = new_time - - def glyphs(self, glyphs, font=None): - if not self.verbose: - return - self("Glyph names:", sorted(glyphs)) - if font: - reverseGlyphMap = font.getReverseGlyphMap() - self("Glyph IDs: ", sorted(reverseGlyphMap[g] for g in glyphs)) - - def font(self, font, file=sys.stdout): - if not self.xml: - return - from fontTools.misc import xmlWriter - writer = xmlWriter.XMLWriter(file) - for tag in font.keys(): - writer.begintag(tag) - writer.newline() - font[tag].toXML(writer, font) - writer.endtag(tag) - writer.newline() - - +@timer("load font") def load_font(fontFile, options, allowVID=False, @@ -2783,6 +2752,7 @@ def load_font(fontFile, return font +@timer("compile and save font") def save_font(font, outfile, options): if options.flavor and not hasattr(font, 'flavor'): raise Exception("fonttools version does not support flavors.") @@ -2816,7 +2786,9 @@ def parse_gids(s): def parse_glyphs(s): return s.replace(',', ' ').split() +@timer("make one with everything (TOTAL TIME)") def main(args=None): + from fontTools import configLogger if args is None: args = sys.argv[1:] @@ -2825,9 +2797,6 @@ def main(args=None): print(__doc__) sys.exit(0) - log = Logger() - args = log.parse_opts(args) - options = Options() args = options.parse_opts(args, ignore_unknown=['gids', 'gids-file', @@ -2841,10 +2810,16 @@ def main(args=None): print("Try pyftsubset --help for more information.", file=sys.stderr) sys.exit(1) + configLogger(level=logging.INFO if options.verbose else logging.WARNING) + if options.timing: + timer.logger.setLevel(logging.DEBUG) + else: + timer.logger.disabled = True + fontfile = args[0] args = args[1:] - subsetter = Subsetter(options=options, log=log) + subsetter = Subsetter(options=options) outfile = fontfile + '.subset' glyphs = [] gids = [] @@ -2896,36 +2871,33 @@ def main(args=None): dontLoadGlyphNames = not options.glyph_names and not glyphs font = load_font(fontfile, options, dontLoadGlyphNames=dontLoadGlyphNames) - log.lapse("load font") - if wildcard_glyphs: + + with timer("compile glyph list"): + if wildcard_glyphs: glyphs.extend(font.getGlyphOrder()) - if wildcard_unicodes: + if wildcard_unicodes: for t in font['cmap'].tables: if t.isUnicode(): unicodes.extend(t.cmap.keys()) - assert '' not in glyphs + assert '' not in glyphs - log.lapse("compile glyph list") - log("Text: '%s'" % text) - log("Unicodes:", unicodes) - log("Glyphs:", glyphs) - log("Gids:", gids) + log.info("Text: '%s'" % text) + log.info("Unicodes: %s", unicodes) + log.info("Glyphs: %s", glyphs) + log.info("Gids: %s", gids) subsetter.populate(glyphs=glyphs, gids=gids, unicodes=unicodes, text=text) subsetter.subset(font) - save_font (font, outfile, options) - log.lapse("compile and save font") + save_font(font, outfile, options) - log.last_time = log.start_time - log.lapse("make one with everything(TOTAL TIME)") - - if log.verbose: + if options.verbose: import os - log("Input font:% 7d bytes: %s" % (os.path.getsize(fontfile), fontfile)) - log("Subset font:% 7d bytes: %s" % (os.path.getsize(outfile), outfile)) + log.info("Input font:% 7d bytes: %s" % (os.path.getsize(fontfile), fontfile)) + log.info("Subset font:% 7d bytes: %s" % (os.path.getsize(outfile), outfile)) - log.font(font) + if options.xml: + font.saveXML(sys.stdout) font.close() @@ -2933,7 +2905,6 @@ def main(args=None): __all__ = [ 'Options', 'Subsetter', - 'Logger', 'load_font', 'save_font', 'parse_gids', diff --git a/Lib/fontTools/ttLib/__init__.py b/Lib/fontTools/ttLib/__init__.py index a3f4fd370..0ef913190 100644 --- a/Lib/fontTools/ttLib/__init__.py +++ b/Lib/fontTools/ttLib/__init__.py @@ -43,10 +43,14 @@ Dumping 'prep' table... from __future__ import print_function, division, absolute_import from fontTools.misc.py23 import * +from fontTools.misc.loggingTools import deprecateArgument, deprecateFunction import os import sys +import logging +log = logging.getLogger(__name__) + class TTLibError(Exception): pass @@ -60,8 +64,8 @@ class TTFont(object): def __init__(self, file=None, res_name_or_index=None, sfntVersion="\000\001\000\000", flavor=None, checkChecksums=False, - verbose=False, recalcBBoxes=True, allowVID=False, ignoreDecompileErrors=False, - recalcTimestamp=True, fontNumber=-1, lazy=None, quiet=False): + verbose=None, recalcBBoxes=True, allowVID=False, ignoreDecompileErrors=False, + recalcTimestamp=True, fontNumber=-1, lazy=None, quiet=None): """The constructor can be called with a few different arguments. When reading a font from disk, 'file' should be either a pathname @@ -119,8 +123,13 @@ class TTFont(object): """ from fontTools.ttLib import sfnt - self.verbose = verbose - self.quiet = quiet + + for name in ("verbose", "quiet"): + val = locals().get(name) + if val is not None: + deprecateArgument(name, "configure logging instead") + setattr(self, name, val) + self.lazy = lazy self.recalcBBoxes = recalcBBoxes self.recalcTimestamp = recalcTimestamp @@ -231,7 +240,7 @@ class TTFont(object): if closeStream: file.close() - def saveXML(self, fileOrPath, progress=None, quiet=False, + def saveXML(self, fileOrPath, progress=None, quiet=None, tables=None, skipTables=None, splitTables=False, disassembleInstructions=True, bitmapGlyphDataFormat='raw'): """Export the font as TTX (an XML-based text file), or as a series of text @@ -244,6 +253,9 @@ class TTFont(object): from fontTools import version from fontTools.misc import xmlWriter + if quiet is not None: + deprecateArgument("quiet", "configure logging instead") + self.disassembleInstructions = disassembleInstructions self.bitmapGlyphDataFormat = bitmapGlyphDataFormat if not tables: @@ -287,7 +299,7 @@ class TTFont(object): writer.newline() else: tableWriter = writer - self._tableToXML(tableWriter, tag, progress, quiet) + self._tableToXML(tableWriter, tag, progress) if splitTables: tableWriter.endtag("ttFont") tableWriter.newline() @@ -297,10 +309,10 @@ class TTFont(object): writer.endtag("ttFont") writer.newline() writer.close() - if self.verbose: - debugmsg("Done dumping TTX") - def _tableToXML(self, writer, tag, progress, quiet): + def _tableToXML(self, writer, tag, progress, quiet=None): + if quiet is not None: + deprecateArgument("quiet", "configure logging instead") if tag in self: table = self[tag] report = "Dumping '%s' table..." % tag @@ -308,11 +320,7 @@ class TTFont(object): report = "No '%s' table found." % tag if progress: progress.setLabel(report) - elif self.verbose: - debugmsg(report) - else: - if not quiet: - print(report) + log.info(report) if tag not in self: return xmlTag = tagToXML(tag) @@ -332,10 +340,13 @@ class TTFont(object): writer.newline() writer.newline() - def importXML(self, fileOrPath, progress=None, quiet=False): + def importXML(self, fileOrPath, progress=None, quiet=None): """Import a TTX file (an XML-based text format), so as to recreate a font object. """ + if quiet is not None: + deprecateArgument("quiet", "configure logging instead") + if "maxp" in self and "post" in self: # Make sure the glyph order is loaded, as it otherwise gets # lost if the XML doesn't contain the glyph order, yet does @@ -345,7 +356,7 @@ class TTFont(object): from fontTools.misc import xmlReader - reader = xmlReader.XMLReader(fileOrPath, self, progress, quiet) + reader = xmlReader.XMLReader(fileOrPath, self, progress) reader.read() def isLoaded(self, tag): @@ -391,21 +402,20 @@ class TTFont(object): return table if self.reader is not None: import traceback - if self.verbose: - debugmsg("Reading '%s' table from disk" % tag) + log.debug("Reading '%s' table from disk", tag) data = self.reader[tag] tableClass = getTableClass(tag) table = tableClass(tag) self.tables[tag] = table - if self.verbose: - debugmsg("Decompiling '%s' table" % tag) + log.debug("Decompiling '%s' table", tag) try: table.decompile(data, self) except: if not self.ignoreDecompileErrors: raise # fall back to DefaultTable, retaining the binary table data - print("An exception occurred during the decompilation of the '%s' table" % tag) + log.exception( + "An exception occurred during the decompilation of the '%s' table", tag) from .tables.DefaultTable import DefaultTable file = StringIO() traceback.print_exc(file=file) @@ -634,8 +644,7 @@ class TTFont(object): else: done.append(masterTable) tabledata = self.getTableData(tag) - if self.verbose: - debugmsg("writing '%s' table to disk" % tag) + log.debug("writing '%s' table to disk", tag) writer[tag] = tabledata done.append(tag) @@ -644,12 +653,10 @@ class TTFont(object): """ tag = Tag(tag) if self.isLoaded(tag): - if self.verbose: - debugmsg("compiling '%s' table" % tag) + log.debug("compiling '%s' table", tag) return self.tables[tag].compile(self) elif self.reader and tag in self.reader: - if self.verbose: - debugmsg("Reading '%s' table from disk" % tag) + log.debug("Reading '%s' table from disk", tag) return self.reader[tag] else: raise KeyError(tag) @@ -901,6 +908,7 @@ def xmlToTag(tag): return Tag(tag + " " * (4 - len(tag))) +@deprecateFunction("use logging instead", category=DeprecationWarning) def debugmsg(msg): import time print(msg + time.strftime(" (%H:%M:%S)", time.localtime(time.time()))) diff --git a/Lib/fontTools/ttLib/sfnt.py b/Lib/fontTools/ttLib/sfnt.py index 175a947a5..4b0476c39 100644 --- a/Lib/fontTools/ttLib/sfnt.py +++ b/Lib/fontTools/ttLib/sfnt.py @@ -18,6 +18,10 @@ from fontTools.misc import sstruct from fontTools.ttLib import getSearchRange import struct from collections import OrderedDict +import logging + + +log = logging.getLogger(__name__) class SFNTReader(object): @@ -118,8 +122,8 @@ class SFNTReader(object): # Be obnoxious, and barf when it's wrong assert checksum == entry.checkSum, "bad checksum for '%s' table" % tag elif checksum != entry.checkSum: - # Be friendly, and just print a warning. - print("bad checksum for '%s' table" % tag) + # Be friendly, and just log a warning. + log.warning("bad checksum for '%s' table", tag) return data def __delitem__(self, tag): diff --git a/Lib/fontTools/ttLib/tables/BitmapGlyphMetrics.py b/Lib/fontTools/ttLib/tables/BitmapGlyphMetrics.py index a6b6d661a..685979a78 100644 --- a/Lib/fontTools/ttLib/tables/BitmapGlyphMetrics.py +++ b/Lib/fontTools/ttLib/tables/BitmapGlyphMetrics.py @@ -4,8 +4,11 @@ from __future__ import print_function, division, absolute_import from fontTools.misc.py23 import * from fontTools.misc import sstruct from fontTools.misc.textTools import safeEval +import logging +log = logging.getLogger(__name__) + bigGlyphMetricsFormat = """ > # big endian height: B @@ -48,7 +51,7 @@ class BitmapGlyphMetrics(object): if name in metricNames: vars(self)[name] = safeEval(attrs['value']) else: - print("Warning: unknown name '%s' being ignored in %s." % name, self.__class__.__name__) + log.warning("unknown name '%s' being ignored in %s.", name, self.__class__.__name__) class BigGlyphMetrics(BitmapGlyphMetrics): diff --git a/Lib/fontTools/ttLib/tables/E_B_D_T_.py b/Lib/fontTools/ttLib/tables/E_B_D_T_.py index 2e0f6b25c..3a316e5d0 100644 --- a/Lib/fontTools/ttLib/tables/E_B_D_T_.py +++ b/Lib/fontTools/ttLib/tables/E_B_D_T_.py @@ -7,6 +7,10 @@ from . import DefaultTable import itertools import os import struct +import logging + + +log = logging.getLogger(__name__) ebdtTableVersionFormat = """ > # big endian @@ -166,7 +170,7 @@ class table_E_B_D_T_(DefaultTable.DefaultTable): assert glyphName not in bitmapGlyphDict, "Duplicate glyphs with the same name '%s' in the same strike." % glyphName bitmapGlyphDict[glyphName] = curGlyph else: - print("Warning: %s being ignored by %s", name, self.__class__.__name__) + log.warning("%s being ignored by %s", name, self.__class__.__name__) # Grow the strike data array to the appropriate size. The XML # format allows the strike index value to be out of order. @@ -196,7 +200,7 @@ class EbdtComponent(object): if name in componentNames: vars(self)[name] = safeEval(attrs['value']) else: - print("Warning: unknown name '%s' being ignored by EbdtComponent." % name) + log.warning("unknown name '%s' being ignored by EbdtComponent.", name) # Helper functions for dealing with binary. @@ -478,7 +482,7 @@ def _createBitmapPlusMetricsMixin(metricsClass): self.metrics = metricsClass() self.metrics.fromXML(name, attrs, content, ttFont) elif name == oppositeMetricsName: - print("Warning: %s being ignored in format %d." % oppositeMetricsName, self.getFormat()) + log.warning("Warning: %s being ignored in format %d.", oppositeMetricsName, self.getFormat()) return BitmapPlusMetricsMixin @@ -692,7 +696,7 @@ class ComponentBitmapGlyph(BitmapGlyph): curComponent.fromXML(name, attrs, content, ttFont) self.componentArray.append(curComponent) else: - print("Warning: '%s' being ignored in component array." % name) + log.warning("'%s' being ignored in component array.", name) class ebdt_bitmap_format_8(BitmapPlusSmallMetricsMixin, ComponentBitmapGlyph): diff --git a/Lib/fontTools/ttLib/tables/E_B_L_C_.py b/Lib/fontTools/ttLib/tables/E_B_L_C_.py index 28a263588..7f7002453 100644 --- a/Lib/fontTools/ttLib/tables/E_B_L_C_.py +++ b/Lib/fontTools/ttLib/tables/E_B_L_C_.py @@ -7,6 +7,10 @@ from .BitmapGlyphMetrics import BigGlyphMetrics, bigGlyphMetricsFormat, SmallGly import struct import itertools from collections import deque +import logging + + +log = logging.getLogger(__name__) eblcHeaderFormat = """ > # big endian @@ -293,7 +297,7 @@ class BitmapSizeTable(object): elif name in dataNames: vars(self)[name] = safeEval(attrs['value']) else: - print("Warning: unknown name '%s' being ignored in BitmapSizeTable." % name) + log.warning("unknown name '%s' being ignored in BitmapSizeTable.", name) class SbitLineMetrics(object): @@ -503,7 +507,7 @@ class FixedSizeIndexSubTableMixin(object): self.metrics = BigGlyphMetrics() self.metrics.fromXML(name, attrs, content, ttFont) elif name == SmallGlyphMetrics.__name__: - print("Warning: SmallGlyphMetrics being ignored in format %d." % self.indexFormat) + log.warning("SmallGlyphMetrics being ignored in format %d.", self.indexFormat) def padBitmapData(self, data): # Make sure that the data isn't bigger than the fixed size. diff --git a/Lib/fontTools/ttLib/tables/O_S_2f_2.py b/Lib/fontTools/ttLib/tables/O_S_2f_2.py index 04200cadd..e6bc4bced 100644 --- a/Lib/fontTools/ttLib/tables/O_S_2f_2.py +++ b/Lib/fontTools/ttLib/tables/O_S_2f_2.py @@ -3,9 +3,11 @@ from fontTools.misc.py23 import * from fontTools.misc import sstruct from fontTools.misc.textTools import safeEval, num2binary, binary2num from fontTools.ttLib.tables import DefaultTable -import warnings +import logging +log = logging.getLogger(__name__) + # panose classification panoseFormat = """ @@ -116,7 +118,7 @@ class table_O_S_2f_2(DefaultTable.DefaultTable): from fontTools import ttLib raise ttLib.TTLibError("unknown format for OS/2 table: version %s" % self.version) if len(data): - warnings.warn("too much 'OS/2' table data") + log.warning("too much 'OS/2' table data") self.panose = sstruct.unpack(panoseFormat, self.panose, Panose()) diff --git a/Lib/fontTools/ttLib/tables/S_V_G_.py b/Lib/fontTools/ttLib/tables/S_V_G_.py index 45e8aad29..c09f56f25 100644 --- a/Lib/fontTools/ttLib/tables/S_V_G_.py +++ b/Lib/fontTools/ttLib/tables/S_V_G_.py @@ -8,6 +8,11 @@ except ImportError: import xml.etree.ElementTree as ET import struct import re +import logging + + +log = logging.getLogger(__name__) + __doc__=""" Compiles/decompiles version 0 and 1 SVG tables from/to XML. @@ -104,7 +109,8 @@ class table_S_V_G_(DefaultTable.DefaultTable): self.decompile_format_1(data, ttFont) else: if self.version != 0: - print("Unknown SVG table version '%s'. Decompiling as version 0." % (self.version)) + log.warning( + "Unknown SVG table version '%s'. Decompiling as version 0.", self.version) self.decompile_format_0(data, ttFont) def decompile_format_0(self, data, ttFont): @@ -314,7 +320,7 @@ class table_S_V_G_(DefaultTable.DefaultTable): if self.colorPalettes.numColorParams == 0: self.colorPalettes = None else: - print("Unknown", name, content) + log.warning("Unknown %s %s", name, content) class DocumentIndexEntry(object): def __init__(self): diff --git a/Lib/fontTools/ttLib/tables/_a_v_a_r.py b/Lib/fontTools/ttLib/tables/_a_v_a_r.py index 3b6b9face..37d984ec7 100644 --- a/Lib/fontTools/ttLib/tables/_a_v_a_r.py +++ b/Lib/fontTools/ttLib/tables/_a_v_a_r.py @@ -8,9 +8,11 @@ from fontTools.ttLib import TTLibError from . import DefaultTable import array import struct -import warnings +import logging +log = logging.getLogger(__name__) + # Apple's documentation of 'avar': # https://developer.apple.com/fonts/TrueType-Reference-Manual/RM06/Chap6avar.html @@ -22,6 +24,7 @@ AVAR_HEADER_FORMAT = """ class table__a_v_a_r(DefaultTable.DefaultTable): + dependencies = ["fvar"] def __init__(self, tag=None): @@ -57,7 +60,7 @@ class table__a_v_a_r(DefaultTable.DefaultTable): fromValue, toValue = struct.unpack(">hh", data[pos:pos+4]) segments[fixedToFloat(fromValue, 14)] = fixedToFloat(toValue, 14) pos = pos + 4 - self.fixupSegments_(warn=warnings.warn) + self.fixupSegments_() def toXML(self, writer, ttFont, progress=None): axisTags = [axis.axisTag for axis in ttFont["fvar"].axes] @@ -81,14 +84,14 @@ class table__a_v_a_r(DefaultTable.DefaultTable): fromValue = safeEval(elementAttrs["from"]) toValue = safeEval(elementAttrs["to"]) if fromValue in segment: - warnings.warn("duplicate entry for %s in axis '%s'" % - (fromValue, axis)) + log.warning("duplicate entry for %s in axis '%s'", + fromValue, axis) segment[fromValue] = toValue - self.fixupSegments_(warn=warnings.warn) + self.fixupSegments_() - def fixupSegments_(self, warn): + def fixupSegments_(self): for axis, mappings in self.segments.items(): for k in [-1.0, 0.0, 1.0]: if mappings.get(k) != k: - warn("avar axis '%s' should map %s to %s" % (axis, k, k)) + log.warning("avar axis '%s' should map %s to %s", axis, k, k) mappings[k] = k diff --git a/Lib/fontTools/ttLib/tables/_a_v_a_r_test.py b/Lib/fontTools/ttLib/tables/_a_v_a_r_test.py index 8894148a1..64f19d0d3 100644 --- a/Lib/fontTools/ttLib/tables/_a_v_a_r_test.py +++ b/Lib/fontTools/ttLib/tables/_a_v_a_r_test.py @@ -7,6 +7,7 @@ from fontTools.ttLib import TTLibError from fontTools.ttLib.tables._a_v_a_r import table__a_v_a_r from fontTools.ttLib.tables._f_v_a_r import table__f_v_a_r, Axis import collections +import logging import unittest @@ -65,15 +66,17 @@ class AxisVariationTableTest(unittest.TestCase): def test_fixupSegments(self): avar = table__a_v_a_r() + logger = logging.getLogger(table__a_v_a_r.__module__) + sio = StringIO() + logger.addHandler(logging.StreamHandler(stream=sio)) avar.segments = {"wdth": {0.3: 0.8, 1.0: 0.7}} - warnings = [] - avar.fixupSegments_(lambda w: warnings.append(w)) + avar.fixupSegments_() self.assertEqual({"wdth": {-1.0: -1.0, 0.0: 0.0, 0.3: 0.8, 1.0: 1.0}}, avar.segments) self.assertEqual([ "avar axis 'wdth' should map -1.0 to -1.0", "avar axis 'wdth' should map 0.0 to 0.0", "avar axis 'wdth' should map 1.0 to 1.0" - ], warnings) + ], sio.getvalue().splitlines()) @staticmethod def makeFont(axisTags): diff --git a/Lib/fontTools/ttLib/tables/_c_m_a_p.py b/Lib/fontTools/ttLib/tables/_c_m_a_p.py index 796cc811a..141a0d4db 100644 --- a/Lib/fontTools/ttLib/tables/_c_m_a_p.py +++ b/Lib/fontTools/ttLib/tables/_c_m_a_p.py @@ -9,6 +9,10 @@ import sys import struct import array import operator +import logging + + +log = logging.getLogger(__name__) class table__c_m_a_p(DefaultTable.DefaultTable): @@ -51,7 +55,10 @@ class table__c_m_a_p(DefaultTable.DefaultTable): format, length = struct.unpack(">HL", data[offset:offset+6]) if not length: - print("Error: cmap subtable is reported as having zero length: platformID %s, platEncID %s, format %s offset %s. Skipping table." % (platformID, platEncID,format, offset)) + log.error( + "cmap subtable is reported as having zero length: platformID %s, " + "platEncID %s, format %s offset %s. Skipping table.", + platformID, platEncID, format, offset) continue table = CmapSubtable.newSubtable(format) table.platformID = platformID diff --git a/Lib/fontTools/ttLib/tables/_g_l_y_f.py b/Lib/fontTools/ttLib/tables/_g_l_y_f.py index 1eb061009..aa7356fad 100644 --- a/Lib/fontTools/ttLib/tables/_g_l_y_f.py +++ b/Lib/fontTools/ttLib/tables/_g_l_y_f.py @@ -13,7 +13,10 @@ from . import ttProgram import sys import struct import array -import warnings +import logging + + +log = logging.getLogger(__name__) # # The Apple and MS rasterizers behave differently for @@ -56,10 +59,11 @@ class table__g_l_y_f(DefaultTable.DefaultTable): self.glyphs[glyphName] = glyph last = next if len(data) - next >= 4: - warnings.warn("too much 'glyf' table data: expected %d, received %d bytes" % - (next, len(data))) + log.warning( + "too much 'glyf' table data: expected %d, received %d bytes", + next, len(data)) if noname: - warnings.warn('%s glyphs have no name' % noname) + log.warning('%s glyphs have no name', noname) if ttFont.lazy is False: # Be lazy for None and True for glyph in self.glyphs.values(): glyph.expand(self) @@ -145,8 +149,7 @@ class table__g_l_y_f(DefaultTable.DefaultTable): if not hasattr(self, "glyphOrder"): self.glyphOrder = ttFont.getGlyphOrder() glyphName = attrs["name"] - if ttFont.verbose: - ttLib.debugmsg("unpacking glyph '%s'" % glyphName) + log.debug("unpacking glyph '%s'", glyphName) glyph = Glyph() for attr in ['xMin', 'yMin', 'xMax', 'yMax']: setattr(glyph, attr, safeEval(attrs.get(attr, '0'))) @@ -453,7 +456,9 @@ class Glyph(object): self.program.fromBytecode(data[:numInstructions]) data = data[numInstructions:] if len(data) >= 4: - warnings.warn("too much glyph data at the end of composite glyph: %d excess bytes" % len(data)) + log.warning( + "too much glyph data at the end of composite glyph: %d excess bytes", + len(data)) def decompileCoordinates(self, data): endPtsOfContours = array.array("h") @@ -545,7 +550,8 @@ class Glyph(object): xDataLen = struct.calcsize(xFormat) yDataLen = struct.calcsize(yFormat) if len(data) - (xDataLen + yDataLen) >= 4: - warnings.warn("too much glyph data: %d excess bytes" % (len(data) - (xDataLen + yDataLen))) + log.warning( + "too much glyph data: %d excess bytes", len(data) - (xDataLen + yDataLen)) xCoordinates = struct.unpack(xFormat, data[:xDataLen]) yCoordinates = struct.unpack(yFormat, data[xDataLen:xDataLen+yDataLen]) return flags, xCoordinates, yCoordinates @@ -734,7 +740,7 @@ class Glyph(object): bbox = calcBounds([coords[last], coords[next]]) if not pointInRect(coords[j], bbox): # Ouch! - warnings.warn("Outline has curve with implicit extrema.") + log.warning("Outline has curve with implicit extrema.") # Ouch! Find analytical curve bounds. pthis = coords[j] plast = coords[last] @@ -1005,7 +1011,6 @@ class GlyphComponent(object): self.flags = int(flags) glyphID = int(glyphID) self.glyphName = glyfTable.getGlyphName(int(glyphID)) - #print ">>", reprflag(self.flags) data = data[4:] if self.flags & ARG_1_AND_2_ARE_WORDS: diff --git a/Lib/fontTools/ttLib/tables/_h_e_a_d.py b/Lib/fontTools/ttLib/tables/_h_e_a_d.py index fd057b5a7..c6e2cae24 100644 --- a/Lib/fontTools/ttLib/tables/_h_e_a_d.py +++ b/Lib/fontTools/ttLib/tables/_h_e_a_d.py @@ -5,9 +5,11 @@ from fontTools.misc.textTools import safeEval, num2binary, binary2num from fontTools.misc.timeTools import timestampFromString, timestampToString, timestampNow from fontTools.misc.timeTools import epoch_diff as mac_epoch_diff # For backward compat from . import DefaultTable -import warnings +import logging +log = logging.getLogger(__name__) + headFormat = """ > # big endian tableVersion: 16.16F @@ -37,7 +39,7 @@ class table__h_e_a_d(DefaultTable.DefaultTable): dummy, rest = sstruct.unpack2(headFormat, data, self) if rest: # this is quite illegal, but there seem to be fonts out there that do this - warnings.warn("extra bytes at the end of 'head' table") + log.warning("extra bytes at the end of 'head' table") assert rest == "\0\0" # For timestamp fields, ignore the top four bytes. Some fonts have @@ -48,11 +50,11 @@ class table__h_e_a_d(DefaultTable.DefaultTable): for stamp in 'created', 'modified': value = getattr(self, stamp) if value > 0xFFFFFFFF: - warnings.warn("'%s' timestamp out of range; ignoring top bytes" % stamp) + log.warning("'%s' timestamp out of range; ignoring top bytes", stamp) value &= 0xFFFFFFFF setattr(self, stamp, value) if value < 0x7C259DC0: # January 1, 1970 00:00:00 - warnings.warn("'%s' timestamp seems very low; regarding as unix timestamp" % stamp) + log.warning("'%s' timestamp seems very low; regarding as unix timestamp", stamp) value += 0x7C259DC0 setattr(self, stamp, value) diff --git a/Lib/fontTools/ttLib/tables/_h_m_t_x.py b/Lib/fontTools/ttLib/tables/_h_m_t_x.py index 1746439c4..9663049d5 100644 --- a/Lib/fontTools/ttLib/tables/_h_m_t_x.py +++ b/Lib/fontTools/ttLib/tables/_h_m_t_x.py @@ -4,7 +4,10 @@ from fontTools.misc.textTools import safeEval from . import DefaultTable import sys import array -import warnings +import logging + + +log = logging.getLogger(__name__) class table__h_m_t_x(DefaultTable.DefaultTable): @@ -31,7 +34,7 @@ class table__h_m_t_x(DefaultTable.DefaultTable): if sys.byteorder != "big": sideBearings.byteswap() if data: - warnings.warn("too much 'hmtx'/'vmtx' table data") + log.warning("too much 'hmtx'/'vmtx' table data") self.metrics = {} glyphOrder = ttFont.getGlyphOrder() for i in range(numberOfMetrics): diff --git a/Lib/fontTools/ttLib/tables/_k_e_r_n.py b/Lib/fontTools/ttLib/tables/_k_e_r_n.py index 2e4e43856..1fa49f1c1 100644 --- a/Lib/fontTools/ttLib/tables/_k_e_r_n.py +++ b/Lib/fontTools/ttLib/tables/_k_e_r_n.py @@ -6,7 +6,10 @@ from fontTools.misc.fixedTools import fixedToFloat as fi2fl, floatToFixed as fl2 from . import DefaultTable import struct import array -import warnings +import logging + + +log = logging.getLogger(__name__) class table__k_e_r_n(DefaultTable.DefaultTable): @@ -118,7 +121,7 @@ class KernTable_format_0(object): # Slower, but will not throw an IndexError on an invalid glyph id. kernTable[(ttFont.getGlyphName(left), ttFont.getGlyphName(right))] = value if len(data) > 6 * nPairs: - warnings.warn("excess data in 'kern' subtable: %d bytes" % len(data)) + log.warning("excess data in 'kern' subtable: %d bytes", len(data)) def compile(self, ttFont): nPairs = len(self.kernTable) diff --git a/Lib/fontTools/ttLib/tables/_l_o_c_a.py b/Lib/fontTools/ttLib/tables/_l_o_c_a.py index 72849cbb8..2fcd52840 100644 --- a/Lib/fontTools/ttLib/tables/_l_o_c_a.py +++ b/Lib/fontTools/ttLib/tables/_l_o_c_a.py @@ -3,7 +3,11 @@ from fontTools.misc.py23 import * from . import DefaultTable import sys import array -import warnings +import logging + + +log = logging.getLogger(__name__) + class table__l_o_c_a(DefaultTable.DefaultTable): @@ -25,7 +29,8 @@ class table__l_o_c_a(DefaultTable.DefaultTable): l.append(locations[i] * 2) locations = l if len(locations) < (ttFont['maxp'].numGlyphs + 1): - warnings.warn("corrupt 'loca' table, or wrong numGlyphs in 'maxp': %d %d" % (len(locations) - 1, ttFont['maxp'].numGlyphs)) + log.warning("corrupt 'loca' table, or wrong numGlyphs in 'maxp': %d %d", + len(locations) - 1, ttFont['maxp'].numGlyphs) self.locations = locations def compile(self, ttFont): diff --git a/Lib/fontTools/ttLib/tables/_n_a_m_e.py b/Lib/fontTools/ttLib/tables/_n_a_m_e.py index 9fe959de6..39afa9309 100644 --- a/Lib/fontTools/ttLib/tables/_n_a_m_e.py +++ b/Lib/fontTools/ttLib/tables/_n_a_m_e.py @@ -5,6 +5,10 @@ from fontTools.misc.textTools import safeEval from fontTools.misc.encodingTools import getEncoding from . import DefaultTable import struct +import logging + + +log = logging.getLogger(__name__) nameRecordFormat = """ > # big endian @@ -25,8 +29,9 @@ class table__n_a_m_e(DefaultTable.DefaultTable): format, n, stringOffset = struct.unpack(">HHH", data[:6]) expectedStringOffset = 6 + n * nameRecordSize if stringOffset != expectedStringOffset: - # XXX we need a warn function - print("Warning: 'name' table stringOffset incorrect. Expected: %s; Actual: %s" % (expectedStringOffset, stringOffset)) + log.error( + "'name' table stringOffset incorrect. Expected: %s; Actual: %s", + expectedStringOffset, stringOffset) stringData = data[stringOffset:] data = data[6:] self.names = [] diff --git a/Lib/fontTools/ttLib/tables/otBase.py b/Lib/fontTools/ttLib/tables/otBase.py index 086b95052..d042eedb0 100644 --- a/Lib/fontTools/ttLib/tables/otBase.py +++ b/Lib/fontTools/ttLib/tables/otBase.py @@ -3,6 +3,9 @@ from fontTools.misc.py23 import * from .DefaultTable import DefaultTable import array import struct +import logging + +log = logging.getLogger(__name__) class OverflowErrorRecord(object): def __init__(self, overflowTuple): @@ -46,12 +49,12 @@ class BaseTTXConverter(DefaultTable): if cachingStats: stats = sorted([(v, k) for k, v in cachingStats.items()]) stats.reverse() - print("cachingsstats for ", self.tableTag) + log.debug("cachingStats for %s", self.tableTag) for v, k in stats: if v < 2: break - print(v, k) - print("---", len(stats)) + log.debug("%s %s", v, k) + log.debug("--- %s", len(stats)) def compile(self, font): """ Create a top-level OTFWriter for the GPOS/GSUB table. @@ -92,7 +95,7 @@ class BaseTTXConverter(DefaultTable): raise # Oh well... overflowRecord = e.value - print("Attempting to fix OTLOffsetOverflowError", e) + log.warning("Attempting to fix OTLOffsetOverflowError %s", e) lastItem = overflowRecord ok = 0 diff --git a/Lib/fontTools/ttLib/tables/otConverters.py b/Lib/fontTools/ttLib/tables/otConverters.py index 67cc0fd3b..8ad07b503 100644 --- a/Lib/fontTools/ttLib/tables/otConverters.py +++ b/Lib/fontTools/ttLib/tables/otConverters.py @@ -3,6 +3,10 @@ from fontTools.misc.py23 import * from fontTools.misc.textTools import safeEval from fontTools.misc.fixedTools import fixedToFloat as fi2fl, floatToFixed as fl2fi from .otBase import ValueRecordFactory +import logging + + +log = logging.getLogger(__name__) def buildConverters(tableSpec, tableNamespace): @@ -329,8 +333,8 @@ class Table(Struct): return None if offset <= 3: # XXX hack to work around buggy pala.ttf - print("*** Warning: offset is not 0, yet suspiciously low (%s). table: %s" \ - % (offset, self.tableClass.__name__)) + log.warning("offset is not 0, yet suspiciously low (%d). table: %s", + offset, self.tableClass.__name__) return None table = self.tableClass() reader = reader.getSubReader(offset) diff --git a/Lib/fontTools/ttLib/tables/otTables.py b/Lib/fontTools/ttLib/tables/otTables.py index 7c4b08043..cdee5bcd7 100644 --- a/Lib/fontTools/ttLib/tables/otTables.py +++ b/Lib/fontTools/ttLib/tables/otTables.py @@ -8,7 +8,10 @@ from __future__ import print_function, division, absolute_import from fontTools.misc.py23 import * from .otBase import BaseTable, FormatSwitchingBaseTable import operator -import warnings +import logging + + +log = logging.getLogger(__name__) class FeatureParams(BaseTable): @@ -46,7 +49,7 @@ class Coverage(FormatSwitchingBaseTable): # this when writing font out. sorted_ranges = sorted(ranges, key=lambda a: a.StartCoverageIndex) if ranges != sorted_ranges: - warnings.warn("GSUB/GPOS Coverage is not sorted by glyph ids.") + log.warning("GSUB/GPOS Coverage is not sorted by glyph ids.") ranges = sorted_ranges del sorted_ranges for r in ranges: @@ -57,14 +60,14 @@ class Coverage(FormatSwitchingBaseTable): try: startID = font.getGlyphID(start, requireReal=True) except KeyError: - warnings.warn("Coverage table has start glyph ID out of range: %s." % start) + log.warning("Coverage table has start glyph ID out of range: %s.", start) continue try: endID = font.getGlyphID(end, requireReal=True) + 1 except KeyError: # Apparently some tools use 65535 to "match all" the range if end != 'glyph65535': - warnings.warn("Coverage table has end glyph ID out of range: %s." % end) + log.warning("Coverage table has end glyph ID out of range: %s.", end) # NOTE: We clobber out-of-range things here. There are legit uses for those, # but none that we have seen in the wild. endID = len(glyphOrder) @@ -107,7 +110,7 @@ class Coverage(FormatSwitchingBaseTable): ranges[i] = r index = index + end - start + 1 if brokenOrder: - warnings.warn("GSUB/GPOS Coverage is not sorted by glyph ids.") + log.warning("GSUB/GPOS Coverage is not sorted by glyph ids.") ranges.sort(key=lambda a: a.StartID) for r in ranges: del r.StartID @@ -288,11 +291,12 @@ class ClassDef(FormatSwitchingBaseTable): try: startID = font.getGlyphID(start, requireReal=True) except KeyError: - warnings.warn("ClassDef table has start glyph ID out of range: %s." % start) + log.warning("ClassDef table has start glyph ID out of range: %s.", start) startID = len(glyphOrder) endID = startID + len(classList) if endID > len(glyphOrder): - warnings.warn("ClassDef table has entries for out of range glyph IDs: %s,%s." % (start, len(classList))) + log.warning("ClassDef table has entries for out of range glyph IDs: %s,%s.", + start, len(classList)) # NOTE: We clobber out-of-range things here. There are legit uses for those, # but none that we have seen in the wild. endID = len(glyphOrder) @@ -309,14 +313,14 @@ class ClassDef(FormatSwitchingBaseTable): try: startID = font.getGlyphID(start, requireReal=True) except KeyError: - warnings.warn("ClassDef table has start glyph ID out of range: %s." % start) + log.warning("ClassDef table has start glyph ID out of range: %s.", start) continue try: endID = font.getGlyphID(end, requireReal=True) + 1 except KeyError: # Apparently some tools use 65535 to "match all" the range if end != 'glyph65535': - warnings.warn("ClassDef table has end glyph ID out of range: %s." % end) + log.warning("ClassDef table has end glyph ID out of range: %s.", end) # NOTE: We clobber out-of-range things here. There are legit uses for those, # but none that we have seen in the wild. endID = len(glyphOrder) diff --git a/Lib/fontTools/ttLib/tables/ttProgram.py b/Lib/fontTools/ttLib/tables/ttProgram.py index a8308c81b..43fa55741 100644 --- a/Lib/fontTools/ttLib/tables/ttProgram.py +++ b/Lib/fontTools/ttLib/tables/ttProgram.py @@ -5,6 +5,10 @@ from fontTools.misc.py23 import * from fontTools.misc.textTools import num2binary, binary2num, readHex import array import re +import logging + + +log = logging.getLogger(__name__) # first, the list of instructions that eat bytes or words from the instruction stream @@ -233,7 +237,7 @@ class Program(object): traceback.print_exc(file=tmp) msg = "An exception occurred during the decompilation of glyph program:\n\n" msg += tmp.getvalue() - print(msg, file=sys.stderr) + log.error(msg) writer.begintag("bytecode") writer.newline() writer.comment(msg.strip()) diff --git a/Lib/fontTools/ttLib/woff2.py b/Lib/fontTools/ttLib/woff2.py index c22517bff..1952682c5 100644 --- a/Lib/fontTools/ttLib/woff2.py +++ b/Lib/fontTools/ttLib/woff2.py @@ -13,6 +13,10 @@ from fontTools.ttLib.sfnt import (SFNTReader, SFNTWriter, DirectoryEntry, WOFFFlavorData, sfntDirectoryFormat, sfntDirectorySize, SFNTDirectoryEntry, sfntDirectoryEntrySize, calcChecksum) from fontTools.ttLib.tables import ttProgram +import logging + + +log = logging.getLogger(__name__) haveBrotli = False try: @@ -28,8 +32,9 @@ class WOFF2Reader(SFNTReader): def __init__(self, file, checkChecksums=1, fontNumber=-1): if not haveBrotli: - print('The WOFF2 decoder requires the Brotli Python extension, available at:\n' - 'https://github.com/google/brotli', file=sys.stderr) + log.error( + 'The WOFF2 decoder requires the Brotli Python extension, available at: ' + 'https://github.com/google/brotli') raise ImportError("No module named brotli") self.file = file @@ -133,8 +138,9 @@ class WOFF2Writer(SFNTWriter): def __init__(self, file, numTables, sfntVersion="\000\001\000\000", flavor=None, flavorData=None): if not haveBrotli: - print('The WOFF2 encoder requires the Brotli Python extension, available at:\n' - 'https://github.com/google/brotli', file=sys.stderr) + log.error( + 'The WOFF2 encoder requires the Brotli Python extension, available at: ' + 'https://github.com/google/brotli') raise ImportError("No module named brotli") self.file = file diff --git a/Lib/fontTools/ttx.py b/Lib/fontTools/ttx.py index 08ada3ae2..c6f058686 100644 --- a/Lib/fontTools/ttx.py +++ b/Lib/fontTools/ttx.py @@ -81,15 +81,20 @@ from fontTools.ttLib import TTFont, TTLibError from fontTools.misc.macCreatorType import getMacCreatorAndType from fontTools.unicode import setUnicodeData from fontTools.misc.timeTools import timestampSinceEpoch +from fontTools.misc.loggingTools import Timer import os import sys import getopt import re +import logging + + +log = logging.getLogger(__name__) + def usage(): from fontTools import version print(__doc__ % version) - sys.exit(2) numberAddedRE = re.compile("#\d+$") @@ -136,8 +141,7 @@ class Options(object): for option, value in rawOptions: # general options if option == "-h": - from fontTools import version - print(__doc__ % version) + usage() sys.exit(0) elif option == "-d": if not os.path.isdir(value): @@ -187,8 +191,16 @@ class Options(object): self.recalcTimestamp = True elif option == "--flavor": self.flavor = value + if self.verbose and self.quiet: + raise getopt.GetoptError("-q and -v options are mutually exclusive") + if self.verbose: + self.logLevel = logging.DEBUG + elif self.quiet: + self.logLevel = logging.WARNING + else: + self.logLevel = logging.INFO if self.mergeFile and self.flavor: - print("-m and --flavor options are mutually exclusive") + raise getopt.GetoptError("-m and --flavor options are mutually exclusive") sys.exit(2) if self.onlyTables and self.skipTables: raise getopt.GetoptError("-t and -x options are mutually exclusive") @@ -221,17 +233,15 @@ def ttList(input, output, options): ttf.close() +@Timer(log, 'Done dumping TTX in %(time).3f seconds') def ttDump(input, output, options): - if not options.quiet: - print('Dumping "%s" to "%s"...' % (input, output)) + log.info('Dumping "%s" to "%s"...', input, output) if options.unicodedata: setUnicodeData(options.unicodedata) - ttf = TTFont(input, 0, verbose=options.verbose, allowVID=options.allowVID, - quiet=options.quiet, + ttf = TTFont(input, 0, allowVID=options.allowVID, ignoreDecompileErrors=options.ignoreDecompileErrors, fontNumber=options.fontNumber) ttf.saveXML(output, - quiet=options.quiet, tables=options.onlyTables, skipTables=options.skipTables, splitTables=options.splitTables, @@ -240,14 +250,14 @@ def ttDump(input, output, options): ttf.close() +@Timer(log, 'Done compiling TTX in %(time).3f seconds') def ttCompile(input, output, options): - if not options.quiet: - print('Compiling "%s" to "%s"...' % (input, output)) + log.info('Compiling "%s" to "%s"...' % (input, output)) ttf = TTFont(options.mergeFile, flavor=options.flavor, recalcBBoxes=options.recalcBBoxes, recalcTimestamp=options.recalcTimestamp, - verbose=options.verbose, allowVID=options.allowVID) - ttf.importXML(input, quiet=options.quiet) + allowVID=options.allowVID) + ttf.importXML(input) if not options.recalcTimestamp: # use TTX file modification time for head "modified" timestamp @@ -256,10 +266,6 @@ def ttCompile(input, output, options): ttf.save(output) - if options.verbose: - import time - print("finished at", time.strftime("%H:%M:%S", time.localtime(time.time()))) - def guessFileType(fileName): base, ext = os.path.splitext(fileName) @@ -305,6 +311,9 @@ def parseOptions(args): raise getopt.GetoptError('Must specify at least one input file') for input in files: + if not os.path.isfile(input): + raise getopt.GetoptError('File not found: "%s"' % input) + continue tp = guessFileType(input) if tp in ("OTF", "TTF", "TTC", "WOFF", "WOFF2"): extension = ".ttx" @@ -319,7 +328,7 @@ def parseOptions(args): extension = "."+options.flavor if options.flavor else ".otf" action = ttCompile else: - print('Unknown file type: "%s"' % input) + raise getopt.GetoptError('Unknown file type: "%s"' % input) continue if options.outputFile: @@ -342,37 +351,43 @@ def waitForKeyPress(): """Force the DOS Prompt window to stay open so the user gets a chance to see what's wrong.""" import msvcrt - print('(Hit any key to exit)') + print('(Hit any key to exit)', file=sys.stderr) while not msvcrt.kbhit(): pass def main(args=None): + from fontTools import configLogger + if args is None: args = sys.argv[1:] try: jobs, options = parseOptions(args) except getopt.GetoptError as e: - print('error:', e, file=sys.stderr) usage() + print("ERROR:", e, file=sys.stderr) + sys.exit(2) + + configLogger(level=options.logLevel) + try: process(jobs, options) except KeyboardInterrupt: - print("(Cancelled.)") + log.error("(Cancelled.)") + sys.exit(1) except SystemExit: if sys.platform == "win32": waitForKeyPress() else: raise except TTLibError as e: - print("Error:",e) + log.error(e) + sys.exit(1) except: + log.exception('Unhandled exception has occurred') if sys.platform == "win32": - import traceback - traceback.print_exc() waitForKeyPress() - else: - raise + sys.exit(1) if __name__ == "__main__": diff --git a/Snippets/interpolate.py b/Snippets/interpolate.py index b325c2c90..fb13729eb 100755 --- a/Snippets/interpolate.py +++ b/Snippets/interpolate.py @@ -27,7 +27,7 @@ from fontTools.ttLib import TTFont from fontTools.ttLib.tables._n_a_m_e import NameRecord from fontTools.ttLib.tables._f_v_a_r import table__f_v_a_r, Axis, NamedInstance from fontTools.ttLib.tables._g_v_a_r import table__g_v_a_r, GlyphVariation -import warnings +import logging def AddFontVariations(font): @@ -75,13 +75,13 @@ def AddGlyphVariations(font, thin, regular, black): thinCoord = GetCoordinates(thin, glyphName) blackCoord = GetCoordinates(black, glyphName) if not regularCoord or not blackCoord or not thinCoord: - warnings.warn("glyph %s not present in all input fonts" % - glyphName) + logging.warning("glyph %s not present in all input fonts", + glyphName) continue if (len(regularCoord) != len(blackCoord) or len(regularCoord) != len(thinCoord)): - warnings.warn("glyph %s has not the same number of " - "control points in all input fonts" % glyphName) + logging.warning("glyph %s has not the same number of " + "control points in all input fonts", glyphName) continue thinDelta = [] blackDelta = [] @@ -129,6 +129,7 @@ def GetCoordinates(font, glyphName): def main(): + logging.basicConfig(format="%(levelname)s: %(message)s") thin = TTFont("/tmp/Roboto/Roboto-Thin.ttf") regular = TTFont("/tmp/Roboto/Roboto-Regular.ttf") black = TTFont("/tmp/Roboto/Roboto-Black.ttf")