Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fixes bug in render_to_log_kwargs #620

Merged
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
7 changes: 5 additions & 2 deletions src/structlog/stdlib.py
Original file line number Diff line number Diff line change
Expand Up @@ -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``.
Expand All @@ -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
},
}
Expand Down
90 changes: 81 additions & 9 deletions tests/test_stdlib.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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`.
"""
Expand All @@ -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
"""
Expand All @@ -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")
Expand Down