From 972ee6764c92e45c45fa3635436c9d041c84a895 Mon Sep 17 00:00:00 2001 From: jderrien Date: Thu, 30 May 2024 11:45:34 +0200 Subject: [PATCH] fix(logging): do not log exceptions twice, deprecate `traceback_line_limit` and fix `pretty_print_tty` (#3507) * fix(logging): `pretty_print_tty` property from `StructLoggingConfig` * fix(logging): do not log exceptions twice and deprecate `traceback_line_limit` --- litestar/logging/config.py | 68 +++++++++++++------ .../unit/test_logging/test_logging_config.py | 13 ++++ .../test_logging/test_structlog_config.py | 17 +++++ .../test_exception_handler_middleware.py | 52 ++------------ 4 files changed, 80 insertions(+), 70 deletions(-) diff --git a/litestar/logging/config.py b/litestar/logging/config.py index c084c5d034..2b1587c89f 100644 --- a/litestar/logging/config.py +++ b/litestar/logging/config.py @@ -10,7 +10,7 @@ from litestar.exceptions import ImproperlyConfiguredException, MissingDependencyException from litestar.serialization.msgspec_hooks import _msgspec_json_encoder from litestar.utils.dataclass import simple_asdict -from litestar.utils.deprecation import deprecated +from litestar.utils.deprecation import deprecated, warn_deprecation __all__ = ("BaseLoggingConfig", "LoggingConfig", "StructLoggingConfig") @@ -90,34 +90,45 @@ def _get_default_handlers() -> dict[str, dict[str, Any]]: def _default_exception_logging_handler_factory( - is_struct_logger: bool, traceback_line_limit: int + is_struct_logger: bool, + traceback_line_limit: int, ) -> ExceptionLoggingHandler: """Create an exception logging handler function. Args: is_struct_logger: Whether the logger is a structlog instance. traceback_line_limit: Maximal number of lines to log from the - traceback. + traceback. This parameter is deprecated and ignored. Returns: An exception logging handler. """ - def _default_exception_logging_handler(logger: Logger, scope: Scope, tb: list[str]) -> None: - # we limit the length of the stack trace to 20 lines. - first_line = tb.pop(0) + if traceback_line_limit != -1: + warn_deprecation( + version="2.9.0", + deprecated_name="traceback_line_limit", + kind="parameter", + info="The value is ignored. Use a custom 'exception_logging_handler' instead.", + removal_in="3.0", + ) + + if is_struct_logger: - if is_struct_logger: + def _default_exception_logging_handler(logger: Logger, scope: Scope, tb: list[str]) -> None: logger.exception( - "Uncaught Exception", + "Uncaught exception", connection_type=scope["type"], path=scope["path"], - traceback="".join(tb[-traceback_line_limit:]), ) - else: - stack_trace = first_line + "".join(tb[-traceback_line_limit:]) + + else: + + def _default_exception_logging_handler(logger: Logger, scope: Scope, tb: list[str]) -> None: logger.exception( - "exception raised on %s connection to route %s\n\n%s", scope["type"], scope["path"], stack_trace + "Uncaught exception (connection_type=%s, path=%s):", + scope["type"], + scope["path"], ) return _default_exception_logging_handler @@ -131,7 +142,11 @@ class BaseLoggingConfig(ABC): log_exceptions: Literal["always", "debug", "never"] """Should exceptions be logged, defaults to log exceptions when ``app.debug == True``'""" traceback_line_limit: int - """Max number of lines to print for exception traceback""" + """Max number of lines to print for exception traceback. + + .. deprecated:: 2.9.0 + This parameter is deprecated and ignored. It will be removed in a future release. + """ exception_logging_handler: ExceptionLoggingHandler | None """Handler function for logging exceptions.""" @@ -205,8 +220,12 @@ class LoggingConfig(BaseLoggingConfig): """Should the root logger be configured, defaults to True for ease of configuration.""" log_exceptions: Literal["always", "debug", "never"] = field(default="debug") """Should exceptions be logged, defaults to log exceptions when 'app.debug == True'""" - traceback_line_limit: int = field(default=20) - """Max number of lines to print for exception traceback""" + traceback_line_limit: int = field(default=-1) + """Max number of lines to print for exception traceback. + + .. deprecated:: 2.9.0 + This parameter is deprecated and ignored. It will be removed in a future release. + """ exception_logging_handler: ExceptionLoggingHandler | None = field(default=None) """Handler function for logging exceptions.""" @@ -421,8 +440,12 @@ class StructLoggingConfig(BaseLoggingConfig): """Whether to cache the logger configuration and reuse.""" log_exceptions: Literal["always", "debug", "never"] = field(default="debug") """Should exceptions be logged, defaults to log exceptions when 'app.debug == True'""" - traceback_line_limit: int = field(default=20) - """Max number of lines to print for exception traceback""" + traceback_line_limit: int = field(default=-1) + """Max number of lines to print for exception traceback. + + .. deprecated:: 2.9.0 + This parameter is deprecated and ignored. It will be removed in a future release. + """ exception_logging_handler: ExceptionLoggingHandler | None = field(default=None) """Handler function for logging exceptions.""" pretty_print_tty: bool = field(default=True) @@ -430,9 +453,9 @@ class StructLoggingConfig(BaseLoggingConfig): def __post_init__(self) -> None: if self.processors is None: - self.processors = default_structlog_processors(not sys.stderr.isatty() and self.pretty_print_tty) + self.processors = default_structlog_processors(as_json=self.as_json()) if self.logger_factory is None: - self.logger_factory = default_logger_factory(not sys.stderr.isatty() and self.pretty_print_tty) + self.logger_factory = default_logger_factory(as_json=self.as_json()) if self.log_exceptions != "never" and self.exception_logging_handler is None: self.exception_logging_handler = _default_exception_logging_handler_factory( is_struct_logger=True, traceback_line_limit=self.traceback_line_limit @@ -445,15 +468,16 @@ def __post_init__(self) -> None: formatters={ "standard": { "()": structlog.stdlib.ProcessorFormatter, - "processors": default_structlog_standard_lib_processors( - as_json=not sys.stderr.isatty() and self.pretty_print_tty - ), + "processors": default_structlog_standard_lib_processors(as_json=self.as_json()), } } ) except ImportError: self.standard_lib_logging_config = LoggingConfig() + def as_json(self) -> bool: + return not (sys.stderr.isatty() and self.pretty_print_tty) + def configure(self) -> GetLogger: """Return logger with the given configuration. diff --git a/tests/unit/test_logging/test_logging_config.py b/tests/unit/test_logging/test_logging_config.py index e318ed730f..80731ffe38 100644 --- a/tests/unit/test_logging/test_logging_config.py +++ b/tests/unit/test_logging/test_logging_config.py @@ -219,3 +219,16 @@ def test_customizing_handler(handlers: Any, expected_handler_class: Any, monkeyp else: formatter = root_logger_handler.formatter assert formatter._fmt == log_format + + +@pytest.mark.parametrize( + "traceback_line_limit, expected_warning_deprecation_called", + [ + [-1, False], + [20, True], + ], +) +def test_traceback_line_limit_deprecation(traceback_line_limit: int, expected_warning_deprecation_called: bool) -> None: + with patch("litestar.logging.config.warn_deprecation") as mock_warning_deprecation: + LoggingConfig(traceback_line_limit=traceback_line_limit) + assert mock_warning_deprecation.called is expected_warning_deprecation_called diff --git a/tests/unit/test_logging/test_structlog_config.py b/tests/unit/test_logging/test_structlog_config.py index 4f8e695496..30e80b7e5c 100644 --- a/tests/unit/test_logging/test_structlog_config.py +++ b/tests/unit/test_logging/test_structlog_config.py @@ -1,6 +1,7 @@ import datetime import sys from typing import Callable +from unittest.mock import patch import pytest import structlog @@ -155,3 +156,19 @@ def test_structlog_config_specify_processors(capsys: CaptureFixture) -> None: {"key": "value1", "event": "message1"}, {"key": "value2", "event": "message2"}, ] + + +@pytest.mark.parametrize( + "isatty, pretty_print_tty, expected_as_json", + [ + (True, True, False), + (True, False, True), + (False, True, True), + (False, False, True), + ], +) +def test_structlog_config_as_json(isatty: bool, pretty_print_tty: bool, expected_as_json: bool) -> None: + with patch("litestar.logging.config.sys.stderr.isatty") as isatty_mock: + isatty_mock.return_value = isatty + logging_config = StructLoggingConfig(pretty_print_tty=pretty_print_tty) + assert logging_config.as_json() is expected_as_json diff --git a/tests/unit/test_middleware/test_exception_handler_middleware.py b/tests/unit/test_middleware/test_exception_handler_middleware.py index cfa10fd7e8..a1540d353c 100644 --- a/tests/unit/test_middleware/test_exception_handler_middleware.py +++ b/tests/unit/test_middleware/test_exception_handler_middleware.py @@ -3,7 +3,6 @@ from unittest.mock import MagicMock import pytest -from _pytest.capture import CaptureFixture from pytest_mock import MockerFixture from starlette.exceptions import HTTPException as StarletteHTTPException from structlog.testing import capture_logs @@ -205,12 +204,10 @@ def handler() -> None: if should_log: assert len(caplog.records) == 1 assert caplog.records[0].levelname == "ERROR" - assert caplog.records[0].message.startswith( - "exception raised on http connection to route /test\n\nTraceback (most recent call last):\n" - ) + assert caplog.records[0].message.startswith("Uncaught exception (connection_type=http, path=/test):") else: assert not caplog.records - assert "exception raised on http connection request to route /test" not in response.text + assert "Uncaught exception" not in response.text @pytest.mark.parametrize( @@ -228,7 +225,6 @@ def handler() -> None: ) def test_exception_handler_struct_logging( get_logger: "GetLogger", - capsys: CaptureFixture, is_debug: bool, logging_config: Optional[LoggingConfig], should_log: bool, @@ -251,50 +247,12 @@ def handler() -> None: assert len(cap_logs) == 1 assert cap_logs[0].get("connection_type") == "http" assert cap_logs[0].get("path") == "/test" - assert cap_logs[0].get("traceback") - assert cap_logs[0].get("event") == "Uncaught Exception" + assert cap_logs[0].get("event") == "Uncaught exception" assert cap_logs[0].get("log_level") == "error" else: assert not cap_logs -def test_traceback_truncate_default_logging( - get_logger: "GetLogger", - caplog: "LogCaptureFixture", -) -> None: - @get("/test") - def handler() -> None: - raise ValueError("Test debug exception") - - app = Litestar([handler], logging_config=LoggingConfig(log_exceptions="always", traceback_line_limit=1)) - - with caplog.at_level("ERROR", "litestar"), TestClient(app=app) as client: - client.app.logger = get_logger("litestar") - response = client.get("/test") - assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR - assert "Internal Server Error" in response.text - - assert len(caplog.records) == 1 - assert caplog.records[0].levelname == "ERROR" - assert caplog.records[0].message == ( - "exception raised on http connection to route /test\n\nTraceback (most recent call last):\nValueError: Test debug exception\n" - ) - - -def test_traceback_truncate_struct_logging() -> None: - @get("/test") - def handler() -> None: - raise ValueError("Test debug exception") - - app = Litestar([handler], logging_config=StructLoggingConfig(log_exceptions="always", traceback_line_limit=1)) - - with TestClient(app=app) as client, capture_logs() as cap_logs: - response = client.get("/test") - assert response.status_code == HTTP_500_INTERNAL_SERVER_ERROR - assert len(cap_logs) == 1 - assert cap_logs[0].get("traceback") == "ValueError: Test debug exception\n" - - def handler(_: Any, __: Any) -> Any: return None @@ -358,9 +316,7 @@ def handler() -> None: assert "Test debug exception" in response.text assert len(caplog.records) == 1 assert caplog.records[0].levelname == "ERROR" - assert caplog.records[0].message.startswith( - "exception raised on http connection to route /test\n\nTraceback (most recent call last):\n" - ) + assert caplog.records[0].message.startswith("Uncaught exception (connection_type=http, path=/test):") def test_get_symbol_name_where_type_doesnt_support_bool() -> None: