Skip to content

Commit c7f841c

Browse files
committed
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.
1 parent 2a18290 commit c7f841c

3 files changed

Lines changed: 107 additions & 8 deletions

File tree

CHANGELOG.md

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,11 @@ You can find our backwards-compatibility policy [here](https://github.com/hynek/
1515

1616
## [Unreleased](https://github.com/hynek/structlog/compare/26.1.0...HEAD)
1717

18+
### Fixed
19+
20+
- `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"`.
21+
[#486](https://github.com/hynek/structlog/issues/486)
22+
1823

1924
## [26.1.0](https://github.com/hynek/structlog/compare/25.5.0...26.1.0) - 2026-06-06
2025

src/structlog/stdlib.py

Lines changed: 39 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -883,6 +883,20 @@ def add_logger_name(
883883
"name", 0, "pathname", 0, "msg", (), None
884884
).__dict__.keys()
885885

886+
# `Logger.makeRecord` raises `KeyError` if `extra` carries a key that already
887+
# exists on the `LogRecord` it builds. That's every key in `_LOG_RECORD_KEYS`,
888+
# plus "message" and "asctime", which aren't on a fresh `LogRecord` but are
889+
# added later by `Formatter.format()` and so are rejected by `makeRecord`
890+
# just the same. `render_to_log_kwargs`/`render_to_log_args_and_kwargs` build
891+
# `extra` straight out of whatever is left in the event dict, so a field
892+
# that happens to share a name with one of these -- "filename" or "module"
893+
# are plausible business field names -- crashes the logging call with that
894+
# `KeyError` instead of logging it.
895+
_RESERVED_LOG_RECORD_KEYS = frozenset(_LOG_RECORD_KEYS) | {
896+
"message",
897+
"asctime",
898+
}
899+
886900

887901
class ExtraAdder:
888902
"""
@@ -960,9 +974,17 @@ def render_to_log_args_and_kwargs(
960974
arguments, keyword arguments are extracted from the *event_dict* and the
961975
rest of the *event_dict* is added as ``extra``.
962976
977+
Keys that collide with an attribute `logging.LogRecord` already carries
978+
(for example ``filename`` or ``module``) are dropped instead of being
979+
added to ``extra``, because the standard library rejects them there with
980+
a `KeyError` at the point of logging.
981+
963982
This allows you to defer formatting to `logging`.
964983
965984
.. versionadded:: 25.1.0
985+
.. versionchanged:: 26.2.0
986+
Keys colliding with `logging.LogRecord` attributes are now dropped
987+
from ``extra`` instead of crashing the standard library.
966988
"""
967989
args = (event_dict.pop("event"), *event_dict.pop("positional_args", ()))
968990

@@ -971,6 +993,8 @@ def render_to_log_args_and_kwargs(
971993
for kwarg_name in LOG_KWARG_NAMES
972994
if kwarg_name in event_dict
973995
}
996+
for key in event_dict.keys() & _RESERVED_LOG_RECORD_KEYS:
997+
del event_dict[key]
974998
if event_dict:
975999
kwargs["extra"] = event_dict
9761000

@@ -989,6 +1013,11 @@ def render_to_log_kwargs(
9891013
extracted from the *event_dict* and the rest of the *event_dict* is added as
9901014
``extra``.
9911015
1016+
Keys that collide with an attribute `logging.LogRecord` already carries
1017+
(for example ``filename`` or ``module``) are dropped instead of being
1018+
added to ``extra``, because the standard library rejects them there with
1019+
a `KeyError` at the point of logging.
1020+
9921021
This allows you to defer formatting to `logging`.
9931022
9941023
.. versionadded:: 17.1.0
@@ -997,16 +1026,18 @@ def render_to_log_kwargs(
9971026
kwargs and not put into ``extra``.
9981027
.. versionchanged:: 24.2.0
9991028
``stackLevel`` corrected to ``stacklevel``.
1029+
.. versionchanged:: 26.2.0
1030+
Keys colliding with `logging.LogRecord` attributes are now dropped
1031+
from ``extra`` instead of crashing the standard library.
10001032
"""
1001-
return {
1002-
"msg": event_dict.pop("event"),
1003-
"extra": event_dict,
1004-
**{
1005-
kw: event_dict.pop(kw)
1006-
for kw in LOG_KWARG_NAMES
1007-
if kw in event_dict
1008-
},
1033+
msg = event_dict.pop("event")
1034+
kwargs = {
1035+
kw: event_dict.pop(kw) for kw in LOG_KWARG_NAMES if kw in event_dict
10091036
}
1037+
for key in event_dict.keys() & _RESERVED_LOG_RECORD_KEYS:
1038+
del event_dict[key]
1039+
1040+
return {"msg": msg, "extra": event_dict, **kwargs}
10101041

10111042

10121043
class ProcessorFormatter(logging.Formatter):

tests/test_stdlib.py

Lines changed: 63 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -870,6 +870,34 @@ def test_pass_kwargs_from_event_dict_as_kwargs(
870870
extra=expected_extra,
871871
)
872872

873+
def test_drops_keys_colliding_with_log_record_attributes(
874+
self, stdlib_logger: logging.Logger, caplog: pytest.LogCaptureFixture
875+
):
876+
"""
877+
A key that collides with an attribute `logging.LogRecord` already
878+
carries (for example "filename") is dropped from `extra` instead of
879+
being passed through, because the standard library raises `KeyError`
880+
when it's asked to overwrite it while building the record.
881+
882+
Cf. https://github.com/hynek/structlog/issues/486
883+
"""
884+
event_dict = {
885+
"event": "message",
886+
"filename": "not-a-real-file.py",
887+
"keep": "this",
888+
}
889+
890+
args, kwargs = render_to_log_args_and_kwargs(
891+
stdlib_logger, "info", event_dict
892+
)
893+
894+
assert {"extra": {"keep": "this"}} == kwargs
895+
896+
with caplog.at_level(logging.INFO):
897+
stdlib_logger.info(*args, **kwargs)
898+
899+
assert "this" == caplog.records[0].keep
900+
873901
def test_integration(
874902
self, stdlib_logger: logging.Logger, event_dict: dict[str, Any]
875903
):
@@ -987,6 +1015,41 @@ def test_handles_special_kw(self, event_dict, stdlib_logger):
9871015
logging.INFO, "message", (), **expected
9881016
)
9891017

1018+
def test_drops_keys_colliding_with_log_record_attributes(
1019+
self, stdlib_logger, caplog: pytest.LogCaptureFixture
1020+
):
1021+
"""
1022+
A key that collides with an attribute `logging.LogRecord` already
1023+
carries (for example "filename") is dropped from `extra` instead of
1024+
being passed through, because the standard library raises `KeyError`
1025+
when it's asked to overwrite it while building the record.
1026+
1027+
"message" collides too: it isn't on a fresh `LogRecord`, but the
1028+
standard library still special-cases and rejects it.
1029+
1030+
Cf. https://github.com/hynek/structlog/issues/486
1031+
"""
1032+
d = render_to_log_kwargs(
1033+
None,
1034+
None,
1035+
{
1036+
"event": "message",
1037+
"filename": "not-a-real-file.py",
1038+
"message": "duplicate-of-msg",
1039+
"keep": "this",
1040+
},
1041+
)
1042+
1043+
assert {
1044+
"msg": "message",
1045+
"extra": {"keep": "this"},
1046+
} == d
1047+
1048+
with caplog.at_level(logging.INFO):
1049+
stdlib_logger.info(**d)
1050+
1051+
assert "this" == caplog.records[0].keep
1052+
9901053
def test_integration_special_kw(self, event_dict, stdlib_logger):
9911054
"""
9921055
render_to_log_kwargs with a wrapped logger calls the stdlib logger

0 commit comments

Comments
 (0)