Clean up test framework for better logs (gaogaotiantian#211)

* Clean up tests
* Pin pywinpty for py3.6
* Change logsparse multiprocess
* Add more print in attached process to debug
* Make uninstall more stable
* Add nightly validation

.github/workflows/python-package.yml

@@ -8,6 +8,8 @@ on:
     branches: [ master ]
   pull_request:
     branches: [ master ]
+  schedule:
+    - cron: '0 10 * * *'
 
 jobs:
   build:

requirements-dev.txt

@@ -2,6 +2,7 @@ setuptools
 wheel
 twine
 coverage
+pywinpty==1.1.6; python_version < '3.7' and sys_platform == 'win32'
 ipywidgets
 mypy
 loky>=3.0.0

src/viztracer/attach.py

@@ -29,6 +29,8 @@ def start_attach(init_kwargs_b64: str):
         return
     attach_status["attached"] = True
     attach_status["save_path"] = init_kwargs["output_file"]
+    if tracer.verbose > 0:
+        print("Detected attaching viztracer, start tracing.", flush=True)
     tracer.start()
 
 
@@ -37,6 +39,8 @@ def stop_attach():
         tracer: VizTracer = get_tracer()
         tracer.stop()
         tracer.save(attach_status["save_path"])
+        if tracer.verbose > 0:
+            print(f"Saved report to {attach_status['save_path']}", flush=True)
         attach_status["attached"] = False
         if attach_status["created_tracer"]:
             tracer.stop()

src/viztracer/main.py

@@ -479,7 +479,8 @@ def attach(self) -> Tuple[bool, Optional[str]]:
             "pid_suffix": False,
             "file_info": True,
             "register_global": True,
-            "dump_raw": False
+            "dump_raw": False,
+            "verbose": 1 if self.verbose != 0 else 0
         })
         b64s = base64.urlsafe_b64encode(json.dumps(self.init_kwargs).encode("ascii")).decode("ascii")
         start_code = f"import viztracer.attach; viztracer.attach.start_attach(\\\"{b64s}\\\")"

tests/base_tmpl.py

@@ -1,18 +1,31 @@
 # Licensed under the Apache License: http://www.apache.org/licenses/LICENSE-2.0
 # For details: https://github.com/gaogaotiantian/viztracer/blob/master/NOTICE.txt
 
-from unittest import TestCase
 import gc
+import io
+import logging
 import os
+import sys
 import time
+from unittest import TestCase
+
+
+logging.basicConfig(
+    level=logging.INFO,
+    format="%(asctime)s %(levelname)s: %(message)s"
+)
 
 
 class BaseTmpl(TestCase):
     def setUp(self):
-        print("{} start".format(self.id()))
+        logging.info("=" * 60)
+        logging.info(f"{self.id()} start")
+        self.stdout = io.StringIO()
+        self.stdout_orig, sys.stdout = sys.stdout, self.stdout
 
     def tearDown(self):
-        print("{} finish".format(self.id()))
+        sys.stdout = self.stdout_orig
+        logging.info(f"{self.id()} finish")
         gc.collect()
 
     def assertEventNumber(self, data, expected_entries):
@@ -40,7 +53,7 @@ def assertFileExists(self, path, timeout=None, msg=None):
 
     def assertFileNotExist(self, path):
         if os.path.exists(path):
-            raise AssertionError(f"file {path} does not exist!")
+            raise AssertionError(f"file {path} does exist!")
 
     def assertTrueTimeout(self, func, timeout):
         start = time.time()

tests/cmdline_tmpl.py

@@ -2,6 +2,7 @@
 # For details: https://github.com/gaogaotiantian/viztracer/blob/master/NOTICE.txt
 
 import json
+import logging
 import os
 import shutil
 import subprocess
@@ -84,10 +85,14 @@ def template(self,
                     wait_time = 5
                 else:
                     wait_time = 2
-            p = subprocess.Popen(cmd_list)
+            p = subprocess.Popen(cmd_list, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
             time.sleep(wait_time)
             p.send_signal(sig)
-            p.wait()
+            p.wait(timeout=60)
+            stdout, stderr = p.stdout.read(), p.stderr.read()
+            p.stdout.close()
+            p.stderr.close()
+            p.stdout, p.stderr = stdout, stderr
             result = p
             if sys.platform == "win32":
                 # If we are on win32, we can't get anything useful from
@@ -101,12 +106,12 @@ def template(self,
             try:
                 result = subprocess.run(cmd_list, stdout=subprocess.PIPE, stderr=subprocess.PIPE, timeout=timeout)
             except subprocess.TimeoutExpired as e:
-                print(e.stdout, e.stderr)
+                logging.error(f"stdout: {e.stdout}")
+                logging.error(f"stderr: {e.stderr}")
                 raise e
         if not (success ^ (result.returncode != 0)):
-            print(success, result.returncode)
-            print(result.stdout)
-            print(result.stderr)
+            logging.error(f"stdout: {result.stdout.decode('utf-8')}")
+            logging.error(f"stderr: {result.stderr.decode('utf-8')}")
         self.assertTrue(success ^ (result.returncode != 0))
         if success:
             if expected_output_file:

tests/package_env.py

@@ -26,8 +26,8 @@ def package_keeper():
         curr_packages = get_curr_packages()
         for pkg in curr_packages:
             if pkg not in orig_packages:
-                subprocess.check_call([sys.executable, "-m", "pip", "uninstall", "-y", pkg])
-        subprocess.check_call([sys.executable, "-m", "pip", "install", *orig_packages])
+                subprocess.check_call([sys.executable, "-m", "pip", "uninstall", "-y", pkg], stdout=subprocess.DEVNULL)
+        subprocess.check_call([sys.executable, "-m", "pip", "install", *orig_packages], stdout=subprocess.DEVNULL)
 
 
 def setup_env(pkg_matrix):
@@ -38,9 +38,9 @@ def setup_env(pkg_matrix):
     for pkg_config in pkg_config_iter:
         for pkg in pkg_config:
             if pkg.startswith("~"):
-                subprocess.check_call([sys.executable, "-m", "pip", "uninstall", "-y", pkg[1:]])
+                subprocess.check_call([sys.executable, "-m", "pip", "uninstall", "-y", pkg[1:]], stdout=subprocess.DEVNULL)
             else:
-                subprocess.check_call([sys.executable, "-m", "pip", "install", pkg])
+                subprocess.check_call([sys.executable, "-m", "pip", "install", pkg], stdout=subprocess.DEVNULL)
         yield
 
 

tests/test_basic.py

@@ -26,6 +26,7 @@ def fib(n):
                 return 1
             return fib(n - 1) + fib(n - 2)
         t = _VizTracer()
+        t.verbose = 0
         t.start()
         fib(5)
         t.stop()
@@ -39,6 +40,7 @@ def fun(n):
             for _ in range(n):
                 random.randrange(n)
         t = _VizTracer(ignore_c_function=True)
+        t.verbose = 0
         t.start()
         fun(10)
         t.stop()
@@ -51,6 +53,7 @@ def fib(n):
                 return 1
             return fib(n - 1) + fib(n - 2)
         t = _VizTracer()
+        t.verbose = 0
         t.start()
         fib(5)
         t.stop()
@@ -61,20 +64,20 @@ def fib(n):
 
 class TestVizTracerBasic(BaseTmpl):
     def test_run(self):
-        snap = VizTracer()
+        snap = VizTracer(verbose=0)
         snap.run("import random; random.randrange(10)", output_file="test_run.json")
         self.assertTrue(os.path.exists("test_run.json"))
         os.remove("test_run.json")
 
     def test_with(self):
-        with VizTracer(output_file="test_with.json") as _:
+        with VizTracer(output_file="test_with.json", verbose=0) as _:
             fib(10)
         self.assertTrue(os.path.exists("test_with.json"))
         os.remove("test_with.json")
 
         had_exception = False
         try:
-            with VizTracer(output_file="test_with.json"):
+            with VizTracer(output_file="test_with.json", verbose=0):
                 _ = 1 / 0
         except ZeroDivisionError:
             had_exception = True
@@ -107,7 +110,7 @@ def test_save(self):
 
 class TestInstant(BaseTmpl):
     def test_addinstant(self):
-        tracer = VizTracer()
+        tracer = VizTracer(verbose=0)
         tracer.start()
         tracer.add_instant('instant - "karma": True')
         tracer.add_instant('instant', args={"karma": True})
@@ -116,7 +119,7 @@ def test_addinstant(self):
         self.assertEventNumber(tracer.data, 2)
 
     def test_invalid_scope(self):
-        tracer = VizTracer()
+        tracer = VizTracer(verbose=0)
         tracer.start()
         tracer.add_instant('instant - "karma": True', scope="invalid")
         tracer.stop()
@@ -128,7 +131,7 @@ class TestFunctionArg(BaseTmpl):
     def test_addfunctionarg(self):
         def f(tracer):
             tracer.add_func_args("hello", "world")
-        tracer = VizTracer()
+        tracer = VizTracer(verbose=0)
         tracer.start()
         f(tracer)
         tracer.stop()
@@ -140,7 +143,7 @@ def f(tracer):
 
 class TestDecorator(BaseTmpl):
     def test_pause_resume(self):
-        tracer = VizTracer()
+        tracer = VizTracer(verbose=0)
 
         @ignore_function(tracer=tracer)
         def ignore(n):
@@ -162,7 +165,7 @@ def f():
         if "__viz_tracer__" in builtins.__dict__:
             builtins.__dict__.pop("__viz_tracer__")
 
-        tracer = VizTracer(register_global=False)
+        tracer = VizTracer(register_global=False, verbose=0)
 
         tracer.start()
         with self.assertRaises(NameError):
@@ -177,7 +180,7 @@ def test_trace_and_save(self):
             wait = 1
         with tempfile.TemporaryDirectory() as tmp_dir:
 
-            @trace_and_save(output_dir=tmp_dir)
+            @trace_and_save(output_dir=tmp_dir, verbose=0)
             def my_function(n):
                 fib(n)
 
@@ -194,7 +197,7 @@ def t():
 
         with tempfile.TemporaryDirectory() as tmp_dir:
 
-            @trace_and_save(output_dir=os.path.join(tmp_dir, "new_dir"))
+            @trace_and_save(output_dir=os.path.join(tmp_dir, "new_dir"), verbose=0)
             def cover_mkdir():
                 return
 
@@ -231,7 +234,7 @@ def t2():
 
 class TestLogPrint(BaseTmpl):
     def test_log_print(self):
-        tracer = VizTracer(log_print=True)
+        tracer = VizTracer(log_print=True, verbose=0)
         tracer.start()
         print("hello")
         print("hello")
@@ -286,7 +289,7 @@ def test_get_tracer(self):
         with self.assertRaises(NameError):
             _ = __viz_tracer__  # noqa: F821
         self.assertIs(get_tracer(), None)
-        tracer = VizTracer()
+        tracer = VizTracer(verbose=0)
         builtins.__dict__["__viz_tracer__"] = tracer
         self.assertIs(get_tracer(), tracer)
         builtins.__dict__.pop("__viz_tracer__")

tests/test_invalid.py

@@ -24,28 +24,28 @@ def test_invalid_args(self):
             "ignore_frozen": ["hello", 1, "True"],
             "log_async": ["hello", 1, "True"]
         }
-        tracer = VizTracer()
+        tracer = VizTracer(verbose=0)
         for args, vals in invalid_args.items():
             for val in vals:
                 self.assertRaises(ValueError, tracer.__setattr__, args, val)
 
 
 class TestInvalidOperation(BaseTmpl):
     def test_generate_without_data(self):
-        tracer = VizTracer()
+        tracer = VizTracer(verbose=0)
         with self.assertRaises(Exception):
             tracer.generate_json()
 
     def test_save_invalid_format(self):
-        tracer = VizTracer()
+        tracer = VizTracer(verbose=0)
         tracer.start()
         _ = len([1, 2])
         tracer.stop()
         with self.assertRaises(Exception):
             tracer.save("test.invalid")
 
     def test_add_invalid_variable(self):
-        tracer = VizTracer()
+        tracer = VizTracer(verbose=0)
         tracer.start()
         with self.assertRaises(Exception):
             tracer.add_variable("a", 1, event="invalid")

tests/test_logging.py

@@ -11,18 +11,20 @@ def test_handler(self):
         tracer = VizTracer()
         handler = VizLoggingHandler()
         handler.setTracer(tracer)
-        logging.basicConfig(handlers=[handler])
+        logging.getLogger().addHandler(handler)
         tracer.start()
         logging.warning("lol")
         tracer.stop()
         entries = tracer.parse()
         self.assertGreater(entries, 10)
+        self.assertTrue(any([entry["ph"] == "i" for entry in tracer.data["traceEvents"]]))
         logging.getLogger().removeHandler(handler)
 
     def test_notracer(self):
         tracer = VizTracer()
         handler = VizLoggingHandler()
-        logging.basicConfig(handlers=[handler])
+        logging.getLogger().addHandler(handler)
         tracer.start()
         logging.warning("lol")
         tracer.stop()
+        logging.getLogger().removeHandler(handler)

tests/test_logsparse.py

@@ -20,32 +20,21 @@ def g():
 """
 
 
-file_pool = """
-from multiprocessing import Process, Pool
+file_multiprocess = """
+from multiprocessing import Process
 from viztracer import log_sparse
-import os
 import time
 
 @log_sparse
 def f(x):
     return x*x
 
 if __name__ == "__main__":
-    process_num = 2
-    with Pool(processes=process_num) as pool:
-        print(pool.map(f, range(10)))
-
-        for i in pool.imap_unordered(f, range(10)):
-            print(i)
-
-        res = pool.apply_async(f, (20,))      # runs in *only* one process
-        print(res.get(timeout=1))             # prints "400"
-
-        res = pool.apply_async(os.getpid, ()) # runs in *only* one process
-        print(res.get(timeout=1))             # prints the PID of that process
-
-        multiple_results = [pool.apply_async(os.getpid, ()) for i in range(process_num)]
-        print([res.get(timeout=1) for res in multiple_results])
+    for i in range(3):
+        p = Process(target=f, args=(i,))
+        p.start()
+        p.join()
+        time.sleep(0.1)
 """
 
 
@@ -71,9 +60,9 @@ def test_multiprocess(self):
         if multiprocessing.get_start_method() == "fork":
             try:
                 self.template(["viztracer", "-o", "result.json", "--log_sparse", "cmdline_test.py"],
-                              script=file_pool,
+                              script=file_multiprocess,
                               expected_output_file="result.json",
-                              expected_entries=21,
+                              expected_entries=3,
                               concurrency="multiprocessing")
             except Exception as e:
                 # coveragepy has some issue with multiprocess pool