Skip to content

Commit 10e95ae

Browse files
YoannAbrielclaude
authored andcommitted
[v3-2-test] Backport #62849: Fix structlog positional formatting for single-dict arguments (#64773)
* Fix dict args in structlog positional formatting When a dict was passed as a positional argument to a log message (e.g. log.warning('message %s', {'a': 10})), both the structlog bound logger and the stdlib logging path would try named substitution first, causing TypeError for positional format specifiers like %s. Fix both paths to match CPython's stdlib logging behavior: try positional formatting (msg % args) first, fall back to named substitution (msg % args[0]) only on TypeError/KeyError. - In _make_airflow_structlogger.meth(): try event % args first, fall back to named substitution on failure - Add positional_arguments_formatter() to replace structlog's built-in PositionalArgumentsFormatter, which has the same ordering bug for stdlib logging records Fixes #62201 Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com> (cherry picked from commit e1e4bdb) * fix: add missing blank line before parametrize decorator (cherry picked from commit 9c6e3a4) --------- Co-authored-by: Claude Sonnet 4.6 <noreply@anthropic.com>
1 parent ec9f46a commit 10e95ae

2 files changed

Lines changed: 109 additions & 5 deletions

File tree

shared/logging/src/airflow_shared/logging/structlog.py

Lines changed: 34 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -95,10 +95,15 @@ def meth(self: Any, event: str, *args: Any, **kw: Any) -> Any:
9595
if not args:
9696
return self._proxy_to_logger(name, event, **kw)
9797

98-
# See https://github.com/python/cpython/blob/3.13/Lib/logging/__init__.py#L307-L326 for reason
99-
if args and len(args) == 1 and isinstance(args[0], Mapping) and args[0]:
100-
return self._proxy_to_logger(name, event % args[0], **kw)
101-
return self._proxy_to_logger(name, event % args, **kw)
98+
# Match CPython's stdlib logging behavior: try positional formatting first,
99+
# fall back to named substitution only if that fails.
100+
# See https://github.com/python/cpython/blob/3.13/Lib/logging/__init__.py#L307-L326
101+
try:
102+
return self._proxy_to_logger(name, event % args, **kw)
103+
except (TypeError, KeyError):
104+
if len(args) == 1 and isinstance(args[0], Mapping) and args[0]:
105+
return self._proxy_to_logger(name, event % args[0], **kw)
106+
raise
102107

103108
meth.__name__ = name
104109
return meth
@@ -216,6 +221,30 @@ def drop_positional_args(logger: Any, method_name: Any, event_dict: EventDict) -
216221
return event_dict
217222

218223

224+
def positional_arguments_formatter(logger: Any, method_name: Any, event_dict: EventDict) -> EventDict:
225+
"""
226+
Format positional arguments matching CPython's stdlib logging behavior.
227+
228+
Replaces structlog's built-in PositionalArgumentsFormatter to correctly handle the case
229+
where a single dict is passed as a positional argument (e.g. ``log.warning('%s', {'a': 1})``).
230+
231+
CPython tries positional formatting first (``msg % args``), and only falls back to named
232+
substitution (``msg % args[0]``) if that raises TypeError or KeyError. structlog's built-in
233+
formatter does it the other way around, causing TypeError for ``%s`` format specifiers.
234+
"""
235+
args = event_dict.get("positional_args")
236+
if args:
237+
try:
238+
event_dict["event"] = event_dict["event"] % args
239+
except (TypeError, KeyError):
240+
if len(args) == 1 and isinstance(args[0], Mapping) and args[0]:
241+
event_dict["event"] = event_dict["event"] % args[0]
242+
else:
243+
raise
244+
del event_dict["positional_args"]
245+
return event_dict
246+
247+
219248
# This is a placeholder fn, that is "edited" in place via the `suppress_logs_and_warning` decorator
220249
# The reason we need to do it this way is that structlog caches loggers on first use, and those include the
221250
# configured processors, so we can't get away with changing the config as it won't have any effect once the
@@ -268,7 +297,7 @@ def structlog_processors(
268297
timestamper,
269298
structlog.contextvars.merge_contextvars,
270299
structlog.processors.add_log_level,
271-
structlog.stdlib.PositionalArgumentsFormatter(),
300+
positional_arguments_formatter,
272301
logger_name,
273302
redact_jwt,
274303
structlog.processors.StackInfoRenderer(),

shared/logging/tests/logging/test_structlog.py

Lines changed: 75 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -623,3 +623,78 @@ def test_without_file_uses_py_warnings_logger(self):
623623
_showwarning("some warning", UserWarning, "foo.py", 1)
624624

625625
mock_get_logger.assert_called_once_with("py.warnings")
626+
627+
628+
@pytest.mark.parametrize(
629+
("get_logger", "message", "args", "expected_event"),
630+
[
631+
# dict passed as positional %s arg — should use positional formatting, not named
632+
pytest.param(
633+
logging.getLogger,
634+
"Info message %s",
635+
({"a": 10},),
636+
"Info message {'a': 10}",
637+
id="stdlib-dict-positional",
638+
),
639+
pytest.param(
640+
structlog.get_logger,
641+
"Info message %s",
642+
({"a": 10},),
643+
"Info message {'a': 10}",
644+
id="structlog-dict-positional",
645+
),
646+
# named substitution with dict should still work
647+
pytest.param(
648+
logging.getLogger,
649+
"%(a)s message",
650+
({"a": 10},),
651+
"10 message",
652+
id="stdlib-dict-named",
653+
),
654+
pytest.param(
655+
structlog.get_logger,
656+
"%(a)s message",
657+
({"a": 10},),
658+
"10 message",
659+
id="structlog-dict-named",
660+
),
661+
# simple non-dict positional arg
662+
pytest.param(
663+
logging.getLogger,
664+
"message %s",
665+
("simple",),
666+
"message simple",
667+
id="stdlib-simple-positional",
668+
),
669+
pytest.param(
670+
structlog.get_logger,
671+
"message %s",
672+
("simple",),
673+
"message simple",
674+
id="structlog-simple-positional",
675+
),
676+
# no args
677+
pytest.param(
678+
logging.getLogger,
679+
"message",
680+
(),
681+
"message",
682+
id="stdlib-no-args",
683+
),
684+
pytest.param(
685+
structlog.get_logger,
686+
"message",
687+
(),
688+
"message",
689+
id="structlog-no-args",
690+
),
691+
],
692+
)
693+
def test_dict_positional_arg_formatting(structlog_config, get_logger, message, args, expected_event):
694+
"""Regression test for dict args passed as positional log arguments (GitHub issue #62201)."""
695+
with structlog_config(json_output=True) as bio:
696+
logger = get_logger("my.logger")
697+
logger.warning(message, *args)
698+
699+
written = json.load(bio)
700+
assert written["event"] == expected_event

0 commit comments

Comments
 (0)