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..f1cebc5 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" @@ -177,6 +184,7 @@ def metadata(self) -> dict[str, Any]: """ # Run command. command = ["cargo", "metadata", "--format-version", "1"] + logger.debug(f"Running Cargo metadata command: `{' '.join(command)}`") with Popen(command, stdout=PIPE, text=True) as p: stdout, _ = p.communicate(timeout=self.command_timeout) if p.returncode != 0: @@ -209,6 +217,7 @@ 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: @@ -237,6 +246,7 @@ def build(self, target_name: str) -> Path: # Run build. command = ["cargo", "build", "--manifest-path", manifest_path] + logger.debug(f"Running Cargo build command: `{' '.join(command)}`") with Popen(command, text=True) as p: _, _ = p.communicate(timeout=self.build_timeout) if p.returncode != 0: @@ -284,6 +294,7 @@ def query(self, query: str = "//...") -> list[str]: """ # Run command. command = ["bazel", "query", query] + logger.debug(f"Running Bazel query command: `{' '.join(command)}`") with Popen(command, stdout=PIPE, text=True) as p: stdout, _ = p.communicate(timeout=self.command_timeout) if p.returncode != 0: @@ -322,6 +333,7 @@ def find_target_path(self, target_name: str, *, expect_exists: bool = True) -> P "--starlark:expr=target.files_to_run.executable.path", target_name, ] + logger.debug(f"Running Bazel cquery command: `{' '.join(command)}`") with Popen(command, stdout=PIPE, text=True) as p: target_str, _ = p.communicate(timeout=self.command_timeout) target_str = target_str.strip() @@ -333,6 +345,7 @@ 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: @@ -346,6 +359,7 @@ def build(self, target_name: str, *options) -> Path: """ # Run build. command = ["bazel", "build", target_name, *options] + logger.debug(f"Running Bazel build command: `{' '.join(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)