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 <hs@ox.cx>

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
 

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
         },
     }

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,16 +673,32 @@ 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.
         """
         d = render_to_log_kwargs(None, None, {"event": "message"})
 
         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")