Drop event dict keys colliding with LogRecord attributes in render_to_log_*

render_to_log_kwargs() and render_to_log_args_and_kwargs() build the
extra kwarg straight out of whatever is left in the event dict once the
event, positional_args, and the exc_info/stack_info/stacklevel trio have
been extracted. If a remaining key happens to share a name with an
attribute that logging.LogRecord already carries (filename, module,
process, message, ...), logging.Logger.makeRecord() rejects the whole
call with a raw KeyError, crashing a documented, non-ProcessorFormatter
configuration on an entirely plausible business field name.

structlog.stdlib.ExtraAdder already filters LogRecord's own attribute
names out of the event dict when merging a record's extra fields in the
other direction. Apply the same filtering here so a colliding key is
dropped from extra instead of reaching logging.Logger.makeRecord() and
crashing it.

Fixes #486.
This commit is contained in:
dualfroz committed 2026-09-06 01:25:03 +02:00
1 parent 0d644c1b5f
commit 350802c5a3
3 files changed
+101 -8

No files matched your search

+5
View File
@@ -15,6 +15,11 @@ You can find our backwards-compatibility policy [here](https://github.com/hynek/
## [Unreleased](https://github.com/hynek/structlog/compare/26.1.0...HEAD)
### Fixed
- `structlog.stdlib.render_to_log_kwargs()` and `structlog.stdlib.render_to_log_args_and_kwargs()` now drop event dict keys that collide with a `logging.LogRecord` attribute (for example `filename` or `module`) instead of crashing the standard library with `KeyError: "Attempt to overwrite '...' in LogRecord"`.
[#486](https://github.com/hynek/structlog/issues/486)
## [26.1.0](https://github.com/hynek/structlog/compare/25.5.0...26.1.0) - 2026-06-06
+33 -8
View File
@@ -883,6 +883,14 @@ _LOG_RECORD_KEYS = logging.LogRecord(
"name", 0, "pathname", 0, "msg", (), None
).__dict__.keys()
# `Logger.makeRecord` raises `KeyError` for an `extra` key already on the
# `LogRecord`: `_LOG_RECORD_KEYS`, plus "message"/"asctime" added later by
# `Formatter.format()`. An event field named "filename" would crash.
_RESERVED_LOG_RECORD_KEYS = frozenset(_LOG_RECORD_KEYS) | {
"message",
"asctime",
}
class ExtraAdder:
"""
@@ -960,9 +968,17 @@ def render_to_log_args_and_kwargs(
arguments, keyword arguments are extracted from the *event_dict* and the
rest of the *event_dict* is added as ``extra``.
Keys that collide with an attribute `logging.LogRecord` already carries
(for example ``filename`` or ``module``) are dropped instead of being
added to ``extra``, because the standard library rejects them there with
a `KeyError` at the point of logging.
This allows you to defer formatting to `logging`.
.. versionadded:: 25.1.0
.. versionchanged:: 26.2.0
Keys colliding with `logging.LogRecord` attributes are now dropped
from ``extra`` instead of crashing the standard library.
"""
args = (event_dict.pop("event"), *event_dict.pop("positional_args", ()))
@@ -971,6 +987,8 @@ def render_to_log_args_and_kwargs(
for kwarg_name in LOG_KWARG_NAMES
if kwarg_name in event_dict
}
for key in event_dict.keys() & _RESERVED_LOG_RECORD_KEYS:
del event_dict[key]
if event_dict:
kwargs["extra"] = event_dict
@@ -989,6 +1007,11 @@ def render_to_log_kwargs(
extracted from the *event_dict* and the rest of the *event_dict* is added as
``extra``.
Keys that collide with an attribute `logging.LogRecord` already carries
(for example ``filename`` or ``module``) are dropped instead of being
added to ``extra``, because the standard library rejects them there with
a `KeyError` at the point of logging.
This allows you to defer formatting to `logging`.
.. versionadded:: 17.1.0
@@ -997,16 +1020,18 @@ def render_to_log_kwargs(
kwargs and not put into ``extra``.
.. versionchanged:: 24.2.0
``stackLevel`` corrected to ``stacklevel``.
.. versionchanged:: 26.2.0
Keys colliding with `logging.LogRecord` attributes are now dropped
from ``extra`` instead of crashing the standard library.
"""
return {
"msg": event_dict.pop("event"),
"extra": event_dict,
**{
kw: event_dict.pop(kw)
for kw in LOG_KWARG_NAMES
if kw in event_dict
},
msg = event_dict.pop("event")
kwargs = {
kw: event_dict.pop(kw) for kw in LOG_KWARG_NAMES if kw in event_dict
}
for key in event_dict.keys() & _RESERVED_LOG_RECORD_KEYS:
del event_dict[key]
return {"msg": msg, "extra": event_dict, **kwargs}
class ProcessorFormatter(logging.Formatter):
+63
View File
@@ -870,6 +870,34 @@ class TestRenderToLogArgsAndKwargs:
extra=expected_extra,
)
def test_drops_keys_colliding_with_log_record_attributes(
self, stdlib_logger: logging.Logger, caplog: pytest.LogCaptureFixture
):
"""
A key that collides with an attribute `logging.LogRecord` already
carries (for example "filename") is dropped from `extra` instead of
being passed through, because the standard library raises `KeyError`
when it's asked to overwrite it while building the record.
Cf. https://github.com/hynek/structlog/issues/486
"""
event_dict = {
"event": "message",
"filename": "not-a-real-file.py",
"keep": "this",
}
args, kwargs = render_to_log_args_and_kwargs(
stdlib_logger, "info", event_dict
)
assert {"extra": {"keep": "this"}} == kwargs
with caplog.at_level(logging.INFO):
stdlib_logger.info(*args, **kwargs)
assert "this" == caplog.records[0].keep
def test_integration(
self, stdlib_logger: logging.Logger, event_dict: dict[str, Any]
):
@@ -987,6 +1015,41 @@ class TestRenderToLogKwargs:
logging.INFO, "message", (), **expected
)
def test_drops_keys_colliding_with_log_record_attributes(
self, stdlib_logger, caplog: pytest.LogCaptureFixture
):
"""
A key that collides with an attribute `logging.LogRecord` already
carries (for example "filename") is dropped from `extra` instead of
being passed through, because the standard library raises `KeyError`
when it's asked to overwrite it while building the record.
"message" collides too: it isn't on a fresh `LogRecord`, but the
standard library still special-cases and rejects it.
Cf. https://github.com/hynek/structlog/issues/486
"""
d = render_to_log_kwargs(
None,
None,
{
"event": "message",
"filename": "not-a-real-file.py",
"message": "duplicate-of-msg",
"keep": "this",
},
)
assert {
"msg": "message",
"extra": {"keep": "this"},
} == d
with caplog.at_level(logging.INFO):
stdlib_logger.info(**d)
assert "this" == caplog.records[0].keep
def test_integration_special_kw(self, event_dict, stdlib_logger):
"""
render_to_log_kwargs with a wrapped logger calls the stdlib logger