Do not mangle log messages when a log formatter returns empty or tuple args (#7936)

scrapy/utils/log.py

@@ -245,7 +245,7 @@ class LogCounterHandler(logging.Handler):
 
 def logformatter_adapter(
     logkws: LogFormatterResult,
-) -> tuple[int, str, dict[str, Any] | tuple[Any, ...]]:
+) -> tuple[Any, ...]:
     """
     Helper that takes the dictionary output from the methods in LogFormatter
     and adapts it into a tuple of positional arguments for logger.log calls.
@@ -253,10 +253,14 @@ def logformatter_adapter(
 
     level = logkws.get("level", logging.INFO)
     message = logkws.get("msg") or ""
-    # NOTE: This also handles 'args' being an empty dict, that case doesn't
-    # play well in logger.log calls
-    args = cast("dict[str, Any]", logkws) if not logkws.get("args") else logkws["args"]
-
+    args = logkws.get("args")
+    # logging interpolates the message whenever it receives any positional
+    # 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:
+        return (level, message)
+    if isinstance(args, tuple):
+        return (level, message, *args)
     return (level, message, args)
 
 

tests/test_utils_log.py

@@ -5,7 +5,7 @@ import logging
 import re
 import sys
 from io import StringIO
-from typing import TYPE_CHECKING, Any
+from typing import TYPE_CHECKING, Any, cast
 
 import pytest
 from twisted.python.failure import Failure
@@ -16,6 +16,7 @@ from scrapy.utils.log import (
     StreamLogger,
     TopLevelFormatter,
     failure_to_exc_info,
+    logformatter_adapter,
 )
 from scrapy.utils.test import get_crawler
 from tests.spiders import LogSpider
@@ -24,6 +25,7 @@ if TYPE_CHECKING:
     from collections.abc import Generator, Mapping, MutableMapping
 
     from scrapy.crawler import Crawler
+    from scrapy.logformatter import LogFormatterResult
 
 
 class TestFailureToExcInfo:
@@ -311,3 +313,36 @@ class TestLoggingWithExtra:
         assert log_contents["message"] == log_message
         assert self.regex_pattern.match(log_contents["spider"])
         assert log_contents["important_info"] == extra["important_info"]
+
+
+class TestLogformatterAdapter:
+    @staticmethod
+    def _log(caplog: pytest.LogCaptureFixture, logkws: LogFormatterResult) -> str:
+        with caplog.at_level(logging.INFO):
+            logging.getLogger(__name__).log(*logformatter_adapter(logkws))
+        return caplog.records[-1].getMessage()
+
+    @pytest.mark.parametrize("args", [None, {}, ()])
+    def test_empty_args(
+        self,
+        caplog: pytest.LogCaptureFixture,
+        args: dict[str, Any] | tuple[Any, ...] | None,
+    ) -> None:
+        logkws = cast(
+            "LogFormatterResult",
+            {"level": logging.INFO, "msg": "90% done", "args": args},
+        )
+        assert self._log(caplog, logkws) == "90% done"
+
+    @pytest.mark.parametrize(
+        ("msg", "args"),
+        [("%(pct)d%% done", {"pct": 90}), ("%d%% done", (90,))],
+    )
+    def test_args(
+        self,
+        caplog: pytest.LogCaptureFixture,
+        msg: str,
+        args: dict[str, Any] | tuple[Any, ...],
+    ) -> None:
+        logkws: LogFormatterResult = {"level": logging.INFO, "msg": msg, "args": args}
+        assert self._log(caplog, logkws) == "90% done"