From 40d85625f6d3fd0cbab856d11fe3db38e10f9ee1 Mon Sep 17 00:00:00 2001 From: hasan7n Date: Sun, 18 Feb 2024 12:57:01 +0100 Subject: [PATCH 1/5] better mlcube download logging --- cli/medperf/entities/cube.py | 4 ++-- cli/medperf/utils.py | 2 -- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/cli/medperf/entities/cube.py b/cli/medperf/entities/cube.py index 7f76900c3..4fd5ce76c 100644 --- a/cli/medperf/entities/cube.py +++ b/cli/medperf/entities/cube.py @@ -249,7 +249,7 @@ def _set_image_hash_from_registry(self): 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() + proc_stdout = combine_proc_sp_text(proc) logging.debug(proc_stdout) if proc.exitstatus != 0: raise ExecutionError("There was an error while inspecting the image hash") @@ -268,7 +268,7 @@ def _get_image_from_registry(self): 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() + proc_out = combine_proc_sp_text(proc) if proc.exitstatus != 0: raise ExecutionError("There was an error while retrieving the MLCube image") logging.debug(proc_out) diff --git a/cli/medperf/utils.py b/cli/medperf/utils.py index 7406065c9..afb8a01a6 100644 --- a/cli/medperf/utils.py +++ b/cli/medperf/utils.py @@ -255,7 +255,6 @@ def combine_proc_sp_text(proc: spawn) -> str: """ ui = config.ui - static_text = ui.text proc_out = "" break_ = False log_filter = _MLCubeOutputFilter(proc.pid) @@ -278,7 +277,6 @@ def combine_proc_sp_text(proc: spawn) -> str: else: proc_out += line ui.print(f"{Fore.WHITE}{Style.DIM}{line.strip()}{Style.RESET_ALL}") - ui.text = static_text return proc_out From 92e63a9a22b47592a31077da39cf8017acc48fec Mon Sep 17 00:00:00 2001 From: hasan7n Date: Sun, 18 Feb 2024 13:24:00 +0100 Subject: [PATCH 2/5] log mlcube output always --- cli/medperf/entities/cube.py | 10 +++------- cli/medperf/utils.py | 13 +++++++++---- 2 files changed, 12 insertions(+), 11 deletions(-) diff --git a/cli/medperf/entities/cube.py b/cli/medperf/entities/cube.py index 4fd5ce76c..915e15039 100644 --- a/cli/medperf/entities/cube.py +++ b/cli/medperf/entities/cube.py @@ -249,8 +249,7 @@ def _set_image_hash_from_registry(self): 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 = combine_proc_sp_text(proc) - logging.debug(proc_stdout) + combine_proc_sp_text(proc) if proc.exitstatus != 0: raise ExecutionError("There was an error while inspecting the image hash") with open(tmp_out_yaml) as f: @@ -268,10 +267,9 @@ def _get_image_from_registry(self): 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 = combine_proc_sp_text(proc) + combine_proc_sp_text(proc) if proc.exitstatus != 0: raise ExecutionError("There was an error while retrieving the MLCube image") - logging.debug(proc_out) def download_config_files(self): try: @@ -366,9 +364,7 @@ def run( 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: + if output_logs is not None: with open(output_logs, "w") as f: f.write(proc_out) if proc.exitstatus != 0: diff --git a/cli/medperf/utils.py b/cli/medperf/utils.py index afb8a01a6..2714f97f0 100644 --- a/cli/medperf/utils.py +++ b/cli/medperf/utils.py @@ -266,17 +266,22 @@ def combine_proc_sp_text(proc: spawn) -> str: line = proc.readline() except TIMEOUT: logging.error("Process timed out") + logging.debug(proc_out) raise ExecutionError("Process timed out") line = line.decode("utf-8", "ignore") if not line: continue - if log_filter.check_line(line): - logging.debug(line) - else: - proc_out += line + # Always log each line just in case the final proc_out + # wasn't logged for some reason + logging.debug(line) + proc_out += line + if not log_filter.check_line(line): ui.print(f"{Fore.WHITE}{Style.DIM}{line.strip()}{Style.RESET_ALL}") + + logging.debug("MLCube process finished") + logging.debug(proc_out) return proc_out From 498fc9c89a0953608d157ee9d0816f67a49de0eb Mon Sep 17 00:00:00 2001 From: Viacheslav Kukushkin Date: Mon, 19 Feb 2024 20:35:12 +0300 Subject: [PATCH 3/5] Rewritten combine_proc_sp_text to read & print new output on \r also Previously we were reading lines separated by \n; now \r also separates a new line to be read --- cli/medperf/ui/cli.py | 12 ++++-- cli/medperf/ui/interface.py | 14 +++---- cli/medperf/ui/stdin.py | 7 +++- cli/medperf/utils.py | 80 ++++++++++++++++++++++--------------- 4 files changed, 68 insertions(+), 45 deletions(-) diff --git a/cli/medperf/ui/cli.py b/cli/medperf/ui/cli.py index 4270e7efc..20cb76ab0 100644 --- a/cli/medperf/ui/cli.py +++ b/cli/medperf/ui/cli.py @@ -11,13 +11,14 @@ def __init__(self): self.spinner = yaspin(color="green") self.is_interactive = False - def print(self, msg: str = ""): + def print(self, msg: str = "", nl: bool = True): """Display a message on the command line Args: msg (str): message to print + nl: if print a new line after message """ - self.__print(msg) + self.__print(msg, nl=nl) def print_error(self, msg: str): """Display an error message on the command line @@ -38,11 +39,14 @@ def print_warning(self, msg: str): msg = typer.style(msg, fg=typer.colors.YELLOW, bold=True) self.__print(msg) - def __print(self, msg: str = ""): + def __print(self, msg: str = "", nl: bool = True): if self.is_interactive: + # TODO: nl does not work for yaspin as new-line character + # is explicitly hardcoded in spinner.write() self.spinner.write(msg) else: - typer.echo(msg) + # pass + typer.echo(msg, nl=nl) def start_interactive(self): """Start an interactive session where messages can be overwritten diff --git a/cli/medperf/ui/interface.py b/cli/medperf/ui/interface.py index 8994e63cc..be5888e95 100644 --- a/cli/medperf/ui/interface.py +++ b/cli/medperf/ui/interface.py @@ -1,10 +1,12 @@ -from abc import ABC, abstractmethod +from abc import ABC, abstractmethod, abstractproperty from contextlib import contextmanager class UI(ABC): + is_interactive: bool = False + @abstractmethod - def print(self, msg: str = ""): + def print(self, msg: str = "", nl: bool = True): """Display a message to the interface. If on interactive session overrides previous message """ @@ -33,19 +35,17 @@ def stop_interactive(self): def interactive(self): """Context managed interactive session. Expected to yield the same instance""" + @property @abstractmethod - def text(self, msg: str): + def text(self): """Displays a messages that overwrites previous messages if they were created during an interactive session. If not supported or not on an interactive session, it is expected to fallback to the UI print function. - - Args: - msg (str): message to display """ @abstractmethod - def prompt(msg: str) -> str: + def prompt(self, msg: str) -> str: """Displays a prompt to the user and waits for an answer""" @abstractmethod diff --git a/cli/medperf/ui/stdin.py b/cli/medperf/ui/stdin.py index 8e459832b..795f552b6 100644 --- a/cli/medperf/ui/stdin.py +++ b/cli/medperf/ui/stdin.py @@ -11,8 +11,8 @@ class StdIn(UI): hidden prompts and interactive prints will not work as expected. """ - def print(self, msg: str = ""): - return print(msg) + def print(self, msg: str = "", nl: bool = True): + return print(msg, end='\n' if nl else '') def print_error(self, msg: str): return self.print(msg) @@ -40,3 +40,6 @@ def prompt(self, msg: str) -> str: def hidden_prompt(self, msg: str) -> str: return self.prompt(msg) + + def print_highlight(self, msg: str = ""): + self.print(msg) diff --git a/cli/medperf/utils.py b/cli/medperf/utils.py index 2714f97f0..57af9a609 100644 --- a/cli/medperf/utils.py +++ b/cli/medperf/utils.py @@ -17,9 +17,11 @@ from pydantic.datetime_parse import parse_datetime from typing import List from colorama import Fore, Style -from pexpect.exceptions import TIMEOUT +from pexpect.exceptions import TIMEOUT, EOF import medperf.config as config from medperf.exceptions import ExecutionError, MedperfException, InvalidEntityError +from medperf.ui.cli import CLI +from medperf.ui.interface import UI def get_file_hash(path: str) -> str: @@ -215,7 +217,7 @@ def dict_pretty_print(in_dict: dict, skip_none_values: bool = True): class _MLCubeOutputFilter: def __init__(self, proc_pid: int): self.log_pattern = re.compile( - r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} \S+ \S+\[(\d+)\] (\S+) (.*)$" + r"^\s*\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} \S+ \S+\[(\d+)\] (\S+) (.*)$" ) # Clear log lines from color / style symbols before matching with regexp self.ansi_escape_pattern = re.compile(r'\x1b\[[0-9;]*[mGK]') @@ -229,15 +231,17 @@ def check_line(self, line: str) -> bool: true if line should be filtered out (==saved to debug file only), false if line should be printed to user also """ - match = self.log_pattern.match(self.ansi_escape_pattern.sub('', line)) + clean_line = self.ansi_escape_pattern.sub('', line) + match = self.log_pattern.match(clean_line) 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 - return (line_pid == self.proc_pid # hide only `mlcube` framework logs - and isinstance(matched_log_level, int) - and matched_log_level < logging.INFO) # hide only debug logs + result = (line_pid == self.proc_pid # hide only `mlcube` framework logs + and isinstance(matched_log_level, int) + and matched_log_level < logging.INFO) # hide only debug logs + return result return False @@ -254,35 +258,47 @@ def combine_proc_sp_text(proc: spawn) -> str: str: all non-carriage-return-ending string captured from proc """ - ui = config.ui + def _read_new_line_from_proc(proc): + buffer: list[bytes] = [] + new_lines = {'\r', '\n'} + try: + while ch := proc.read(1): + + if ch.decode('utf-8', 'ignore') in new_lines: + res = b''.join(buffer).decode('utf-8') + buffer = [] + yield res + buffer.append(ch) + except EOF: + yield b''.join(buffer).decode('utf-8') + + ui: UI = config.ui + ui_was_interactive = ui.is_interactive + ui.stop_interactive() proc_out = "" - break_ = False log_filter = _MLCubeOutputFilter(proc.pid) - while not break_: - if not proc.isalive(): - break_ = True - try: - line = proc.readline() - except TIMEOUT: - logging.error("Process timed out") - logging.debug(proc_out) - raise ExecutionError("Process timed out") - line = line.decode("utf-8", "ignore") - - if not line: - continue - - # Always log each line just in case the final proc_out - # wasn't logged for some reason - logging.debug(line) - proc_out += line - if not log_filter.check_line(line): - ui.print(f"{Fore.WHITE}{Style.DIM}{line.strip()}{Style.RESET_ALL}") - - logging.debug("MLCube process finished") - logging.debug(proc_out) - return proc_out + try: + for line in _read_new_line_from_proc(proc): + if not line: + break + + # Always log each line just in case the final proc_out + # wasn't logged for some reason + logging.debug(line) + proc_out += line + if not log_filter.check_line(line): + ui.print(f"{Fore.WHITE}{Style.DIM}{line}{Style.RESET_ALL}", nl=False) + + logging.debug("MLCube process finished") + return proc_out + except TIMEOUT: + logging.error("Process timed out") + raise ExecutionError("Process timed out") + finally: + logging.debug(proc_out) + if ui_was_interactive: + ui.start_interactive() def get_folders_hash(paths: List[str]) -> str: From 7f2649914fa377fa1b2ea51cc27b9f40df74e9cc Mon Sep 17 00:00:00 2001 From: Viacheslav Kukushkin Date: Mon, 19 Feb 2024 21:10:52 +0300 Subject: [PATCH 4/5] Fixed tests for new-line print param --- cli/medperf/tests/ui/test_cli.py | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/cli/medperf/tests/ui/test_cli.py b/cli/medperf/tests/ui/test_cli.py index d9fe82663..5ccad2afb 100644 --- a/cli/medperf/tests/ui/test_cli.py +++ b/cli/medperf/tests/ui/test_cli.py @@ -21,7 +21,18 @@ def test_print_displays_message_through_typer(self, mocker, cli, msg): cli.print(msg) # Assert - spy.assert_called_once_with(msg) + spy.assert_called_once_with(msg, nl=True) + + @pytest.mark.parametrize("nl", [True, False]) + def test_print_typer_new_line(self, mocker, cli, msg, nl): + # Arrange + spy = mocker.patch("typer.echo") + + # Act + cli.print(msg, nl=nl) + + # Assert + spy.assert_called_once_with(msg, nl=nl) def test_print_displays_message_through_yaspin_when_interactive( self, mocker, cli, msg From 2b106ea4cdf294b3b8f2f99cf2d688d5f264abe5 Mon Sep 17 00:00:00 2001 From: Viacheslav Kukushkin Date: Fri, 23 Feb 2024 16:18:05 +0300 Subject: [PATCH 5/5] Linter fixes --- cli/medperf/ui/interface.py | 2 +- cli/medperf/utils.py | 35 ++++++++++++++++++----------------- 2 files changed, 19 insertions(+), 18 deletions(-) diff --git a/cli/medperf/ui/interface.py b/cli/medperf/ui/interface.py index be5888e95..3c6903d19 100644 --- a/cli/medperf/ui/interface.py +++ b/cli/medperf/ui/interface.py @@ -1,4 +1,4 @@ -from abc import ABC, abstractmethod, abstractproperty +from abc import ABC, abstractmethod from contextlib import contextmanager diff --git a/cli/medperf/utils.py b/cli/medperf/utils.py index 6b1e0717e..bc11a6f80 100644 --- a/cli/medperf/utils.py +++ b/cli/medperf/utils.py @@ -16,13 +16,12 @@ from pexpect import spawn from datetime import datetime from pydantic.datetime_parse import parse_datetime -from typing import List +from typing import List, Generator from colorama import Fore, Style from pexpect.exceptions import TIMEOUT, EOF from git import Repo, GitCommandError import medperf.config as config from medperf.exceptions import ExecutionError, MedperfException, InvalidEntityError -from medperf.ui.cli import CLI from medperf.ui.interface import UI @@ -247,6 +246,21 @@ def check_line(self, line: str) -> bool: return False +def _read_new_line_from_proc(proc: spawn) -> Generator[str]: + buffer: list[bytes] = [] + new_lines = {'\r', '\n'} + try: + while ch := proc.read(1): + + if ch.decode('utf-8', 'ignore') in new_lines: + res = b''.join(buffer).decode('utf-8') + buffer = [] + yield res + buffer.append(ch) + except EOF: + yield b''.join(buffer).decode('utf-8') + + def combine_proc_sp_text(proc: spawn) -> str: """Combines the output of a process and the spinner. Joins any string captured from the process with the @@ -260,20 +274,6 @@ def combine_proc_sp_text(proc: spawn) -> str: str: all non-carriage-return-ending string captured from proc """ - def _read_new_line_from_proc(proc): - buffer: list[bytes] = [] - new_lines = {'\r', '\n'} - try: - while ch := proc.read(1): - - if ch.decode('utf-8', 'ignore') in new_lines: - res = b''.join(buffer).decode('utf-8') - buffer = [] - yield res - buffer.append(ch) - except EOF: - yield b''.join(buffer).decode('utf-8') - ui: UI = config.ui ui_was_interactive = ui.is_interactive ui.stop_interactive() @@ -293,7 +293,6 @@ def _read_new_line_from_proc(proc): ui.print(f"{Fore.WHITE}{Style.DIM}{line}{Style.RESET_ALL}", nl=False) logging.debug("MLCube process finished") - return proc_out except TIMEOUT: logging.error("Process timed out") raise ExecutionError("Process timed out") @@ -302,6 +301,8 @@ def _read_new_line_from_proc(proc): if ui_was_interactive: ui.start_interactive() + return proc_out + def get_folders_hash(paths: List[str]) -> str: """Generates a hash for all the contents of the fiven folders. This procedure