impl: add logging to library

improve debugging with logging statements

Author: PiotrKorkus

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.

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())

testing_utils/build_tools.py

@@ -17,13 +17,15 @@
 __all__ = ["BuildTools", "CargoTools", "BazelTools"]
 
 import json
+import logging
 from abc import ABC, abstractmethod
 from pathlib import Path
 from subprocess import PIPE, Popen, TimeoutExpired
 from typing import Any
 
 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:

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:

testing_utils/log_container.py

@@ -16,13 +16,16 @@
 
 __all__ = ["LogContainer"]
 
+import logging
 import re
 from itertools import groupby
 from operator import attrgetter
 from typing import Any
 
 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(

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())

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

testing_utils/net/connection.py

@@ -10,13 +10,16 @@
 #
 # SPDX-License-Identifier: Apache-2.0
 # *******************************************************************************
+import logging
 from socket import (
     SOCK_STREAM,
     socket,
 )
 
 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

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:
     """

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)