Skip to content

Commit a891ef8

Browse files
build(flake8): Add S019 rule banning reserved LogRecord keys in logging extra= (#117562)
## Summary Passing a reserved `LogRecord` attribute (`name`, `message`, `args`, `module`, …) as a key in a logging `extra=` dict raises `KeyError: "Attempt to overwrite 'X' in LogRecord"` **at runtime**, when the log line actually fires. Nothing static catches it — it passes ruff, mypy, and a human skim — and it recently caused a silent production incident in preprod snapshots (the log call meant to aid debugging was the thing that crashed; see #117550). This adds a custom **S019** flake8 rule (Sentry's `S###` family in `tools/flake8_plugin.py`) that flags this class before runtime, and fixes the only two existing violations it surfaces repo-wide. This follows up a review question on #117550 ("can this class of problem be prevented before runtime?"). ## Changes - **S019 rule** (`tools/flake8_plugin.py`): flags `logger.<level>(..., extra={...})` calls whose `extra` dict has a literal string key colliding with a reserved `LogRecord` attribute. Auto-registered via the existing `S=` prefix plugin (no config change). - **`test_S019`** (`tests/tools/test_flake8_plugin.py`): covers `name`/`message` hits, a non-reserved key (ok), and a dynamic `extra=var` (not flagged). - **Fixes for the two surfaced violations:** - `hybridcloud/apigateway/proxy.py`: `"message"` → `"error"` in a breaker-config warning (would have crashed when invalid config was hit). - `preprod/snapshots/tasks.py`: `"name"` → `"image_name"` (same fix as #117550; identical change, no conflict whichever merges first). ## Known limitation Only **literal** `extra={...}` dicts with constant string keys are checked. Dynamic dicts (`extra=some_var`, `extra={**spread}`, computed keys) can't be detected statically — but the literal case is the one that actually bites. ## Test Plan - [x] `test_S019` passes; full `tests/tools/test_flake8_plugin.py` suite green (18 tests) - [x] `flake8 --select=S019 src tests tools` reports clean after the two fixes (was 2 hits before) - [x] ruff + mypy clean on changed files
1 parent 9fae755 commit a891ef8

3 files changed

Lines changed: 71 additions & 1 deletion

File tree

src/sentry/hybridcloud/apigateway/proxy.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -151,7 +151,7 @@ def proxy_cell_request(request: HttpRequest, cell: Cell, url_name: str) -> HttpR
151151
),
152152
)
153153
except Exception as e:
154-
logger.warning("apigateway.invalid-breaker-config", extra={"message": str(e)})
154+
logger.warning("apigateway.invalid-breaker-config", extra={"error": str(e)})
155155

156156
if circuit_breaker is not None:
157157
if not circuit_breaker.should_allow_request():

tests/tools/test_flake8_plugin.py

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -393,3 +393,23 @@ def test_S015_current_or_future_year() -> None:
393393
)
394394
== []
395395
)
396+
397+
398+
def test_S019() -> None:
399+
src = """\
400+
import logging
401+
402+
logger = logging.getLogger(__name__)
403+
404+
logger.info("m", extra={"name": 1})
405+
logger.warning("m", extra={"message": "x"})
406+
logger.info("m", extra={"ok_key": 1})
407+
logger.info("m", extra=other)
408+
"""
409+
expected = [
410+
"t.py:5:24: S019 'name' is a reserved LogRecord attribute; using it as a key in "
411+
"logging extra= raises KeyError at runtime",
412+
"t.py:6:27: S019 'message' is a reserved LogRecord attribute; using it as a key in "
413+
"logging extra= raises KeyError at runtime",
414+
]
415+
assert _run(src) == expected

tools/flake8_plugin.py

Lines changed: 50 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -55,6 +55,43 @@
5555
S018_fqn = "django.core.cache.backends.memcached.PyMemcacheCache" # noqa: S018
5656
S018_module = "django.core.cache.backends.memcached"
5757

58+
S019_fmt = (
59+
"S019 {!r} is a reserved LogRecord attribute; using it as a key in "
60+
"logging extra= raises KeyError at runtime"
61+
)
62+
S019_logging_methods = frozenset(
63+
("debug", "info", "warning", "warn", "error", "exception", "critical", "fatal", "log")
64+
)
65+
# Keys rejected by logging.Logger.makeRecord: the attributes set in
66+
# LogRecord.__init__ plus the explicit "message"/"asctime" guard.
67+
S019_logrecord_attrs = frozenset(
68+
(
69+
"name",
70+
"msg",
71+
"args",
72+
"levelname",
73+
"levelno",
74+
"pathname",
75+
"filename",
76+
"module",
77+
"exc_info",
78+
"exc_text",
79+
"stack_info",
80+
"lineno",
81+
"funcName",
82+
"created",
83+
"msecs",
84+
"relativeCreated",
85+
"thread",
86+
"threadName",
87+
"processName",
88+
"process",
89+
"taskName",
90+
"message",
91+
"asctime",
92+
)
93+
)
94+
5895

5996
# --- S015: do not hardcode current or future UTC year as test "now" ---
6097
# Flag year >= current UTC year at lint time. Module/class scope + freeze_time(datetime(...)).
@@ -300,6 +337,19 @@ def visit_Call(self, node: ast.Call) -> None:
300337
if keyword.arg == "SENTRY_OPTIONS":
301338
self.errors.append((keyword.lineno, keyword.col_offset, S011_msg))
302339

340+
if isinstance(node.func, ast.Attribute) and node.func.attr in S019_logging_methods:
341+
for keyword in node.keywords:
342+
if keyword.arg == "extra" and isinstance(keyword.value, ast.Dict):
343+
for key in keyword.value.keys:
344+
if (
345+
isinstance(key, ast.Constant)
346+
and isinstance(key.value, str)
347+
and key.value in S019_logrecord_attrs
348+
):
349+
self.errors.append(
350+
(key.lineno, key.col_offset, S019_fmt.format(key.value))
351+
)
352+
303353
self.generic_visit(node)
304354

305355

0 commit comments

Comments
 (0)