diff --git a/lisa/platform_.py b/lisa/platform_.py index c433a5143e..1504848697 100644 --- a/lisa/platform_.py +++ b/lisa/platform_.py @@ -177,7 +177,7 @@ def prepare_environment(self, environment: Environment) -> Environment: def deploy_environment(self, environment: Environment) -> None: platform_runbook = cast(schema.Platform, self.runbook) - log = get_logger(f"deploy[{environment.name}]", parent=self._log) + log = get_logger("", parent=environment.log) log.info(f"deploying environment: {environment.name}") timer = create_timer() environment.platform = self diff --git a/lisa/runners/lisa_runner.py b/lisa/runners/lisa_runner.py index c9fa1abbc2..1f3bd22d5c 100644 --- a/lisa/runners/lisa_runner.py +++ b/lisa/runners/lisa_runner.py @@ -34,6 +34,7 @@ deep_update_dict, is_unittest, ) +from lisa.util.logger import add_handler, remove_handler from lisa.util.parallel import Task, check_cancelled from lisa.variable import VariableEntry @@ -293,6 +294,8 @@ def _deploy_environment_task( try: try: # Attempt to deploy the environment + log_file_handler = test_results[0].get_log_file_handler() + add_handler(log_file_handler, environment.log) self.platform.deploy_environment(environment) assert ( environment.status == EnvironmentStatus.Deployed @@ -318,6 +321,7 @@ def _deploy_environment_task( result=test_results[0], exception=identifier, ) + remove_handler(log_file_handler, environment.log) self._delete_environment_task(environment=environment, test_results=[]) def _initialize_environment_task( @@ -616,12 +620,14 @@ def _attach_failed_environment_to_result( # so deployment failure can be tracked. environment.platform = self.platform result.environment = environment - result.handle_exception(exception=exception, log=self._log, phase="deployment") + + result.handle_exception(exception=exception, log=result.log, phase="deployment") self._log.info( f"'{environment.name}' attached to test case " f"'{result.runtime_data.metadata.full_name}({result.id_})': " f"{exception}" ) + result.close_log_file_handler() # release environment reference to optimize memory. result.environment = None diff --git a/lisa/testsuite.py b/lisa/testsuite.py index 1e6dbedabd..1c8ef6cdbb 100644 --- a/lisa/testsuite.py +++ b/lisa/testsuite.py @@ -4,6 +4,7 @@ from __future__ import annotations import copy +import logging import traceback from dataclasses import dataclass, field from functools import wraps @@ -83,6 +84,7 @@ class TestResult: check_results: Optional[search_space.ResultReason] = None information: Dict[str, Any] = field(default_factory=dict) log_file: str = "" + _log_file_handler: Optional[logging.FileHandler] = None stacktrace: Optional[str] = None retried_times: int = 0 @@ -91,6 +93,10 @@ def __post_init__(self, *args: Any, **kwargs: Any) -> None: self._timer: Timer self._environment_information: Dict[str, Any] = {} + parent_log = get_logger("suite", self.runtime_data.metadata.suite.name) + self.log = get_logger("case", self.name, parent=parent_log) + self.case_log_path = self.__create_case_log_path() + self._log_file_handler = self.get_log_file_handler() @property def is_queued(self) -> bool: @@ -265,6 +271,32 @@ def check_platform( return result + def get_log_file_handler(self) -> logging.FileHandler: + if not self._log_file_handler: + case_log_file = self.case_log_path / f"{self.case_log_path.name}.log" + self._log_file_handler = create_file_handler(case_log_file, self.log) + self.log_file = case_log_file.relative_to( + constants.RUN_LOCAL_LOG_PATH + ).as_posix() + return self._log_file_handler + + def close_log_file_handler(self) -> None: + if self._log_file_handler: + remove_handler(self._log_file_handler, self.log) + self._log_file_handler.close() + self._log_file_handler = None + + def save_nodes_serial_console_logs(self) -> None: + if not self.environment: + raise LisaException("Environment is not set for saving environment logs") + nodes = self.environment.nodes + for node in nodes.list(): + if hasattr(node, "features") and node.features.is_supported(SerialConsole): + serial_console = node.features[SerialConsole] + log_dir = self.case_log_path / Path(f"serial_console_{node.name}") + log_dir.mkdir(parents=True) + serial_console.get_console_log(log_dir, force_run=True) + def _send_result_message(self, stacktrace: Optional[str] = None) -> None: self.elapsed = self.get_elapsed() @@ -316,6 +348,23 @@ def _send_result_message(self, stacktrace: Optional[str] = None) -> None: notifier.notify(result_message) + @retry(exceptions=FileExistsError, tries=30, delay=0.1) + def __create_case_log_path(self) -> Path: + case_name = self.runtime_data.name + while True: + path = ( + constants.RUN_LOCAL_LOG_PATH + / "tests" + / f"{get_datetime_path()}-{case_name}" + ) + if not path.exists(): + break + sleep(0.1) + # avoid to create folder for UT + if not is_unittest(): + path.mkdir(parents=True) + return path + @dataclass class TestCaseRequirement: @@ -636,18 +685,15 @@ def start( raise LisaException("after_suite is not supported. Please use after_case") # replace to case's logger temporarily for case_result in case_results: - case_name = case_result.runtime_data.name - case_result.environment = environment - case_log = get_logger("case", case_name, parent=self.__log) + case_log = case_result.log + case_log_handler = case_result.get_log_file_handler() + add_handler(case_log_handler, environment.log) + case_log_path = case_result.case_log_path - case_log_path = self.__create_case_log_path(case_name) case_part_path = self.__get_test_part_path(case_log_path) case_working_path = self.__get_case_working_path(case_part_path) case_unique_name = case_log_path.name - case_log_file = case_log_path / f"{case_log_path.name}.log" - case_log_handler = create_file_handler(case_log_file, case_log) - add_handler(case_log_handler, environment.log) case_kwargs = test_kwargs.copy() case_kwargs.update({"case_name": case_unique_name}) @@ -662,9 +708,6 @@ def start( ) is_continue: bool = is_suite_continue total_timer = create_timer() - case_result.log_file = case_log_file.relative_to( - constants.RUN_LOCAL_LOG_PATH - ).as_posix() case_result.set_status(TestStatus.RUNNING, "") # check for positive value just to be clearer @@ -708,7 +751,7 @@ def start( if case_result.status == TestStatus.FAILED: try: - self.__save_serial_log(environment, case_log_path) + case_result.save_nodes_serial_console_logs() except Exception as e: suite_log.debug( f"exception thrown during serial console log read. [{e}]" @@ -717,10 +760,8 @@ def start( case_log.info( f"result: {case_result.status.name}, " f"elapsed: {total_timer}" ) - remove_handler(case_log_handler, case_log) remove_handler(case_log_handler, environment.log) - if case_log_handler: - case_log_handler.close() + case_result.close_log_file_handler() if self._should_stop: suite_log.info("received stop message, stop run") @@ -729,31 +770,6 @@ def start( def stop(self) -> None: self._should_stop = True - def __save_serial_log(self, environment: Environment, log_path: Path) -> None: - nodes = environment.nodes - for node in nodes.list(): - if hasattr(node, "features") and node.features.is_supported(SerialConsole): - serial_console = node.features[SerialConsole] - log_dir = log_path / Path(f"serial_console_{node.name}") - log_dir.mkdir(parents=True) - serial_console.get_console_log(log_dir, force_run=True) - - @retry(exceptions=FileExistsError, tries=30, delay=0.1) - def __create_case_log_path(self, case_name: str) -> Path: - while True: - path = ( - constants.RUN_LOCAL_LOG_PATH - / "tests" - / f"{get_datetime_path()}-{case_name}" - ) - if not path.exists(): - break - sleep(0.1) - # avoid to create folder for UT - if not is_unittest(): - path.mkdir(parents=True) - return path - def __get_test_part_path(self, log_path: Path) -> Path: if is_unittest(): return Path()