Merge pull request #483 from anthrotype/logging

implement logging

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"]

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:
+			log.log(DEBUG, "CFFWriter.toFile() iteration: %d", count)
-				print("CFFWriter.toFile() iteration:", count)
 			count = count + 1
 			pos = 0
 			posList = [pos]
@@ -149,8 +152,7 @@ class CFFWriter(object):
 			if posList == lastPosList:
 				break
 			lastPosList = posList
-		if DEBUG:
+		log.log(DEBUG, "CFFWriter.toFile() writing to file.")
-			print("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:
+		log.log(DEBUG, "loading %s at %s", name, file.tell())
-			print("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:
+		log.log(DEBUG, "    index count: %s offSize: %s", count, offSize)
-			print("    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:
+		log.log(DEBUG, "    end of %s at %s", name, file.tell())
-			print("    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:
+			log.log(DEBUG, "loading charset at %s", value)
-				print("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:
+			log.log(DEBUG, "    charset end at %s", file.tell())
-				print("    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:
+			log.log(DEBUG, "loading Encoding at %s", value)
-				print("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:
+		log.log(DEBUG, "-- compiling %s for %s", self.__class__.__name__, reason)
-			print("-- compiling %s for %s" % (self.__class__.__name__, reason))
-			print("in baseDict: ", self)
 		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:
+		if offset is not None:
-			print("loading %s at %s" % (self.__class__.__name__, offset))
+			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:
+		log.log(DEBUG, "    length %s is %d", self.__class__.__name__, len(data))
-			print("    length %s is %s" % (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)

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,7 +772,7 @@ 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]
 
 				clazz = ttLib.getTableClass(tag)
@@ -775,10 +781,9 @@ class Merger(object):
 
 				if table is not NotImplemented and table is not False:
 					mega[tag] = table
-				self.log("Merged '%s'." % tag)
+					log.info("Merged '%s'.", tag)
 				else:
-				self.log("Dropped '%s'." % tag)
+					log.info("Dropped '%s'.", tag)
-			self.log.lapse("merge '%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'
+	with timer("compile and save font"):
 		font.save(outfile)
-	log.lapse("compile and save font")
 
-	log.last_time = log.start_time
-	log.lapse("make one with everything(TOTAL TIME)")
 
 if __name__ == "__main__":
 	main()

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)

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)
 

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:
+				log.debug(
-					print('ps error:\n- - - - - - -')
+					'ps error:\n'
-					print(self.tokenizer.buf[self.tokenizer.pos-50:self.tokenizer.pos])
+					'- - - - - - -\n'
-					print('>>>')
+					'%s\n'
-					print(self.tokenizer.buf[self.tokenizer.pos:self.tokenizer.pos+50])
+					'>>>\n'
-					print('- - - - - - -')
+					'%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'):

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,6 +28,9 @@ class XMLReader(object):
 			self._closeStream = False
 		self.ttFont = ttFont
 		self.progress = progress
+		if quiet is not None:
+			from fontTools.misc.loggingTools import deprecateArgument
+			deprecateArgument("quiet", "configure logging instead")
 			self.quiet = quiet
 		self.root = None
 		self.contentStack = []
@@ -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:
+			log.info(msg)
-				ttLib.debugmsg(msg)
-			else:
-				if not self.quiet:
-					print(msg)
 			if tag == "GlyphOrder":
 				tableClass = ttLib.GlyphOrder
 			elif "ERROR" in attrs or ('raw' in attrs and safeEval(attrs['raw'])):

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)
+log = logging.getLogger(__name__)
-	pass
+
 
 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__()

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'):
+                with timer("load '%s'" % tag):
                     table = font[tag]
-                self.log.lapse("load '%s'" % tag)
+                with timer("prune '%s'" % tag):
                     retain = table.prune_pre_subset(self.options)
-                self.log.lapse("prune '%s'" % tag)
                 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:
+            with timer("close glyph list over 'cmap'"):
                 font['cmap'].closure_glyphs(self)
                 self.glyphs.intersection_update(realGlyphs)
-            self.log.lapse("close glyph list over 'cmap'")
         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" %
+            with timer("close glyph list over 'GSUB'"):
+                log.info("Closing glyph list over 'GSUB': %d glyphs before",
                          len(self.glyphs))
-            self.log.glyphs(self.glyphs, font=font)
+                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" %
+                log.info("Closed glyph list over 'GSUB': %d glyphs after",
                          len(self.glyphs))
-            self.log.glyphs(self.glyphs, font=font)
+                log.glyphs(self.glyphs, font=font)
-            self.log.lapse("close glyph list over 'GSUB'")
         self.glyphs_gsubed = frozenset(self.glyphs)
 
         if 'MATH' in font:
-            self.log("Closing glyph list over 'MATH': %d glyphs before" %
+            with timer("close glyph list over 'MATH'"):
+                log.info("Closing glyph list over 'MATH': %d glyphs before",
                          len(self.glyphs))
-            self.log.glyphs(self.glyphs, font=font)
+                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" %
+                log.info("Closed glyph list over 'MATH': %d glyphs after",
                          len(self.glyphs))
-            self.log.glyphs(self.glyphs, font=font)
+                log.glyphs(self.glyphs, font=font)
-            self.log.lapse("close glyph list over 'MATH'")
         self.glyphs_mathed = frozenset(self.glyphs)
 
         if 'COLR' in font:
-            self.log("Closing glyph list over 'COLR': %d glyphs before" %
+            with timer("close glyph list over 'COLR'"):
+                log.info("Closing glyph list over 'COLR': %d glyphs before",
                          len(self.glyphs))
-            self.log.glyphs(self.glyphs, font=font)
+                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" %
+                log.info("Closed glyph list over 'COLR': %d glyphs after",
                          len(self.glyphs))
-            self.log.glyphs(self.glyphs, font=font)
+                log.glyphs(self.glyphs, font=font)
-            self.log.lapse("close glyph list over 'COLR'")
         self.glyphs_colred = frozenset(self.glyphs)
 
         if 'glyf' in font:
-            self.log("Closing glyph list over 'glyf': %d glyphs before" %
+            with timer("close glyph list over 'glyf'"):
+                log.info("Closing glyph list over 'glyf': %d glyphs before",
                          len(self.glyphs))
-            self.log.glyphs(self.glyphs, font=font)
+                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" %
+                log.info("Closed glyph list over 'glyf': %d glyphs after",
                          len(self.glyphs))
-            self.log.glyphs(self.glyphs, font=font)
+                log.glyphs(self.glyphs, font=font)
-            self.log.lapse("close glyph list over 'glyf'")
         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'):
+                with timer("subset '%s'" % tag):
                     table = font[tag]
                     self.glyphs = self.glyphs_all
                     retain = table.subset_glyphs(self)
                     del self.glyphs
-                self.log.lapse("subset '%s'" % tag)
                 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]
 
+        with timer("subset GlyphOrder"):
             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")
 
     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'):
+                with timer("prune '%s'" % tag):
                     table = font[tag]
                     retain = table.prune_post_subset(self.options)
-                self.log.lapse("prune '%s'" % tag)
                 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):
+@timer("load font")
-
-    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()
-
-
 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,7 +2871,8 @@ def main(args=None):
 
     dontLoadGlyphNames = not options.glyph_names and not glyphs
     font = load_font(fontfile, options, dontLoadGlyphNames=dontLoadGlyphNames)
-    log.lapse("load font")
+
+    with timer("compile glyph list"):
         if wildcard_glyphs:
             glyphs.extend(font.getGlyphOrder())
         if wildcard_unicodes:
@@ -2905,27 +2881,23 @@ def main(args=None):
                     unicodes.extend(t.cmap.keys())
         assert '' not in glyphs
 
-    log.lapse("compile glyph list")
+    log.info("Text: '%s'" % text)
-    log("Text: '%s'" % text)
+    log.info("Unicodes: %s", unicodes)
-    log("Unicodes:", unicodes)
+    log.info("Glyphs: %s", glyphs)
-    log("Glyphs:", glyphs)
+    log.info("Gids: %s", gids)
-    log("Gids:", 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")
 
-    log.last_time = log.start_time
+    if options.verbose:
-    log.lapse("make one with everything(TOTAL TIME)")
-
-    if log.verbose:
         import os
-        log("Input font:% 7d bytes: %s" % (os.path.getsize(fontfile), fontfile))
+        log.info("Input font:% 7d bytes: %s" % (os.path.getsize(fontfile), fontfile))
-        log("Subset font:% 7d bytes: %s" % (os.path.getsize(outfile), outfile))
+        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',

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,
+			verbose=None, recalcBBoxes=True, allowVID=False, ignoreDecompileErrors=False,
-			recalcTimestamp=True, fontNumber=-1, lazy=None, quiet=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:
+		log.info(report)
-			debugmsg(report)
-		else:
-			if not quiet:
-				print(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:
+				log.debug("Reading '%s' table from disk", tag)
-					debugmsg("Reading '%s' table from disk" % tag)
 				data = self.reader[tag]
 				tableClass = getTableClass(tag)
 				table = tableClass(tag)
 				self.tables[tag] = table
-				if self.verbose:
+				log.debug("Decompiling '%s' table", tag)
-					debugmsg("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:
+		log.debug("writing '%s' table to disk", tag)
-			debugmsg("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:
+			log.debug("compiling '%s' table", tag)
-				debugmsg("compiling '%s' table" % tag)
 			return self.tables[tag].compile(self)
 		elif self.reader and tag in self.reader:
-			if self.verbose:
+			log.debug("Reading '%s' table from disk", tag)
-				debugmsg("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())))

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.
+				# Be friendly, and just log a warning.
-				print("bad checksum for '%s' table" % tag)
+				log.warning("bad checksum for '%s' table", tag)
 		return data
 
 	def __delitem__(self, tag):

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):

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):

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.

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())
 

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):

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'" %
+                            log.warning("duplicate entry for %s in axis '%s'",
-                                          (fromValue, axis))
+                                        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

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_()
-        avar.fixupSegments_(lambda w: warnings.append(w))
         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):

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

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" %
+			log.warning(
-					(next, len(data)))
+				"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:
+		log.debug("unpacking glyph '%s'", glyphName)
-			ttLib.debugmsg("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:

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)
 

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):

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)

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):

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
+			log.error(
-			print("Warning: 'name' table stringOffset incorrect. Expected: %s; Actual: %s" % (expectedStringOffset, stringOffset))
+				"'name' table stringOffset incorrect. Expected: %s; Actual: %s",
+				expectedStringOffset, stringOffset)
 		stringData = data[stringOffset:]
 		data = data[6:]
 		self.names = []

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)
+				log.debug("%s %s", v, k)
-			print("---", len(stats))
+			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

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" \
+			log.warning("offset is not 0, yet suspiciously low (%d). table: %s",
-					% (offset, self.tableClass.__name__))
+					offset, self.tableClass.__name__)
 			return None
 		table = self.tableClass()
 		reader = reader.getSubReader(offset)

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)

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())

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'
+			log.error(
-				  'https://github.com/google/brotli', file=sys.stderr)
+				'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'
+			log.error(
-				  'https://github.com/google/brotli', file=sys.stderr)
+				'The WOFF2 encoder requires the Brotli Python extension, available at: '
+				'https://github.com/google/brotli')
 			raise ImportError("No module named brotli")
 
 		self.file = file

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
+				usage()
-				print(__doc__ % version)
 				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:
+	log.info('Dumping "%s" to "%s"...', input, output)
-		print('Dumping "%s" to "%s"...' % (input, output))
 	if options.unicodedata:
 		setUnicodeData(options.unicodedata)
-	ttf = TTFont(input, 0, verbose=options.verbose, allowVID=options.allowVID,
+	ttf = TTFont(input, 0, allowVID=options.allowVID,
-			quiet=options.quiet,
 			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:
+	log.info('Compiling "%s" to "%s"...' % (input, output))
-		print('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)
+			allowVID=options.allowVID)
-	ttf.importXML(input, quiet=options.quiet)
+	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:
+		sys.exit(1)
-			raise
 
 
 if __name__ == "__main__":

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" %
+            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 "
+            logging.warning("glyph %s has not the same number of "
-                          "control points in all input fonts" % glyphName)
+                            "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")