diff --git a/integration-tests/.pytest.ini b/integration-tests/.pytest.ini index e1cf224243..d18f328ccb 100644 --- a/integration-tests/.pytest.ini +++ b/integration-tests/.pytest.ini @@ -1,21 +1,26 @@ [pytest] addopts = - --capture=no --code-highlight=yes --color=yes - -rA + --show-capture=no --strict-config --strict-markers + --tb=short --verbose + +console_output_style = classic + env = D:CLP_BUILD_DIR=../build D:CLP_CORE_BINS_DIR=../build/core D:CLP_PACKAGE_DIR=../build/clp-package D:INTEGRATION_TESTS_PROJECT_ROOT=./ -log_cli = True -log_cli_date_format = %Y-%m-%d %H:%M:%S,%f -log_cli_format = %(name)s %(asctime)s [%(levelname)s] %(message)s -log_cli_level = INFO + +log_file_mode = a +log_file_level = INFO +log_file_format = %(asctime)s.%(msecs)03d %(levelname)s %(message)s +log_file_date_format = %Y-%m-%d %H:%M:%S + markers = clp: mark tests that use the CLP storage engine clp_json: mark tests that use the clp-json package diff --git a/integration-tests/tests/conftest.py b/integration-tests/tests/conftest.py index 1741453b3a..9f680f3d8b 100644 --- a/integration-tests/tests/conftest.py +++ b/integration-tests/tests/conftest.py @@ -1,7 +1,13 @@ """Global pytest setup.""" +import datetime +from collections.abc import Iterator, Sequence +from pathlib import Path + import pytest +from tests.utils.utils import resolve_path_env_var + # Make the fixtures defined in `tests/fixtures/` globally available without imports. pytest_plugins = [ "tests.fixtures.integration_test_logs", @@ -11,15 +17,122 @@ ] +BLUE = "\033[34m" +BOLD = "\033[1m" +RESET = "\033[0m" + +_test_log_dir: Path | None = None + + +def get_test_log_dir() -> Path: + """ + Returns the unique log directory for this test run. + + :return: The path to the log directory for this test run. + :raise pytest.fail: If `_test_log_dir` is not initialized. + """ + if _test_log_dir is None: + pytest.fail("test log directory has not been initialized") + return _test_log_dir + + +@pytest.hookimpl(tryfirst=True) +def pytest_configure(config: pytest.Config) -> None: # noqa: ARG001 + """ + Initializes the unique log directory for this test run. Creates the directory under + `$CLP_BUILD_DIR/integration_tests/test_logs/` Stores the path to `_test_log_dir` for retrieval + via `get_test_log_dir()`. + + :param config: + """ + global _test_log_dir # noqa:PLW0603 + + now = datetime.datetime.now() # noqa: DTZ005 + test_run_id = now.strftime("%Y-%m-%d-%H-%M-%S") + + _test_log_dir = ( + resolve_path_env_var("CLP_BUILD_DIR") + / "integration_tests" + / "test_logs" + / f"testrun_{test_run_id}" + ) + _test_log_dir.mkdir(parents=True, exist_ok=True) + + def pytest_addoption(parser: pytest.Parser) -> None: """ - Adds options for pytest. + Adds options for `pytest`. :param parser: """ parser.addoption( "--base-port", action="store", - default="55000", + default="56000", help="Base port for CLP package integration tests.", ) + + +def pytest_itemcollected(item: pytest.Item) -> None: + """ + Applies ANSI bold and blue formatting to each collected test's node ID, for the purposes of + test output readability. + + :param item: + """ + item._nodeid = f"{BOLD}{BLUE}{item.nodeid}{RESET}" # noqa: SLF001 + + +@pytest.hookimpl(tryfirst=True) +def pytest_report_header(config: pytest.Config) -> str: # noqa: ARG001 + """ + Adds a line to the session header that reports the unique log directory for this test run. + + :param config: + :return: A string containing the log directory path for display in the session header. + """ + return f"Log directory for this test run: {get_test_log_dir()}" + + +def pytest_report_collectionfinish( + config: pytest.Config, # noqa: ARG001 + start_path: Path, # noqa: ARG001 + items: Sequence[pytest.Item], +) -> str | list[str]: + """ + Reports the list of collected tests for this session after collection is complete. + + :param config: + :param start_path: + :param items: + :return: A formatted string listing each test name, or a warning if no tests were collected. + """ + report: str = "" + if len(items) == 0: + report = f"{BOLD}No tests match the specified parameters.{RESET}\n" + else: + report = f"{BOLD}The following tests will run:{RESET}\n" + for item in items: + report += f"\t{BOLD}{BLUE}{item.nodeid}{RESET}\n" + report += f"\n{BOLD}Running tests now...{RESET}" + return report + + +@pytest.hookimpl(wrapper=True) +def pytest_runtest_setup(item: pytest.Item) -> Iterator[None]: + """ + Redirects the pytest logging plugin's output to the test_output.log file in the unique log + directory for this test run. The file will be created automatically if it does not already + exist. + + :param item: + :raise pytest.fail: If the `logging-plugin` is not registered with the plugin manager. + """ + config = item.config + logging_plugin = config.pluginmanager.get_plugin("logging-plugin") + if logging_plugin is None: + pytest.fail("Expected pytest plugin 'logging-plugin' to be registered.") + + test_output_log_file = get_test_log_dir() / "test_output.log" + logging_plugin.set_log_path(str(test_output_log_file)) + yield diff --git a/integration-tests/tests/fixtures/package_instance.py b/integration-tests/tests/fixtures/package_instance.py index c4425cdca5..c8df638fb2 100644 --- a/integration-tests/tests/fixtures/package_instance.py +++ b/integration-tests/tests/fixtures/package_instance.py @@ -29,14 +29,5 @@ def fixt_package_instance(fixt_package_test_config: PackageTestConfig) -> Iterat start_clp_package(fixt_package_test_config) instance = PackageInstance(package_test_config=fixt_package_test_config) yield instance - except RuntimeError: - mode_config = fixt_package_test_config.mode_config - mode_name = mode_config.mode_name - base_port = fixt_package_test_config.base_port - pytest.fail( - f"Failed to start the {mode_name} package. This could mean that one of the ports" - f" derived from base_port={base_port} was unavailable. You can specify a new value for" - " base_port with the '--base-port' flag." - ) finally: stop_clp_package(fixt_package_test_config) diff --git a/integration-tests/tests/fixtures/package_test_config.py b/integration-tests/tests/fixtures/package_test_config.py index e10ae7f3b9..e93642e7f1 100644 --- a/integration-tests/tests/fixtures/package_test_config.py +++ b/integration-tests/tests/fixtures/package_test_config.py @@ -1,5 +1,6 @@ """Fixtures that create and remove temporary config files for CLP packages.""" +import logging from collections.abc import Iterator import pytest @@ -7,6 +8,8 @@ from tests.utils.config import PackageModeConfig, PackagePathConfig, PackageTestConfig from tests.utils.port_utils import assign_ports_from_base +logger = logging.getLogger(__name__) + @pytest.fixture(scope="module") def fixt_package_test_config( @@ -25,6 +28,8 @@ def fixt_package_test_config( clp_config_obj = mode_config.clp_config # Assign ports based on the clp base port CLI option. + log_msg = f"Assigning ports to the '{mode_config.mode_name}' package." + logger.info(log_msg) base_port_string = request.config.getoption("--base-port") try: base_port = int(base_port_string) @@ -34,6 +39,10 @@ def fixt_package_test_config( assign_ports_from_base(base_port, clp_config_obj) # Construct PackageTestConfig. + log_msg = ( + f"Constructing the PackageTestConfig object for the '{mode_config.mode_name}' package." + ) + logger.info(log_msg) package_test_config = PackageTestConfig( path_config=fixt_package_path_config, mode_config=mode_config, diff --git a/integration-tests/tests/package_tests/clp_json/test_clp_json.py b/integration-tests/tests/package_tests/clp_json/test_clp_json.py index bf5a471647..c8e56ff8b3 100644 --- a/integration-tests/tests/package_tests/clp_json/test_clp_json.py +++ b/integration-tests/tests/package_tests/clp_json/test_clp_json.py @@ -49,10 +49,11 @@ def test_clp_json_startup(fixt_package_instance: PackageInstance) -> None: :param fixt_package_instance: """ + logger.info("Starting test: 'test_clp_json_startup'") + validate_package_instance(fixt_package_instance) - log_msg = "test_clp_json_startup was successful." - logger.info(log_msg) + logger.info("Test complete: 'test_clp_json_startup'") @pytest.mark.compression @@ -62,6 +63,8 @@ def test_clp_json_compression_json_multifile(fixt_package_instance: PackageInsta :param fixt_package_instance: """ + logger.info("Starting test: 'test_clp_json_compression_json_multifile'") + validate_package_instance(fixt_package_instance) # Clear archives before compressing. @@ -87,12 +90,11 @@ def test_clp_json_compression_json_multifile(fixt_package_instance: PackageInsta # Check the correctness of compression. verify_package_compression(compression_job.path_to_original_dataset, package_test_config) - log_msg = "test_clp_json_compression_json_multifile was successful." - logger.info(log_msg) - # Clear archives. package_path_config.clear_package_archives() + logger.info("Test complete: 'test_clp_json_compression_json_multifile'") + @pytest.mark.search def test_clp_json_search(fixt_package_instance: PackageInstance) -> None: @@ -101,6 +103,8 @@ def test_clp_json_search(fixt_package_instance: PackageInstance) -> None: :param fixt_package_instance: """ + logger.info("Starting test: 'test_clp_json_search'") + validate_package_instance(fixt_package_instance) # TODO: compress a dataset @@ -111,7 +115,6 @@ def test_clp_json_search(fixt_package_instance: PackageInstance) -> None: assert True - log_msg = "test_clp_json_search was successful." - logger.info(log_msg) + logger.info("Test complete: 'test_clp_json_search'") # TODO: clean up clp-package/var/data, clp-package/var/log, and clp-package/var/tmp diff --git a/integration-tests/tests/package_tests/clp_text/test_clp_text.py b/integration-tests/tests/package_tests/clp_text/test_clp_text.py index a9ec962d6d..3150f1601c 100644 --- a/integration-tests/tests/package_tests/clp_text/test_clp_text.py +++ b/integration-tests/tests/package_tests/clp_text/test_clp_text.py @@ -47,10 +47,11 @@ @pytest.mark.startup def test_clp_text_startup(fixt_package_instance: PackageInstance) -> None: """Tests package startup.""" + logger.info("Starting test: 'test_clp_text_startup'") + validate_package_instance(fixt_package_instance) - log_msg = "test_clp_text_startup was successful." - logger.info(log_msg) + logger.info("Test complete: 'test_clp_text_startup'") @pytest.mark.compression @@ -60,6 +61,8 @@ def test_clp_text_compression_text_multifile(fixt_package_instance: PackageInsta :param fixt_package_instance: """ + logger.info("Starting test: 'test_clp_text_compression_text_multifile'") + validate_package_instance(fixt_package_instance) # Clear archives before compressing. @@ -80,8 +83,7 @@ def test_clp_text_compression_text_multifile(fixt_package_instance: PackageInsta # Check the correctness of compression. verify_package_compression(compression_job.path_to_original_dataset, package_test_config) - log_msg = "test_clp_text_compression_text_multifile was successful." - logger.info(log_msg) - # Clear archives. package_path_config.clear_package_archives() + + logger.info("Test complete: 'test_clp_text_compression_text_multifile'") diff --git a/integration-tests/tests/test_identity_transformation.py b/integration-tests/tests/test_identity_transformation.py index 9d95f357a8..38ca8e8c79 100644 --- a/integration-tests/tests/test_identity_transformation.py +++ b/integration-tests/tests/test_identity_transformation.py @@ -5,13 +5,13 @@ import pytest -from tests.utils.asserting_utils import run_and_assert from tests.utils.config import ( ClpCorePathConfig, CompressionTestPathConfig, IntegrationTestLogs, IntegrationTestPathConfig, ) +from tests.utils.subprocess_utils import run_and_log_subprocess from tests.utils.utils import ( is_dir_tree_content_equal, is_json_file_structurally_equal, @@ -73,10 +73,10 @@ def test_clp_identity_transform( src_path, ] # fmt: on - run_and_assert(compression_cmd) + run_and_log_subprocess(compression_cmd) decompression_cmd = [bin_path, "x", compression_path, decompression_path] - run_and_assert(decompression_cmd) + run_and_log_subprocess(decompression_cmd) input_path = test_paths.logs_source_dir output_path = test_paths.decompression_dir @@ -148,5 +148,5 @@ def _clp_s_compress_and_decompress( src_path = str(test_paths.logs_source_dir) compression_path = str(test_paths.compression_dir) decompression_path = str(test_paths.decompression_dir) - run_and_assert([bin_path, "c", compression_path, src_path]) - run_and_assert([bin_path, "x", compression_path, decompression_path]) + run_and_log_subprocess([bin_path, "c", compression_path, src_path]) + run_and_log_subprocess([bin_path, "x", compression_path, decompression_path]) diff --git a/integration-tests/tests/utils/asserting_utils.py b/integration-tests/tests/utils/asserting_utils.py index 7cbc7c0e4a..02d926b4f9 100644 --- a/integration-tests/tests/utils/asserting_utils.py +++ b/integration-tests/tests/utils/asserting_utils.py @@ -1,10 +1,7 @@ """Utilities that raise pytest assertions on failure.""" import logging -import shlex -import subprocess from pathlib import Path -from typing import Any import pytest from clp_package_utils.general import EXTRACT_FILE_CMD @@ -14,31 +11,16 @@ from tests.utils.clp_mode_utils import compare_mode_signatures from tests.utils.config import PackageInstance, PackageTestConfig from tests.utils.docker_utils import list_running_services_in_compose_project -from tests.utils.utils import clear_directory, is_dir_tree_content_equal, load_yaml_to_dict +from tests.utils.subprocess_utils import run_and_log_subprocess +from tests.utils.utils import ( + clear_directory, + is_dir_tree_content_equal, + load_yaml_to_dict, +) logger = logging.getLogger(__name__) -def run_and_assert(cmd: list[str], **kwargs: Any) -> subprocess.CompletedProcess[Any]: - """ - Runs a command with subprocess and asserts that it succeeds with pytest. - - :param cmd: Command and arguments to execute. - :param kwargs: Additional keyword arguments passed through to the subprocess. - :return: The completed process object, for inspection or further handling. - :raise: pytest.fail if the command exits with a non-zero return code. - """ - logger.info("Running command: %s", shlex.join(cmd)) - - try: - proc = subprocess.run(cmd, check=True, **kwargs) - except subprocess.CalledProcessError as e: - pytest.fail(f"Command failed: {' '.join(cmd)}: {e}") - except subprocess.TimeoutExpired as e: - pytest.fail(f"Command timed out: {' '.join(cmd)}: {e}") - return proc - - def validate_package_instance(package_instance: PackageInstance) -> None: """ Validate that the given package instance is running by performing two checks: validate that the @@ -47,6 +29,11 @@ def validate_package_instance(package_instance: PackageInstance) -> None: :param package_instance: """ + log_msg = ( + f"Validating the '{package_instance.package_test_config.mode_config.mode_name}' package." + ) + logger.info(log_msg) + # Ensure that all package components are running. _validate_package_running(package_instance) @@ -121,6 +108,8 @@ def verify_package_compression( :param package_test_config: """ mode = package_test_config.mode_config.mode_name + log_msg = f"Verifying {mode} package compression." + logger.info(log_msg) if mode == "clp-json": # TODO: Waiting for PR 1299 to be merged. @@ -144,7 +133,7 @@ def verify_package_compression( ] # Run decompression command and assert that it succeeds. - run_and_assert(decompress_cmd) + run_and_log_subprocess(decompress_cmd) # Verify content equality. output_path = decompression_dir / path_to_original_dataset.relative_to( diff --git a/integration-tests/tests/utils/config.py b/integration-tests/tests/utils/config.py index 75f97c4d46..f6f2407d75 100644 --- a/integration-tests/tests/utils/config.py +++ b/integration-tests/tests/utils/config.py @@ -1,7 +1,5 @@ """Define all python classes used in `integration-tests`.""" -from __future__ import annotations - import re from dataclasses import dataclass, field, InitVar from pathlib import Path diff --git a/integration-tests/tests/utils/logging_utils.py b/integration-tests/tests/utils/logging_utils.py new file mode 100644 index 0000000000..516b2cb5e1 --- /dev/null +++ b/integration-tests/tests/utils/logging_utils.py @@ -0,0 +1,64 @@ +"""Utilities for logging during the test run.""" + +import datetime +import logging +import subprocess +from pathlib import Path + +from tests.conftest import get_test_log_dir + +logger = logging.getLogger(__name__) + + +def log_subprocess_output_to_file( + proc: subprocess.CompletedProcess[str], + cmd: list[str], +) -> None: + """ + Logs subprocess output summary to a unique file. + + :param proc: + :param cmd: + """ + now = datetime.datetime.now() # noqa: DTZ005 + test_run_id = now.strftime("%Y-%m-%d-%H-%M-%S") + subprocess_output_file_path = ( + get_test_log_dir() / "subprocess_output" / f"{Path(cmd[0]).name}_{test_run_id}.log" + ) + subprocess_output_file_path.parent.mkdir(parents=True, exist_ok=True) + + stdout_content = proc.stdout or "(empty)" + stderr_content = proc.stderr or "(empty)" + + if not stdout_content.endswith("\n"): + stdout_content += "\n" + if not stderr_content.endswith("\n"): + stderr_content += "\n" + + sep = "-" * 32 + lines = [ + "SUBPROCESS RUN SUMMARY\n", + f"{sep}\n", + f"Timestamp at completion : {now.strftime('%Y-%m-%d %H:%M:%S')}\n", + f"Command : {cmd}\n", + f"Return Code : {proc.returncode}\n", + "\n\n", + "captured stdout\n", + f"{sep}\n", + stdout_content, + "\n", + "\n\n", + "captured stderr\n", + f"{sep}\n", + stderr_content, + "\n", + ] + + with subprocess_output_file_path.open("w", encoding="utf-8") as log_file: + log_file.writelines(lines) + + log_msg = ( + f"Subprocess returned. stdout and stderr written to log file:" + f" '{subprocess_output_file_path}'" + ) + logger.info(log_msg) diff --git a/integration-tests/tests/utils/package_utils.py b/integration-tests/tests/utils/package_utils.py index 01d67f4a07..b578676ed4 100644 --- a/integration-tests/tests/utils/package_utils.py +++ b/integration-tests/tests/utils/package_utils.py @@ -1,12 +1,10 @@ """Provides utility functions related to the CLP package used across `integration-tests`.""" -from tests.utils.asserting_utils import run_and_assert from tests.utils.config import ( PackageCompressionJob, PackageTestConfig, ) - -DEFAULT_CMD_TIMEOUT_SECONDS = 120.0 +from tests.utils.subprocess_utils import run_and_log_subprocess def start_clp_package(package_test_config: PackageTestConfig) -> None: @@ -14,7 +12,7 @@ def start_clp_package(package_test_config: PackageTestConfig) -> None: Starts an instance of the CLP package. :param package_test_config: - :raise: Propagates `run_and_assert`'s errors. + :raise: Propagates `run_and_log_subprocess`'s errors. """ path_config = package_test_config.path_config start_script_path = path_config.start_script_path @@ -26,7 +24,7 @@ def start_clp_package(package_test_config: PackageTestConfig) -> None: "--config", str(temp_config_file_path), ] # fmt: on - run_and_assert(start_cmd, timeout=DEFAULT_CMD_TIMEOUT_SECONDS) + run_and_log_subprocess(start_cmd) def stop_clp_package(package_test_config: PackageTestConfig) -> None: @@ -34,7 +32,7 @@ def stop_clp_package(package_test_config: PackageTestConfig) -> None: Stops the running instance of the CLP package. :param package_test_config: - :raise: Propagates `run_and_assert`'s errors. + :raise: Propagates `run_and_log_subprocess`'s errors. """ path_config = package_test_config.path_config stop_script_path = path_config.stop_script_path @@ -46,7 +44,7 @@ def stop_clp_package(package_test_config: PackageTestConfig) -> None: "--config", str(temp_config_file_path), ] # fmt: on - run_and_assert(stop_cmd, timeout=DEFAULT_CMD_TIMEOUT_SECONDS) + run_and_log_subprocess(stop_cmd) def run_package_compression_script( @@ -78,4 +76,4 @@ def run_package_compression_script( compress_cmd.append(str(compression_job.path_to_original_dataset)) # Run compression command for this job and assert that it succeeds. - run_and_assert(compress_cmd, timeout=DEFAULT_CMD_TIMEOUT_SECONDS) + run_and_log_subprocess(compress_cmd) diff --git a/integration-tests/tests/utils/subprocess_utils.py b/integration-tests/tests/utils/subprocess_utils.py new file mode 100644 index 0000000000..bb89e1aee2 --- /dev/null +++ b/integration-tests/tests/utils/subprocess_utils.py @@ -0,0 +1,36 @@ +"""Utilities for subprocess management.""" + +import logging +import subprocess +from pathlib import Path + +import pytest + +from tests.utils.logging_utils import log_subprocess_output_to_file + +DEFAULT_CMD_TIMEOUT_SECONDS = 120.0 +logger = logging.getLogger(__name__) + + +def run_and_log_subprocess(cmd: list[str]) -> subprocess.CompletedProcess[str]: + """ + Runs a subprocess from `cmd` and logs output. + + :param cmd: + """ + log_msg = f"Running '{Path(cmd[0]).name}' subprocess. Command: {cmd}" + logger.info(log_msg) + proc = subprocess.run( + cmd, + capture_output=True, + timeout=DEFAULT_CMD_TIMEOUT_SECONDS, + check=False, + text=True, + ) + + log_subprocess_output_to_file(proc, cmd) + + if proc.returncode != 0: + pytest.fail(f"Subprocess '{Path(cmd[0]).name}' returned a non-zero exit code.") + + return proc