Added filtering on MLCube framework logs

- MLCube Framework debug+info logs are printed to debug file only
- MLCube Framework warning+error logs are printed to stdout + debug file
- Container logs are printed to stdout + debug file

cli/medperf/commands/compatibility_test/run.py

@@ -88,11 +88,12 @@ def run(
         test_exec.prepare_dataset()
         test_exec.initialize_report()
         results = test_exec.cached_results()
-        logging.info('Existing results are found. Test would not be re-executed.')
-        logging.debug(f'Existing results: {results}')
         if results is None:
             results = test_exec.execute()
             test_exec.write(results)
+        else:
+            logging.info('Existing results are found. Test would not be re-executed.')
+            logging.debug(f'Existing results: {results}')
         return test_exec.data_uid, results
 
     def __init__(

cli/medperf/entities/cube.py

@@ -245,8 +245,9 @@ def _set_image_hash_from_registry(self):
         # Retrieve image hash from MLCube
         logging.debug(f"Retrieving {self.id} image hash")
         tmp_out_yaml = generate_tmp_path()
-        cmd = f"mlcube inspect --mlcube={self.cube_path} --format=yaml"
+        cmd = f"mlcube --log-level {config.loglevel} inspect --mlcube={self.cube_path} --format=yaml"
         cmd += f" --platform={config.platform} --output-file {tmp_out_yaml}"
+        logging.info(f"Running MLCube command: {cmd}")
         with pexpect.spawn(cmd, timeout=config.mlcube_inspect_timeout) as proc:
             proc_stdout = proc.read()
         logging.debug(proc_stdout)
@@ -262,9 +263,10 @@ def _set_image_hash_from_registry(self):
     def _get_image_from_registry(self):
         # Retrieve image from image registry
         logging.debug(f"Retrieving {self.id} image")
-        cmd = f"mlcube configure --mlcube={self.cube_path} --platform={config.platform}"
+        cmd = f"mlcube --log-level {config.loglevel} configure --mlcube={self.cube_path} --platform={config.platform}"
         if config.platform == "singularity":
             cmd += f" -Psingularity.image={self._converted_singularity_image_name}"
+        logging.info(f"Running MLCube command: {cmd}")
         with pexpect.spawn(cmd, timeout=config.mlcube_configure_timeout) as proc:
             proc_out = proc.read()
         if proc.exitstatus != 0:
@@ -313,7 +315,7 @@ def run(
             kwargs (dict): additional arguments that are passed directly to the mlcube command
         """
         kwargs.update(string_params)
-        cmd = "mlcube run"
+        cmd = f"mlcube --log-level {config.loglevel} run"
         cmd += f" --mlcube={self.cube_path} --task={task} --platform={config.platform} --network=none"
         if config.gpus is not None:
             cmd += f" --gpus={config.gpus}"
@@ -361,9 +363,9 @@ def run(
         cmd += " -Pplatform.accelerator_count=0"
 
         logging.info(f"Running MLCube command: {cmd}")
-        proc = pexpect.spawn(cmd, timeout=timeout)
-        proc_out = combine_proc_sp_text(proc)
-        proc.close()
+        with pexpect.spawn(cmd, timeout=timeout) as proc:
+            proc_out = combine_proc_sp_text(proc)
+
         if output_logs is None:
             logging.debug(proc_out)
         else:

cli/medperf/logging/__init__.py

@@ -5,7 +5,7 @@
 
 
 def setup_logging(log_file: str, loglevel: str):
-    log_fmt = "%(asctime)s | %(levelname)s: %(message)s"
+    log_fmt = "%(asctime)s | %(module)s.%(funcName)s | %(levelname)s: %(message)s"
     handler = handlers.RotatingFileHandler(log_file, backupCount=20)
     handler.setFormatter(logging.Formatter(log_fmt))
     logging.basicConfig(

cli/medperf/utils.py

@@ -228,6 +228,12 @@ def combine_proc_sp_text(proc: spawn) -> str:
     static_text = ui.text
     proc_out = ""
     break_ = False
+    log_pattern = re.compile(
+        r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} \S+ \S+\[(\d+)\] (DEBUG|INFO) (.*)$"
+    )
+
+    # Clear log lines from color / style symbols before matching with regexp
+    ansi_escape_pattern = re.compile(r'\x1b\[[0-9;]*[mGK]')
     while not break_:
         if not proc.isalive():
             break_ = True
@@ -237,11 +243,29 @@ def combine_proc_sp_text(proc: spawn) -> str:
             logging.error("Process timed out")
             raise ExecutionError("Process timed out")
         line = line.decode("utf-8", "ignore")
-        if line:
+
+        if not line:
+            continue
+
+        match = log_pattern.match(ansi_escape_pattern.sub('', line))
+        line_should_be_filtered = False
+        if match:
+            line_pid, matched_log_level_str, content = match.groups()
+            matched_log_level = logging.getLevelName(matched_log_level_str)
+
+            # if line matches conditions, it is just logged to debug; else, shown to user
+            line_should_be_filtered = (line_pid == str(proc.pid)  # hide only `mlcube` framework logs
+                                       and isinstance(matched_log_level, int)
+                                       and matched_log_level < logging.WARNING)  # hide only debug and info logs
+            # ui.print(
+            #     f"{Fore.WHITE}{Style.DIM}line matched: {line_pid}, {matched_log_level_str}, {matched_log_level}, {line_should_be_filtered}{Style.RESET_ALL}")
+
+        if line_should_be_filtered:
+            logging.debug(line)
+        else:
             proc_out += line
             ui.print(f"{Fore.WHITE}{Style.DIM}{line.strip()}{Style.RESET_ALL}")
             ui.text = static_text
-
     return proc_out