Drop event dict keys colliding with LogRecord attributes in render_to_log_*

[dualfroz]

Problem

structlog.stdlib.render_to_log_kwargs() and
structlog.stdlib.render_to_log_args_and_kwargs() are documented, standard
processors for "rendering your log entries entirely within logging" (see
docs/standard-library.md, "Processors" section). Both build the extra
kwarg they hand to the standard library out of whatever event dict keys are
left after 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,
args, name, message, and so on are all plausible field names for
someone's structured business data -- the standard library's own
Logger.makeRecord() rejects the call outright:

>>> import logging, structlog
>>> structlog.configure(
...     processors=[structlog.stdlib.render_to_log_kwargs],
...     logger_factory=structlog.stdlib.LoggerFactory(),
...     wrapper_class=structlog.stdlib.BoundLogger,
... )
>>> logging.basicConfig(level=logging.DEBUG)
>>> log = structlog.get_logger("test")
>>> log.debug("hello", filename="not-a-file.py")
Traceback (most recent call last):
  ...
  File ".../logging/__init__.py", line 1656, in makeRecord
    raise KeyError("Attempt to overwrite %r in LogRecord" % key)
KeyError: "Attempt to overwrite 'filename' in LogRecord"

No ProcessorFormatter involved -- this is the plain "defer formatting to
logging" configuration from the docs. The log call itself raises, taking
down whatever code path tried to log.

Root cause

src/structlog/stdlib.py, render_to_log_kwargs() (around line 1001,
pre-fix) and render_to_log_args_and_kwargs() (around line 961, pre-fix):
after popping event/positional_args/LOG_KWARG_NAMES, both functions
put the entire remaining event dict under extra unconditionally. They
never check it against the names logging.LogRecord already reserves for
itself.

This is exactly the reverse of what structlog.stdlib.ExtraAdder already
does a few dozen lines above in the same file: ExtraAdder merges a
LogRecord's own extra fields into an event dict, and it explicitly
filters out _LOG_RECORD_KEYS (a LogRecord's standard attribute names) so
that record-internal fields do not leak in as noise. render_to_log_kwargs/
render_to_log_args_and_kwargs do the same round trip in the opposite
direction (event dict -> extra on a soon-to-be-built LogRecord) but had
no equivalent filter.

Two names collide that are not in a fresh LogRecord.__dict__ at all:
"message" and "asctime". Logger.makeRecord() special-cases both and
rejects them regardless, because Formatter.format() adds them later:

if (key in ["message", "asctime"]) or (key in rv.__dict__):
    raise KeyError("Attempt to overwrite %r in LogRecord" % key)

Issue and prior state

This is #486, open since the
report against a Gunicorn integration. The maintainer identified the same
root cause in the issue thread and proposed the same fix direction ("this
needs to be fixed in render_to_log_kwargs and
render_to_log_args_and_kwargs by not putting these fields under these
names into extra"), but the only change that shipped
(commit 5400612, "docs/stdlib: add warning about ProcessorFormatter")
only documents a different, narrower footgun: not to combine
render_to_log_kwargs/render_to_log_args_and_kwargs with
ProcessorFormatter (a real but separate problem, since ProcessorFormatter
adds its own extra={"_logger": ..., "_name": ...} on top). It does not
touch the underlying collision, which reproduces with a plain, non-
ProcessorFormatter configuration as shown above.

Fix

Reuse the existing _LOG_RECORD_KEYS constant (already computed from a
fresh LogRecord for ExtraAdder), extended with "message" and
"asctime" as _RESERVED_LOG_RECORD_KEYS. Both render_to_log_kwargs()
and render_to_log_args_and_kwargs() now delete any event dict key that
intersects with that set before handing the remainder to logging as
extra. Non-colliding data is passed through exactly as before.

This drops the colliding field's value rather than renaming or raising.
That mirrors ExtraAdder's own established precedent for the reverse
direction in this same file, and it means the fix trades a crash for a
silent, best-effort log entry instead of no log entry (and a raised
exception) at all -- see "Flags" below for the alternative the maintainer's
wording also allows.

[codspeed]

Merging this PR will not alter performance

✅ 10 untouched benchmarks

---

_{Comparing dualfroz:dualfroz/fix-render-to-log-kwargs-reserved-keys (6c697cd) with main (bf3cfd0)¹}

Footnotes

1. No successful run was found on main (73393f3) during the generation of this report, so bf3cfd0 was used instead as the comparison base. There might be some changes unrelated to this pull request in this report. ↩

[feiiiiii5]

Verified on both trees. The fix is correct, complete, and doesn't over-drop — and the reserved set matches CPython's actual check exactly, which is the part I expected to be wrong.

The crash is real and wider than the body's example. Driving the full structlog → Logger.makeRecord path with 23 names makeRecord rejects, base raises for 21 (the other two, exc_info and stack_info, are already pulled into explicit kwargs by LOG_KWARG_NAMES). Branch raises for 0 and drops all of them, in both render_to_log_kwargs and render_to_log_args_and_kwargs — filename, module, pathname, funcName, lineno, process, thread, name, msg, args, levelname, levelno, created, msecs, relativeCreated, exc_text, message, asctime, taskName among them.

message and asctime are the two a naive implementation would miss, since Formatter.format() adds them after the record exists and they're absent from a fresh LogRecord.__dict__. Including them explicitly is right, and it matches CPython, whose makeRecord checks ["message", "asctime"] in addition to record.__dict__. Deriving the rest from a sample record also means taskName is picked up on 3.12+ and correctly absent on older versions, where makeRecord wouldn't reject it either.

No over-dropping, which was my other worry — these all still reach the record untouched: user_id, order_id, filename_suffix, module_name, msg_id, myargs. The match is exact rather than prefix- or substring-based.

Coverage is complete in the source. kwargs["extra"] is built from the event dict in exactly those two functions; the only other extra= in stdlib.py is the fixed {"_logger": ..., "_name": ...} pair, and ProcessorFormatter never routes event-dict keys through extra.

Tests. tests/test_stdlib.py: base 2 failed, 141 passed, branch 143 passed. Full suite: base 6 failed, 895 passed, branch 4 failed, 897 passed — the 4 shared failures are test_packaging.py::TestLegacyMetadataHack, failing identically in both trees. Diffing the failure sets, base has exactly the 2 new tests extra and the branch has nothing extra, so nothing regressed.

One design question, your call rather than a blocker. The fix trades a loud crash for silent data loss: a business field genuinely named filename or module now vanishes with no signal, and someone debugging missing log fields has nothing to grep for. I'm not opposed — raising from inside a processor re-breaks the log call, which is the bug you're fixing — but a warnings.warn, or a line in docs/standard-library.md (which your body cites as where people learn about these processors) saying the field was dropped and should be renamed, would help. I raise it only because "silently gone" and "documented as dropped" are different failure modes for a user.

Also worth confirming: the versionchanged directives say 26.2.0 while the CHANGELOG's Unreleased section compares against 26.1.0.