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

@@ -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,18 +440,22 @@ 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)
     """Pretty print log output when run from an interactive terminal."""
 
     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.
 

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

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

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: