add tf2onnx logging, enhance verbosity support

Author: nbcsm

tests/backend_test_base.py

@@ -30,12 +30,7 @@ def setUp(self):
         # reset name generation on every test
         utils.INTERNAL_NAME = 1
         np.random.seed(1)  # Make it reproducible.
-
         self.logger = logging.getLogger(self.__class__.__name__)
-        if not self.config.is_debug_mode:
-            # suppress log info of tensorflow so that result of test can be seen much easier
-            os.environ['TF_CPP_MIN_LOG_LEVEL'] = '3'
-            tf.logging.set_verbosity(tf.logging.WARN)
 
     def tearDown(self):
         if not self.config.is_debug_mode:

tests/common.py

@@ -4,15 +4,14 @@
 """ test common utilities."""
 
 import argparse
-import logging
 import os
 import sys
 import unittest
 from collections import defaultdict
 
 from distutils.version import LooseVersion
 from parameterized import parameterized
-from tf2onnx import constants, utils
+from tf2onnx import constants, logging, utils
 
 __all__ = ["TestConfig", "get_test_config", "unittest_main", "check_onnxruntime_backend",
            "check_tf_min_version", "skip_tf_versions", "check_onnxruntime_min_version",
@@ -31,6 +30,7 @@ def __init__(self):
         self.target = os.environ.get("TF2ONNX_TEST_TARGET", ",".join(constants.DEFAULT_TARGET)).split(',')
         self.backend = os.environ.get("TF2ONNX_TEST_BACKEND", "onnxruntime")
         self.backend_version = self._get_backend_version()
+        self.log_level = logging.WARNING
         self.is_debug_mode = False
         self.temp_dir = utils.get_temp_directory()
 
@@ -86,6 +86,7 @@ def load():
             parser.add_argument("--opset", type=int, default=config.opset, help="opset to test against")
             parser.add_argument("--target", default=",".join(config.target), choices=constants.POSSIBLE_TARGETS,
                                 help="target platform")
+            parser.add_argument("--verbose", "-v", help="verbose output, option is additive", action="count")
             parser.add_argument("--debug", help="output debugging information", action="store_true")
             parser.add_argument("--temp_dir", help="temp dir")
             parser.add_argument("unittest_args", nargs='*')
@@ -94,6 +95,7 @@ def load():
             config.backend = args.backend
             config.opset = args.opset
             config.target = args.target.split(',')
+            config.log_level = logging.get_adjusted_level(args.verbose, config.log_level)
             config.is_debug_mode = args.debug
             if args.temp_dir:
                 config.temp_dir = args.temp_dir
@@ -116,8 +118,8 @@ def get_test_config():
 
 def unittest_main():
     config = get_test_config()
-    logging.basicConfig(level=logging.WARNING, format=constants.LOG_FORMAT)
-    with utils.set_log_level(logging.getLogger(), logging.INFO) as logger:
+    logging.basicConfig(level=config.log_level)
+    with logging.set_scope_level(logging.INFO) as logger:
         logger.info(config)
     unittest.main()
 

tests/conftest.py

@@ -3,13 +3,12 @@
 
 """ print pytest config."""
 
-import logging
 from common import get_test_config
-from tf2onnx import constants, utils
+from tf2onnx import logging
 
 
 def pytest_configure():
     config = get_test_config()
-    logging.basicConfig(level=logging.WARNING, format=constants.LOG_FORMAT)
-    with utils.set_log_level(logging.getLogger(), logging.INFO) as logger:
+    logging.basicConfig(level=config.log_level)
+    with logging.set_scope_level(logging.INFO) as logger:
         logger.info(config)

tests/run_pretrained_models.py

@@ -15,7 +15,6 @@
 import time
 import traceback
 import zipfile
-import logging
 
 import PIL.Image
 import numpy as np
@@ -28,12 +27,11 @@
 import yaml
 
 import tf2onnx
-from tf2onnx import constants, loader, optimizer, utils
+from tf2onnx import loader, logging, optimizer, utils
 from tf2onnx.tfonnx import process_tf_graph
 
 # pylint: disable=broad-except,logging-not-lazy,unused-argument,unnecessary-lambda
 
-logging.basicConfig(level=logging.INFO, format=constants.LOG_FORMAT)
 logger = logging.getLogger("run_pretrained")
 
 TEMP_DIR = os.path.join(utils.get_temp_directory(), "run_pretrained")
@@ -331,10 +329,10 @@ def get_args():
     parser.add_argument("--target", default="", help="target platform")
     parser.add_argument("--backend", default="onnxruntime",
                         choices=["caffe2", "onnxmsrtnext", "onnxruntime"], help="backend to use")
-    parser.add_argument("--verbose", help="verbose output", action="store_true")
     parser.add_argument("--opset", type=int, default=None, help="opset to use")
     parser.add_argument("--extra_opset", default=None,
                         help="extra opset with format like domain:version, e.g. com.microsoft:1")
+    parser.add_argument("--verbose", "-v", help="verbose output, option is additive", action="count")
     parser.add_argument("--debug", help="debug vlog", action="store_true")
     parser.add_argument("--list", help="list tests", action="store_true")
     parser.add_argument("--onnx-file", help="create onnx file in directory")
@@ -372,11 +370,9 @@ def tests_from_yaml(fname):
 
 
 def main():
-    # suppress log info of tensorflow so that result of test can be seen much easier
-    os.environ['TF_CPP_MIN_LOG_LEVEL'] = '3'
-    tf.logging.set_verbosity(tf.logging.WARN)
-
     args = get_args()
+    logging.basicConfig(level=logging.get_adjusted_level(args.verbose))
+
     Test.cache_dir = args.cache
     Test.target = args.target
     tests = tests_from_yaml(args.config)

tf2onnx/__init__.py

@@ -6,8 +6,8 @@
 from __future__ import print_function
 from __future__ import unicode_literals
 
-
 __all__ = ["utils", "graph_matcher", "graph", "loader", "tfonnx", "shape_inference", "schemas"]
 
 from .version import version as __version__
+from . import logging
 from tf2onnx import tfonnx, utils, graph, graph_matcher, shape_inference, schemas  # pylint: disable=wrong-import-order

tf2onnx/constants.py

@@ -5,7 +5,9 @@
 common constants
 """
 
-from . import utils
+from onnx import helper
+
+TF2ONNX_PACKAGE_NAME = __name__.split('.')[0]
 
 # Built-in supported domains
 ONNX_DOMAIN = ""
@@ -16,7 +18,7 @@
 PREFERRED_OPSET = 7
 
 # Default opset for custom ops
-TENSORFLOW_OPSET = utils.make_opsetid("ai.onnx.converters.tensorflow", 1)
+TENSORFLOW_OPSET = helper.make_opsetid("ai.onnx.converters.tensorflow", 1)
 
 # Target for the generated onnx graph. It possible targets:
 # onnx-1.1 = onnx at v1.1 (winml in rs4 is based on this)
@@ -32,5 +34,3 @@
 NHWC_TO_NCHW = [0, 3, 1, 2]
 HWCN_TO_NCHW = [3, 2, 0, 1]
 NCHW_TO_HWCN = [2, 3, 1, 0]
-
-LOG_FORMAT = "%(asctime)s - %(levelname)s - %(name)s: %(message)s"

tf2onnx/convert.py

@@ -10,12 +10,11 @@
 from __future__ import unicode_literals
 
 import argparse
-import logging
 import tensorflow as tf
 
-from tf2onnx import constants, loader, utils
 from tf2onnx.graph import GraphUtil
 from tf2onnx.tfonnx import process_tf_graph, tf_optimize
+from . import constants, loader, logging, utils
 
 
 # pylint: disable=unused-argument
@@ -38,7 +37,7 @@ def get_args():
     parser.add_argument("--target", default=",".join(constants.DEFAULT_TARGET), choices=constants.POSSIBLE_TARGETS,
                         help="target platform")
     parser.add_argument("--continue_on_error", help="continue_on_error", action="store_true")
-    parser.add_argument("--verbose", help="verbose output", action="store_true")
+    parser.add_argument("--verbose", "-v", help="verbose output, option is additive", action="count")
     parser.add_argument("--fold_const", help="enable tf constant_folding transformation before conversion",
                         action="store_true")
     # experimental
@@ -70,6 +69,7 @@ def get_args():
         if len(tokens) != 2:
             raise ValueError("invalid extra_opset argument")
         args.extra_opset = [utils.make_opsetid(tokens[0], int(tokens[1]))]
+
     return args
 
 
@@ -80,7 +80,7 @@ def default_custom_op_handler(ctx, node, name, args):
 
 def main():
     args = get_args()
-    logging.basicConfig(level=logging.INFO, format=constants.LOG_FORMAT)
+    logging.basicConfig(level=logging.get_adjusted_level(args.verbose))
 
     # override unknown dimensions from -1 to 1 (aka batchsize 1) since not every runtime does
     # support unknown dimensions.

tf2onnx/logging.py

@@ -0,0 +1,100 @@
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT license.
+
+"""
+A wrapper of built-in logging with custom level support and utilities.
+"""
+
+from contextlib import contextmanager
+import logging as _logging
+from logging import *  # pylint: disable=wildcard-import, unused-wildcard-import
+import os
+import types
+
+import tensorflow as tf
+
+from . import constants
+
+VERBOSE = 15
+
+
+def _verbose(self, message, *args, **kwargs):
+    if self.isEnabledFor(VERBOSE):
+        self._log(VERBOSE, message, args, **kwargs)  # pylint: disable=protected-access
+
+
+def getLogger(name=None):  # pylint: disable=invalid-name, function-redefined
+    logger = _logging.getLogger(name)
+    # Inject verbose method to logger object instead logging module
+    logger.verbose = types.MethodType(_verbose, logger)
+    return logger
+
+
+_SIMPLE_LOG_FORMAT = "%(message)s"
+_VERBOSE_LOG_FORMAT = "%(asctime)s - %(levelname)s - %(name)s: %(message)s"
+
+
+def basicConfig(**kwargs):  # pylint: disable=invalid-name, function-redefined
+    """ Do basic configuration for the logging system. tf verbosity is updated accordingly. """
+    # Choose pre-defined format if format argument is not specified
+    if "format" not in kwargs:
+        level = kwargs.get("level", _logging.root.level)
+        kwargs["format"] = _SIMPLE_LOG_FORMAT if level >= INFO else _VERBOSE_LOG_FORMAT
+
+    _logging.basicConfig(**kwargs)
+    set_tf_verbosity(_logging.getLogger().getEffectiveLevel())
+
+
+_VERBOSITY_TO_LEVEL = {
+    1: VERBOSE,
+    2: DEBUG
+}
+
+
+def get_adjusted_level(verbosity, raw_level=INFO):
+    """ If verbosity is specified, return corresponding level, otherwise, return raw_level. """
+    return _VERBOSITY_TO_LEVEL.get(verbosity, raw_level)
+
+
+def set_level(level):
+    """ Set logging level for tf2onnx package. tf verbosity is updated accordingly. """
+    _logging.getLogger(constants.TF2ONNX_PACKAGE_NAME).setLevel(level)
+    set_tf_verbosity(level)
+
+
+def set_tf_verbosity(level):
+    """ Set TF logging verbosity."""
+    tf.logging.set_verbosity(level)
+
+    # TF_CPP_MIN_LOG_LEVEL:
+    #   0 = all messages are logged (default behavior)
+    #   1 = INFO messages are not printed
+    #   2 = INFO and WARNING messages are not printed
+    #   3 = INFO, WARNING, and ERROR messages are not printed
+    if level <= INFO:
+        tf_cpp_min_log_level = "0"
+    elif level <= WARNING:
+        tf_cpp_min_log_level = "1"
+    elif level <= ERROR:
+        tf_cpp_min_log_level = "2"
+    else:
+        tf_cpp_min_log_level = "3"
+    os.environ["TF_CPP_MIN_LOG_LEVEL"] = tf_cpp_min_log_level
+
+
+@contextmanager
+def set_scope_level(level, logger=None):
+    """
+    Set logging level to logger within context, reset level to previous value when exit context.
+    TF verbosity is NOT affected.
+    """
+    if logger is None:
+        logger = getLogger()
+
+    current_level = logger.level
+    logger.setLevel(level)
+
+    try:
+        yield logger
+    finally:
+        logger.setLevel(current_level)

tf2onnx/utils.py

@@ -9,7 +9,6 @@
 from __future__ import print_function
 from __future__ import unicode_literals
 
-from contextlib import contextmanager
 import os
 import re
 import shutil
@@ -438,15 +437,3 @@ def is_onnx_domain(domain):
     if domain is None or domain == "":
         return True
     return False
-
-
-@contextmanager
-def set_log_level(logger, level):
-    """ Override current logger level within context. """
-    current_level = logger.getEffectiveLevel()
-    logger.setLevel(level)
-
-    try:
-        yield logger
-    finally:
-        logger.setLevel(current_level)