diff --git a/litestar/logging/config.py b/litestar/logging/config.py index d9d376e3f2..1c19ccb751 100644 --- a/litestar/logging/config.py +++ b/litestar/logging/config.py @@ -2,13 +2,13 @@ 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 queue import Queue 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 +49,17 @@ } if sys.version_info >= (3, 12, 0): - default_handlers["queue_listener"]["handlers"] = ["console"] + default_handlers["queue_listener"].update( + { + "class": "logging.handlers.QueueHandler", + "queue": Queue(-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 +238,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..7f07afdfde 100644 --- a/litestar/logging/standard.py +++ b/litestar/logging/standard.py @@ -2,7 +2,7 @@ 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 @@ -18,7 +18,7 @@ class QueueListenerHandler(QueueHandler): """Configure queue listener and handler to support non-blocking logging configuration.""" def __init__(self, handlers: list[Any] | None = None) -> None: - """Initialize `?QueueListenerHandler`. + """Initialize `QueueListenerHandler`. Args: handlers: Optional 'ConvertingList' @@ -31,4 +31,18 @@ def __init__(self, handlers: list[Any] | None = None) -> None: atexit.register(self.listener.stop) else: - QueueListenerHandler = QueueHandler + + class LoggingQueueListener(QueueListener): + """Custom `QueueListener` which starts and stops the listening process.""" + + def __init__(self, queue: Queue[LogRecord], *handlers: Handler, respect_handler_level: bool = False) -> None: + """Initialize `LoggingQueueListener`. + + 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) diff --git a/tests/helpers.py b/tests/helpers.py index 241efb9764..c12c4a7551 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: ... @@ -68,3 +82,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..e250daa2a9 100644 --- a/tests/unit/test_logging/test_logging_config.py +++ b/tests/unit/test_logging/test_logging_config.py @@ -1,20 +1,32 @@ 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 from litestar.logging.config import LoggingConfig, _get_default_handlers, default_handlers, default_picologging_handlers from litestar.logging.picologging import QueueListenerHandler as PicologgingQueueListenerHandler -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 sys.version_info < (3, 12, 0): + from litestar.logging.standard import QueueListenerHandler as StandardQueueListenerHandler 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 +78,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 +137,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 +153,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 +177,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 +188,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 isinstance(root_logger_handler, 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 e698131b6d..c8fe08adf4 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("/")