add statistics and test result for test progress

1. add statistics and test result for test case progress
2. inherit from unittest to get all assert methods
3. add perf_timer for profiling, and improve current profiling
4. add document for tool.py
5. add init.py for mypy checking
6. other minor improvements

examples/testsuites/withscript.py

@@ -35,4 +35,7 @@ class WithScript(TestSuite):
         node = self.environment.default_node
         script: CustomScript = node.get_tool(self._echo_script)
         result = script.run()
-        log.info(f"result stdout: {result.stdout}")
+        log.info(f"result1 stdout: {result.stdout}")
+        # the second time should be faster, without uploading
+        result = script.run()
+        log.info(f"result2 stdout: {result.stdout}")

lisa/core/customScript.py

@@ -178,6 +178,8 @@ class CustomScriptBuilder:
         self.name = f"custom_{command_identifier}_{hash_result.hexdigest()}"
 
     def build(self, node: Node) -> CustomScript:
-        return CustomScript(
+        script = CustomScript(
             self.name, node, self._local_rootpath, self._files, self._command
         )
+        script.initialize()
+        return script

lisa/core/decorator/testCaseMetadata.py

@@ -1,8 +1,6 @@
-from timeit import default_timer as timer
 from typing import Callable, Optional
 
 from lisa.core.testFactory import TestFactory
-from lisa.util.logger import log
 
 
 class TestCaseMetadata:
@@ -15,10 +13,6 @@ class TestCaseMetadata:
         factory.add_method(func, self._description, self._priority)
 
         def wrapper(*args: object) -> None:
-            log.info(f"case '{func.__name__}' started")
-            start = timer()
             func(*args)
-            end = timer()
-            log.info(f"case '{func.__name__}' ended with {end - start:.3f} sec")
 
         return wrapper

lisa/core/decorator/testSuiteMetadata.py

@@ -8,6 +8,7 @@ from lisa.core.testSuite import TestSuite
 if TYPE_CHECKING:
     from lisa.core.environment import Environment
     from lisa.core.testFactory import TestSuiteData
+    from lisa.core.testResult import TestResult
 
 
 class TestSuiteMetadata:
@@ -39,7 +40,7 @@ class TestSuiteMetadata:
         def wrapper(
             test_class: Type[TestSuite],
             environment: Environment,
-            cases: List[str],
+            cases: List[TestResult],
             metadata: TestSuiteData,
         ) -> TestSuite:
             return test_class(environment, cases, metadata)

lisa/core/node.py

@@ -12,6 +12,7 @@ from lisa.util.connectionInfo import ConnectionInfo
 from lisa.util.exceptions import LisaException
 from lisa.util.executableResult import ExecutableResult
 from lisa.util.logger import log
+from lisa.util.perf_timer import create_timer
 from lisa.util.process import Process
 from lisa.util.shell import Shell
 
@@ -45,7 +46,7 @@ class Node:
         self._tools: Dict[str, Tool] = dict()
 
         self._is_initialized: bool = False
-        self._isLinux: bool = True
+        self._is_linux: bool = True
 
     @staticmethod
     def create(
@@ -124,22 +125,23 @@ class Node:
         tool = self._tools.get(tool_key)
         if tool is None:
             # the Tool is not installed on current node, try to install it.
-            tool_prefix = f"tool '{tool_key}'"
+            tool_prefix = f"tool[{tool_key}]"
             log.debug(f"{tool_prefix} is initializing")
 
             if isinstance(tool_type, CustomScriptBuilder):
-                tool_key = tool_type.name
                 tool = tool_type.build(self)
             else:
-                tool_key = tool_type.__name__
                 cast_tool_type = cast(Type[Tool], tool_type)
                 tool = cast_tool_type(self)
+                tool.initialize()
 
             if not tool.is_installed:
                 log.debug(f"{tool_prefix} is not installed")
                 if tool.can_install:
                     log.debug(f"{tool_prefix} installing")
+                    timer = create_timer()
                     is_success = tool.install()
+                    log.debug(f"{tool_prefix} installed in {timer}")
                     if not is_success:
                         raise LisaException(f"{tool_prefix} install failed")
                 else:
@@ -191,7 +193,7 @@ class Node:
     @property
     def is_linux(self) -> bool:
         self._initialize()
-        return self._isLinux
+        return self._is_linux
 
     def _initialize(self) -> None:
         if not self._is_initialized:
@@ -207,8 +209,8 @@ class Node:
                 self.operating_system,
             ) = uname.get_linux_information(no_error_log=True)
             if (not self.kernel_release) or ("Linux" not in self.operating_system):
-                self._isLinux = False
-            if self._isLinux:
+                self._is_linux = False
+            if self._is_linux:
                 log.info(
                     f"initialized Linux node '{self.name}', "
                     f"kernelRelease: {self.kernel_release}, "

lisa/core/testResult.py

@@ -0,0 +1,18 @@
+from __future__ import annotations
+
+from dataclasses import dataclass
+from enum import Enum
+from typing import TYPE_CHECKING
+
+if TYPE_CHECKING:
+    from lisa.core.testFactory import TestCaseData
+
+TestStatus = Enum("TestStatus", ["NOTRUN", "RUNNING", "FAILED", "PASSED", "SKIPPED"])
+
+
+@dataclass
+class TestResult:
+    case: TestCaseData
+    status: TestStatus = TestStatus.NOTRUN
+    elapsed: float = 0
+    errorMessage: str = ""

lisa/core/testSuite.py

@@ -1,26 +1,31 @@
 from __future__ import annotations
 
+import unittest
 from abc import ABCMeta
 from typing import TYPE_CHECKING, List
 
 from lisa.core.action import Action
 from lisa.core.actionStatus import ActionStatus
+from lisa.core.testResult import TestResult, TestStatus
 from lisa.util.logger import log
+from lisa.util.perf_timer import create_timer
 
 if TYPE_CHECKING:
     from lisa.core.environment import Environment
     from lisa.core.testFactory import TestSuiteData
 
 
-class TestSuite(Action, metaclass=ABCMeta):
+class TestSuite(Action, unittest.TestCase, metaclass=ABCMeta):
     def __init__(
-        self, environment: Environment, cases: List[str], testsuite_data: TestSuiteData,
+        self,
+        environment: Environment,
+        case_results: List[TestResult],
+        testsuite_data: TestSuiteData,
     ) -> None:
         self.environment = environment
         # test cases to run, must be a test method in this class.
-        self.cases = cases
+        self.case_results = case_results
         self.testsuite_data = testsuite_data
-
         self._should_stop = False
 
     @property
@@ -44,20 +49,70 @@ class TestSuite(Action, metaclass=ABCMeta):
         return "TestSuite"
 
     async def start(self) -> None:
+        suite_prefix = f"suite[{self.testsuite_data.name}]"
         if self.skiprun:
-            log.info(f"suite[{self.testsuite_data.name}] skipped on this run")
+            log.info(f"{suite_prefix} skipped on this run")
+            for case_result in self.case_results:
+                case_result.status = TestStatus.SKIPPED
             return
+
+        timer = create_timer()
         self.before_suite()
-        for test_case in self.cases:
-            self.before_case()
-            test_method = getattr(self, test_case)
-            test_method()
-            self.after_case()
+        log.debug(f"{suite_prefix} before_suite end with {timer}")
+
+        for case_result in self.case_results:
+            case_name = case_result.case.name
+            case_prefix = f"case[{self.testsuite_data.name}.{case_name}]"
+            test_method = getattr(self, case_name)
+
+            log.info(f"{case_prefix} started")
+            is_continue: bool = True
+            total_timer = create_timer()
+
+            timer = create_timer()
+            try:
+                self.before_case()
+            except Exception as identifier:
+                log.error(f"{case_prefix} before_case failed {identifier}")
+                is_continue = False
+            case_result.elapsed = timer.elapsed()
+            log.debug(f"{case_prefix} before_case end with {timer}")
+
+            if is_continue:
+                timer = create_timer()
+                try:
+                    test_method()
+                    case_result.status = TestStatus.PASSED
+                except Exception as identifier:
+                    log.error(f"{case_prefix} failed {identifier}")
+                    case_result.status = TestStatus.FAILED
+                    case_result.errorMessage = str(identifier)
+                case_result.elapsed = timer.elapsed()
+                log.debug(f"{case_prefix} method end with {timer}")
+            else:
+                case_result.status = TestStatus.SKIPPED
+                case_result.errorMessage = f"{case_prefix} skipped as beforeCase failed"
+
+            timer = create_timer()
+            try:
+                self.after_case()
+            except Exception as identifier:
+                log.error(f"{case_prefix} after_case failed {identifier}")
+            log.debug(f"{case_prefix} after_case end with {timer}")
+
+            case_result.elapsed = total_timer.elapsed()
+            log.info(
+                f"{case_prefix} result: {case_result.status.name}, "
+                f"elapsed: {total_timer}"
+            )
             if self._should_stop:
                 log.info("received stop message, stop run")
                 self.set_status(ActionStatus.STOPPED)
                 break
+
+        timer = create_timer()
         self.after_suite()
+        log.debug(f"{suite_prefix} after_suite end with {timer}")
 
     async def stop(self) -> None:
         self.set_status(ActionStatus.STOPPING)

lisa/core/tool.py

@@ -12,39 +12,102 @@ if TYPE_CHECKING:
 
 
 class Tool(ABC):
+    """
+    The base class, which wraps an executable, package, or scripts on a node.
+    A tool can be installed, and execute on a node. When a tool is needed, call
+    Node.getTool() to get one object. The getTool checks if it's installed. If it's
+    not installed, then check if it can be installed, and then install or fail.
+    After the tool instance returned, the run/Async of the tool will call
+    execute/Async of node. So that the command passes to current node.
+
+    The must be implemented methods are marked with @abstractmethod, includes
+    command: it's the command name, like echo, ntttcp. it uses in run/Async to run it,
+             and isInstalledInternal to check if it's installed.
+
+    The should be implemented methods throws NotImplementedError, but not marked as
+    abstract method, includes,
+    canInstall: specify if a tool can be installed or not. If a tool is not builtin, it
+                must implement this method.
+    installInternal: If a tool is not builtin, it must implement this method. This
+                     method needs to install a tool, and make sure it can be detected
+                     by isInstalledInternal.
+
+    The may be implemented methods is empty, includes
+    initialize: It's called when a tool is created, and before to call any other
+                methods. It can be used to initialize variables or time-costing
+                operations.
+    dependencies: All dependented tools, they will be checked and installed before
+                  current tool installed. For example, ntttcp uses git to clone code
+                  and build. So it depends on Git tool.
+
+    See details on method descriptions.
+    """
+
     def __init__(self, node: Node) -> None:
+        """
+        It's not recommended to replace this __init__ method. Anything need to be
+        initialized, should be in initialize() method.
+        """
         self.node: Node = node
-        self.initialize()
-
-        self._isInstalled: Optional[bool] = None
-
-    def initialize(self) -> None:
-        pass
-
-    @property
-    def name(self) -> str:
-        return self.__class__.__name__
-
-    @property
-    def dependencies(self) -> List[Type[Tool]]:
-        """
-        declare all dependencies here
-        they can be batch check and installed.
-        """
-        return []
+        # triple states, None means not checked.
+        self._is_installed: Optional[bool] = None
 
     @property
     @abstractmethod
     def command(self) -> str:
+        """
+        Return command string, which can be run in console. For example, echo.
+        The command can be different under different conditions. For example,
+        package management is 'yum' on CentOS, but 'apt' on Ubuntu.
+        """
         raise NotImplementedError()
 
     @property
-    @abstractmethod
     def can_install(self) -> bool:
+        """
+        Indicates if the tool supports installation or not. If it can return true,
+        installInternal must be implemented.
+        """
         raise NotImplementedError()
 
+    def _install_internal(self) -> bool:
+        """
+        Execute installation process like build, install from packages. If other tools
+        are dependented, specify them in dependencies. Other tools can be used here,
+        refer to ntttcp implementation.
+        """
+        raise NotImplementedError()
+
+    def initialize(self) -> None:
+        """
+        Declare and initialize variables here, or some time costing initialization.
+        This method is called before other methods, when initialing on a node.
+        """
+        pass
+
+    @property
+    def dependencies(self) -> List[Type[Tool]]:
+        """
+        Declare all dependencies here, it can be other tools, but prevent to be a
+        circle dependency. The depdendented tools are checked and installed firstly.
+        """
+        return []
+
+    @property
+    def name(self) -> str:
+        """
+        Unique name to a tool and used as path of tool. Don't change it, or there may
+        be unpredictable behavior.
+        """
+        return self.__class__.__name__
+
     @property
     def _is_installed_internal(self) -> bool:
+        """
+        Default implementation to check if a tool exists. This method is called by
+        isInstalled, and cached result. Builtin tools can override it can return True
+        directly to save time.
+        """
         if self.node.is_linux:
             where_command = "command -v"
         else:
@@ -52,20 +115,27 @@ class Tool(ABC):
         result = self.node.execute(
             f"{where_command} {self.command}", shell=True, no_info_log=True
         )
-        self._isInstalled = result.exit_code == 0
-        return self._isInstalled
+        self._is_installed = result.exit_code == 0
+        return self._is_installed
 
     @property
     def is_installed(self) -> bool:
+        """
+        Return if a tool installed. In most cases, overriding inInstalledInternal is
+        enough. But if want to disable cached result and check tool every time,
+        override this method. Notice, remote operations take times, that why caching is
+        necessary.
+        """
         # the check may need extra cost, so cache it's result.
-        if self._isInstalled is None:
-            self._isInstalled = self._is_installed_internal
-        return self._isInstalled
-
-    def _install_internal(self) -> bool:
-        raise NotImplementedError()
+        if self._is_installed is None:
+            self._is_installed = self._is_installed_internal
+        return self._is_installed
 
     def install(self) -> bool:
+        """
+        Default behavior of install a tool, including dependencies. It doesn't need to
+        be overrided.
+        """
         # check dependencies
         for dependency in self.dependencies:
             self.node.get_tool(dependency)
@@ -80,7 +150,14 @@ class Tool(ABC):
         no_info_log: bool = False,
         cwd: Optional[pathlib.PurePath] = None,
     ) -> Process:
-        command = f"{self.command} {parameters}"
+        """
+        Run a command async and return the Process. The process is used for async, or
+        kill directly.
+        """
+        if parameters:
+            command = f"{self.command} {parameters}"
+        else:
+            command = self.command
         process = self.node.executeasync(
             command, shell, no_error_log=no_error_log, cwd=cwd, no_info_log=no_info_log,
         )
@@ -94,6 +171,9 @@ class Tool(ABC):
         no_info_log: bool = False,
         cwd: Optional[pathlib.PurePath] = None,
     ) -> ExecutableResult:
+        """
+        Run a process and wait for result.
+        """
         process = self.runasync(
             parameters=parameters,
             shell=shell,

lisa/test_runner/lisarunner.py

@@ -1,9 +1,10 @@
-from typing import cast
+from typing import Dict, List, cast
 
 from lisa.core.actionStatus import ActionStatus
 from lisa.core.environmentFactory import EnvironmentFactory
 from lisa.core.platform import Platform
-from lisa.core.testFactory import TestFactory
+from lisa.core.testFactory import TestFactory, TestSuiteData
+from lisa.core.testResult import TestResult, TestStatus
 from lisa.core.testRunner import TestRunner
 from lisa.core.testSuite import TestSuite
 from lisa.util import constants
@@ -29,6 +30,17 @@ class LISARunner(TestRunner):
         test_factory = TestFactory()
         suites = test_factory.suites
 
+        # select test cases
+        test_cases_results: List[TestResult] = []
+        test_suites: Dict[TestSuiteData, List[TestResult]] = dict()
+        for test_suite_data in suites.values():
+            for test_case_data in test_suite_data.cases.values():
+                test_result = TestResult(case=test_case_data)
+                test_cases_results.append(test_result)
+                test_suite_cases = test_suites.get(test_case_data.suite, [])
+                test_suite_cases.append(test_result)
+                test_suites[test_case_data.suite] = test_suite_cases
+
         environment_factory = EnvironmentFactory()
         platform_type = self.platform.platform_type()
         # request environment
@@ -36,11 +48,26 @@ class LISARunner(TestRunner):
         environment = environment_factory.get_environment()
         log.info(f"platform {platform_type} environment requested")
 
-        for test_suite_data in suites.values():
+        log.info(f"start running {len(test_cases_results)} cases")
+        for test_suite_data in test_suites:
             test_suite: TestSuite = test_suite_data.test_class(
-                environment, list(test_suite_data.cases.keys()), test_suite_data
+                environment, test_suites.get(test_suite_data, []), test_suite_data
             )
-            await test_suite.start()
+            try:
+                await test_suite.start()
+            except Exception as identifier:
+                log.error(f"suite[{test_suite_data}] failed: {identifier}")
+
+        result_count_dict: Dict[TestStatus, int] = dict()
+        for result in test_cases_results:
+            result_count = result_count_dict.get(result.status, 0)
+            result_count += 1
+            result_count_dict[result.status] = result_count
+
+        log.info("result summary")
+        log.info(f"    TOTAL\t: {len(test_cases_results)} ")
+        for key in TestStatus:
+            log.info(f"    {key.name}\t: {result_count_dict.get(key, 0)} ")
 
         # delete enviroment after run
         log.info(f"platform {platform_type} environment {environment.name} deleting")

lisa/tool/echo.py

@@ -9,10 +9,6 @@ class Echo(Tool):
             command = "cmd /c echo"
         return command
 
-    @property
-    def can_install(self) -> bool:
-        return False
-
     @property
     def _is_installed_internal(self) -> bool:
         return True

lisa/tool/ntttcp.py

@@ -23,7 +23,7 @@ class Ntttcp(Tool):
             can_install = True
         return can_install
 
-    def install(self) -> bool:
+    def _install_internal(self) -> bool:
         tool_path = self.node.get_tool_path(self)
         self.node.shell.mkdir(tool_path)
         git = self.node.get_tool(Git)

lisa/tool/uname.py

@@ -24,10 +24,6 @@ class Uname(Tool):
     def command(self) -> str:
         return "uname"
 
-    @property
-    def can_install(self) -> bool:
-        return False
-
     @property
     def _is_installed_internal(self) -> bool:
         return True

lisa/util/perf_timer.py

@@ -0,0 +1,20 @@
+from timeit import default_timer as timer
+from typing import Optional
+
+
+class Timer:
+    def __init__(self) -> None:
+        self.start = timer()
+        self._elapsed: Optional[float] = None
+
+    def elapsed(self, stop: bool = True) -> float:
+        if self._elapsed is None or not stop:
+            self._elapsed = timer() - self.start
+        return self._elapsed
+
+    def __str__(self) -> str:
+        return f"{self.elapsed():.3f} sec"
+
+
+def create_timer() -> Timer:
+    return Timer()

lisa/util/process.py

@@ -2,13 +2,13 @@ import logging
 import pathlib
 import shlex
 import time
-from timeit import default_timer as timer
 from typing import TYPE_CHECKING, Dict, Optional, Type
 
 import spur  # type: ignore
 
 from lisa.util.executableResult import ExecutableResult
 from lisa.util.logger import log
+from lisa.util.perf_timer import create_timer
 from lisa.util.shell import Shell
 
 if TYPE_CHECKING:
@@ -93,8 +93,7 @@ class Process:
         try:
             real_shell = self._shell.inner_shell
             assert real_shell
-            self._start_timer = timer()
-            log.debug(f"cwd '{cwd_path}'")
+            self._timer = create_timer()
             self._process = real_shell.spawn(
                 command=split_command,
                 stdout=self.stdout_writer,
@@ -109,22 +108,19 @@ class Process:
         except (FileNotFoundError, spur.errors.NoSuchCommandError) as identifier:
             # FileNotFoundError: not found command on Windows
             # NoSuchCommandError: not found command on remote Linux
-            self._end_timer = timer()
             self._process = ExecutableResult(
-                "", identifier.strerror, 1, self._end_timer - self._start_timer
+                "", identifier.strerror, 1, self._timer.elapsed()
             )
             log.debug(f"{self._cmd_prefix} not found command: {identifier}")
 
     def wait_result(self, timeout: float = 600) -> ExecutableResult:
         budget_time = timeout
+        timer = create_timer()
 
-        while self.is_running() and budget_time >= 0:
-            start = timer()
+        while self.is_running() and budget_time >= timer.elapsed(False):
             time.sleep(0.01)
-            end = timer()
-            budget_time = budget_time - (end - start)
 
-        if budget_time < 0:
+        if budget_time < timer.elapsed():
             if self._process is not None:
                 log.warn(f"{self._cmd_prefix}timeout in {timeout} sec, and killed")
             self.kill()
@@ -132,19 +128,18 @@ class Process:
         if not isinstance(self._process, ExecutableResult):
             assert self._process
             proces_result = self._process.wait_for_result()
-            self._end_timer = timer()
             self.stdout_writer.close()
             self.stderr_writer.close()
-            result = ExecutableResult(
+            result: ExecutableResult = ExecutableResult(
                 proces_result.output.strip(),
                 proces_result.stderr_output.strip(),
                 proces_result.return_code,
-                self._end_timer - self._start_timer,
+                self._timer.elapsed(),
             )
         else:
             result = self._process
 
-        log.debug(f"{self._cmd_prefix}executed with {result.elapsed:.3f} sec")
+        log.debug(f"{self._cmd_prefix}executed with {self._timer}")
         return result
 
     def kill(self) -> None: