[LOG] Replace printing with modularized logging

doc/log-and-err.md

@@ -0,0 +1,38 @@
+## Logging
+
+### Modularization
+
+We support the following logging "keys":
+
+- `fuzz`: fuzzing loop;
+- `mgen`: model generation;
+- `exec`: model execution;
+- `viz`: graphviz visualization;
+- `dtest`: dtype_test;
+
+The show messages above "INFO" level (see [Python's logging module](https://docs.python.org/3/library/logging.html)). To show debug level message, add `hydra.verbose=[${keys}]` (also see [hydra.logging](https://hydra.cc/docs/1.2/tutorials/basic/running_your_app/logging/)).
+
+```shell
+# Show debug information related to `fuzz`:
+${NNSMITH_CMD} hydra.verbose=fuzz
+# Show debug info for `fuzz` and `exec`:
+${NNSMITH_CMD} hydra.verbose=[fuzz,exec]
+```
+
+#### Logging things into file
+
+By default, NNSmith logs things in `console` mode where loggings will only be flushed to STDIO.
+
+To log outputs into a file, add flag `hydra/job_logging=file`. The log file will be in [`${hydra.runtime.output_dir}/${hydra.job.name}.log`](https://hydra.cc/docs/1.2/tutorials/basic/running_your_app/working_directory/) (e.g., `output/${DATE}/${JOB_ID}/${APP}.log`).
+
+## Errors
+
+See `nnsmith/error.py`:
+
+- `ConstraintError`: Unsatisfiable constraints which is a hint to re-try;
+- `InternalError`: NNSmith has some internal bugs that should be fixed.
+
+Takeways:
+
+- Catch `ConstraintError` as a hint to re-try graph generation (no satisfiable solution yet);
+- Never catch `InternalError` -- but let the maintainer know the issue and fix it.

nnsmith/cli/fuzz.py

@@ -31,7 +31,6 @@ def __init__(
     ):
         self.cfg = cfg
 
-        self.verbose = cfg["fuzz"]["verbose"]
         self.reporter = Reporter(cfg["fuzz"]["root"])
 
         self.factory = BackendFactory.init(
@@ -70,7 +69,6 @@ def make_testcase(self, seed) -> TestCase:
             seed=seed,
             max_nodes=mgen_cfg["max_nodes"],
             timeout_ms=mgen_cfg["timeout_ms"],
-            verbose=mgen_cfg["verbose"],
         )
 
         fixed_graph, concrete_abstensors = concretize_graph(

nnsmith/cli/model_exec.py

@@ -17,8 +17,8 @@
 from omegaconf import DictConfig, ListConfig
 
 from nnsmith.backends import BackendFactory
+from nnsmith.logging import EXEC_LOG
 from nnsmith.materialize import BugReport, Model, Oracle, TestCase
-from nnsmith.util import fail_print, note_print, succ_print
 
 
 def verify_testcase(
@@ -30,20 +30,19 @@ def verify_testcase(
     def check_result(bug_report_or, msg=None) -> bool:  # succ?
         msg = "" if msg is None else msg
         if not isinstance(bug_report_or, BugReport):
-            if cmp_cfg["verbose"]:
-                succ_print(f"[PASS] {msg}")
+            EXEC_LOG.info(f"[PASS] {msg}")
             return True
         else:
             bug_report = bug_report_or
-            fail_print("[FAIL] ")
-            fail_print(bug_report.log)
+            EXEC_LOG.warn("[FAIL] ")
+            EXEC_LOG.warn(bug_report.log)
             if output_dir is not None:
-                note_print("Saving bug report to {}".format(output_dir))
+                EXEC_LOG.debug("Saving bug report to {}".format(output_dir))
                 bug_report.dump(output_dir)
             return False
 
     bug_or_res = factory.checked_compile_and_exec(testcase)
-    if check_result(bug_or_res, msg="Compile + Execution"):
+    if check_result(bug_or_res, msg=f"Compile + Execution [{factory}]"):
         if testcase.oracle.output is not None:  # we have output results && no bug yet
             # do result verification
             if not check_result(
@@ -52,7 +51,7 @@ def check_result(bug_report_or, msg=None) -> bool:  # succ?
                     testcase,
                     equal_nan=cmp_cfg["equal_nan"],
                 ),
-                msg="Result Verification w/ Oracle",
+                msg=f"Result Verification w/ Oracle from {testcase.oracle.provider}",
             ):
                 return False
     else:
@@ -69,7 +68,7 @@ def check_result(bug_report_or, msg=None) -> bool:  # succ?
         cmp_testcase = cmp_fac.make_testcase(
             testcase.model, input=testcase.oracle.input
         )
-        if check_result(cmp_testcase, "Compile + Execution (`cmp.with`)"):
+        if check_result(cmp_testcase, f"Compile + Execution [`cmp.with`: {cmp_fac}]"):
             if not check_result(
                 factory.verify_results(
                     bug_or_res,
@@ -89,7 +88,7 @@ def check_result(bug_report_or, msg=None) -> bool:  # succ?
 def main(cfg: DictConfig):
     cmp_cfg = cfg["cmp"]
     seed = random.getrandbits(32) if cmp_cfg["seed"] is None else cmp_cfg["seed"]
-    note_print(f"Using seed {seed}")
+    EXEC_LOG.info(f"Using seed {seed}")
 
     model_cfg = cfg["model"]
     ModelType = Model.init(model_cfg["type"])
@@ -119,7 +118,9 @@ def main(cfg: DictConfig):
 
         # 1. Use raw_input as test_inputs if specified;
         if cmp_cfg["raw_input"] is not None:
-            note_print("Using raw input from {} as oracle".format(cmp_cfg["raw_input"]))
+            EXEC_LOG.info(
+                "Using raw input from {} as oracle".format(cmp_cfg["raw_input"])
+            )
             test_inputs = pickle.load(Path(cmp_cfg["raw_input"]).open("rb"))
             assert isinstance(
                 test_inputs, dict
@@ -138,14 +139,14 @@ def main(cfg: DictConfig):
                 oracle_path = cmp_cfg["oracle"]
 
             if oracle_path is not None:
-                note_print("Using oracle from {}".format(oracle_path))
+                EXEC_LOG.info("Using oracle from {}".format(oracle_path))
                 res = pickle.load(Path(oracle_path).open("rb"))
                 test_inputs = res["input"]
                 test_outputs = res["output"]
                 provider = res["provider"]
 
         if test_inputs is None:
-            note_print("Generating input data from BackendFactory.make_random_input")
+            EXEC_LOG.info("Generating input data from BackendFactory.make_random_input")
             test_inputs = BackendFactory.make_random_input(model.input_like)
             provider = f"random inputs"
 

nnsmith/cli/model_gen.py

@@ -1,10 +1,12 @@
+import logging
 import os
 import random
 
 import hydra
 from omegaconf import DictConfig
 
 from nnsmith.graph_gen import concretize_graph, random_model_gen, viz
+from nnsmith.logging import MGEN_LOG
 from nnsmith.materialize import Model, Schedule, TestCase
 from nnsmith.util import mkdir
 
@@ -17,29 +19,26 @@ def main(cfg: DictConfig):
 
     seed = random.getrandbits(32) if mgen_cfg["seed"] is None else mgen_cfg["seed"]
 
-    print(f"Using seed {seed}")
+    MGEN_LOG.info(f"Using seed {seed}")
 
     # TODO(@ganler): skip operators outside of model gen with `cfg[exclude]`
     model_cfg = cfg["model"]
     ModelType = Model.init(model_cfg["type"])
     ModelType.add_seed_setter()
 
-    verbose = mgen_cfg["verbose"]
-
     gen = random_model_gen(
         opset=ModelType.operators(),
         init_rank=mgen_cfg["init_rank"],
         seed=seed,
         max_nodes=mgen_cfg["max_nodes"],
         timeout_ms=mgen_cfg["timeout_ms"],
-        verbose=verbose,
     )
-    print(
+    MGEN_LOG.info(
         f"{len(gen.get_solutions())} symbols and {len(gen.solver.assertions())} constraints."
     )
 
-    if verbose:
-        print("solution:", ", ".join(map(str, gen.get_solutions())))
+    if MGEN_LOG.getEffectiveLevel() <= logging.DEBUG:
+        MGEN_LOG.debug("solution:" + ", ".join(map(str, gen.get_solutions())))
 
     fixed_graph, concrete_abstensors = concretize_graph(
         gen.abstract_graph, gen.tensor_dataflow, gen.get_solutions()

nnsmith/config/hydra/job_logging/console.yaml

@@ -0,0 +1,15 @@
+version: 1
+formatters:
+  colorlog:
+    '()': 'colorlog.ColoredFormatter'
+    format: "%(log_color)s%(levelname)-7s%(reset)s %(purple)s%(name)-6s%(reset)s - %(message)s"
+handlers:
+  console:
+    class: logging.StreamHandler
+    formatter: colorlog
+    stream: ext://sys.stdout
+root:
+  level: INFO
+  handlers: [console]
+
+disable_existing_loggers: false

nnsmith/config/hydra/job_logging/file.yaml

@@ -0,0 +1,21 @@
+version: 1
+formatters:
+  colorlog:
+    '()': 'colorlog.ColoredFormatter'
+    format: "%(log_color)s%(levelname)-7s%(reset)s %(purple)s%(name)-6s%(reset)s - %(message)s"
+  simple:
+    format: '[%(asctime)s][%(name)s][%(levelname)s] - %(message)s'
+handlers:
+  console:
+    class: logging.StreamHandler
+    formatter: colorlog
+    stream: ext://sys.stdout
+  file:
+    class: logging.FileHandler
+    formatter: simple
+    filename: ${hydra.runtime.output_dir}/${hydra.job.name}.log
+root:
+  level: INFO
+  handlers: [console, file]
+
+disable_existing_loggers: false

nnsmith/config/main.yaml

@@ -31,7 +31,6 @@ mgen: # model gen.
   timeout_ms: 50000
   save: "nnsmith_output"
   seed: null
-  verbose: false # WARNING: temporary; later should go categorized logging
 
 # backend config
 backend:
@@ -50,7 +49,6 @@ fuzz:
   time: 14400
   root: "???"
   seed: null
-  verbose: false
 
 cmp:
   equal_nan: true    # skip regarding it as a bug if with fp exception values.
@@ -71,4 +69,6 @@ cmp:
   bug_presence: "report" # or "crash"
   save: null # path to save the bug report if `bug_presence` is "report"
 
-  verbose: false
+defaults:
+  - override hydra/job_logging: console
+  - override hydra/hydra_logging: colorlog

nnsmith/error.py

@@ -1,4 +1,5 @@
-from abc import ABC
+import logging
+from abc import ABC, abstractmethod
 
 
 class InternalError(Exception):
@@ -14,61 +15,67 @@ class ConstraintError(Exception):
 
 
 class BaseChecker(ABC):
-    _EXCEPTION_TYPE = None
+    @classmethod
+    @abstractmethod
+    def handler(cls, msg):
+        pass
 
     @classmethod
     def eq(cls, lhs, rhs, msg=""):
         if lhs != rhs:
-            raise cls._EXCEPTION_TYPE(f"Failed asertion :: {msg} | {lhs} != {rhs}")
+            cls.handler(f"Failed asertion :: {msg} | {lhs} != {rhs}")
 
     @classmethod
     def gt(cls, lhs, rhs, msg=""):
         if lhs <= rhs:
-            raise cls._EXCEPTION_TYPE(f"Failed asertion :: {msg} | {lhs} <= {rhs}")
+            cls.handler(f"Failed asertion :: {msg} | {lhs} <= {rhs}")
 
     @classmethod
     def ge(cls, lhs, rhs, msg=""):
         if lhs < rhs:
-            raise cls._EXCEPTION_TYPE(f"Failed asertion :: {msg} | {lhs} < {rhs}")
+            cls.handler(f"Failed asertion :: {msg} | {lhs} < {rhs}")
 
     @classmethod
     def lt(cls, lhs, rhs, msg=""):
         if lhs >= rhs:
-            raise cls._EXCEPTION_TYPE(f"Failed asertion :: {msg} | {lhs} >= {rhs}")
+            cls.handler(f"Failed asertion :: {msg} | {lhs} >= {rhs}")
 
     @classmethod
     def le(cls, lhs, rhs, msg=""):
         if lhs > rhs:
-            raise cls._EXCEPTION_TYPE(f"Failed asertion :: {msg} | {lhs} > {rhs}")
+            cls.handler(f"Failed asertion :: {msg} | {lhs} > {rhs}")
 
     @classmethod
     def none(cls, obj, msg=""):
         if obj is not None:
-            raise cls._EXCEPTION_TYPE(f"Failed asertion :: {msg} | expr is not None")
+            cls.handler(f"Failed asertion :: {msg} | expr is not None")
 
     @classmethod
     def not_none(cls, obj, msg=""):
         if obj is None:
-            raise cls._EXCEPTION_TYPE(f"Failed asertion :: {msg} | expr is None")
+            cls.handler(f"Failed asertion :: {msg} | expr is None")
 
     @classmethod
     def true(cls, cond, msg=""):
         if not cond:
-            raise cls._EXCEPTION_TYPE(
-                f"Failed asertion :: {msg} | condition is not True"
-            )
+            cls.handler(f"Failed asertion :: {msg} | condition is not True")
 
     @classmethod
     def false(cls, cond, msg=""):
         if cond:
-            raise cls._EXCEPTION_TYPE(
-                f"Failed asertion :: {msg} | condition is not False"
-            )
+            cls.handler(f"Failed asertion :: {msg} | condition is not False")
 
 
 class SanityCheck(BaseChecker):
-    _EXCEPTION_TYPE = InternalError
+    @classmethod
+    def handler(cls, msg):
+        raise ConstraintError(msg)
 
 
 class ConstraintCheck(BaseChecker):
-    _EXCEPTION_TYPE = ConstraintError
+    @classmethod
+    def handler(cls, msg):
+        logging.critical(msg)
+        raise InternalError(
+            msg + " | Reporting bugs @ https://github.com/ise-uiuc/nnsmith/issues"
+        )