Merge pull request #453 from nbcsm/logging

refine logging infrastructure

Author: nbcsm

README.md

@@ -161,7 +161,7 @@ optional arguments:
   --tests TESTS      tests to run
   --backend BACKEND  backend to use
   --config           yaml config file
-  --verbose          verbose output
+  --verbose          verbose output, option is additive
   --opset OPSET      target opset to use
   --perf csv-file    capture performance numbers or tensorflow and onnx runtime
   --debug            dump generated graph with shape info
@@ -199,7 +199,7 @@ tf2onnx.tfonnx.process_tf_graph(tf_graph,
         Args:
             tf_graph: tensorflow graph
             continue_on_error: if an op can't be processed (aka there is no mapping), continue
-            verbose: print summary stats
+            verbose: print summary stats (deprecated)
             target: list of workarounds applied to help certain platforms
             opset: the opset to be used (int, default is latest)
             custom_op_handlers: dictionary of custom ops handlers

tests/backend_test_base.py

@@ -26,20 +26,11 @@
 class Tf2OnnxBackendTestBase(unittest.TestCase):
     def setUp(self):
         self.config = get_test_config()
-        self.maxDiff = None
         tf.reset_default_graph()
         # reset name generation on every test
         utils.INTERNAL_NAME = 1
         np.random.seed(1)  # Make it reproducible.
-
-        self.log = logging.getLogger("tf2onnx.unitest." + str(type(self)))
-        if self.config.is_debug_mode:
-            self.log.setLevel(logging.DEBUG)
-        else:
-            # 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)
-            self.log.setLevel(logging.INFO)
+        self.logger = logging.getLogger(self.__class__.__name__)
 
     def tearDown(self):
         if not self.config.is_debug_mode:
@@ -125,15 +116,15 @@ def run_test_case(self, feed_dict, input_names_with_port, output_names_with_port
                 os.makedirs(self.test_data_directory)
             model_path = os.path.join(self.test_data_directory, self._testMethodName + "_original.pb")
             utils.save_protobuf(model_path, sess.graph_def)
-            self.log.debug("created file %s", model_path)
+            self.logger.debug("created file %s", model_path)
 
         graph_def = tf_optimize(input_names_with_port, output_names_with_port,
                                 sess.graph_def, constant_fold)
 
         if self.config.is_debug_mode:
             model_path = os.path.join(self.test_data_directory, self._testMethodName + "_after_tf_optimize.pb")
             utils.save_protobuf(model_path, graph_def)
-            self.log.debug("created file  %s", model_path)
+            self.logger.debug("created file  %s", model_path)
 
         tf.reset_default_graph()
         tf.import_graph_def(graph_def, name='')
@@ -162,5 +153,5 @@ def save_onnx_model(self, model_proto, feed_dict, postfix=""):
                                             model_proto, include_test_data=self.config.is_debug_mode,
                                             as_text=self.config.is_debug_mode)
 
-        self.log.debug("create model file: %s", target_path)
+        self.logger.debug("create model file: %s", target_path)
         return target_path

tests/common.py

@@ -11,7 +11,7 @@
 
 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",
@@ -30,7 +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.is_debug_mode = False
+        self.log_level = logging.WARNING
         self.temp_dir = utils.get_temp_directory()
 
     @property
@@ -45,6 +45,10 @@ def is_onnxruntime_backend(self):
     def is_caffe2_backend(self):
         return self.backend == "caffe2"
 
+    @property
+    def is_debug_mode(self):
+        return utils.is_debug_mode()
+
     def _get_tf_version(self):
         import tensorflow as tf
         return LooseVersion(tf.__version__)
@@ -85,15 +89,19 @@ 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='*')
 
             args = parser.parse_args()
+            if args.debug:
+                utils.set_debug_mode(True)
+
             config.backend = args.backend
             config.opset = args.opset
             config.target = args.target.split(',')
-            config.is_debug_mode = args.debug
+            config.log_level = logging.get_verbosity_level(args.verbose, config.log_level)
             if args.temp_dir:
                 config.temp_dir = args.temp_dir
 
@@ -114,7 +122,10 @@ def get_test_config():
 
 
 def unittest_main():
-    print(get_test_config())
+    config = get_test_config()
+    logging.basicConfig(level=config.log_level)
+    with logging.set_scope_level(logging.INFO) as logger:
+        logger.info(config)
     unittest.main()
 
 

tests/conftest.py

@@ -4,7 +4,11 @@
 """ print pytest config."""
 
 from common import get_test_config
+from tf2onnx import logging
 
 
 def pytest_configure():
-    print(get_test_config())
+    config = get_test_config()
+    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,15 +27,12 @@
 import yaml
 
 import tf2onnx
-from tf2onnx import loader
-from tf2onnx import utils
-from tf2onnx import optimizer
+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)
-log = logging.getLogger("tf2onnx")
+logger = logging.getLogger("run_pretrained")
 
 TEMP_DIR = os.path.join(utils.get_temp_directory(), "run_pretrained")
 PERFITER = 1000
@@ -157,7 +153,7 @@ def run_tensorflow(self, sess, inputs):
 
     def to_onnx(self, tf_graph, opset=None, extra_opset=None, shape_override=None, input_names=None):
         """Convert graph to tensorflow."""
-        return process_tf_graph(tf_graph, continue_on_error=False, verbose=True, opset=opset,
+        return process_tf_graph(tf_graph, continue_on_error=False, opset=opset,
                                 extra_opset=extra_opset, target=Test.target, shape_override=shape_override,
                                 input_names=input_names, output_names=self.output_names)
 
@@ -207,7 +203,7 @@ def create_onnx_file(name, model_proto, inputs, outdir):
         utils.save_protobuf(model_path, model_proto)
         print("\tcreated", model_path)
 
-    def run_test(self, name, backend="caffe2", debug=False, onnx_file=None, opset=None, extra_opset=None,
+    def run_test(self, name, backend="caffe2", onnx_file=None, opset=None, extra_opset=None,
                  perf=None, fold_const=None):
         """Run complete test against backend."""
         print(name)
@@ -245,7 +241,7 @@ def run_test(self, name, backend="caffe2", debug=False, onnx_file=None, opset=No
                 inputs[k] = v
 
         graph_def = tf2onnx.tfonnx.tf_optimize(inputs.keys(), self.output_names, graph_def, fold_const)
-        if debug:
+        if utils.is_debug_mode():
             utils.save_protobuf(os.path.join(TEMP_DIR, name + "_after_tf_optimize.pb"), graph_def)
         shape_override = {}
         g = tf.import_graph_def(graph_def, name='')
@@ -257,7 +253,7 @@ def run_test(self, name, backend="caffe2", debug=False, onnx_file=None, opset=No
                 dtype = tf.as_dtype(t.dtype).name
                 v = inputs[k]
                 if dtype != v.dtype:
-                    log.warning("input dtype doesn't match tensorflow's")
+                    logger.warning("input dtype doesn't match tensorflow's")
                     inputs[k] = np.array(v, dtype=dtype)
             if self.force_input_shape:
                 for k, v in inputs.items():
@@ -275,13 +271,13 @@ def run_test(self, name, backend="caffe2", debug=False, onnx_file=None, opset=No
                 onnx_graph = self.to_onnx(sess.graph, opset=opset, extra_opset=extra_opset,
                                           shape_override=shape_override, input_names=inputs.keys())
                 model_proto = onnx_graph.make_model("converted from tf2onnx")
-                new_model_proto = optimizer.optimize_graph(onnx_graph, debug=debug).make_model("optimized")
+                new_model_proto = optimizer.optimize_graph(onnx_graph).make_model("optimized")
                 if new_model_proto:
                     model_proto = new_model_proto
                 else:
                     print("\tNON-CRITICAL, optimizers are not applied successfully")
                 print("\tto_onnx", "OK")
-                if debug:
+                if utils.is_debug_mode():
                     onnx_graph.dump_graph()
                 if onnx_file:
                     self.create_onnx_file(name, model_proto, inputs, onnx_file)
@@ -333,11 +329,11 @@ 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("--debug", help="debug vlog", action="store_true")
+    parser.add_argument("--verbose", "-v", help="verbose output, option is additive", action="count")
+    parser.add_argument("--debug", help="debug mode", action="store_true")
     parser.add_argument("--list", help="list tests", action="store_true")
     parser.add_argument("--onnx-file", help="create onnx file in directory")
     parser.add_argument("--perf", help="capture performance numbers")
@@ -374,11 +370,11 @@ 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_verbosity_level(args.verbose))
+    if args.debug:
+        utils.set_debug_mode(True)
+
     Test.cache_dir = args.cache
     Test.target = args.target
     tests = tests_from_yaml(args.config)
@@ -398,15 +394,15 @@ def main():
             continue
         count += 1
         try:
-            ret = t.run_test(test, backend=args.backend, debug=args.debug, onnx_file=args.onnx_file,
+            ret = t.run_test(test, backend=args.backend, onnx_file=args.onnx_file,
                              opset=args.opset, extra_opset=args.extra_opset, perf=args.perf,
                              fold_const=args.fold_const)
         except Exception as ex:
             ret = None
             tb = traceback.format_exc()
             print(ex, tb)
         finally:
-            if not args.debug:
+            if not utils.is_debug_mode():
                 utils.delete_directory(TEMP_DIR)
         if not ret:
             failed += 1

tests/test_backend.py

@@ -188,7 +188,7 @@ def test_maxpool(self):
                 mp = tf.nn.max_pool(x, ksize, strides, padding=padding)
                 _ = tf.identity(mp, name=_TFOUTPUT)
 
-                self.log.debug(str(p))
+                self.logger.debug(str(p))
                 self._run_test_case([_OUTPUT], {_INPUT: x_val})
 
     @unittest.skipIf(get_test_config().is_onnxruntime_backend and get_test_config().backend_version == "0.2.1",
@@ -207,7 +207,7 @@ def test_avgpool(self):
                 mp = tf.nn.avg_pool(x, ksize, strides, padding=padding)
                 _ = tf.identity(mp, name=_TFOUTPUT)
 
-                self.log.debug(str(p))
+                self.logger.debug(str(p))
                 self._run_test_case([_OUTPUT], {_INPUT: x_val}, rtol=1e-06)
 
     def _conv_test(self, x_val, w, strides=None, padding="VALID", dilations=None, rtol=1e-07):
@@ -1125,7 +1125,7 @@ def test_pad_const_default_val(self):
             paddings = tf.constant(pad)
             op = tf.pad(x, paddings, mode)
             _ = tf.identity(op, name=_TFOUTPUT)
-            self.log.debug(str(p))
+            self.logger.debug(str(p))
             self._run_test_case([_OUTPUT], {_INPUT: x_val})
 
     @skip_caffe2_backend()

tests/test_graph.py

@@ -7,8 +7,6 @@
 from __future__ import print_function
 from __future__ import unicode_literals
 
-import os
-import unittest
 from collections import namedtuple
 
 import numpy as np
@@ -17,14 +15,14 @@
 import tensorflow as tf
 from onnx import helper
 
-import tf2onnx
 from tf2onnx import constants, utils
 from tf2onnx.graph import GraphUtil
 from tf2onnx.graph_matcher import OpTypePattern, GraphMatcher
 from tf2onnx.tfonnx import process_tf_graph
 from tf2onnx.handler import tf_op
 
-from common import get_test_config, unittest_main, check_tf_min_version, check_tf_max_version
+from backend_test_base import Tf2OnnxBackendTestBase
+from common import unittest_main, check_tf_min_version, check_tf_max_version
 
 
 # pylint: disable=missing-docstring,unused-argument,unused-variable
@@ -91,32 +89,21 @@ def onnx_pretty(g, args=None):
     return helper.printable_graph(model_proto.graph)
 
 
-class Tf2OnnxGraphTests(unittest.TestCase):
+class Tf2OnnxGraphTests(Tf2OnnxBackendTestBase):
     """Test cases."""
     maxDiff = None
 
     def setUp(self):
-        """Setup test."""
-        # reset name generation on every test
-        # 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)
-
-        self.config = get_test_config()
-
-        tf2onnx.utils.INTERNAL_NAME = 1
-        tf.reset_default_graph()
-        arg = namedtuple("Arg", "input inputs outputs verbose continue_on_error")
-        self._args0 = arg(input="test", inputs=[], outputs=["output:0"],
-                          verbose=False, continue_on_error=False)
-        self._args1 = arg(input="test", inputs=["input:0"], outputs=["output:0"],
-                          verbose=False, continue_on_error=False)
+        super().setUp()
+        arg = namedtuple("Arg", "input inputs outputs continue_on_error")
+        self._args0 = arg(input="test", inputs=[], outputs=["output:0"], continue_on_error=False)
+        self._args1 = arg(input="test", inputs=["input:0"], outputs=["output:0"], continue_on_error=False)
         self._args2 = arg(input="test", inputs=["input1:0", "input2:0"], outputs=["output:0"],
-                          verbose=False, continue_on_error=False)
+                          continue_on_error=False)
         self._args3 = arg(input="test", inputs=["input1:0", "input2:0", "prob:0"], outputs=["output:0"],
-                          verbose=False, continue_on_error=False)
+                          continue_on_error=False)
         self._args4 = arg(input="test", inputs=["input1:0", "input2:0"], outputs=["output1:0", "output2:0"],
-                          verbose=False, continue_on_error=False)
+                          continue_on_error=False)
 
     def test_abs(self):
         with tf.Session() as sess: