refine debug logging

Author: nbcsm

tests/run_pretrained_models.py

@@ -245,6 +245,7 @@ def run_test(self, name, backend="caffe2", onnx_file=None, opset=None, extra_ops
             else:
                 tf_results = self.run_tensorflow(sess, inputs)
                 logger.info("TensorFlow OK")
+
             model_proto = None
             try:
                 # convert model to onnx
@@ -253,12 +254,11 @@ def run_test(self, name, backend="caffe2", onnx_file=None, opset=None, extra_ops
                 model_proto = onnx_graph.make_model("converted from tf2onnx")
                 model_proto = optimizer.optimize_graph(onnx_graph).make_model("optimized")
                 logger.info("To_ONNX, OK")
-                if utils.is_debug_mode():
-                    onnx_graph.dump_graph()
                 if onnx_file:
                     self.create_onnx_file(name, model_proto, inputs, onnx_file)
             except Exception:
                 logger.error("To_ONNX FAIL", exc_info=1)
+                return False
 
         try:
             onnx_results = None

tf2onnx/graph.py

@@ -152,6 +152,27 @@ def __str__(self):
     def __repr__(self):
         return "<onnx op type='%s' name=%s>" % (self.type, self._op.name)
 
+    @property
+    def summary(self):
+        """Return node summary information."""
+        lines = []
+        lines.append("OP={}".format(self.type))
+        lines.append("Name={}".format(self.name))
+
+        g = self.graph
+        if self.input:
+            lines.append("Inputs:")
+            for name in self.input:
+                lines.append("\t{}={}, {}, {}".format(name, g.get_node_by_output(name).type, g.get_shape(name),
+                                                      g.get_dtype(name)))
+
+        if self.output:
+            for name in self.output:
+                lines.append("Outpus:")
+                lines.append("\t{}={}, {}".format(name, g.get_shape(name), g.get_dtype(name)))
+
+        return '\n'.join(lines)
+
     def get_attr(self, name, default=None):
         """Get raw attribute value."""
         attr = self.attr.get(name, default)
@@ -436,6 +457,8 @@ def make_node(self, op_type, inputs, attr=None, output_count=1, outputs=None, sk
         if op_name_scope:
             name = "_".join([op_name_scope, name])
 
+        logger.debug("Making node: %s", name)
+
         if outputs is None:
             outputs = [name + ":" + str(i) for i in range(output_count)]
 
@@ -479,6 +502,7 @@ def make_node(self, op_type, inputs, attr=None, output_count=1, outputs=None, sk
         if (not shapes or not dtypes) and infer_shape_dtype:
             self.update_node_shape_dtype(node, override=False)
 
+        logger.debug("Made node: %s\n%s", node.name, node.summary)
         self._nodes.append(node)
         return node
 
@@ -904,7 +928,11 @@ def dump_graph(self):
         """Dump graph with shapes (helpful for debugging)."""
         for node in self.get_nodes():
             input_names = ["{}{}".format(n, self.get_shape(n)) for n in node.input]
-            print("{} {} {} {}".format(node.type, self.get_shape(node.output[0]), node.name, ", ".join(input_names)))
+            logger.debug("%s %s %s %s",
+                         node.type,
+                         self.get_shape(node.output[0]),
+                         node.name,
+                         ", ".join(input_names))
 
     def follow_inputs(self, node, num, space=""):
         """Follow inputs for (helpful for debugging)."""

tf2onnx/onnx_opset/nn.py

@@ -19,9 +19,9 @@
 from tf2onnx.handler import tf_op
 from tf2onnx.onnx_opset import common, controlflow, tensor
 
-
 logger = logging.getLogger(__name__)
 
+
 # pylint: disable=unused-argument,missing-docstring,unused-variable
 
 def spatial_map(shape, perm):
@@ -151,8 +151,10 @@ def add_padding(ctx, node, kernel_shape, strides, dilations=None, spatial=2):
                 output_shape = spatial_map(output_shape, constants.NHWC_TO_NCHW)
             # calculate pads
             if any(input_shape[i + 2] == -1 or output_shape[i + 2] == -1 for i in range(spatial)):
-                logger.debug("node %s has unknown dim %d for pads calculation, fallback to auto_pad",
-                             node.name, input_shape)
+                logger.debug(
+                    "node %s has unknown dim for pads calculation, fallback to auto_pad: "
+                    "input_shape=%s, output_shape=%s",
+                    node.name, input_shape, output_shape)
                 node.set_attr("auto_pad", "SAME_UPPER")
             else:
                 for i in range(spatial):
@@ -327,6 +329,7 @@ def _convert(cls, ctx, node, **kwargs):
         add_padding(ctx, node, kernel_shape, strides)
         conv_convert_inputs(ctx, node, with_kernel=False)
 
+
 @tf_op(["MaxPoolWithArgmax"], onnx_op="MaxPool")
 class MaxPoolWithArgmaxOp:
     @classmethod

tf2onnx/tfonnx.py

@@ -533,11 +533,14 @@ def rewrite_conv2d_with_pad(g, ops):
 
 
 def tensorflow_onnx_mapping(g, continue_on_error, ops_mapping):
+    logger.verbose("Mapping TF node to ONNX node(s)")
     mapped_op = collections.Counter()
     unmapped_op = collections.Counter()
 
     ops = [n for n in g.get_nodes()]
     for node in ops:
+        logger.debug("Process node: %s\n%s", node.name, node.summary)
+
         if node.need_skip():
             logger.debug("explicitly skip node " + node.name)
             continue
@@ -574,12 +577,8 @@ def tensorflow_onnx_mapping(g, continue_on_error, ops_mapping):
             func(g, node, **kwargs)
             node.skip_conversion = True
         except Exception as ex:
-            type_, value_, traceback_ = sys.exc_info()
-            logger.error("node %s: exception %s" % (node.name, ex))
-            ex_ext = traceback.format_exception(type_, value_, traceback_)
-            if continue_on_error:
-                logger.info(ex_ext)
-            else:
+            logger.error("Failed to convert node %s\n%s", node.name, node.summary, exc_info=1)
+            if not continue_on_error:
                 raise ex
 
     return mapped_op, unmapped_op