From be9af3f909e89c923e4d892410221e48c6c8e49c Mon Sep 17 00:00:00 2001 From: jderrien Date: Fri, 22 Mar 2024 15:08:16 +0100 Subject: [PATCH] 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 --- litestar/logging/config.py | 36 ++++-- litestar/logging/standard.py | 49 +++++--- tests/helpers.py | 44 ++++++- .../unit/test_logging/test_logging_config.py | 117 ++++++++++++------ .../test_exception_handler_middleware.py | 9 +- .../test_logging_middleware.py | 9 +- 6 files changed, 191 insertions(+), 73 deletions(-) diff --git a/litestar/logging/config.py b/litestar/logging/config.py index d9d376e3f2..a4a3713939 100644 --- a/litestar/logging/config.py +++ b/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) diff --git a/litestar/logging/standard.py b/litestar/logging/standard.py index 467b2f1215..131c0edf62 100644 --- a/litestar/logging/standard.py +++ b/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] diff --git a/tests/helpers.py b/tests/helpers.py index 10456706b8..d550098352 100644 --- a/tests/helpers.py +++ b/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 diff --git a/tests/unit/test_logging/test_logging_config.py b/tests/unit/test_logging/test_logging_config.py index 2e363d45cb..e318ed730f 100644 --- a/tests/unit/test_logging/test_logging_config.py +++ b/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 diff --git a/tests/unit/test_middleware/test_exception_handler_middleware.py b/tests/unit/test_middleware/test_exception_handler_middleware.py index 4ecf7cf839..5371ca4847 100644 --- a/tests/unit/test_middleware/test_exception_handler_middleware.py +++ b/tests/unit/test_middleware/test_exception_handler_middleware.py @@ -1,5 +1,5 @@ from inspect import getinnerframes -from typing import TYPE_CHECKING, Any, Callable, Optional +from typing import TYPE_CHECKING, Any, Callable, Generator, Optional import pytest from _pytest.capture import CaptureFixture @@ -17,6 +17,7 @@ from litestar.testing import TestClient, create_test_client from litestar.types import ExceptionHandlersMap from litestar.types.asgi_types import HTTPScope +from tests.helpers import cleanup_logging_impl if TYPE_CHECKING: from _pytest.logging import LogCaptureFixture @@ -29,6 +30,12 @@ async def dummy_app(scope: Any, receive: Any, send: Any) -> None: return None +@pytest.fixture(autouse=True) +def cleanup_logging() -> Generator: + with cleanup_logging_impl(): + yield + + @pytest.fixture() def app() -> Litestar: return Litestar() diff --git a/tests/unit/test_middleware/test_logging_middleware.py b/tests/unit/test_middleware/test_logging_middleware.py index 6ce6e5dea1..35f9f6ca47 100644 --- a/tests/unit/test_middleware/test_logging_middleware.py +++ b/tests/unit/test_middleware/test_logging_middleware.py @@ -1,5 +1,5 @@ from logging import INFO -from typing import TYPE_CHECKING, Any, Dict +from typing import TYPE_CHECKING, Any, Dict, Generator import pytest from structlog.testing import capture_logs @@ -18,6 +18,7 @@ from litestar.params import Body from litestar.status_codes import HTTP_200_OK, HTTP_201_CREATED from litestar.testing import create_test_client +from tests.helpers import cleanup_logging_impl if TYPE_CHECKING: from _pytest.logging import LogCaptureFixture @@ -30,6 +31,12 @@ pytestmark = pytest.mark.usefixtures("reset_httpx_logging") +@pytest.fixture(autouse=True) +def cleanup_logging() -> Generator: + with cleanup_logging_impl(): + yield + + @pytest.fixture def handler() -> HTTPRouteHandler: @get("/")