feat(integration-tests): Clean up logging and error reporting in integration tests.

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

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

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)

integration-tests/tests/fixtures/package_test_config.py

@@ -1,12 +1,15 @@
 """Fixtures that create and remove temporary config files for CLP packages."""
 
+import logging
 from collections.abc import Iterator
 
 import pytest
 
 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,

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

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'")

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