clean up logging configuration

Lib/fontmake/__main__.py

@@ -20,6 +20,7 @@
 from contextlib import contextmanager
 from textwrap import dedent
 
+from fontTools.misc.loggingTools import configLogger
 from ufo2ft import CFFOptimization
 from ufo2ft.featureWriters import loadFeatureWriterFromString
 from ufo2ft.filters import loadFilterFromString
@@ -181,6 +182,21 @@ def _make_tempdirs(parser, args):
             shutil.rmtree(td)
 
 
+def _configure_logging(level=None, timing=False):
+    fmt = "%(levelname)s:%(name)s:%(message)s"
+    if level is not None:
+        # NOTE: configuring the root logger with basicConfig should be done only once,
+        # preferably from inside main(); calling subsequent times has no effect.
+        logging.basicConfig(level=level, format=fmt)
+    # fontTools.subset's logger is too chatty, we set it to WARNING
+    logging.getLogger("fontTools.subset").setLevel(logging.WARNING)
+    if timing:
+        # timing-related DEBUG messages get a separate configuration so we
+        # can enable them without needing to lower the global verbosity level
+        configLogger(logger="fontmake.timer", level=logging.DEBUG, format=fmt)
+        configLogger(logger="ufo2ft.timer", level=logging.DEBUG, format=fmt)
+
+
 def main(args=None):
     parser = ArgumentParser()
     parser.add_argument("--version", action="version", version=__version__)
@@ -564,6 +580,9 @@ def main(args=None):
 
     args = vars(parser.parse_args(args))
 
+    level = args.pop("verbose")
+    _configure_logging(level, timing=args.pop("timing"))
+
     specs = args.pop("feature_writer_specs")
     if specs is not None:
         args["feature_writers"] = _loadFeatureWriters(parser, specs)
@@ -607,13 +626,9 @@ def main(args=None):
                     "[mutatormath] extra"
                 )
 
-    PRINT_TRACEBACK = args.get("verbose", "INFO") == "DEBUG"
+    PRINT_TRACEBACK = level == "DEBUG"
     try:
-        project = FontProject(
-            timing=args.pop("timing"),
-            verbose=args.pop("verbose"),
-            validate_ufo=args.pop("validate_ufo"),
-        )
+        project = FontProject(validate_ufo=args.pop("validate_ufo"))
 
         if inputs.glyphs_path:
             with _make_tempdirs(parser, args):

Lib/fontmake/font_project.py

@@ -32,7 +32,7 @@
 import ufoLib2
 from fontTools import designspaceLib
 from fontTools.designspaceLib.split import splitInterpolable
-from fontTools.misc.loggingTools import Timer, configLogger
+from fontTools.misc.loggingTools import Timer
 from fontTools.misc.plistlib import load as readPlist
 from fontTools.ttLib import TTFont
 from fontTools.varLib.interpolate_layout import interpolate_layout
@@ -115,11 +115,29 @@ def temporarily_disabling_axis_maps(designspace_path):
 class FontProject:
     """Provides methods for building fonts."""
 
-    def __init__(self, timing=False, verbose="INFO", validate_ufo=False):
-        logging.basicConfig(level=getattr(logging, verbose.upper()))
-        logging.getLogger("fontTools.subset").setLevel(logging.WARNING)
-        if timing:
-            configLogger(logger=timer.logger, level=logging.DEBUG)
+    def __init__(
+        self,
+        timing=None,  # deprecated
+        verbose=None,  # deprecated
+        validate_ufo=False,
+    ):
+        if verbose is not None or timing is not None:
+            from warnings import warn
+
+            from fontmake.__main__ import _configure_logging
+
+            warn(
+                "The 'verbose'/'timing' arguments are deprecated. "
+                "Logging configuration is global and should not be "
+                "specified in the FontProject constructor. "
+                "Use the logging API to configure fontmake's loggers "
+                "for your application. E.g. fontmake main() function "
+                "uses logging.basicConfig().",
+                UserWarning,
+                stacklevel=2,
+            )
+
+            _configure_logging(verbose, timing)
 
         logger.debug(
             "ufoLib UFO validation is %s", "enabled" if validate_ufo else "disabled"

tests/test_main.py

@@ -1,6 +1,9 @@
 import logging
 import platform
+import re
 import shutil
+import subprocess
+import sys
 from textwrap import dedent
 
 import fontTools.designspaceLib as designspaceLib
@@ -1018,3 +1021,33 @@ def test_main_designspace_v5_dont_interpolate_discrete_axis(data_dir, tmp_path):
     )
     assert (tmp_path / "MutatorSansCondensedVariable_Weight.ttf").exists()
     assert (tmp_path / "MutatorSansExtendedVariable_Weight.ttf").exists()
+
+
+def test_timing_logger(data_dir, tmp_path):
+    # check that --timing flag logs timing-related DEBUG messages even if the
+    # logging level (as set by --verbose flag) is higher
+    result = subprocess.run(
+        [
+            sys.executable,
+            "-m",
+            "fontmake",
+            "--timing",
+            "--verbose",
+            "CRITICAL",
+            "-m",
+            str(data_dir / "DesignspaceTest" / "DesignspaceTest.designspace"),
+            "-i",
+            "-o",
+            "ttf",
+            "--output-dir",
+            str(tmp_path),
+        ],
+        capture_output=True,
+        check=True,
+    )
+
+    assert re.match(
+        r"^DEBUG:fontmake.timer:Took [\.0-9]+s to run 'save_otfs'\r?$",
+        result.stderr.decode(),
+        flags=re.MULTILINE,
+    )