Deprecate interpolating log formatter messages with the returned dict (#7971)

scrapy/utils/log.py

@@ -2,7 +2,9 @@ from __future__ import annotations
 
 import logging
 import pprint
+import re
 import sys
+import warnings
 from collections.abc import MutableMapping
 from logging.config import dictConfig
 from typing import TYPE_CHECKING, Any, cast
@@ -12,6 +14,7 @@ from twisted.python import log as twisted_log
 from twisted.python.failure import Failure
 
 import scrapy
+from scrapy.exceptions import ScrapyDeprecationWarning
 from scrapy.settings import Settings
 from scrapy.utils.versions import get_versions
 
@@ -242,6 +245,9 @@ class LogCounterHandler(logging.Handler):
         self.crawler.stats.inc_value(sname)
 
 
+_MSG_MAPPING_PLACEHOLDER = re.compile(r"%\(\w+\)")
+
+
 def logformatter_adapter(
     logkws: LogFormatterResult,
 ) -> tuple[Any, ...]:
@@ -257,6 +263,20 @@ def logformatter_adapter(
     # argument, so empty args are left out. Tuple args become one positional
     # argument each, while a dict is a single positional argument.
     if not args:
+        if _MSG_MAPPING_PLACEHOLDER.search(message):
+            # The log formatter method has already returned, so there is no
+            # frame of it left in the stack to point at. msg is part of the
+            # warning message instead, so that each offending method gets its
+            # own warning.
+            warnings.warn(
+                f"A log formatter method returned msg {message!r} with "
+                f"%(name)s placeholders and no args. Interpolating msg with "
+                f"the returned dict is deprecated, return those values under "
+                f"args instead.",
+                ScrapyDeprecationWarning,
+                stacklevel=1,
+            )
+            return (level, message, logkws)
         return (level, message)
     if isinstance(args, tuple):
         return (level, message, *args)

tests/test_utils_log.py

@@ -4,12 +4,14 @@ import json
 import logging
 import re
 import sys
+import warnings
 from io import StringIO
 from typing import TYPE_CHECKING, Any, cast
 
 import pytest
 from twisted.python.failure import Failure
 
+from scrapy.exceptions import ScrapyDeprecationWarning
 from scrapy.utils.log import (
     LogCounterHandler,
     SpiderLoggerAdapter,
@@ -332,7 +334,9 @@ class TestLogformatterAdapter:
             "LogFormatterResult",
             {"level": logging.INFO, "msg": "90% done", "args": args},
         )
-        assert self._log(caplog, logkws) == "90% done"
+        with warnings.catch_warnings():
+            warnings.simplefilter("error", ScrapyDeprecationWarning)
+            assert self._log(caplog, logkws) == "90% done"
 
     @pytest.mark.parametrize(
         ("msg", "args"),
@@ -345,4 +349,16 @@ class TestLogformatterAdapter:
         args: dict[str, Any] | tuple[Any, ...],
     ) -> None:
         logkws: LogFormatterResult = {"level": logging.INFO, "msg": msg, "args": args}
-        assert self._log(caplog, logkws) == "90% done"
+        with warnings.catch_warnings():
+            warnings.simplefilter("error", ScrapyDeprecationWarning)
+            assert self._log(caplog, logkws) == "90% done"
+
+    def test_msg_mapping_placeholders_without_args(
+        self, caplog: pytest.LogCaptureFixture
+    ) -> None:
+        logkws = cast(
+            "LogFormatterResult",
+            {"level": logging.INFO, "msg": "%(pct)d%% done", "pct": 90},
+        )
+        with pytest.warns(ScrapyDeprecationWarning, match="no args"):
+            assert self._log(caplog, logkws) == "90% done"