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:
1 parent
8c44a07642
commit
a286ef460b
3 files changed
+107
-8
No files matched your search
@@ -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
|
||||
|
||||
Reference in new issue
Block a user