diff --git a/cli/medperf/commands/compatibility_test/run.py b/cli/medperf/commands/compatibility_test/run.py index 15f2de04e..31d5020a8 100644 --- a/cli/medperf/commands/compatibility_test/run.py +++ b/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__( diff --git a/cli/medperf/entities/cube.py b/cli/medperf/entities/cube.py index 5b0c66270..d38377421 100644 --- a/cli/medperf/entities/cube.py +++ b/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: diff --git a/cli/medperf/logging/__init__.py b/cli/medperf/logging/__init__.py index 90886122e..a2f50893b 100644 --- a/cli/medperf/logging/__init__.py +++ b/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( diff --git a/cli/medperf/utils.py b/cli/medperf/utils.py index 528806ca9..bc09d84ae 100644 --- a/cli/medperf/utils.py +++ b/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