Adjust tests for new logging

tests/fixtures.py

@@ -1,15 +1,44 @@
 from __future__ import annotations
 
+import logging
+import logging.config
+from functools import wraps
 from types import SimpleNamespace
-from typing import TYPE_CHECKING
+from typing import Callable, ParamSpec, TypeVar
 
 import pytest
 
-from pip_manage._logging import setup_logging
 from pip_manage._pip_interface import _OutdatedPackage
 
-if TYPE_CHECKING:
-    import logging
+_P = ParamSpec("_P")
+_R = TypeVar("_R")
+
+
+# https://github.com/pytest-dev/pytest/discussions/11618
+def retain_pytest_handlers(f: Callable[_P, _R]) -> Callable[_P, _R]:
+    @wraps(f)
+    def wrapper(*args: _P.args, **kwargs: _P.kwargs) -> _R:
+        pytest_handlers: list[logging.Handler] = [
+            handler
+            for handler in logging.root.handlers
+            if handler.__module__ == "_pytest.logging"
+        ]
+        ret: _R = f(*args, **kwargs)
+        for handler in pytest_handlers:
+            if handler not in logging.root.handlers:
+                logging.root.addHandler(handler)
+        return ret
+
+    return wrapper
+
+
+@pytest.fixture(autouse=True)
+def _keep_pytest_handlers_during_dict_config(monkeypatch: pytest.MonkeyPatch) -> None:
+    monkeypatch.setattr(
+        logging.config,
+        "dictConfig",
+        retain_pytest_handlers(logging.config.dictConfig),
+    )
 
 
 @pytest.fixture()
@@ -29,11 +58,6 @@ def sample_subprocess_output() -> bytes:
     )
 
 
-@pytest.fixture(scope="session")
-def logger() -> logging.Logger:
-    return setup_logging("test")
-
-
 @pytest.fixture()
 def dummy_dependencies() -> list[SimpleNamespace]:
     package_a: SimpleNamespace = SimpleNamespace(

tests/logging_test.py

@@ -5,16 +5,15 @@
 
 import pytest
 
-from pip_manage._logging import _StdOutFilter, set_logging_level
-from tests.fixtures import logger  # pylint: disable=W0611
+from pip_manage._logging import _ColoredFormatter, _NonErrorFilter, setup_logging
 
 
 def test_stdout_filter_is_subclass_of_logging_filter() -> None:
-    assert issubclass(_StdOutFilter, logging.Filter)
+    assert issubclass(_NonErrorFilter, logging.Filter)
 
 
 def test_stdout_filter_override() -> None:
-    assert _StdOutFilter().filter.__override__
+    assert getattr(_NonErrorFilter().filter, "__override__", False)
 
 
 @pytest.mark.parametrize(
@@ -28,7 +27,7 @@ def test_stdout_filter_override() -> None:
                 0,
                 "test",
                 None,
-                (None, None, None),
+                None,
             ),
             id="DEBUG",
         ),
@@ -40,14 +39,14 @@ def test_stdout_filter_override() -> None:
                 0,
                 "test",
                 None,
-                (None, None, None),
+                None,
             ),
             id="INFO",
         ),
     ],
 )
 def test_stdout_filter_passes(record: logging.LogRecord) -> None:
-    assert _StdOutFilter().filter(record)
+    assert _NonErrorFilter().filter(record)
 
 
 @pytest.mark.parametrize(
@@ -61,7 +60,7 @@ def test_stdout_filter_passes(record: logging.LogRecord) -> None:
                 0,
                 "test",
                 None,
-                (None, None, None),
+                None,
             ),
             id="WARNING",
         ),
@@ -73,7 +72,7 @@ def test_stdout_filter_passes(record: logging.LogRecord) -> None:
                 0,
                 "test",
                 None,
-                (None, None, None),
+                None,
             ),
             id="ERROR",
         ),
@@ -85,50 +84,91 @@ def test_stdout_filter_passes(record: logging.LogRecord) -> None:
                 0,
                 "test",
                 None,
-                (None, None, None),
+                None,
             ),
             id="CRITICAL",
         ),
     ],
 )
 def test_stdout_filter_no_passes(record: logging.LogRecord) -> None:
-    assert not _StdOutFilter().filter(record)
+    assert not _NonErrorFilter().filter(record)
 
 
-def test_setup_logging(logger: logging.Logger) -> None:
-    assert logger.name == "test"
-    assert logger.level == logging.NOTSET
-    assert len(logger.handlers) == 2
+def test_colored_formatter_is_subclass_of_logging_formatter() -> None:
+    assert issubclass(_ColoredFormatter, logging.Formatter)
 
-    stderr_handler: logging.Handler = logger.handlers[0]
-    assert stderr_handler.name == "stderr"
-    assert stderr_handler.level == logging.WARNING
-    assert stderr_handler.formatter._fmt == "%(levelname)s: %(message)s"  # type: ignore[union-attr]
 
-    stdout_handler: logging.Handler = logger.handlers[1]
-    assert stdout_handler.name == "stdout"
-    assert stdout_handler.level == logging.DEBUG
-    assert stdout_handler.formatter._fmt == "%(message)s"  # type: ignore[union-attr]
-    assert len(stdout_handler.filters) == 1
-    assert isinstance(stdout_handler.filters[0], _StdOutFilter)
+def test_colored_formatter_override() -> None:
+    assert getattr(_ColoredFormatter().format, "__override__", False)
+
+
+def test_colored_formatter_class_vars() -> None:
+    assert {
+        "DEBUG": "\x1b[0;37m",
+        "INFO": "\x1b[0;32m",
+        "WARNING": "\x1b[0;33m",
+        "ERROR": "\x1b[0;31m",
+        "CRITICAL": "\x1b[1;31m",
+    } == _ColoredFormatter.COLORS
+    assert _ColoredFormatter.RESET == "\x1b[0m"
 
-    logger.handlers.clear()
+
+@pytest.mark.parametrize(
+    ("level", "prefix"),
+    [
+        (logging.DEBUG, "\x1b[0;37mDEBUG"),
+        (logging.INFO, "\x1b[0;32mINFO"),
+        (logging.WARNING, "\x1b[0;33mWARNING"),
+        (logging.ERROR, "\x1b[0;31mERROR"),
+        (logging.CRITICAL, "\x1b[1;31mCRITICAL"),
+    ],
+)
+def test_colored_formatter_format(level: int, prefix: str) -> None:
+    test_record: logging.LogRecord = logging.LogRecord(
+        "test",
+        level,
+        "test",
+        0,
+        "test",
+        None,
+        None,
+    )
+    assert _ColoredFormatter().format(test_record) == f"{prefix}: test\x1b[0m"
 
 
 @pytest.mark.parametrize(
-    ("verbose", "logger_level"),
+    ("verbose", "level"),
     [
         pytest.param(True, logging.DEBUG, id="verbose"),
         pytest.param(False, logging.INFO, id="non_verbose"),
     ],
 )
-def test_set_logging_level(
-    logger: logging.Logger,
-    verbose: bool,  # noqa: FBT001
-    logger_level: int,
-) -> None:
-    set_logging_level(logger, verbose=verbose)
-    assert logger.level == logger_level
+def test_setup_logging(verbose: bool, level: int) -> None:  # noqa: FBT001
+    setup_logging("test", verbose=verbose)
+    root_logger: logging.Logger = logging.getLogger()
+    assert root_logger.level == logging.DEBUG
+    assert len(root_logger.handlers) == 2
+
+    stdout_handler: logging.Handler = root_logger.handlers[0]
+    assert stdout_handler.name == "stdout"
+    assert stdout_handler.level == logging.DEBUG
+    assert isinstance(stdout_handler.formatter, logging.Formatter)
+    assert stdout_handler.formatter._fmt == "%(message)s"
+    assert len(stdout_handler.filters) == 1
+    assert isinstance(stdout_handler.filters[0], _NonErrorFilter)
+
+    stderr_handler: logging.Handler = root_logger.handlers[1]
+    assert stderr_handler.name == "stderr"
+    assert stderr_handler.level == logging.WARNING
+    assert isinstance(stderr_handler.formatter, _ColoredFormatter)
+    assert stderr_handler.formatter._fmt == "%(message)s"
+    assert not stderr_handler.filters
+
+    test_logger: logging.Logger = logging.getLogger("test")
+    assert test_logger.level == level
+    assert test_logger.propagate
+    assert not test_logger.handlers
+    assert not test_logger.filters
 
 
 if __name__ == "__main__":

tests/pip_purge_test.py

@@ -13,7 +13,10 @@
 
 from pip_manage import pip_purge
 from pip_manage._pip_interface import PIP_CMD
-from tests.fixtures import dummy_dependencies  # pylint: disable=W0611
+from tests.fixtures import (  # pylint: disable=W0611
+    _keep_pytest_handlers_during_dict_config,
+    dummy_dependencies,
+)
 
 
 def _raise_package_not_found_error_when_package_c(package: str) -> None:
@@ -52,11 +55,6 @@ def test_constants(
     assert constant == expected
 
 
-def test_default_settings_pip_purge_logger() -> None:
-    assert pip_purge._logger.name == "pip-purge"
-    assert len(pip_purge._logger.handlers) == 2
-
-
 def test_parse_args_empty_args() -> None:
     assert pip_purge._parse_args([]) == (
         argparse.Namespace(
@@ -428,7 +426,7 @@ def test_main_verbose_flag_sets_logger_level_to_debug(
         "subprocess.call",
     ) as mock_subprocess_call:
         exit_code: int = pip_purge.main(["package_a", arg])
-    assert pip_purge._logger.level == logging.DEBUG
+    assert logging.getLogger("pip-purge").level == logging.DEBUG
     mock_subprocess_call.assert_called_once_with(
         [*PIP_CMD, "uninstall", "package_a", "package_b", "package_e"],
         stdout=sys.stdout,
@@ -453,7 +451,7 @@ def test_main_no_verbose_flag_sets_logger_level_to_info(
         "subprocess.call",
     ) as mock_subprocess_call:
         exit_code: int = pip_purge.main(["package_a"])
-    assert pip_purge._logger.level == logging.INFO
+    assert logging.getLogger("pip-purge").level == logging.INFO
     mock_subprocess_call.assert_called_once_with(
         [*PIP_CMD, "uninstall", "package_a", "package_b", "package_e"],
         stdout=sys.stdout,
@@ -473,7 +471,14 @@ def test_main_error_exit_when_no_packages_provided(
         "subprocess.call",
     ) as mock_subprocess_call:
         exit_code: int = pip_purge.main([])
-    assert caplog.record_tuples == [("pip-purge", 40, "No packages provided")]
+    assert caplog.record_tuples == [
+        (
+            "pip-purge",
+            40,
+            "\x1b[0;31mERROR: You must give at least one requirement to "
+            "uninstall\x1b[0m",
+        ),
+    ]
     mock_subprocess_call.assert_not_called()
     assert exit_code == 1
 
@@ -492,9 +497,14 @@ def test_main_warn_about_unrecognized_args_before_error_exit_when_no_packages_pr
     assert (
         "pip-purge",
         30,
-        "Unrecognized arguments: '-a', '-b'",
+        "\x1b[0;33mWARNING: Unrecognized arguments: '-a', '-b'\x1b[0m",
+    ) in caplog.record_tuples
+    assert (
+        "pip-purge",
+        40,
+        "\x1b[0;31mERROR: You must give at least one requirement to "
+        "uninstall\x1b[0m",
     ) in caplog.record_tuples
-    assert ("pip-purge", 40, "No packages provided") in caplog.record_tuples
     mock_subprocess_call.assert_not_called()
     assert exit_code == 1
 
@@ -519,7 +529,7 @@ def test_main_warn_about_unrecognized_args(
     assert (
         "pip-purge",
         30,
-        "Unrecognized arguments: '-a', '-b'",
+        "\x1b[0;33mWARNING: Unrecognized arguments: '-a', '-b'\x1b[0m",
     ) in caplog.record_tuples
     mock_subprocess_call.assert_called_once_with(
         [*PIP_CMD, "uninstall", "-y", "package_a", "package_b", "package_e"],
@@ -547,7 +557,11 @@ def test_main_warn_about_not_installed_packages(
     ):
         exit_code: int = pip_purge.main(["package_a", "package_x"])
     assert caplog.record_tuples == [
-        ("pip-purge", 30, "package_x is not installed"),
+        (
+            "pip-purge",
+            30,
+            "\x1b[0;33mWARNING: Skipping package_x as it is not installed\x1b[0m",
+        ),
         (
             "pip-purge",
             20,