Properly mock logger in logging config tests

#3
#4
https://docs.python.org/3/library/unittest.mock.html#where-to-patch

- Mock the root logger object directly: The project previously had a
  `mock_logger` pytest fixture in conftest.py that instantiated a root
  logger with `logging.getLogger()`. The individual log level attributes
  were then patched with `mocker.patch.object(logger, "debug")`. This
  was problematic, because Mypy thought that the logger didn't have the
  attributes, requiring many `# type: ignore[attr-defined]` comments.
  Instead of `logging.getLogger()`, the root logger object itself will
  be directly patched whenever it is used for testing.
- Remove `# type: ignore[attr-defined]` Mypy comments: now that the
  `mock_logger` is a proper `MockerFixture`, pytest and pytest-mock
  will create the necessary attributes automatically.
- Improve exception handling when configuring logging: raise
  `ImportError` if module spec is not created
- Simplify `dict` type annotations
- Move error messages to error log level instead of debug: makes more
  sense for errors to be logged as errors
- Add `e.__class__.__name__` to log messages when exceptions are raised:
  helps to have the exception class name
- Correct `logging_conf_tmp_path_incorrect_extension` pytest fixture:
  should actually create a file

README.md

@@ -332,7 +332,7 @@ ENV APP_MODULE="package.custom.module:api" WORKERS_PER_CORE="2"
     from inboard import logging_conf
 
 
-    LOGGING_CONFIG: Dict[str, Any] = logging_conf.LOGGING_CONFIG
+    LOGGING_CONFIG: dict = logging_conf.LOGGING_CONFIG
     # only show access logs when running Uvicorn with LOG_LEVEL=debug
     LOGGING_CONFIG["loggers"]["gunicorn.access"] = {"propagate": False}
     LOGGING_CONFIG["loggers"]["uvicorn.access"] = {

inboard/start.py

@@ -26,7 +26,7 @@ def set_conf_path(module_stem: str) -> str:
 def configure_logging(
     logger: Logger = logging.getLogger(),
     logging_conf: str = os.getenv("LOGGING_CONF", "inboard.logging_conf"),
-) -> Dict[str, Any]:
+) -> dict:
     """Configure Python logging based on a path to a logging module or file."""
     try:
         logging_conf_path = Path(logging_conf)
@@ -35,23 +35,20 @@ def configure_logging(
             if logging_conf_path.is_file() and logging_conf_path.suffix == ".py"
             else importlib.util.find_spec(logging_conf)
         )
-        if spec:
-            logging_conf_module = importlib.util.module_from_spec(spec)
-            spec.loader.exec_module(logging_conf_module)  # type: ignore[union-attr]
-        if hasattr(logging_conf_module, "LOGGING_CONFIG"):
-            logging_conf_dict = getattr(logging_conf_module, "LOGGING_CONFIG")
-        else:
-            raise AttributeError(f"No LOGGING_CONFIG in {logging_conf_module}.")
-        if isinstance(logging_conf_dict, dict):
-            logging.config.dictConfig(logging_conf_dict)
-            message = f"Logging dict config loaded from {logging_conf_path}."
-            logger.debug(message)
-            return logging_conf_dict
-        else:
-            raise TypeError("LOGGING_CONFIG is not a dictionary instance.")
+        if not spec:
+            raise ImportError(f"Unable to import {logging_conf}")
+        logging_conf_module = importlib.util.module_from_spec(spec)
+        spec.loader.exec_module(logging_conf_module)  # type: ignore[union-attr]
+        if not hasattr(logging_conf_module, "LOGGING_CONFIG"):
+            raise AttributeError(f"No LOGGING_CONFIG in {logging_conf_module.__name__}")
+        logging_conf_dict = getattr(logging_conf_module, "LOGGING_CONFIG")
+        if not isinstance(logging_conf_dict, dict):
+            raise TypeError("LOGGING_CONFIG is not a dictionary instance")
+        logging.config.dictConfig(logging_conf_dict)
+        logger.debug(f"Logging dict config loaded from {logging_conf_path}.")
+        return logging_conf_dict
     except Exception as e:
-        message = f"Error when setting logging module: {e}."
-        logger.debug(message)
+        logger.error(f"Error when setting logging module: {e.__class__.__name__} {e}.")
         raise
 
 

tests/conftest.py

@@ -2,7 +2,7 @@
 import os
 import shutil
 from pathlib import Path
-from typing import Any, Dict, List
+from typing import List
 
 import pytest
 from fastapi.testclient import TestClient
@@ -81,7 +81,7 @@ def gunicorn_conf_tmp_file_path(
 
 
 @pytest.fixture
-def logging_conf_dict(mocker: MockerFixture) -> Dict[str, Any]:
+def logging_conf_dict(mocker: MockerFixture) -> dict:
     """Load logging configuration dictionary from logging configuration module."""
     return mocker.patch.dict(logging_conf_module.LOGGING_CONFIG)
 
@@ -122,11 +122,16 @@ def logging_conf_tmp_path_no_dict(tmp_path_factory: pytest.TempPathFactory) -> P
     return tmp_dir
 
 
-@pytest.fixture
-def logging_conf_tmp_path_incorrect_extension(tmp_path: Path) -> Path:
+@pytest.fixture(scope="session")
+def logging_conf_tmp_path_incorrect_extension(
+    tmp_path_factory: pytest.TempPathFactory,
+) -> Path:
     """Create custom temporary logging config file with incorrect extension."""
-    tmp_file = tmp_path / "tmp_logging_conf.txt"
-    return Path(tmp_file)
+    tmp_dir = tmp_path_factory.mktemp("tmp_log_incorrect_extension")
+    tmp_file = tmp_dir / "tmp_logging_conf"
+    with open(Path(tmp_file), "x") as f:
+        f.write("This file doesn't have the correct extension.\n")
+    return tmp_dir
 
 
 @pytest.fixture(scope="session")

tests/test_start.py

@@ -127,125 +127,133 @@ class TestConfigureLogging:
     """
 
     def test_configure_logging_file(
-        self, logging_conf_file_path: Path, mock_logger: logging.Logger
+        self, logging_conf_file_path: Path, mocker: MockerFixture
     ) -> None:
         """Test `start.configure_logging` with correct logging config file path."""
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
         start.configure_logging(
             logger=mock_logger, logging_conf=str(logging_conf_file_path)
         )
-        mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
+        mock_logger.debug.assert_called_once_with(
             f"Logging dict config loaded from {logging_conf_file_path}."
         )
 
     def test_configure_logging_module(
-        self, logging_conf_module_path: str, mock_logger: logging.Logger
+        self, logging_conf_module_path: str, mocker: MockerFixture
     ) -> None:
         """Test `start.configure_logging` with correct logging config module path."""
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
         start.configure_logging(
             logger=mock_logger, logging_conf=logging_conf_module_path
         )
-        mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
+        mock_logger.debug.assert_called_once_with(
             f"Logging dict config loaded from {logging_conf_module_path}."
         )
 
-    def test_configure_logging_module_incorrect(
-        self, mock_logger: logging.Logger
-    ) -> None:
+    def test_configure_logging_module_incorrect(self, mocker: MockerFixture) -> None:
         """Test `start.configure_logging` with incorrect logging config module path."""
-        with pytest.raises(ImportError):
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
+        mock_logger_error_msg = "Error when setting logging module"
+        with pytest.raises(ModuleNotFoundError):
             start.configure_logging(logger=mock_logger, logging_conf="no.module.here")
-            import_error_msg = "Unable to import no.module.here."
-            logger_error_msg = "Error when configuring logging:"
-            mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
-                f"{logger_error_msg} {import_error_msg}."
-            )
+        assert mock_logger_error_msg in mock_logger.error.call_args.args[0]
+        assert "ModuleNotFoundError" in mock_logger.error.call_args.args[0]
 
     def test_configure_logging_tmp_file(
-        self, logging_conf_tmp_file_path: Path, mock_logger: logging.Logger
+        self, logging_conf_tmp_file_path: Path, mocker: MockerFixture
     ) -> None:
-        """Test `start.configure_logging` with correct logging config file path."""
-        start.configure_logging(
-            logger=mock_logger, logging_conf=f"{logging_conf_tmp_file_path}/tmp_log.py"
-        )
-        mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
-            f"Logging dict config loaded from {logging_conf_tmp_file_path}/tmp_log.py."
+        """Test `start.configure_logging` with temporary logging config file path."""
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
+        logging_conf_file = f"{logging_conf_tmp_file_path}/tmp_log.py"
+        start.configure_logging(logger=mock_logger, logging_conf=logging_conf_file)
+        mock_logger.debug.assert_called_once_with(
+            f"Logging dict config loaded from {logging_conf_file}."
         )
 
     def test_configure_logging_tmp_file_incorrect_extension(
         self,
         logging_conf_tmp_path_incorrect_extension: Path,
-        mock_logger: logging.Logger,
+        mocker: MockerFixture,
     ) -> None:
         """Test `start.configure_logging` with incorrect temporary file type."""
-        with pytest.raises(ImportError):
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
+        incorrect_logging_conf = logging_conf_tmp_path_incorrect_extension.joinpath(
+            "tmp_logging_conf"
+        )
+        logger_error_msg = "Error when setting logging module"
+        import_error_msg = f"Unable to import {incorrect_logging_conf}"
+        with pytest.raises(ImportError) as e:
             start.configure_logging(
                 logger=mock_logger,
-                logging_conf=str(logging_conf_tmp_path_incorrect_extension),
-            )
-            import_error_msg = (
-                f"Unable to import {logging_conf_tmp_path_incorrect_extension}."
-            )
-            logger_error_msg = "Error when configuring logging:"
-            mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
-                f"{logger_error_msg} {import_error_msg}."
+                logging_conf=str(incorrect_logging_conf),
             )
+        assert str(e.value) in import_error_msg
+        mock_logger.error.assert_called_once_with(
+            f"{logger_error_msg}: ImportError {import_error_msg}."
+        )
+        with open(incorrect_logging_conf, "r") as f:
+            contents = f.read()
+            assert "This file doesn't have the correct extension" in contents
 
     def test_configure_logging_tmp_module(
         self,
         logging_conf_tmp_file_path: Path,
-        mock_logger: logging.Logger,
+        mocker: MockerFixture,
         monkeypatch: pytest.MonkeyPatch,
     ) -> None:
         """Test `start.configure_logging` with temporary logging config path."""
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
         monkeypatch.syspath_prepend(logging_conf_tmp_file_path)
         monkeypatch.setenv("LOGGING_CONF", "tmp_log")
         assert os.getenv("LOGGING_CONF") == "tmp_log"
         start.configure_logging(logger=mock_logger, logging_conf="tmp_log")
-        mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
+        mock_logger.debug.assert_called_once_with(
             "Logging dict config loaded from tmp_log."
         )
 
     def test_configure_logging_tmp_module_incorrect_type(
         self,
         logging_conf_tmp_path_incorrect_type: Path,
-        mock_logger: logging.Logger,
+        mocker: MockerFixture,
         monkeypatch: pytest.MonkeyPatch,
     ) -> None:
         """Test `start.configure_logging` with temporary logging config path.
         - Correct module name
         - `LOGGING_CONFIG` object with incorrect type
         """
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
         monkeypatch.syspath_prepend(logging_conf_tmp_path_incorrect_type)
         monkeypatch.setenv("LOGGING_CONF", "incorrect_type")
+        logger_error_msg = "Error when setting logging module"
+        type_error_msg = "LOGGING_CONFIG is not a dictionary instance"
         assert os.getenv("LOGGING_CONF") == "incorrect_type"
         with pytest.raises(TypeError):
             start.configure_logging(logger=mock_logger, logging_conf="incorrect_type")
-            logger_error_msg = "Error when configuring logging:"
-            type_error_msg = "LOGGING_CONFIG is not a dictionary instance."
-            mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
-                f"{logger_error_msg} {type_error_msg}."
-            )
+        mock_logger.error.assert_called_once_with(
+            f"{logger_error_msg}: TypeError {type_error_msg}."
+        )
 
     def test_configure_logging_tmp_module_no_dict(
         self,
         logging_conf_tmp_path_no_dict: Path,
-        mock_logger: logging.Logger,
+        mocker: MockerFixture,
         monkeypatch: pytest.MonkeyPatch,
     ) -> None:
         """Test `start.configure_logging` with temporary logging config path.
         - Correct module name
         - No `LOGGING_CONFIG` object
         """
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
         monkeypatch.syspath_prepend(logging_conf_tmp_path_no_dict)
         monkeypatch.setenv("LOGGING_CONF", "no_dict")
+        logger_error_msg = "Error when setting logging module"
+        attribute_error_msg = "No LOGGING_CONFIG in no_dict"
         assert os.getenv("LOGGING_CONF") == "no_dict"
         with pytest.raises(AttributeError):
             start.configure_logging(logger=mock_logger, logging_conf="no_dict")
-            logger_error_msg = "Error when configuring logging:"
-            attribute_error_msg = "No LOGGING_CONFIG in no_dict."
-            mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
-                f"{logger_error_msg} {attribute_error_msg}."
-            )
+        mock_logger.error.assert_called_once_with(
+            f"{logger_error_msg}: AttributeError {attribute_error_msg}."
+        )
 
 
 class TestSetAppModule: