From 317d6531258dc0080b67742a0dad2d77c49244a2 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:15:09 +0000
Subject: [PATCH 01/38] [loggingTools] module containing tools for adapting the
 Python logging package to fontTools (and viceversa)

---
 Lib/fontTools/misc/loggingTools.py | 450 +++++++++++++++++++++++++++++
 1 file changed, 450 insertions(+)
 create mode 100644 Lib/fontTools/misc/loggingTools.py

diff --git a/Lib/fontTools/misc/loggingTools.py b/Lib/fontTools/misc/loggingTools.py
new file mode 100644
index 000000000..e391a02a4
--- /dev/null
+++ b/Lib/fontTools/misc/loggingTools.py
@@ -0,0 +1,450 @@
+""" 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)
+
+
+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:
+				handler.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.01...
+	>>> time.sleep(0.02)
+	>>> print("Second lap:", timer.split())
+	Second lap: 0.02...
+	>>> print("Overall time:", timer.time())
+	Overall time: 0.03...
+
+	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.01... 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 0.01... 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 0.02... 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 0.02... 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=None):
+	""" Raise a warning about deprecated function argument 'name'. """
+	warnings.warn(
+		"%r is deprecated; %s" % (name, msg), category=category, stacklevel=3)
+
+
+def deprecateFunction(msg, category=None):
+	""" 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)

From 1034699a21dc0cf4862624d076d487deae7df9e2 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:20:59 +0000
Subject: [PATCH 02/38] [fontTools.__init__] add NullHandler to avoid "no
 handlers could be found" error.

---
 Lib/fontTools/__init__.py | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/Lib/fontTools/__init__.py b/Lib/fontTools/__init__.py
index 761983d7c..bec5418ef 100644
--- a/Lib/fontTools/__init__.py
+++ b/Lib/fontTools/__init__.py
@@ -1,4 +1,10 @@
 from __future__ import print_function, division, absolute_import
 from fontTools.misc.py23 import *
+import logging
+
+# add a do-nothing handler to the libary's top-level logger, to avoid
+# "no handlers could be found" error if client doesn't configure logging
+log = logging.getLogger(__name__)
+log.addHandler(logging.NullHandler())
 
 version = "3.0"

From 0c313bc1d2412698faaab290994d7c99e39caff5 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:21:38 +0000
Subject: [PATCH 03/38] [fontTools.__init__] export 'configLogger' in the
 top-level module to make it easier for clients to import

---
 Lib/fontTools/__init__.py | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/Lib/fontTools/__init__.py b/Lib/fontTools/__init__.py
index bec5418ef..6bd3c4c0f 100644
--- a/Lib/fontTools/__init__.py
+++ b/Lib/fontTools/__init__.py
@@ -7,4 +7,9 @@ import logging
 log = logging.getLogger(__name__)
 log.addHandler(logging.NullHandler())
 
+# clients may call this to configure logging with a predefined handler and format
+from fontTools.misc.loggingTools import configLogger
+
 version = "3.0"
+
+__all__ = ["version", "log", "configLogger"]

From 769efc3d0dea6d4ca9febf97b379d3c5b591a9dc Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:25:50 +0000
Subject: [PATCH 04/38] [ttLib] replace print statements with logger; deprecate
 'quiet' and 'verbose' arguments; deprecate 'debugmsg' func

Previously, when TTX was run in verbose mode, the messages printed to the console would also show the time
each one was logged -- e.g. "blah blah  (15:23:24)" -- using the 'debugmsg' function which is defined here.
Even though the logging package would allow to do the same thing (via 'datefmt' and "%(asctime)s"), I decided
drop this, as I think it's not very interesting...
I'll replace it with the overall elapsed time in seconds, in a follow-up commit.
---
 Lib/fontTools/ttLib/__init__.py | 62 +++++++++++++++++++--------------
 1 file changed, 35 insertions(+), 27 deletions(-)

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

From de5dca010bb4a44862451abfe7eff31447221cf9 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:26:59 +0000
Subject: [PATCH 05/38] [xmlReader] replace print with logger; deprecate
 'quiet' argument

---
 Lib/fontTools/misc/xmlReader.py | 18 ++++++++++--------
 1 file changed, 10 insertions(+), 8 deletions(-)

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

From 967b994449f898e841fa63b18608bed660bd416b Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:27:59 +0000
Subject: [PATCH 06/38] [sfnt] replace print with logger

---
 Lib/fontTools/ttLib/sfnt.py | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

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

From 6a92ae085bcf84af1e1b5b5f8a145a112908ab2f Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:29:03 +0000
Subject: [PATCH 07/38] [woff2] replace print with logger

---
 Lib/fontTools/ttLib/woff2.py | 14 ++++++++++----
 1 file changed, 10 insertions(+), 4 deletions(-)

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

From 85f9f442ea683d2d243535bfe851ed8e7a97f3af Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:30:09 +0000
Subject: [PATCH 08/38] [BitmapGlyphMetrics] replace print with logger

---
 Lib/fontTools/ttLib/tables/BitmapGlyphMetrics.py | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

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

From 74cb889f4e1918457cc68290c35b0760b3ff0ab0 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:32:34 +0000
Subject: [PATCH 09/38] [E_B_D_T_] replace print with logger

---
 Lib/fontTools/ttLib/tables/E_B_D_T_.py | 12 ++++++++----
 1 file changed, 8 insertions(+), 4 deletions(-)

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

From 7d67e9c257e01705049fdae9188194a68ea105dc Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:33:10 +0000
Subject: [PATCH 10/38] [E_B_L_C_] replace print with logger

---
 Lib/fontTools/ttLib/tables/E_B_L_C_.py | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

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.

From e46be4d7d6fc0b915fb403764dd4f875b4a80004 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:33:40 +0000
Subject: [PATCH 11/38] [O_S_2f_2] replace print with logger

---
 Lib/fontTools/ttLib/tables/O_S_2f_2.py | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

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

From c5659b28a20e427801311fc4f7793b873d77f13d Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:34:51 +0000
Subject: [PATCH 12/38] [S_V_G_] replace print with logger

---
 Lib/fontTools/ttLib/tables/S_V_G_.py | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

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

From 9b21ea6a09df862849d8e89aa67e7cf8f2d39fea Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:35:34 +0000
Subject: [PATCH 13/38] [_a_v_a_r] replace warnings with logger

---
 Lib/fontTools/ttLib/tables/_a_v_a_r.py | 17 ++++++++++-------
 1 file changed, 10 insertions(+), 7 deletions(-)

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

From 77658c952f7abd43b641194950caa1063a8daab3 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:38:45 +0000
Subject: [PATCH 14/38] [_a_v_a_r_test] use StringIO to capture logger's output
 in test case

---
 Lib/fontTools/ttLib/tables/_a_v_a_r_test.py | 9 ++++++---
 1 file changed, 6 insertions(+), 3 deletions(-)

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

From ff853c38b886d7c1c814b982d782efa109bc8663 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:39:20 +0000
Subject: [PATCH 15/38] [_c_m_a_p] replace print with logger

---
 Lib/fontTools/ttLib/tables/_c_m_a_p.py | 9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

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

From dff078ed515083206bc26593c7ea3aed9541070a Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:40:07 +0000
Subject: [PATCH 16/38] [_g_l_y_f] replace print and warnings with logger

---
 Lib/fontTools/ttLib/tables/_g_l_y_f.py | 25 +++++++++++++++----------
 1 file changed, 15 insertions(+), 10 deletions(-)

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:

From f85e2f295d317e0be6e815a98d0f007109d24929 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:40:41 +0000
Subject: [PATCH 17/38] [_h_e_a_d] replace warnings with logger

---
 Lib/fontTools/ttLib/tables/_h_e_a_d.py | 10 ++++++----
 1 file changed, 6 insertions(+), 4 deletions(-)

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)
 

From abe3202412e57cee4ba3d1787dd23c2722930fd6 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:41:05 +0000
Subject: [PATCH 18/38] [_h_m_t_x] replace warnings with logger

---
 Lib/fontTools/ttLib/tables/_h_m_t_x.py | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

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

From 7d36de99efac32944e530c8c597636d3b3029d09 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:41:33 +0000
Subject: [PATCH 19/38] [_k_e_r_n] replace warnings with logger

---
 Lib/fontTools/ttLib/tables/_k_e_r_n.py | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

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)

From 0ce31f7b0a2b4915dc41fbea320dd2a4006dcc83 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:41:56 +0000
Subject: [PATCH 20/38] [_l_o_c_a] replace warnings with logger

---
 Lib/fontTools/ttLib/tables/_l_o_c_a.py | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

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

From 2b30dc2134d6a2b0ada5c5139247405a627e5462 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:42:27 +0000
Subject: [PATCH 21/38] [_n_a_m_e] replace print with logger

---
 Lib/fontTools/ttLib/tables/_n_a_m_e.py | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

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 = []

From 10bf8ecd857bb798c752dbcac158d6b8b3c7c2ab Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:43:21 +0000
Subject: [PATCH 22/38] [otBase] replace print with logger

---
 Lib/fontTools/ttLib/tables/otBase.py | 11 +++++++----
 1 file changed, 7 insertions(+), 4 deletions(-)

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

From 6f8e1502ffceeeb9487a83b0fff210d3618da9ae Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:43:54 +0000
Subject: [PATCH 23/38] [otConverters] replace print with logger

---
 Lib/fontTools/ttLib/tables/otConverters.py | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

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)

From af91f9e791e1fdd3684e78f5daabb65416af53eb Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:44:42 +0000
Subject: [PATCH 24/38] [otTables] replace warnings with logger

---
 Lib/fontTools/ttLib/tables/otTables.py | 22 +++++++++++++---------
 1 file changed, 13 insertions(+), 9 deletions(-)

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)

From 48db539c446cebb8848b8a7e860aca2a790eaee2 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:45:05 +0000
Subject: [PATCH 25/38] [ttProgram] replace print with logger

---
 Lib/fontTools/ttLib/tables/ttProgram.py | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

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

From e68e7332a4c409af5f292e6993fe46819d327c78 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:50:57 +0000
Subject: [PATCH 26/38] [cffLib] replace print with logger (but keep debug
 messages off)

All these debug messages were disabled, and I don't wish to re-enable them
while running TTX in verbose mode. So here I use a custom level less than
logging.DEBUGm to make sure they will be muted even when the logger's level
is equal to logging.DEBUG.
---
 Lib/fontTools/cffLib.py | 43 +++++++++++++++++------------------------
 1 file changed, 18 insertions(+), 25 deletions(-)

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)

From e4f0f3ec30787226a22bfeb64940e1856f8e2f72 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:51:24 +0000
Subject: [PATCH 27/38] [psCharStrings] replace print with logger

---
 Lib/fontTools/misc/psCharStrings.py | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

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)
 

From b6145de7cb0d544b9c340f3682ffefecf001114e Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 14:52:08 +0000
Subject: [PATCH 28/38] [psLib] replace print with logger

---
 Lib/fontTools/misc/psLib.py | 21 ++++++++++++++-------
 1 file changed, 14 insertions(+), 7 deletions(-)

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

From e5b6be00a0919779d6464b6c56571c165fecc5e4 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 15:15:40 +0000
Subject: [PATCH 29/38] [ttx] replace print with logger; make -v and -q
 mutually exclusive; don't use deprecated 'verbose' and 'quiet' arguments

The default logger level for TTX is set to logging.INFO. Anything equal or above that level
will be logged. Anything below that will not.
If the -v option is passed, the threshold is lowered to logging.DEBUG.
If the -q option is passed, the threshold is increased to logging.WARNING.
---
 Lib/fontTools/ttx.py | 67 +++++++++++++++++++++++++++-----------------
 1 file changed, 41 insertions(+), 26 deletions(-)

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__":

From b62f5509524a49101ab6f211f1c3b63458f52f5e Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 15:43:03 +0000
Subject: [PATCH 30/38] [mtiLib] replace print with logger

inside main(), I just do a basic config for the library logger, but keep
the debug messages from mtiLib turned off.
---
 Lib/fontTools/mtiLib/__init__.py | 38 ++++++++++++++++++--------------
 1 file changed, 22 insertions(+), 16 deletions(-)

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

From 3d8b498ad108b4ce488d164be2972a525ccccfe7 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 15:51:37 +0000
Subject: [PATCH 31/38] [Snippets/interpolate] replace warnings with logging

Here I use logging.basicConfig to configure the root logger, and hence all the other loggers,
including fontTools'.

I could have used fontTools.configLogger as well (and get predefined formatter, etc.), but wanted
to show that one can also configure the fontTools logger using the built-in logging configuration
functions (e.g. basicConfig, config.dictConfig and config.fileConfig).
---
 Snippets/interpolate.py | 11 ++++++-----
 1 file changed, 6 insertions(+), 5 deletions(-)

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

From c5febaf1a5c14d6e80a5f209292468cbf0ca45f2 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 16:13:31 +0000
Subject: [PATCH 32/38] [subset] remove custom Logger and use logging instead

The Subsetter class now uses a module-level 'log', and no longer uses
its own custom Logger. This has been removed, and its features replaced
by equivalents.

log.lapse() are replaced with Timer context manager/decorator (these should make clearer where the elapsed time starts/stops);

log.glyphs() is kept for convenience: it is bound dynamically to the logger instance instead of subclassing logging.Logger, as it's only
useful in here.

log.font() is replaced by `font.saveXML(sys.stdout)`.

A distinct sub-logger is configured for timing messages, to allow --timing option to be enabled independently from --verbose
---
 Lib/fontTools/subset/__init__.py | 271 ++++++++++++++-----------------
 1 file changed, 121 insertions(+), 150 deletions(-)

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',

From 6544482d924f902db5e00c5e07be7aba75e85f2d Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 16:16:11 +0000
Subject: [PATCH 33/38] [merge] remove custom Logger and use logging instead

this follows the same changes applied to subset.py module in d03ce32
---
 Lib/fontTools/merge.py | 100 +++++++++++++----------------------------
 1 file changed, 32 insertions(+), 68 deletions(-)

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

From e8edfad59ad1cf1cc52568dba7630e9b6f652be2 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 16:39:23 +0000
Subject: [PATCH 34/38] [loggingTools] on Windows, warnings.warn doesn't like
 category=None, set it to UserWarning (which is the default)

---
 Lib/fontTools/misc/loggingTools.py | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/Lib/fontTools/misc/loggingTools.py b/Lib/fontTools/misc/loggingTools.py
index e391a02a4..ee9d5ec4b 100644
--- a/Lib/fontTools/misc/loggingTools.py
+++ b/Lib/fontTools/misc/loggingTools.py
@@ -426,13 +426,13 @@ class ChannelsFilter(logging.Filter):
 		return False
 
 
-def deprecateArgument(name, msg, category=None):
+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=None):
+def deprecateFunction(msg, category=UserWarning):
 	""" Decorator to raise a warning when a deprecated function is called. """
 	def decorator(func):
 		@wraps(func)

From 3664462a639b65f38152dff6212cab215d3d7c90 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Sun, 24 Jan 2016 16:56:18 +0000
Subject: [PATCH 35/38] [loggingTools] use ellipsis for elapsed time in
 doctestes to fix AppVeyor build

https://ci.appveyor.com/project/anthrotype/fonttools/build/1.0.53/job/2p08d9sbcfelvwx6
---
 Lib/fontTools/misc/loggingTools.py | 14 +++++++-------
 1 file changed, 7 insertions(+), 7 deletions(-)

diff --git a/Lib/fontTools/misc/loggingTools.py b/Lib/fontTools/misc/loggingTools.py
index ee9d5ec4b..78f41b94c 100644
--- a/Lib/fontTools/misc/loggingTools.py
+++ b/Lib/fontTools/misc/loggingTools.py
@@ -229,19 +229,19 @@ class Timer(object):
 	>>> timer = Timer()
 	>>> time.sleep(0.01)
 	>>> print("First lap:", timer.split())
-	First lap: 0.01...
+	First lap: 0.0...
 	>>> time.sleep(0.02)
 	>>> print("Second lap:", timer.split())
-	Second lap: 0.02...
+	Second lap: 0.0...
 	>>> print("Overall time:", timer.time())
-	Overall time: 0.03...
+	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.01... seconds
+	0.0... seconds
 
 	If initialised with a logger, it can log the elapsed time automatically
 	upon exiting the with-statement.
@@ -251,7 +251,7 @@ class Timer(object):
 	>>> configLogger(level="DEBUG", format="%(message)s", stream=sys.stdout)
 	>>> with Timer(log, 'do something'):
 	...     time.sleep(0.01)
-	Took 0.01... to do something
+	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.
@@ -262,7 +262,7 @@ class Timer(object):
 	elapsed time: 0.01...s
 	>>> with timer('redo it', level=logging.INFO):
 	...     time.sleep(0.02)
-	Took 0.02... to redo it
+	Took ... to redo it
 
 	It can also be used as a function decorator to log the time elapsed to run
 	the decorated function.
@@ -276,7 +276,7 @@ class Timer(object):
 	>>> test1()
 	Took 0.01... to run 'test1'
 	>>> test2()
-	Took 0.02... to run test 2
+	Took ... to run test 2
 	"""
 
 	# timeit.default_timer choses the most accurate clock for each platform

From 141cc7b6c29e96c1b0d8621db4d6c103e4909eb2 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Fri, 29 Jan 2016 17:28:53 +0000
Subject: [PATCH 36/38] [loggingTools] typo

---
 Lib/fontTools/misc/loggingTools.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/Lib/fontTools/misc/loggingTools.py b/Lib/fontTools/misc/loggingTools.py
index 78f41b94c..f2a302ea7 100644
--- a/Lib/fontTools/misc/loggingTools.py
+++ b/Lib/fontTools/misc/loggingTools.py
@@ -167,7 +167,7 @@ def configLogger(**kwargs):
 			h.setFormatter(fmt)
 		if not h.filters:
 			for f in filters:
-				handler.addFilter(f)
+				h.addFilter(f)
 		logger.addHandler(h)
 	if logger.name != "root":
 		# stop searching up the hierarchy for handlers

From f3116ad4d00ed2aaaf83d6cadb4c9e1d21e364d8 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Fri, 29 Jan 2016 18:36:21 +0000
Subject: [PATCH 37/38] [loggingTools] add Logger class with support for
 'lastResort' stderr handler

Both _StderrHandler and Logger.callHandlers included here are taken from Python 3.5's
logging.py source.

I only set logging.lastResort if it's not already set (i.e. for Python < 3.2).
---
 Lib/fontTools/misc/loggingTools.py | 52 ++++++++++++++++++++++++++++++
 1 file changed, 52 insertions(+)

diff --git a/Lib/fontTools/misc/loggingTools.py b/Lib/fontTools/misc/loggingTools.py
index f2a302ea7..04a435d02 100644
--- a/Lib/fontTools/misc/loggingTools.py
+++ b/Lib/fontTools/misc/loggingTools.py
@@ -87,6 +87,58 @@ class LevelFormatter(logging.Formatter):
 		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.

From 6eac5d05c0b9e6d74ea61097880a2b893f4506fa Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Fri, 29 Jan 2016 18:44:43 +0000
Subject: [PATCH 38/38] [fontTools.__init__] use 'lastResort' handler instead
 of NullHandler

I think it's better to follow the current Python 3 behavior in the situation
where the user doesn't provide any explicit logging configuration.

Before Python 3.2, when no handlers were found when a logging event occurred,
either the events would be silently dropped (if logging.raiseExceptions is
set to False), or it would throw a single "No handlers could be found" warning
(this was the default behavior).

With Python 3.2 and later, the default behavior is that the events are output
using a "handler of last resort". The latter works like StreamHandler
that writes messages (without formatting) to the current value of sys.stderr
(thus respecting any redirections which may be in effect).
---
 Lib/fontTools/__init__.py | 13 +++++++------
 1 file changed, 7 insertions(+), 6 deletions(-)

diff --git a/Lib/fontTools/__init__.py b/Lib/fontTools/__init__.py
index 6bd3c4c0f..743471efc 100644
--- a/Lib/fontTools/__init__.py
+++ b/Lib/fontTools/__init__.py
@@ -1,14 +1,15 @@
 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)
 
-# add a do-nothing handler to the libary's top-level logger, to avoid
-# "no handlers could be found" error if client doesn't configure logging
 log = logging.getLogger(__name__)
-log.addHandler(logging.NullHandler())
-
-# clients may call this to configure logging with a predefined handler and format
-from fontTools.misc.loggingTools import configLogger
 
 version = "3.0"