From b2d4ba51d1122f9cda3d82b8a90b03179d16009f Mon Sep 17 00:00:00 2001 From: Fraser <39111573+fraser-langton@users.noreply.github.com> Date: Wed, 15 May 2024 11:32:26 +1000 Subject: [PATCH 1/8] fixes bug in render_to_log_kwargs --- CHANGELOG.md | 6 +++ src/structlog/stdlib.py | 16 +++++-- tests/test_stdlib.py | 100 ++++++++++++++++++++++++++++++++++++---- 3 files changed, 109 insertions(+), 13 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 645fffaf..17d7d196 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/issues/619) + + ## [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..84f88670 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -397,7 +397,9 @@ async def _dispatch_to_sync( """ Merge contextvars and log using the sync logger in a thread pool. """ - scs_token = _ASYNC_CALLING_STACK.set(sys._getframe().f_back.f_back) # type: ignore[union-attr, arg-type, unused-ignore] + scs_token = _ASYNC_CALLING_STACK.set( + sys._getframe().f_back.f_back + ) # type: ignore[union-attr, arg-type, unused-ignore] ctx = contextvars.copy_context() try: @@ -605,7 +607,9 @@ async def _dispatch_to_sync( """ Merge contextvars and log using the sync logger in a thread pool. """ - scs_token = _ASYNC_CALLING_STACK.set(sys._getframe().f_back.f_back) # type: ignore[union-attr, arg-type, unused-ignore] + scs_token = _ASYNC_CALLING_STACK.set( + sys._getframe().f_back.f_back + ) # type: ignore[union-attr, arg-type, unused-ignore] ctx = contextvars.copy_context() try: @@ -878,6 +882,8 @@ def render_to_log_kwargs( ) -> EventDict: """ Render ``event_dict`` into keyword arguments for `logging.log`. + reserved stdlib keywords are in logging.Logger._log + https://github.com/python/cpython/blob/main/Lib/logging/__init__.py#L1632 The ``event`` field is translated into ``msg`` and the rest of the *event_dict* is added as ``extra``. @@ -886,15 +892,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:: Unreleased + ``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..f251b406 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() +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,17 @@ 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() + (level, msg, args), kwargs = mock_log.call_args + assert level == logging.INFO + assert msg == "message" + assert args == () + assert kwargs == {"extra": {}} + + def test_add_extra_event_dict(self, event_dict, stdlib_logger): """ Adds all remaining data from `event_dict` into `extra`. """ @@ -689,9 +711,19 @@ 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() + (level, msg, args), kwargs = mock_log.call_args + assert level == logging.INFO + assert msg == "message" + assert args == () + assert kwargs == {"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 +732,72 @@ 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) + mock_log.assert_called_once() + (level, msg, args), kwargs = mock_log.call_args + assert level == logging.INFO + assert msg == "message" + assert args == () + expected.pop("msg") + assert expected == kwargs + + def test_integration_special_kw(self, event_dict, stdlib_logger): + """ + test the render_to_log_kwargs processor with a wrapped logger calls the stdlib logger + correctly + + reserved stdlib keywords are in logging.Logger._log + https://github.com/python/cpython/blob/main/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) + mock_log.assert_called_once() + (level, msg, args), kwargs = mock_log.call_args + assert level == logging.INFO + assert msg == "message" + assert args == () + expected.pop("msg") + assert expected == kwargs @pytest.fixture(name="configure_for_processor_formatter") From f916874b8a02a6868b9a58bec8f74d573d060ec9 Mon Sep 17 00:00:00 2001 From: Fraser <39111573+fraser-langton@users.noreply.github.com> Date: Wed, 15 May 2024 11:38:17 +1000 Subject: [PATCH 2/8] fix autoformatting --- src/structlog/stdlib.py | 10 +++------- 1 file changed, 3 insertions(+), 7 deletions(-) diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index 84f88670..df4a1b64 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -397,9 +397,7 @@ async def _dispatch_to_sync( """ Merge contextvars and log using the sync logger in a thread pool. """ - scs_token = _ASYNC_CALLING_STACK.set( - sys._getframe().f_back.f_back - ) # type: ignore[union-attr, arg-type, unused-ignore] + scs_token = _ASYNC_CALLING_STACK.set(sys._getframe().f_back.f_back) # type: ignore[union-attr, arg-type, unused-ignore] ctx = contextvars.copy_context() try: @@ -607,9 +605,7 @@ async def _dispatch_to_sync( """ Merge contextvars and log using the sync logger in a thread pool. """ - scs_token = _ASYNC_CALLING_STACK.set( - sys._getframe().f_back.f_back - ) # type: ignore[union-attr, arg-type, unused-ignore] + scs_token = _ASYNC_CALLING_STACK.set(sys._getframe().f_back.f_back) # type: ignore[union-attr, arg-type, unused-ignore] ctx = contextvars.copy_context() try: @@ -894,7 +890,7 @@ def render_to_log_kwargs( .. versionchanged:: 22.1.0 ``exc_info``, ``stack_info``, and ``stacklevel`` are passed as proper kwargs and not put into ``extra``. - .. versionchanged:: Unreleased + .. versionchanged:: 24.2.0 ``stackLevel`` corrected to ``stacklevel``. """ return { From 69ebb64d0b04a60faa0a6050a718f60ead25678e Mon Sep 17 00:00:00 2001 From: Fraser <39111573+fraser-langton@users.noreply.github.com> Date: Wed, 15 May 2024 11:41:17 +1000 Subject: [PATCH 3/8] fix docstring --- src/structlog/stdlib.py | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index df4a1b64..d959fc06 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -877,9 +877,7 @@ def render_to_log_kwargs( _: logging.Logger, __: str, event_dict: EventDict ) -> EventDict: """ - Render ``event_dict`` into keyword arguments for `logging.log`. - reserved stdlib keywords are in logging.Logger._log - https://github.com/python/cpython/blob/main/Lib/logging/__init__.py#L1632 + Render ``event_dict`` into keyword arguments for `logging.log` (see `logging.Logger._log`). The ``event`` field is translated into ``msg`` and the rest of the *event_dict* is added as ``extra``. From 23107f31509a611adc3a55d0f3776d278290205e Mon Sep 17 00:00:00 2001 From: Fraser <39111573+fraser-langton@users.noreply.github.com> Date: Wed, 15 May 2024 11:43:23 +1000 Subject: [PATCH 4/8] add PR link now it exists --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 17d7d196..c77e48fa 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -42,7 +42,7 @@ You can find our backwards-compatibility policy [here](https://github.com/hynek/ ### Fixed - `structlog.stdlib.render_to_log_kwargs` now correctly passes stacklevel as a kwarg to stdlib logging. - [#619](https://github.com/hynek/structlog/issues/619) + [#619](https://github.com/hynek/structlog/pull/620) From 61368b49ac72288bdda1a59a29b03990599107eb Mon Sep 17 00:00:00 2001 From: Fraser <39111573+fraser-langton@users.noreply.github.com> Date: Wed, 15 May 2024 11:55:28 +1000 Subject: [PATCH 5/8] fix docstring --- src/structlog/stdlib.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index d959fc06..fc67f5b8 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -877,7 +877,8 @@ def render_to_log_kwargs( _: logging.Logger, __: str, event_dict: EventDict ) -> EventDict: """ - Render ``event_dict`` into keyword arguments for `logging.log` (see `logging.Logger._log`). + Render ``event_dict`` into keyword arguments for `logging.log`. + See the Python logging.Logger._log for kwargs reference. The ``event`` field is translated into ``msg`` and the rest of the *event_dict* is added as ``extra``. From 7c22b33be0d6180a65812c751009094347d74944 Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Sat, 25 May 2024 08:25:39 -0400 Subject: [PATCH 6/8] Small fixes --- src/structlog/stdlib.py | 2 +- tests/test_stdlib.py | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index fc67f5b8..dbb530f9 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -878,7 +878,7 @@ def render_to_log_kwargs( ) -> EventDict: """ Render ``event_dict`` into keyword arguments for `logging.log`. - See the Python logging.Logger._log for kwargs reference. + 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``. diff --git a/tests/test_stdlib.py b/tests/test_stdlib.py index f251b406..8f114a4d 100644 --- a/tests/test_stdlib.py +++ b/tests/test_stdlib.py @@ -673,8 +673,8 @@ def _copy_allowed( } -@pytest.fixture() -def stdlib_logger(): +@pytest.fixture(name="stdlib_logger") +def _stdlib_logger(): logger = logging.getLogger("test_logger") logger.setLevel(logging.DEBUG) From d5308748a362fb23b1f711298df429c51ffabaec Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Mon, 27 May 2024 23:06:25 +0200 Subject: [PATCH 7/8] Simplify asserts --- tests/test_stdlib.py | 42 ++++++++++++++++-------------------------- 1 file changed, 16 insertions(+), 26 deletions(-) diff --git a/tests/test_stdlib.py b/tests/test_stdlib.py index 8f114a4d..7768aad8 100644 --- a/tests/test_stdlib.py +++ b/tests/test_stdlib.py @@ -695,12 +695,8 @@ def test_default(self, stdlib_logger): # 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() - (level, msg, args), kwargs = mock_log.call_args - assert level == logging.INFO - assert msg == "message" - assert args == () - assert kwargs == {"extra": {}} + + mock_log.assert_called_once_with(logging.INFO, "message", (), extra={}) def test_add_extra_event_dict(self, event_dict, stdlib_logger): """ @@ -714,12 +710,10 @@ def test_add_extra_event_dict(self, event_dict, stdlib_logger): # 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() - (level, msg, args), kwargs = mock_log.call_args - assert level == logging.INFO - assert msg == "message" - assert args == () - assert kwargs == {"extra": event_dict} + + mock_log.assert_called_once_with( + logging.INFO, "message", (), extra=event_dict + ) def test_handles_special_kw(self, event_dict, stdlib_logger): """ @@ -755,13 +749,11 @@ def test_handles_special_kw(self, event_dict, stdlib_logger): # 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() - (level, msg, args), kwargs = mock_log.call_args - assert level == logging.INFO - assert msg == "message" - assert args == () - expected.pop("msg") - assert expected == kwargs + + expected.pop("msg") + mock_log.assert_called_once_with( + logging.INFO, "message", (), **expected + ) def test_integration_special_kw(self, event_dict, stdlib_logger): """ @@ -791,13 +783,11 @@ def test_integration_special_kw(self, event_dict, stdlib_logger): # now check struct logger passes those kwargs to stdlib with patch.object(stdlib_logger, "_log") as mock_log: struct_logger.info("message", **event_dict) - mock_log.assert_called_once() - (level, msg, args), kwargs = mock_log.call_args - assert level == logging.INFO - assert msg == "message" - assert args == () - expected.pop("msg") - assert expected == kwargs + + expected.pop("msg") + mock_log.assert_called_once_with( + logging.INFO, "message", (), **expected + ) @pytest.fixture(name="configure_for_processor_formatter") From 09c1b730cae1a28aac5b01280f5b14085c16b650 Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Mon, 27 May 2024 23:11:25 +0200 Subject: [PATCH 8/8] Fix comment --- tests/test_stdlib.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/test_stdlib.py b/tests/test_stdlib.py index 7768aad8..13a8e3b6 100644 --- a/tests/test_stdlib.py +++ b/tests/test_stdlib.py @@ -757,11 +757,11 @@ def test_handles_special_kw(self, event_dict, stdlib_logger): def test_integration_special_kw(self, event_dict, stdlib_logger): """ - test the render_to_log_kwargs processor with a wrapped logger calls the 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/main/Lib/logging/__init__.py#L1632 + https://github.com/python/cpython/blob/ae7b17673f29efe17b416cbcfbf43b5b3ff5977c/Lib/logging/__init__.py#L1632 """ expected = { "msg": "message",