fix(logging): queue_listener handler for Python >= 3.12 (#3185)

* fix(logging): queue_listener handler for Python >= 3.12

* Update litestar/logging/standard.py

* Update litestar/logging/standard.py

* Update litestar/logging/standard.py

* refactor(logging): refactor `litestar.logging.standard` to get correct API docs

---------

Co-authored-by: Jacob Coffee <[email protected]>

litestar/logging/config.py

@@ -2,13 +2,12 @@
 
 import sys
 from abc import ABC, abstractmethod
-from dataclasses import asdict, dataclass, field
+from dataclasses import asdict, dataclass, field, fields
 from importlib.util import find_spec
 from logging import INFO
 from typing import TYPE_CHECKING, Any, Callable, Literal, cast
 
 from litestar.exceptions import ImproperlyConfiguredException, MissingDependencyException
-from litestar.serialization import encode_json
 from litestar.serialization.msgspec_hooks import _msgspec_json_encoder
 from litestar.utils.deprecation import deprecated
 
@@ -49,7 +48,20 @@
 }
 
 if sys.version_info >= (3, 12, 0):
-    default_handlers["queue_listener"]["handlers"] = ["console"]
+    default_handlers["queue_listener"].update(
+        {
+            "class": "logging.handlers.QueueHandler",
+            "queue": {
+                "()": "queue.Queue",
+                "maxsize": -1,
+            },
+            "listener": "litestar.logging.standard.LoggingQueueListener",
+            "handlers": ["console"],
+        }
+    )
+
+    # do not format twice, the console handler will do the job
+    del default_handlers["queue_listener"]["formatter"]
 
 
 default_picologging_handlers: dict[str, dict[str, Any]] = {
@@ -228,21 +240,25 @@ def configure(self) -> GetLogger:
             A 'logging.getLogger' like function.
         """
 
-        if "picologging" in str(encode_json(self.handlers)):
+        excluded_fields: tuple[str, ...]
+        if "picologging" in " ".join([handler["class"] for handler in self.handlers.values()]):
             try:
                 from picologging import config, getLogger
             except ImportError as e:
                 raise MissingDependencyException("picologging") from e
 
-            values = {
-                k: v
-                for k, v in asdict(self).items()
-                if v is not None and k not in ("incremental", "configure_root_logger")
-            }
+            excluded_fields = ("incremental", "configure_root_logger")
         else:
             from logging import config, getLogger  # type: ignore[no-redef, assignment]
 
-            values = {k: v for k, v in asdict(self).items() if v is not None and k not in ("configure_root_logger",)}
+            excluded_fields = ("configure_root_logger",)
+
+        values = {
+            _field.name: getattr(self, _field.name)
+            for _field in fields(self)
+            if getattr(self, _field.name) is not None and _field.name not in excluded_fields
+        }
+
         if not self.configure_root_logger:
             values.pop("root")
         config.dictConfig(values)

litestar/logging/standard.py

@@ -1,34 +1,47 @@
 from __future__ import annotations
 
 import atexit
-import sys
-from logging import StreamHandler
+from logging import Handler, LogRecord, StreamHandler
 from logging.handlers import QueueHandler, QueueListener
 from queue import Queue
 from typing import Any
 
 from litestar.logging._utils import resolve_handlers
 
-__all__ = ("QueueListenerHandler",)
+__all__ = ("LoggingQueueListener", "QueueListenerHandler")
 
 
-if sys.version_info < (3, 12):
+class LoggingQueueListener(QueueListener):
+    """Custom ``QueueListener`` which starts and stops the listening process."""
 
-    class QueueListenerHandler(QueueHandler):
-        """Configure queue listener and handler to support non-blocking logging configuration."""
+    def __init__(self, queue: Queue[LogRecord], *handlers: Handler, respect_handler_level: bool = False) -> None:
+        """Initialize ``LoggingQueueListener``.
 
-        def __init__(self, handlers: list[Any] | None = None) -> None:
-            """Initialize `?QueueListenerHandler`.
+        Args:
+            queue: The queue to send messages to
+            *handlers: A list of handlers which will handle entries placed on the queue
+            respect_handler_level: If ``respect_handler_level`` is ``True``, a handler's level is respected (compared with the level for the message) when deciding whether to pass messages to that handler
+        """
+        super().__init__(queue, *handlers, respect_handler_level=respect_handler_level)
+        self.start()
+        atexit.register(self.stop)
 
-            Args:
-                handlers: Optional 'ConvertingList'
-            """
-            super().__init__(Queue(-1))
-            handlers = resolve_handlers(handlers) if handlers else [StreamHandler()]
-            self.listener = QueueListener(self.queue, *handlers)
-            self.listener.start()
 
-            atexit.register(self.listener.stop)
+class QueueListenerHandler(QueueHandler):
+    """Configure queue listener and handler to support non-blocking logging configuration.
 
-else:
-    QueueListenerHandler = QueueHandler
+    .. caution::
+
+        This handler doesn't work with Python >= 3.12 and ``logging.config.dictConfig``. It might
+        be deprecated in the future. Please use ``logging.QueueHandler`` instead.
+    """
+
+    def __init__(self, handlers: list[Any] | None = None) -> None:
+        """Initialize ``QueueListenerHandler``.
+
+        Args:
+            handlers: Optional 'ConvertingList'
+        """
+        super().__init__(Queue(-1))
+        handlers = resolve_handlers(handlers) if handlers else [StreamHandler()]
+        self.listener = LoggingQueueListener(self.queue, *handlers)  # type: ignore[arg-type]

tests/helpers.py

@@ -1,10 +1,15 @@
 from __future__ import annotations
 
+import atexit
 import inspect
+import logging
 import random
 import sys
-from contextlib import AbstractContextManager
-from typing import Any, AsyncContextManager, Awaitable, ContextManager, TypeVar, cast, overload
+from contextlib import AbstractContextManager, contextmanager
+from typing import Any, AsyncContextManager, Awaitable, ContextManager, Generator, TypeVar, cast, overload
+
+import picologging
+from _pytest.logging import LogCaptureHandler, _LiveLoggingNullHandler
 
 from litestar._openapi.schema_generation import SchemaCreator
 from litestar._openapi.schema_generation.plugins import openapi_schema_plugins
@@ -28,6 +33,15 @@ def randbytes(n: int) -> bytes:
     randbytes = RANDOM.randbytes
 
 
+if sys.version_info >= (3, 12):
+    getHandlerByName = logging.getHandlerByName
+else:
+    from logging import _handlers  # type: ignore[attr-defined]
+
+    def getHandlerByName(name: str) -> Any:
+        return _handlers.get(name)
+
+
 @overload
 async def maybe_async(obj: Awaitable[T]) -> T: ...
 
@@ -66,3 +80,29 @@ def get_schema_for_field_definition(
     if isinstance(result, Schema):
         return result
     return creator.schema_registry.from_reference(result).schema
+
+
+@contextmanager
+def cleanup_logging_impl() -> Generator:
+    # Reset root logger (`logging` module)
+    std_root_logger: logging.Logger = logging.getLogger()
+    for std_handler in std_root_logger.handlers:
+        # Don't interfere with PyTest handler config
+        if not isinstance(std_handler, (_LiveLoggingNullHandler, LogCaptureHandler)):
+            std_root_logger.removeHandler(std_handler)
+
+    # Reset root logger (`picologging` module)
+    pico_root_logger: picologging.Logger = picologging.getLogger()
+    for pico_handler in pico_root_logger.handlers:
+        pico_root_logger.removeHandler(pico_handler)
+
+    yield
+
+    # Stop queue_listener listener (mandatory for the 'logging' module with Python 3.12,
+    # else the test suite would hang on at the end of the tests and some tests would fail)
+    queue_listener_handler = getHandlerByName("queue_listener")
+    if queue_listener_handler and hasattr(queue_listener_handler, "listener"):
+        atexit.unregister(queue_listener_handler.listener.stop)
+        queue_listener_handler.listener.stop()
+        queue_listener_handler.close()
+        del queue_listener_handler

tests/unit/test_logging/test_logging_config.py

@@ -1,9 +1,12 @@
 import logging
 import sys
-from typing import TYPE_CHECKING, Any, Dict
+import time
+from logging.handlers import QueueHandler
+from typing import TYPE_CHECKING, Any, Dict, Generator, Optional
 from unittest.mock import Mock, patch
 
 import pytest
+from _pytest.logging import LogCaptureHandler, _LiveLoggingNullHandler
 
 from litestar import Request, get
 from litestar.exceptions import ImproperlyConfiguredException
@@ -12,9 +15,16 @@
 from litestar.logging.standard import QueueListenerHandler as StandardQueueListenerHandler
 from litestar.status_codes import HTTP_200_OK
 from litestar.testing import create_test_client
+from tests.helpers import cleanup_logging_impl
 
 if TYPE_CHECKING:
-    from _pytest.logging import LogCaptureFixture
+    from _pytest.capture import CaptureFixture
+
+
+@pytest.fixture(autouse=True)
+def cleanup_logging() -> Generator:
+    with cleanup_logging_impl():
+        yield
 
 
 @pytest.mark.parametrize(
@@ -66,14 +76,45 @@ def test_dictconfig_startup(dict_config_class: str, handlers: Any) -> None:
             assert dict_config_mock.called
 
 
-def test_standard_queue_listener_logger(caplog: "LogCaptureFixture") -> None:
-    with caplog.at_level("INFO", logger="test_logger"):
-        logger = logging.getLogger("test_logger")
-        logger.info("Testing now!")
-        assert "Testing now!" in caplog.text
-        var = "test_var"
-        logger.info("%s", var)
-        assert var in caplog.text
+def test_standard_queue_listener_logger(capsys: "CaptureFixture[str]") -> None:
+    def wait_log_queue(queue: Any, sleep_time: float = 0.1, max_retries: int = 5) -> None:
+        retry = 0
+        while queue.qsize() > 0 and retry < max_retries:
+            retry += 1
+            time.sleep(sleep_time)
+
+    def assert_log(queue: Any, expected: str, count: Optional[int] = None) -> None:
+        wait_log_queue(queue)
+        log_output = capsys.readouterr().err.strip()
+        if count is not None:
+            assert len(log_output.split("\n")) == count
+        assert log_output == expected
+
+    with patch("litestar.logging.config.find_spec") as find_spec_mock:
+        find_spec_mock.return_value = False
+        get_logger = LoggingConfig(
+            formatters={"standard": {"format": "%(levelname)s :: %(name)s :: %(message)s"}},
+            loggers={
+                "test_logger": {
+                    "level": "INFO",
+                    "handlers": ["queue_listener"],
+                    "propagate": False,
+                },
+            },
+        ).configure()
+
+    logger = get_logger("test_logger")
+    assert isinstance(logger, logging.Logger)  # type: ignore[unreachable]
+
+    handler = logger.handlers[0]  # type: ignore[unreachable]
+    assert isinstance(handler, QueueHandler if sys.version_info >= (3, 12, 0) else StandardQueueListenerHandler)
+
+    logger.info("Testing now!")
+    assert_log(handler.queue, expected="INFO :: test_logger :: Testing now!", count=1)
+
+    var = "test_var"
+    logger.info("%s", var)
+    assert_log(handler.queue, expected="INFO :: test_logger :: test_var", count=1)
 
 
 @patch("picologging.config.dictConfig")
@@ -94,9 +135,10 @@ def test_get_logger_without_logging_config() -> None:
 
 def test_get_default_logger() -> None:
     with create_test_client(logging_config=LoggingConfig(handlers=default_handlers)) as client:
-        assert isinstance(client.app.logger.handlers[0], StandardQueueListenerHandler)
+        expected_handler_class = QueueHandler if sys.version_info >= (3, 12, 0) else StandardQueueListenerHandler
+        assert isinstance(client.app.logger.handlers[0], expected_handler_class)
         new_logger = client.app.get_logger()
-        assert isinstance(new_logger.handlers[0], StandardQueueListenerHandler)
+        assert isinstance(new_logger.handlers[0], expected_handler_class)
 
 
 def test_get_picologging_logger() -> None:
@@ -109,7 +151,7 @@ def test_get_picologging_logger() -> None:
 @pytest.mark.parametrize(
     "handlers, listener",
     [
-        [default_handlers, StandardQueueListenerHandler],
+        [default_handlers, QueueHandler if sys.version_info >= (3, 12, 0) else StandardQueueListenerHandler],
         [default_picologging_handlers, PicologgingQueueListenerHandler],
     ],
 )
@@ -133,7 +175,7 @@ def test_validation() -> None:
 @pytest.mark.parametrize(
     "handlers, listener",
     [
-        [default_handlers, StandardQueueListenerHandler],
+        [default_handlers, QueueHandler if sys.version_info >= (3, 12, 0) else StandardQueueListenerHandler],
         [default_picologging_handlers, PicologgingQueueListenerHandler],
     ],
 )
@@ -144,43 +186,36 @@ def test_root_logger(handlers: Any, listener: Any) -> None:
     assert isinstance(root_logger.handlers[0], listener)  # type: ignore[attr-defined]
 
 
-@pytest.mark.parametrize(
-    "handlers, listener",
-    [
-        [default_handlers, StandardQueueListenerHandler],
-        [default_picologging_handlers, PicologgingQueueListenerHandler],
-    ],
-)
-def test_root_logger_no_config(handlers: Any, listener: Any) -> None:
+@pytest.mark.parametrize("handlers", [default_handlers, default_picologging_handlers])
+def test_root_logger_no_config(handlers: Any) -> None:
     logging_config = LoggingConfig(handlers=handlers, configure_root_logger=False)
     get_logger = logging_config.configure()
     root_logger = get_logger()
-    for handler in root_logger.handlers:  # type: ignore[attr-defined]
-        root_logger.removeHandler(handler)  # type: ignore[attr-defined]
-    get_logger = logging_config.configure()
-    root_logger = get_logger()
-    if handlers["console"]["class"] == "logging.StreamHandler":
-        assert not isinstance(root_logger.handlers[0], listener)  # type: ignore[attr-defined]
+    if isinstance(root_logger, logging.Logger):  # type: ignore[unreachable]
+        # pytest automatically configures some handlers
+        for handler in root_logger.handlers:  # type: ignore[unreachable]
+            assert isinstance(handler, (_LiveLoggingNullHandler, LogCaptureHandler))
     else:
-        assert len(root_logger.handlers) < 1  # type: ignore[attr-defined]
+        assert len(root_logger.handlers) == 0  # type: ignore[attr-defined]
 
 
 @pytest.mark.parametrize(
-    "handlers, listener",
+    "handlers, expected_handler_class",
     [
-        pytest.param(
-            default_handlers,
-            StandardQueueListenerHandler,
-            marks=pytest.mark.xfail(
-                condition=sys.version_info >= (3, 12), reason="change to QueueHandler/QueueListener config in 3.12"
-            ),
-        ),
+        [default_handlers, QueueHandler if sys.version_info >= (3, 12, 0) else StandardQueueListenerHandler],
         [default_picologging_handlers, PicologgingQueueListenerHandler],
     ],
 )
-def test_customizing_handler(handlers: Any, listener: Any, monkeypatch: pytest.MonkeyPatch) -> None:
-    monkeypatch.setitem(handlers["queue_listener"], "handlers", ["cfg://handlers.console"])
-    logging_config = LoggingConfig(handlers=handlers)
+def test_customizing_handler(handlers: Any, expected_handler_class: Any, monkeypatch: pytest.MonkeyPatch) -> None:
+    log_format = "%(levelname)s :: %(name)s :: %(message)s"
+    formatters = {"standard": {"format": log_format}}
+    logging_config = LoggingConfig(formatters=formatters, handlers=handlers)
     get_logger = logging_config.configure()
     root_logger = get_logger()
-    assert isinstance(root_logger.handlers[0], listener)  # type: ignore[attr-defined]
+    root_logger_handler = root_logger.handlers[0]  # type: ignore[attr-defined]
+    assert isinstance(root_logger_handler, expected_handler_class)
+    if type(root_logger_handler) is QueueHandler:
+        formatter = root_logger_handler.listener.handlers[0].formatter  # type: ignore[attr-defined]
+    else:
+        formatter = root_logger_handler.formatter
+    assert formatter._fmt == log_format