From 5320752d43bf80720724f569dfc0f55b0ecd53de Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Wed, 21 Dec 2022 20:55:53 -0600 Subject: [PATCH 01/11] feat: add console output for exceptions in debug mode --- starlite/middleware/exceptions/middleware.py | 2 ++ .../test_exception_handler_middleware.py | 27 +++++++++++++++++++ 2 files changed, 29 insertions(+) diff --git a/starlite/middleware/exceptions/middleware.py b/starlite/middleware/exceptions/middleware.py index 81ef378aca..f3c08cc73b 100644 --- a/starlite/middleware/exceptions/middleware.py +++ b/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.logger): + logger.debug("Exception in ASGI application", exc_info=True) for hook in starlite_app.after_exception: await hook(e, scope, starlite_app.state) diff --git a/tests/middleware/test_exception_handler_middleware.py b/tests/middleware/test_exception_handler_middleware.py index 6f5acde532..0519df6389 100644 --- a/tests/middleware/test_exception_handler_middleware.py +++ b/tests/middleware/test_exception_handler_middleware.py @@ -118,3 +118,30 @@ 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 + + +def test_exception_handler_middleware_debug_logging() -> None: + from unittest.mock import patch + + @get("/test") + def handler() -> None: + raise RuntimeError() + + with create_test_client(handler) as client, patch("logging.Logger.debug") as mock_debug: + client.app.debug = True + response = client.get("/test") + assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR + mock_debug.assert_called_once_with("Exception in ASGI application", exc_info=True) + + with create_test_client(handler) as client, patch("logging.Logger.debug") as mock_debug: + client.app.debug = False + response = client.get("/test") + assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR + mock_debug.assert_not_called() + + with create_test_client(handler) as client, patch("logging.Logger.debug") as mock_debug: + client.app.debug = False + client.app.logger = None + response = client.get("/test") + assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR + mock_debug.assert_not_called() From 0f19be726682b23e25300f9e7e0d4c79881f5306 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Sat, 21 Jan 2023 13:08:06 -0600 Subject: [PATCH 02/11] chore: middleware debug logging updates --- .../test_exception_handler_middleware.py | 37 ++++++++++++------- 1 file changed, 24 insertions(+), 13 deletions(-) diff --git a/tests/middleware/test_exception_handler_middleware.py b/tests/middleware/test_exception_handler_middleware.py index 0519df6389..8937f52f60 100644 --- a/tests/middleware/test_exception_handler_middleware.py +++ b/tests/middleware/test_exception_handler_middleware.py @@ -3,12 +3,14 @@ from starlette.exceptions import HTTPException as StarletteHTTPException -from starlite import HTTPException, Request, Response, Starlite, get +from starlite import HTTPException, LoggingConfig, Request, Response, Starlite, 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 @@ -120,28 +122,37 @@ async def after_exception_hook_handler(exc: Exception, scope: "Scope", state: "S assert client.app.state.called -def test_exception_handler_middleware_debug_logging() -> None: - from unittest.mock import patch - +def test_exception_handler_middleware_debug_logging(caplog: "LogCaptureFixture") -> None: @get("/test") def handler() -> None: - raise RuntimeError() + raise ValueError("Test debug exception") - with create_test_client(handler) as client, patch("logging.Logger.debug") as mock_debug: + # Debug On -> Exception is logged + with create_test_client(handler, logging_config=LoggingConfig()) as client: + caplog.set_level("DEBUG") client.app.debug = True response = client.get("/test") assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR - mock_debug.assert_called_once_with("Exception in ASGI application", exc_info=True) + assert "Internal Server Error" in caplog.text + assert "ValueError" in caplog.text + assert "Test debug exception" in caplog.text - with create_test_client(handler) as client, patch("logging.Logger.debug") as mock_debug: + # Debug Off -> Exception is not logged + with create_test_client(handler, logging_config=LoggingConfig()) as client: + caplog.set_level("INFO") client.app.debug = False response = client.get("/test") assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR - mock_debug.assert_not_called() + assert "Exception in ASGI application" not in caplog.text + assert "ValueError" not in caplog.text + assert "Test debug exception" not in caplog.text - with create_test_client(handler) as client, patch("logging.Logger.debug") as mock_debug: - client.app.debug = False - client.app.logger = None + # Debug On + No Logger -> No Debug Logging + with create_test_client(handler, logging_config=None) as client: + caplog.set_level("DEBUG") + client.app.debug = True response = client.get("/test") assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR - mock_debug.assert_not_called() + assert "Internal Server Error" not in caplog.text + assert "ValueError" not in caplog.text + assert "Test debug exception" not in caplog.text From ad951a3db5d6df2e8b31363fa85921a781edc32f Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Mon, 23 Jan 2023 16:53:58 -0600 Subject: [PATCH 03/11] feat: #958 testing passing --- .../test_exception_handler_middleware.py | 25 ++++++++----------- 1 file changed, 11 insertions(+), 14 deletions(-) diff --git a/tests/middleware/test_exception_handler_middleware.py b/tests/middleware/test_exception_handler_middleware.py index 8937f52f60..b1f37dadf6 100644 --- a/tests/middleware/test_exception_handler_middleware.py +++ b/tests/middleware/test_exception_handler_middleware.py @@ -128,31 +128,28 @@ def handler() -> None: raise ValueError("Test debug exception") # Debug On -> Exception is logged - with create_test_client(handler, logging_config=LoggingConfig()) as client: - caplog.set_level("DEBUG") + with caplog.at_level("DEBUG"), create_test_client(handler, logging_config=LoggingConfig()) as client: client.app.debug = True response = client.get("/test") assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR assert "Internal Server Error" in caplog.text - assert "ValueError" in caplog.text - assert "Test debug exception" in caplog.text + assert "ValueError" in response.text + assert "Test debug exception" in response.text - # Debug Off -> Exception is not logged - with create_test_client(handler, logging_config=LoggingConfig()) as client: - caplog.set_level("INFO") + # Debug Off -> Exception is not logged + with caplog.at_level("INFO"), create_test_client(handler, logging_config=LoggingConfig()) as client: client.app.debug = False response = client.get("/test") assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR assert "Exception in ASGI application" not in caplog.text - assert "ValueError" not in caplog.text - assert "Test debug exception" not in caplog.text + assert "ValueError" in response.text + assert "Test debug exception" in response.text # Debug On + No Logger -> No Debug Logging - with create_test_client(handler, logging_config=None) as client: - caplog.set_level("DEBUG") + with caplog.at_level("DEBUG"), create_test_client(handler, logging_config=None) as client: client.app.debug = True response = client.get("/test") assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR - assert "Internal Server Error" not in caplog.text - assert "ValueError" not in caplog.text - assert "Test debug exception" not in caplog.text + assert "Internal Server Error" in caplog.text + assert "Test debug exception" in response.text + assert "ValueError" in response.text From 998c4cdccfe31c8e400d833eb97937c2674a28e5 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Tue, 24 Jan 2023 16:46:37 -0600 Subject: [PATCH 04/11] Update starlite/middleware/exceptions/middleware.py Co-authored-by: Na'aman Hirschfeld --- starlite/middleware/exceptions/middleware.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/starlite/middleware/exceptions/middleware.py b/starlite/middleware/exceptions/middleware.py index 5ec1ddce38..44ee963d17 100644 --- a/starlite/middleware/exceptions/middleware.py +++ b/starlite/middleware/exceptions/middleware.py @@ -48,7 +48,7 @@ async def __call__(self, scope: "Scope", receive: "Receive", send: "Send") -> No except Exception as e: # pylint: disable=broad-except starlite_app = scope["app"] if self.debug and (logger := starlite_app.logger): - logger.debug("Exception in ASGI application", exc_info=True) + 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) From 5f37e991d98e43d5cff8516ca659896d414b65ab Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Thu, 26 Jan 2023 20:34:19 -0600 Subject: [PATCH 05/11] chore: fixed test for middleware debug logging (#958) --- tests/middleware/test_exception_handler_middleware.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/middleware/test_exception_handler_middleware.py b/tests/middleware/test_exception_handler_middleware.py index b1f37dadf6..394f67a913 100644 --- a/tests/middleware/test_exception_handler_middleware.py +++ b/tests/middleware/test_exception_handler_middleware.py @@ -150,6 +150,6 @@ def handler() -> None: client.app.debug = True response = client.get("/test") assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR - assert "Internal Server Error" in caplog.text + assert "Internal Server Error" not in caplog.text assert "Test debug exception" in response.text assert "ValueError" in response.text From bac6a185dbcb40ea609bb21413bab772af1fe9e5 Mon Sep 17 00:00:00 2001 From: provinzkraut <25355197+provinzkraut@users.noreply.github.com> Date: Tue, 31 Jan 2023 13:53:45 +0100 Subject: [PATCH 06/11] Update tests/middleware/test_exception_handler_middleware.py --- .../test_exception_handler_middleware.py | 43 ++++++++----------- 1 file changed, 19 insertions(+), 24 deletions(-) diff --git a/tests/middleware/test_exception_handler_middleware.py b/tests/middleware/test_exception_handler_middleware.py index 394f67a913..4b5e47fc70 100644 --- a/tests/middleware/test_exception_handler_middleware.py +++ b/tests/middleware/test_exception_handler_middleware.py @@ -121,35 +121,30 @@ async def after_exception_hook_handler(exc: Exception, scope: "Scope", state: "S assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR assert client.app.state.called - -def test_exception_handler_middleware_debug_logging(caplog: "LogCaptureFixture") -> None: +@pytest.mark.parametrize( + "debug,logging_config", + [ + (True, LoggingConfig()), + (False, LoggingConfig()), + (False, None), + ], +) +def test_exception_handler_middleware_debug_logging( + caplog: "LogCaptureFixture", debug: bool, logging_config: Optional[LoggingConfig] +) -> None: @get("/test") def handler() -> None: raise ValueError("Test debug exception") - # Debug On -> Exception is logged - with caplog.at_level("DEBUG"), create_test_client(handler, logging_config=LoggingConfig()) as client: - client.app.debug = True - response = client.get("/test") - assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR - assert "Internal Server Error" in caplog.text - assert "ValueError" in response.text - assert "Test debug exception" in response.text - - # Debug Off -> Exception is not logged - with caplog.at_level("INFO"), create_test_client(handler, logging_config=LoggingConfig()) as client: - client.app.debug = False - response = client.get("/test") - assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR - assert "Exception in ASGI application" not in caplog.text - assert "ValueError" in response.text - assert "Test debug exception" in response.text + app = Starlite([handler], logging_config=logging_config, debug=debug) - # Debug On + No Logger -> No Debug Logging - with caplog.at_level("DEBUG"), create_test_client(handler, logging_config=None) as client: - client.app.debug = True + with caplog.at_level("DEBUG", "starlite"), TestClient(app=app) as client: response = client.get("/test") assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR - assert "Internal Server Error" not in caplog.text assert "Test debug exception" in response.text - assert "ValueError" in response.text + + if debug and logging_config: + assert len(caplog.records) == 1 + # other assertions for the content of this record here + else: + assert not caplog.records From e42d92712f39c5cf278a85f9f47dabe688224e83 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Tue, 31 Jan 2023 22:52:36 -0600 Subject: [PATCH 07/11] chore: fixed test for middleware debug logging (#958) --- .../test_exception_handler_middleware.py | 16 +++++++++++++--- 1 file changed, 13 insertions(+), 3 deletions(-) diff --git a/tests/middleware/test_exception_handler_middleware.py b/tests/middleware/test_exception_handler_middleware.py index 4b5e47fc70..6f56ee04d8 100644 --- a/tests/middleware/test_exception_handler_middleware.py +++ b/tests/middleware/test_exception_handler_middleware.py @@ -1,9 +1,18 @@ 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, LoggingConfig, 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 @@ -121,6 +130,7 @@ async def after_exception_hook_handler(exc: Exception, scope: "Scope", state: "S assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR assert client.app.state.called + @pytest.mark.parametrize( "debug,logging_config", [ @@ -142,7 +152,7 @@ def handler() -> None: 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 # other assertions for the content of this record here From dc74af2958e9bbabb3c2d025ee364202f2957dc4 Mon Sep 17 00:00:00 2001 From: Peter Schutt Date: Fri, 3 Feb 2023 19:36:48 +1000 Subject: [PATCH 08/11] 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. --- tests/middleware/conftest.py | 20 +++++++++++++++++++ .../test_exception_handler_middleware.py | 4 +++- tests/middleware/test_logging_middleware.py | 13 ------------ 3 files changed, 23 insertions(+), 14 deletions(-) create mode 100644 tests/middleware/conftest.py diff --git a/tests/middleware/conftest.py b/tests/middleware/conftest.py new file mode 100644 index 0000000000..547cc976c7 --- /dev/null +++ b/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() diff --git a/tests/middleware/test_exception_handler_middleware.py b/tests/middleware/test_exception_handler_middleware.py index 6f56ee04d8..959b9d1ba9 100644 --- a/tests/middleware/test_exception_handler_middleware.py +++ b/tests/middleware/test_exception_handler_middleware.py @@ -22,6 +22,7 @@ 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: @@ -140,7 +141,7 @@ async def after_exception_hook_handler(exc: Exception, scope: "Scope", state: "S ], ) def test_exception_handler_middleware_debug_logging( - caplog: "LogCaptureFixture", debug: bool, logging_config: Optional[LoggingConfig] + get_logger: "GetLogger", caplog: "LogCaptureFixture", debug: bool, logging_config: Optional[LoggingConfig] ) -> None: @get("/test") def handler() -> None: @@ -149,6 +150,7 @@ def handler() -> None: 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 diff --git a/tests/middleware/test_logging_middleware.py b/tests/middleware/test_logging_middleware.py index 4cb99c22cb..9d1fe88ebe 100644 --- a/tests/middleware/test_logging_middleware.py +++ b/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] From 9bc01e61cecdb4fd7d5c883386bccde9210c0b0d Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 3 Feb 2023 11:10:01 -0600 Subject: [PATCH 09/11] chore: Updated assertions (#958) --- tests/middleware/test_exception_handler_middleware.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/tests/middleware/test_exception_handler_middleware.py b/tests/middleware/test_exception_handler_middleware.py index 959b9d1ba9..9ee77fc0d3 100644 --- a/tests/middleware/test_exception_handler_middleware.py +++ b/tests/middleware/test_exception_handler_middleware.py @@ -157,6 +157,8 @@ def handler() -> None: if debug and logging_config: assert len(caplog.records) == 1 - # other assertions for the content of this record here + 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 From 8a0d0edf7cf07907366d4173ebe3b3c2febccca8 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 3 Feb 2023 15:32:59 -0600 Subject: [PATCH 10/11] Update starlite/middleware/exceptions/middleware.py Co-authored-by: Na'aman Hirschfeld --- starlite/middleware/exceptions/middleware.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/starlite/middleware/exceptions/middleware.py b/starlite/middleware/exceptions/middleware.py index 44ee963d17..b60cea2ced 100644 --- a/starlite/middleware/exceptions/middleware.py +++ b/starlite/middleware/exceptions/middleware.py @@ -47,7 +47,7 @@ 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.logger): + if self.debug and (logger := starlite_app.get_logge()): 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) From dffccbf9a7ae20cdc8921196af552951a42154a3 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 3 Feb 2023 15:37:12 -0600 Subject: [PATCH 11/11] chore: update logger method --- starlite/middleware/exceptions/middleware.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/starlite/middleware/exceptions/middleware.py b/starlite/middleware/exceptions/middleware.py index b60cea2ced..afe6716bd7 100644 --- a/starlite/middleware/exceptions/middleware.py +++ b/starlite/middleware/exceptions/middleware.py @@ -47,7 +47,7 @@ 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_logge()): + 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)