(958) Add exception logging in debug mode (#976)

* feat: add console output for exceptions in debug mode

* chore: middleware debug logging updates

* feat: #958 testing passing

* Update starlite/middleware/exceptions/middleware.py

Co-authored-by: Na'aman Hirschfeld <nhirschfeld@gmail.com>

* chore: fixed test for middleware debug logging (#958)

* Update tests/middleware/test_exception_handler_middleware.py

* chore: fixed test for middleware debug logging (#958)

* Use `get_logger` fixture to test exception logged in debug.

- moves get_logger fixture to conftest.py for middleware tests
- patches app logger in tests with one that propagates so caplog works.

* chore: Updated assertions (#958)

* Update starlite/middleware/exceptions/middleware.py

Co-authored-by: Na'aman Hirschfeld <nhirschfeld@gmail.com>

* chore: update logger method

---------

Co-authored-by: Jacob Coffee <jcoffee5@oreillyauto.com>
Co-authored-by: Cody Fincher <204685+cofin@users.noreply.github.com>
Co-authored-by: Na'aman Hirschfeld <nhirschfeld@gmail.com>
Co-authored-by: provinzkraut <25355197+provinzkraut@users.noreply.github.com>
Co-authored-by: Peter Schutt <peter@topsport.com.au>
Co-authored-by: Peter Schutt <peter_schutt@bigpond.com>
Co-authored-by: Peter Schutt <peter.github@proton.me>

starlite/middleware/exceptions/middleware.py

@@ -47,6 +47,8 @@ async def __call__(self, scope: "Scope", receive: "Receive", send: "Send") -> No
             await self.app(scope, receive, send)
         except Exception as e:  # pylint: disable=broad-except
             starlite_app = scope["app"]
+            if self.debug and (logger := starlite_app.get_logger()):
+                logger.debug("exception raised for request to route %s", scope["path"], exc_info=True)
             for hook in starlite_app.after_exception:
                 await hook(e, scope, starlite_app.state)
 

tests/middleware/conftest.py

@@ -0,0 +1,20 @@
+from typing import TYPE_CHECKING
+
+import pytest
+
+from starlite.config.logging import LoggingConfig, default_handlers
+
+if TYPE_CHECKING:
+    from starlite.types.callable_types import GetLogger
+
+
+@pytest.fixture
+def get_logger() -> "GetLogger":
+    # due to the limitations of caplog we have to place this call here.
+    # we also have to allow propagation.
+    return LoggingConfig(
+        handlers=default_handlers,
+        loggers={
+            "starlite": {"level": "DEBUG", "handlers": ["queue_listener"], "propagate": True},
+        },
+    ).configure()

tests/middleware/test_exception_handler_middleware.py

@@ -1,16 +1,28 @@
 import json
-from typing import TYPE_CHECKING, Any
+from typing import TYPE_CHECKING, Any, Optional
 
+import pytest
 from starlette.exceptions import HTTPException as StarletteHTTPException
 
-from starlite import HTTPException, Request, Response, Starlite, get
+from starlite import (
+    HTTPException,
+    LoggingConfig,
+    Request,
+    Response,
+    Starlite,
+    TestClient,
+    get,
+)
 from starlite.middleware.exceptions import ExceptionHandlerMiddleware
 from starlite.status_codes import HTTP_500_INTERNAL_SERVER_ERROR
 from starlite.testing import create_test_client
 
 if TYPE_CHECKING:
+    from _pytest.logging import LogCaptureFixture
+
     from starlite.datastructures import State
     from starlite.types import Scope
+    from starlite.types.callable_types import GetLogger
 
 
 async def dummy_app(scope: Any, receive: Any, send: Any) -> None:
@@ -118,3 +130,35 @@ async def after_exception_hook_handler(exc: Exception, scope: "Scope", state: "S
         response = client.get("/test")
         assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR
         assert client.app.state.called
+
+
+@pytest.mark.parametrize(
+    "debug,logging_config",
+    [
+        (True, LoggingConfig()),
+        (False, LoggingConfig()),
+        (False, None),
+    ],
+)
+def test_exception_handler_middleware_debug_logging(
+    get_logger: "GetLogger", caplog: "LogCaptureFixture", debug: bool, logging_config: Optional[LoggingConfig]
+) -> None:
+    @get("/test")
+    def handler() -> None:
+        raise ValueError("Test debug exception")
+
+    app = Starlite([handler], logging_config=logging_config, debug=debug)
+
+    with caplog.at_level("DEBUG", "starlite"), TestClient(app=app) as client:
+        client.app.logger = get_logger("starlite")
+        response = client.get("/test")
+        assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR
+        assert "Test debug exception" in response.text
+
+        if debug and logging_config:
+            assert len(caplog.records) == 1
+            assert caplog.records[0].levelname == "DEBUG"
+            assert "exception raised for request to route" in caplog.records[0].message
+        else:
+            assert not caplog.records
+            assert "exception raised for request to route" not in response.text

tests/middleware/test_logging_middleware.py

@@ -6,7 +6,6 @@
 
 from starlite import Cookie, LoggingConfig, Response, StructLoggingConfig, get, post
 from starlite.config.compression import CompressionConfig
-from starlite.config.logging import default_handlers
 from starlite.middleware import LoggingMiddlewareConfig
 from starlite.status_codes import HTTP_200_OK
 from starlite.testing import create_test_client
@@ -26,18 +25,6 @@ def handler() -> Response:
     )
 
 
-@pytest.fixture
-def get_logger() -> "GetLogger":
-    # due to the limitations of caplog we have to place this call here.
-    # we also have to allow propagation.
-    return LoggingConfig(
-        handlers=default_handlers,
-        loggers={
-            "starlite": {"level": "INFO", "handlers": ["queue_listener"], "propagate": True},
-        },
-    ).configure()
-
-
 def test_logging_middleware_regular_logger(get_logger: "GetLogger", caplog: "LogCaptureFixture") -> None:
     with create_test_client(
         route_handlers=[handler], middleware=[LoggingMiddlewareConfig().middleware]