tune runtime process logger with the external swcli verbose setting

client/starwhale/consts/__init__.py

@@ -7,6 +7,7 @@
 
 ENV_SW_CLI_CONFIG = "SW_CLI_CONFIG"
 ENV_LOG_LEVEL = "SW_LOG_LEVEL"
+ENV_LOG_VERBOSE_COUNT = "SW_LOG_VERBOSE_COUNT"
 ENV_SW_IMAGE_REPO = "SW_IMAGE_REPO"
 # SW_LOCAL_STORAGE env used for generating default swcli config
 # and overriding 'storage.root' swcli config in runtime

client/starwhale/core/runtime/process.py

@@ -9,7 +9,7 @@
 import dill
 
 from starwhale.utils import console
-from starwhale.consts import PythonRunEnv
+from starwhale.consts import PythonRunEnv, ENV_LOG_VERBOSE_COUNT
 from starwhale.base.uri import URI
 from starwhale.base.type import URIType, InstanceType
 from starwhale.utils.venv import (
@@ -57,19 +57,19 @@ def run(self) -> None:
         if not os.path.exists(_pkl_path):
             raise NotFoundError(f"dill file: {_pkl_path}")
 
+        verbose = int(os.environ.get(ENV_LOG_VERBOSE_COUNT, "0"))
         try:
             cmd = [
                 self._get_activate_cmd(),
-                f'{self._prefix_path}/bin/python3 -c \'import dill; dill.load(open("{_pkl_path}", "rb"))()\'',
+                f'{self._prefix_path}/bin/python3 -c \'from starwhale.utils.debug import init_logger; init_logger({verbose}); import dill; dill.load(open("{_pkl_path}", "rb"))()\'',
             ]
             console.print(
                 f":rooster: run process in the python isolated environment(prefix: {self._prefix_path})"
             )
-            # TODO: tune subprocess output with log-level
             check_call(
                 ["bash", "-c", " && ".join(cmd)],
                 env={self.EnvInActivatedProcess: "1"},
-                log=console.print,
+                log=print,
             )
         finally:
             os.unlink(_pkl_path)

client/starwhale/utils/debug.py

@@ -5,7 +5,7 @@
 from rich import traceback
 from loguru import logger
 
-from starwhale.consts import ENV_LOG_LEVEL
+from starwhale.consts import ENV_LOG_LEVEL, ENV_LOG_VERBOSE_COUNT
 
 
 def init_logger(verbose: int) -> None:
@@ -15,16 +15,11 @@ def init_logger(verbose: int) -> None:
     elif verbose == 1:
         lvl = logging.INFO
     else:
-        fmt = (
-            "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | "
-            "<level>{level: <6}</level> | "
-            "<level>{message}</level>"
-        )
         lvl = logging.DEBUG
 
     lvl_name = logging.getLevelName(lvl)
-
     os.environ[ENV_LOG_LEVEL] = lvl_name
+    os.environ[ENV_LOG_VERBOSE_COUNT] = str(verbose)
 
     # TODO: custom debug for tb install
     traceback.install(show_locals=True, max_frames=1, width=200)

client/starwhale/utils/process.py

@@ -1,35 +1,38 @@
 import os
 import typing as t
-from select import select
 from subprocess import PIPE, Popen, STDOUT, CalledProcessError
 
 from loguru import logger
 
 
 def log_check_call(*args: t.Any, **kwargs: t.Any) -> int:
     log = kwargs.pop("log", logger.debug)
+    kwargs["bufsize"] = 1
     kwargs["stdout"] = PIPE
     kwargs["stderr"] = STDOUT
     env = os.environ.copy()
     env.update(kwargs.get("env", {}))
+    env["PYTHONUNBUFFERED"] = "1"
     kwargs["env"] = env
     kwargs["universal_newlines"] = True
-    env["PYTHONUNBUFFERED"] = "1"
 
     output = []
     p = Popen(*args, **kwargs)
-    log(f"cmd: {p.args!r}")
+    logger.debug(f"cmd: {p.args!r}")
+
+    def _print_log() -> None:
+        line = p.stdout.readline()  # type: ignore
+        if line:
+            log(line.rstrip())
+            output.append(line)
+
     while True:
-        fds, _, _ = select([p.stdout], [], [], 30)  # timeout 30s
-        for fd in fds:
-            for line in fd.readlines():
-                log(line.rstrip())
-                output.append(line)
-        else:
-            if p.poll() is not None:
-                break
+        _print_log()
+        if p.poll() is not None:
+            break
 
     p.wait()
+    _print_log()
 
     try:
         p.stdout.close()  # type: ignore

client/tests/utils/test_process.py

@@ -16,9 +16,9 @@ def _log(s: t.Any) -> None:
             log=_log,
         )
 
-        assert len(save_logs) >= 2
+        assert len(save_logs) >= 1
 
         with self.assertRaises(FileNotFoundError):
             log_check_call(["err"])
 
-        assert len(save_logs) >= 2
+        assert len(save_logs) >= 1