Properly mock logger in app module 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.
- Correct module spec syntax in `set_app_module()`: importlib needs the
  module path without the app instance name at the end. The way this
  function was written before, importlib was just returning `None`.
  inboard should be able to find the app module before continuing, or
  raise an `ImportError` exception if module spec is not created.
- 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

Author: br3ndonland

inboard/start.py

@@ -56,12 +56,12 @@ def set_app_module(logger: Logger = logging.getLogger()) -> str:
     """Set the name of the Python module with the app instance to run."""
     try:
         app_module = str(os.getenv("APP_MODULE"))
-        importlib.util.find_spec(app_module)
+        if not importlib.util.find_spec((module := app_module.split(sep=":")[0])):
+            raise ImportError(f"Unable to find or import {module}")
         logger.debug(f"App module set to {app_module}.")
         return app_module
     except Exception as e:
-        message = f"Error when setting app module: {e}."
-        logger.debug(message)
+        logger.error(f"Error when setting app module: {e.__class__.__name__} {e}.")
         raise
 
 

tests/test_start.py

@@ -262,93 +262,98 @@ class TestSetAppModule:
     """
 
     def test_set_app_module_asgi(
-        self, mock_logger: logging.Logger, monkeypatch: pytest.MonkeyPatch
+        self, mocker: MockerFixture, monkeypatch: pytest.MonkeyPatch
     ) -> None:
         """Test `start.set_app_module` using module path to base ASGI app."""
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
         monkeypatch.setenv("APP_MODULE", "inboard.app.main_base:app")
         start.set_app_module(logger=mock_logger)
-        mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
+        mock_logger.debug.assert_called_once_with(
             "App module set to inboard.app.main_base:app."
         )
 
     def test_set_app_module_fastapi(
-        self, mock_logger: logging.Logger, monkeypatch: pytest.MonkeyPatch
+        self, mocker: MockerFixture, monkeypatch: pytest.MonkeyPatch
     ) -> None:
         """Test `start.set_app_module` using module path to FastAPI app."""
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
         monkeypatch.setenv("APP_MODULE", "inboard.app.main_fastapi:app")
         start.set_app_module(logger=mock_logger)
-        mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
+        mock_logger.debug.assert_called_once_with(
             "App module set to inboard.app.main_fastapi:app."
         )
 
     def test_set_app_module_starlette(
-        self, mock_logger: logging.Logger, monkeypatch: pytest.MonkeyPatch
+        self, mocker: MockerFixture, monkeypatch: pytest.MonkeyPatch
     ) -> None:
         """Test `start.set_app_module` using module path to Starlette app."""
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
         monkeypatch.setenv("APP_MODULE", "inboard.app.main_starlette:app")
         start.set_app_module(logger=mock_logger)
-        mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
+        mock_logger.debug.assert_called_once_with(
             "App module set to inboard.app.main_starlette:app."
         )
 
     def test_set_app_module_custom_asgi(
         self,
         app_module_tmp_path: Path,
-        mock_logger: logging.Logger,
+        mocker: MockerFixture,
         monkeypatch: pytest.MonkeyPatch,
     ) -> None:
         """Test `start.set_app_module` with custom module path to base ASGI app."""
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
         monkeypatch.syspath_prepend(app_module_tmp_path)
         monkeypatch.setenv("APP_MODULE", "tmp_app.main_base:app")
         start.set_app_module(logger=mock_logger)
-        mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
+        mock_logger.debug.assert_called_once_with(
             "App module set to tmp_app.main_base:app."
         )
 
     def test_set_app_module_custom_fastapi(
         self,
         app_module_tmp_path: Path,
-        mock_logger: logging.Logger,
+        mocker: MockerFixture,
         monkeypatch: pytest.MonkeyPatch,
     ) -> None:
         """Test `start.set_app_module` with custom module path to FastAPI app."""
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
         monkeypatch.syspath_prepend(app_module_tmp_path)
         monkeypatch.setenv("APP_MODULE", "tmp_app.main_fastapi:app")
         start.set_app_module(logger=mock_logger)
-        mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
+        mock_logger.debug.assert_called_once_with(
             "App module set to tmp_app.main_fastapi:app."
         )
 
     def test_set_app_module_custom_starlette(
         self,
         app_module_tmp_path: Path,
-        mock_logger: logging.Logger,
+        mocker: MockerFixture,
         monkeypatch: pytest.MonkeyPatch,
     ) -> None:
         """Test `start.set_app_module` with custom module path to Starlette app."""
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
         monkeypatch.syspath_prepend(app_module_tmp_path)
         monkeypatch.setenv("APP_MODULE", "tmp_app.main_starlette:app")
         start.set_app_module(logger=mock_logger)
-        mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
+        mock_logger.debug.assert_called_once_with(
             "App module set to tmp_app.main_starlette:app."
         )
 
     def test_set_app_module_incorrect(
         self,
         mocker: MockerFixture,
-        mock_logger: logging.Logger,
         monkeypatch: pytest.MonkeyPatch,
     ) -> None:
         """Test `start.set_app_module` with incorrect module path."""
-        with pytest.raises(ModuleNotFoundError):
-            incorrect_module = "inboard.app.incorrect.main:app"
-            monkeypatch.setenv("APP_MODULE", incorrect_module)
-            logger_error_msg = "Error when setting app module:"
-            incorrect_module_msg = f"No module named {incorrect_module}"
+        mock_logger = mocker.patch.object(start.logging, "root", autospec=True)
+        monkeypatch.setenv("APP_MODULE", "inboard.app.incorrect:app")
+        logger_error_msg = "Error when setting app module"
+        incorrect_module_msg = "Unable to find or import inboard.app.incorrect"
+        with pytest.raises(ImportError):
             start.set_app_module(logger=mock_logger)
-            mock_logger.debug.assert_called_once_with(  # type: ignore[attr-defined]
-                f"{logger_error_msg} {incorrect_module_msg}."
-            )
+        mock_logger.error.assert_called_once_with(
+            f"{logger_error_msg}: ImportError {incorrect_module_msg}."
+        )
 
 
 class TestRunPreStartScript: