diff --git a/CHANGELOG.md b/CHANGELOG.md index b23d71a7..2389823a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -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 diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index 2906598d..f9e91d7c 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -883,6 +883,14 @@ def add_logger_name( "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): diff --git a/tests/test_stdlib.py b/tests/test_stdlib.py index 36699025..45f71b91 100644 --- a/tests/test_stdlib.py +++ b/tests/test_stdlib.py @@ -870,6 +870,34 @@ def test_pass_kwargs_from_event_dict_as_kwargs( 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 @@ def test_handles_special_kw(self, event_dict, stdlib_logger): 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