diff --git a/README.md b/README.md index 29203c1..67f0e6e 100644 --- a/README.md +++ b/README.md @@ -7,6 +7,34 @@ Test framework tools and helpers for performance stack project. This repository provided utilities to assist with test automation, log handling, and result parsing. It is designed to be a set of helper libraries for test frameworks or custom test runners. + +## Logging + +`testing-utils` uses Python's standard logging module. All modules log via a package logger, which you can configure in your application. +By default, the logger uses a `NullHandler`. To see logs, configure logging in your main script: + +```python +import logging +logging.basicConfig(level=logging.INFO) +``` + +or provide logging config in pytest configuration: + +```ini +log_cli = true +log_cli_level = DEBUG +log_cli_format = %(asctime)s %(levelname)s %(message)s +log_cli_date_format = %Y-%m-%d %H:%M:%S +``` + +You can also attach handlers or change the log level for the `testing_utils` logger specifically: + +```python +import logging +logger = logging.getLogger("testing_utils") +logger.setLevel(logging.DEBUG) +``` + ## Features - **Test scenarios libraries**: Rust and C++ libraries for implementing test scenarios. diff --git a/testing_utils/__init__.py b/testing_utils/__init__.py index 3a1406b..911517e 100644 --- a/testing_utils/__init__.py +++ b/testing_utils/__init__.py @@ -21,8 +21,12 @@ "result_entry", "scenario", ] +import logging + from . import cap_utils from .build_tools import BazelTools, BuildTools, CargoTools from .log_container import LogContainer from .result_entry import ResultEntry from .scenario import Scenario, ScenarioResult + +logging.getLogger(__name__).addHandler(logging.NullHandler()) diff --git a/testing_utils/build_tools.py b/testing_utils/build_tools.py index 5b63499..032573a 100644 --- a/testing_utils/build_tools.py +++ b/testing_utils/build_tools.py @@ -17,6 +17,7 @@ __all__ = ["BuildTools", "CargoTools", "BazelTools"] import json +import logging from abc import ABC, abstractmethod from pathlib import Path from subprocess import PIPE, Popen, TimeoutExpired @@ -24,6 +25,7 @@ import pytest +logger = logging.getLogger(__package__) # region common @@ -47,6 +49,11 @@ def __init__(self, option_prefix: str = "", command_timeout: float = 10.0, build build_timeout : float Build command timeout in seconds. """ + logger.debug( + f"Initializing BuildTools: option_prefix={option_prefix}, " + f"command_timeout={command_timeout}, " + f"build_timeout={build_timeout}" + ) if option_prefix: self._target_path_flag = f"--{option_prefix}-target-path" self._target_name_flag = f"--{option_prefix}-target-name" @@ -56,6 +63,17 @@ def __init__(self, option_prefix: str = "", command_timeout: float = 10.0, build self._command_timeout = command_timeout self._build_timeout = build_timeout + def _command_str(self, command: list[Any]) -> str: + """ + Create a command string from command parts. + + Parameters + ---------- + command : list[Any] + Command as a list. + """ + return " ".join(str(c) for c in command) + @property def command_timeout(self) -> float: """ @@ -131,7 +149,7 @@ def select_target_path(self, config: pytest.Config, *, expect_exists: bool) -> P raise pytest.UsageError(f'Either "{self._target_path_flag}" or "{self._target_name_flag}" must be set') @abstractmethod - def build(self, target_name: str) -> Path: + def build(self, target_name: str, *build_parameters: str) -> Path: """ Run build for selected target. Returns path to built executable. @@ -140,6 +158,8 @@ def build(self, target_name: str) -> Path: ---------- target_name : str Name of the target to build. + build_parameters : str + Additional parameters to pass to build command. """ @@ -177,6 +197,7 @@ def metadata(self) -> dict[str, Any]: """ # Run command. command = ["cargo", "metadata", "--format-version", "1"] + logger.debug(f"Running Cargo metadata command: `{self._command_str(command)}`") with Popen(command, stdout=PIPE, text=True) as p: stdout, _ = p.communicate(timeout=self.command_timeout) if p.returncode != 0: @@ -209,9 +230,10 @@ def find_target_path(self, target_name: str, *, expect_exists: bool = True) -> P if expect_exists and not target_path.exists(): raise RuntimeError(f"Executable not found: {target_path}") + logger.debug(f"Found target path: {target_path}") return target_path - def build(self, target_name: str) -> Path: + def build(self, target_name: str, *build_parameters: str) -> Path: """ Run build for selected target. Manifest path is taken from Cargo metadata. @@ -221,6 +243,8 @@ def build(self, target_name: str) -> Path: ---------- target_name : str Name of the target to build. + build_parameters : list[str] | None + Additional parameters to pass to build command. """ # Read metadata. metadata = self.metadata() @@ -236,7 +260,8 @@ def build(self, target_name: str) -> Path: manifest_path = Path(pkg_entry["manifest_path"]).resolve() # Run build. - command = ["cargo", "build", "--manifest-path", manifest_path] + command = ["cargo", "build", "--manifest-path", manifest_path, *build_parameters] + logger.debug(f"Running Cargo build command: `{self._command_str(command)}`") with Popen(command, text=True) as p: _, _ = p.communicate(timeout=self.build_timeout) if p.returncode != 0: @@ -255,7 +280,13 @@ class BazelTools(BuildTools): Utilities for interacting with Bazel. """ - def __init__(self, option_prefix: str = "", command_timeout: float = 10.0, build_timeout: float = 180.0) -> None: + def __init__( + self, + option_prefix: str = "", + config: str = "", + command_timeout: float = 10.0, + build_timeout: float = 180.0, + ) -> None: """ Create Bazel tools instance. @@ -265,12 +296,18 @@ def __init__(self, option_prefix: str = "", command_timeout: float = 10.0, build Prefix for options expected by 'select_target_path'. - '' will expect '--target-path' and '--target-name'. - 'cpp' will expect '--cpp-target-path' and '--cpp-target-name'. + config : str + Explicitly define config used by Bazel commands. + E.g., "per-x86_64-linux" adds "--config=per-x86_64-linux". command_timeout : float Common command timeout in seconds. build_timeout : float "bazel build" timeout in seconds. """ super().__init__(option_prefix, command_timeout, build_timeout) + # Store 'config' as command parameter nested in a list. + # This is required to avoid empty parts ('') of commands. + self.config_param = [f"--config={config}"] if config else [] def query(self, query: str = "//...") -> list[str]: """ @@ -284,6 +321,7 @@ def query(self, query: str = "//...") -> list[str]: """ # Run command. command = ["bazel", "query", query] + logger.debug(f"Running Bazel query command: `{self._command_str(command)}`") with Popen(command, stdout=PIPE, text=True) as p: stdout, _ = p.communicate(timeout=self.command_timeout) if p.returncode != 0: @@ -320,8 +358,10 @@ def find_target_path(self, target_name: str, *, expect_exists: bool = True) -> P "cquery", "--output=starlark", "--starlark:expr=target.files_to_run.executable.path", + *self.config_param, target_name, ] + logger.debug(f"Running Bazel cquery command: `{self._command_str(command)}`") with Popen(command, stdout=PIPE, text=True) as p: target_str, _ = p.communicate(timeout=self.command_timeout) target_str = target_str.strip() @@ -333,9 +373,10 @@ def find_target_path(self, target_name: str, *, expect_exists: bool = True) -> P if expect_exists and not target_path.exists(): raise RuntimeError(f"Executable not found: {target_path}") + logger.debug(f"Found target path: {target_path}") return target_path - def build(self, target_name: str, *options) -> Path: + def build(self, target_name: str, *build_parameters: str) -> Path: """ Run build for selected target. @@ -343,9 +384,12 @@ def build(self, target_name: str, *options) -> Path: ---------- target_name : str Name of the target to build. + build_parameters : str + Additional parameters to pass to build command. """ # Run build. - command = ["bazel", "build", target_name, *options] + command = ["bazel", "build", *self.config_param, target_name, *build_parameters] + logger.debug(f"Running Bazel build command: `{self._command_str(command)}`") with Popen(command, text=True) as p: _, _ = p.communicate(timeout=self.build_timeout) if p.returncode != 0: diff --git a/testing_utils/cap_utils.py b/testing_utils/cap_utils.py index d689811..fc3c449 100644 --- a/testing_utils/cap_utils.py +++ b/testing_utils/cap_utils.py @@ -4,10 +4,14 @@ __all__ = ["get_caps", "set_caps"] + +import logging import re from pathlib import Path from subprocess import DEVNULL, PIPE, Popen +logger = logging.getLogger(__package__) + def get_caps(executable_path: Path | str) -> dict[str, str]: """ @@ -42,6 +46,7 @@ def get_caps(executable_path: Path | str) -> dict[str, str]: for name in names.split(","): result[name] = perms + logger.debug(f"Capabilities for {executable_path}: {result}") return result @@ -70,6 +75,7 @@ def set_caps(executable_path: Path | str, caps: dict[str, str]) -> None: caps_str, str(executable_path), ] + logger.debug(f"Setting capabilities: `{' '.join(command)}`") with Popen(command) as p: _, _ = p.communicate() if p.returncode != 0: diff --git a/testing_utils/log_container.py b/testing_utils/log_container.py index 51ae34d..23777c9 100644 --- a/testing_utils/log_container.py +++ b/testing_utils/log_container.py @@ -16,6 +16,7 @@ __all__ = ["LogContainer"] +import logging import re from itertools import groupby from operator import attrgetter @@ -23,6 +24,8 @@ from .result_entry import ResultEntry +logger = logging.getLogger(__package__) + class _NotSet: """ @@ -98,6 +101,7 @@ def _logs_by_field_field_only(self, field: str, *, reverse: bool) -> list[Result if not reverse: logs.append(log) + logger.debug(f"Filtered {len(logs)} logs by {'NOT' if reverse else ''}{field=}") return logs def _logs_by_field_regex_match(self, field: str, pattern: str, *, reverse: bool) -> list[ResultEntry]: @@ -131,6 +135,7 @@ def _logs_by_field_regex_match(self, field: str, pattern: str, *, reverse: bool) found = regex.search(str(found_value)) is not None if found ^ reverse: logs.append(log) + logger.debug(f"Filtered {len(logs)} logs by {field=} with {'reversed' if reverse else ''}{pattern=}") return logs def _logs_by_field_exact_match(self, field: str, value: Any, *, reverse: bool) -> list[ResultEntry]: @@ -159,6 +164,7 @@ def _logs_by_field_exact_match(self, field: str, value: Any, *, reverse: bool) - found = isinstance(found_value, type(value)) and found_value == value if found ^ reverse: logs.append(log) + logger.debug(f"Filtered {len(logs)} logs by {field=} with {'reversed' if reverse else ''}{value=}") return logs def _logs_by_field( diff --git a/testing_utils/net/__init__.py b/testing_utils/net/__init__.py index 80bc475..3647097 100644 --- a/testing_utils/net/__init__.py +++ b/testing_utils/net/__init__.py @@ -18,5 +18,9 @@ "address", "connection", ] +import logging + from .address import Address, IPAddress from .connection import create_connection + +logging.getLogger(__name__).addHandler(logging.NullHandler()) diff --git a/testing_utils/net/address.py b/testing_utils/net/address.py index 9c88ec5..75d97bb 100644 --- a/testing_utils/net/address.py +++ b/testing_utils/net/address.py @@ -10,6 +10,7 @@ # # SPDX-License-Identifier: Apache-2.0 # ******************************************************************************* +import logging from dataclasses import dataclass from ipaddress import IPv4Address, IPv6Address, ip_address from socket import ( @@ -20,6 +21,7 @@ from typing import Any type IPAddress = IPv4Address | IPv6Address +logger = logging.getLogger(__package__) @dataclass diff --git a/testing_utils/net/connection.py b/testing_utils/net/connection.py index 63c6692..f640bd6 100644 --- a/testing_utils/net/connection.py +++ b/testing_utils/net/connection.py @@ -10,6 +10,7 @@ # # SPDX-License-Identifier: Apache-2.0 # ******************************************************************************* +import logging from socket import ( SOCK_STREAM, socket, @@ -17,6 +18,8 @@ from .address import Address +logger = logging.getLogger(__package__) + def create_connection(address: Address, timeout: float | None = 3.0) -> socket: """ @@ -32,4 +35,5 @@ def create_connection(address: Address, timeout: float | None = 3.0) -> socket: s = socket(address.family(), SOCK_STREAM) s.settimeout(timeout) s.connect(address.to_raw()) + logger.debug(f"Created connection to {address} with {timeout=}s") return s diff --git a/testing_utils/result_entry.py b/testing_utils/result_entry.py index 73e169f..fc633a7 100644 --- a/testing_utils/result_entry.py +++ b/testing_utils/result_entry.py @@ -16,9 +16,12 @@ __all__ = ["ResultEntry"] +import logging import re from typing import Any +logger = logging.getLogger(__package__) + class ResultEntry: """ diff --git a/testing_utils/scenario.py b/testing_utils/scenario.py index 3e9d74a..611066b 100644 --- a/testing_utils/scenario.py +++ b/testing_utils/scenario.py @@ -17,6 +17,7 @@ __all__ = ["ScenarioResult", "Scenario"] import json +import logging from abc import ABC, abstractmethod from dataclasses import dataclass from datetime import timedelta @@ -30,6 +31,8 @@ from .log_container import LogContainer from .result_entry import ResultEntry +logger = logging.getLogger(__package__) + @dataclass class ScenarioResult: @@ -142,14 +145,17 @@ def _run_command(self, command: list[str], execution_timeout: float, *args, **kw """ hang = False stderr_param = PIPE if self.capture_stderr() else None + logger.info(f"Running command: `{' '.join(command)}` with timeout {execution_timeout}s") with Popen(command, stdout=PIPE, stderr=stderr_param, text=True) as p: try: stdout, stderr = p.communicate(timeout=execution_timeout) except TimeoutExpired: + logger.warning(f"Command timed out after {execution_timeout}s") hang = True p.kill() stdout, stderr = p.communicate() + logger.debug(f"Command finished with return code {p.returncode}") return ScenarioResult(stdout, stderr, p.returncode, hang) @pytest.fixture(scope="class") @@ -198,4 +204,5 @@ def logs(self, results: ScenarioResult, *args, **kwargs) -> LogContainer: # Convert messages to list of ResultEntry and create log container. result_entries = [ResultEntry(msg) for msg in messages] + logger.debug(f"Captured {len(result_entries)} log entries from scenario results") return LogContainer(result_entries) diff --git a/tests/test_build_tools.py b/tests/test_build_tools.py index 8f76f21..8b24a50 100644 --- a/tests/test_build_tools.py +++ b/tests/test_build_tools.py @@ -404,6 +404,15 @@ def test_params_unset(self, built_tmp_project: tuple[str, Path]) -> None: with pytest.raises(pytest.UsageError): _ = tools.select_target_path(cfg, expect_exists=True) # type: ignore + def test_build_additional_params(self, tools_type: type[BuildTools], tmp_project: tuple[str, Path]) -> None: + target_name, path = tmp_project + with cwd(path): + tools = tools_type() + target_path = tools.build(target_name, "--verbose") + + # Check executable exists. + assert target_path.exists() + class TestBazelTools(TestBuildTools): """