From b16e08f0c2989be813b666c62e633a70e59cfb42 Mon Sep 17 00:00:00 2001 From: Fraser <39111573+fraser-langton@users.noreply.github.com> Date: Tue, 28 May 2024 07:13:43 +1000 Subject: [PATCH] fixes bug in render_to_log_kwargs (#620) * fixes bug in render_to_log_kwargs * fix autoformatting * fix docstring * add PR link now it exists * fix docstring * Small fixes * Simplify asserts * Fix comment --------- Co-authored-by: Hynek Schlawack --- CHANGELOG.md | 6 +++ src/structlog/stdlib.py | 7 +++- tests/test_stdlib.py | 90 ++++++++++++++++++++++++++++++++++++----- 3 files changed, 92 insertions(+), 11 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 645fffaf..c77e48fa 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -39,6 +39,12 @@ You can find our backwards-compatibility policy [here](https://github.com/hynek/ [#606](https://github.com/hynek/structlog/pull/606) +### Fixed + +- `structlog.stdlib.render_to_log_kwargs` now correctly passes stacklevel as a kwarg to stdlib logging. + [#619](https://github.com/hynek/structlog/pull/620) + + ## [24.1.0](https://github.com/hynek/structlog/compare/23.3.0...24.1.0) - 2024-01-08 diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index ce64bd96..dbb530f9 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -878,6 +878,7 @@ def render_to_log_kwargs( ) -> EventDict: """ Render ``event_dict`` into keyword arguments for `logging.log`. + See `logging.Logger`'s ``_log`` method for kwargs reference. The ``event`` field is translated into ``msg`` and the rest of the *event_dict* is added as ``extra``. @@ -886,15 +887,17 @@ def render_to_log_kwargs( .. versionadded:: 17.1.0 .. versionchanged:: 22.1.0 - ``exc_info``, ``stack_info``, and ``stackLevel`` are passed as proper + ``exc_info``, ``stack_info``, and ``stacklevel`` are passed as proper kwargs and not put into ``extra``. + .. versionchanged:: 24.2.0 + ``stackLevel`` corrected to ``stacklevel``. """ return { "msg": event_dict.pop("event"), "extra": event_dict, **{ kw: event_dict.pop(kw) - for kw in ("exc_info", "stack_info", "stackLevel") + for kw in ("exc_info", "stack_info", "stacklevel") if kw in event_dict }, } diff --git a/tests/test_stdlib.py b/tests/test_stdlib.py index 1c690f1f..13a8e3b6 100644 --- a/tests/test_stdlib.py +++ b/tests/test_stdlib.py @@ -13,6 +13,7 @@ from io import StringIO from typing import Any, Callable, Collection, Dict +from unittest.mock import patch import pytest import pytest_asyncio @@ -24,6 +25,7 @@ ReturnLogger, configure, get_context, + wrap_logger, ) from structlog._config import _CONFIG from structlog._log_levels import CRITICAL, NAME_TO_LEVEL, WARN @@ -671,8 +673,18 @@ def _copy_allowed( } +@pytest.fixture(name="stdlib_logger") +def _stdlib_logger(): + logger = logging.getLogger("test_logger") + logger.setLevel(logging.DEBUG) + + yield logger + + logging.basicConfig() + + class TestRenderToLogKW: - def test_default(self): + def test_default(self, stdlib_logger): """ Translates `event` to `msg` and handles otherwise empty `event_dict`s. """ @@ -680,7 +692,13 @@ def test_default(self): assert {"msg": "message", "extra": {}} == d - def test_add_extra_event_dict(self, event_dict): + # now check stdlib logger likes those kwargs + with patch.object(stdlib_logger, "_log") as mock_log: + stdlib_logger.info(**d) + + mock_log.assert_called_once_with(logging.INFO, "message", (), extra={}) + + def test_add_extra_event_dict(self, event_dict, stdlib_logger): """ Adds all remaining data from `event_dict` into `extra`. """ @@ -689,9 +707,17 @@ def test_add_extra_event_dict(self, event_dict): assert {"msg": "message", "extra": event_dict} == d - def test_handles_special_kw(self, event_dict): + # now check stdlib logger likes those kwargs + with patch.object(stdlib_logger, "_log") as mock_log: + stdlib_logger.info(**d) + + mock_log.assert_called_once_with( + logging.INFO, "message", (), extra=event_dict + ) + + def test_handles_special_kw(self, event_dict, stdlib_logger): """ - "exc_info", "stack_info", and "stackLevel" aren't passed as extras. + "exc_info", "stack_info", and "stacklevel" aren't passed as extras. Cf. https://github.com/hynek/structlog/issues/424 """ @@ -700,22 +726,68 @@ def test_handles_special_kw(self, event_dict): event_dict["exc_info"] = True event_dict["stack_info"] = False - event_dict["stackLevel"] = 1 + event_dict["stacklevel"] = 1 + event_dict["stackLevel"] = 1 # not a reserved kw d = render_to_log_kwargs(None, None, event_dict) - - assert { + expected = { "msg": "message", "exc_info": True, "stack_info": False, - "stackLevel": 1, + "stacklevel": 1, "extra": { "b": [3, 4], "x": 7, "y": "test", "z": (1, 2), + "stackLevel": 1, }, - } == d + } + + assert expected == d + + # now check stdlib logger likes those kwargs + with patch.object(stdlib_logger, "_log") as mock_log: + stdlib_logger.info(**d) + + expected.pop("msg") + mock_log.assert_called_once_with( + logging.INFO, "message", (), **expected + ) + + def test_integration_special_kw(self, event_dict, stdlib_logger): + """ + render_to_log_kwargs with a wrapped logger calls the stdlib logger + correctly + + reserved stdlib keywords are in logging.Logger._log + https://github.com/python/cpython/blob/ae7b17673f29efe17b416cbcfbf43b5b3ff5977c/Lib/logging/__init__.py#L1632 + """ + expected = { + "msg": "message", + "exc_info": True, + "stack_info": False, + "stacklevel": 1, + "extra": {**event_dict}, + } + + event_dict["exc_info"] = True + event_dict["stack_info"] = False + event_dict["stacklevel"] = 1 + + struct_logger = wrap_logger( + stdlib_logger, + processors=[render_to_log_kwargs], + ) + + # now check struct logger passes those kwargs to stdlib + with patch.object(stdlib_logger, "_log") as mock_log: + struct_logger.info("message", **event_dict) + + expected.pop("msg") + mock_log.assert_called_once_with( + logging.INFO, "message", (), **expected + ) @pytest.fixture(name="configure_for_processor_formatter")