Add SpiderLoggerAdapter, change Spider.logger to return SpiderLoggerAdapter (#6324)

scrapy/spiders/__init__.py

@@ -21,6 +21,7 @@ if TYPE_CHECKING:
 
     from scrapy.crawler import Crawler
     from scrapy.settings import BaseSettings
+    from scrapy.utils.log import SpiderLoggerAdapter
 
 
 class Spider(object_ref):
@@ -41,9 +42,11 @@ class Spider(object_ref):
             self.start_urls: List[str] = []
 
     @property
-    def logger(self) -> logging.LoggerAdapter:
+    def logger(self) -> SpiderLoggerAdapter:
+        from scrapy.utils.log import SpiderLoggerAdapter
+
         logger = logging.getLogger(self.name)
-        return logging.LoggerAdapter(logger, {"spider": self})
+        return SpiderLoggerAdapter(logger, {"spider": self})
 
     def log(self, message: Any, level: int = logging.DEBUG, **kw: Any) -> None:
         """Log the given message at the given log level

scrapy/utils/log.py

@@ -5,7 +5,17 @@ import sys
 import warnings
 from logging.config import dictConfig
 from types import TracebackType
-from typing import TYPE_CHECKING, Any, List, Optional, Tuple, Type, Union, cast
+from typing import (
+    TYPE_CHECKING,
+    Any,
+    List,
+    MutableMapping,
+    Optional,
+    Tuple,
+    Type,
+    Union,
+    cast,
+)
 
 from twisted.python import log as twisted_log
 from twisted.python.failure import Failure
@@ -249,3 +259,16 @@ def logformatter_adapter(logkws: dict) -> Tuple[int, str, dict]:
     args = logkws if not logkws.get("args") else logkws["args"]
 
     return (level, message, args)
+
+
+class SpiderLoggerAdapter(logging.LoggerAdapter):
+    def process(
+        self, msg: str, kwargs: MutableMapping[str, Any]
+    ) -> Tuple[str, MutableMapping[str, Any]]:
+        """Method that augments logging with additional 'extra' data"""
+        if isinstance(kwargs.get("extra"), MutableMapping):
+            kwargs["extra"].update(self.extra)
+        else:
+            kwargs["extra"] = self.extra
+
+        return msg, kwargs

tests/spiders.py

@@ -3,6 +3,7 @@ Some spiders used for testing and benchmarking
 """
 import asyncio
 import time
+from typing import Optional
 from urllib.parse import urlencode
 
 from twisted.internet import defer
@@ -77,6 +78,28 @@ class DelaySpider(MetaSpider):
         self.t2_err = time.time()
 
 
+class LogSpider(MetaSpider):
+    name = "log_spider"
+
+    def log_debug(self, message: str, extra: Optional[dict] = None):
+        self.logger.debug(message, extra=extra)
+
+    def log_info(self, message: str, extra: Optional[dict] = None):
+        self.logger.info(message, extra=extra)
+
+    def log_warning(self, message: str, extra: Optional[dict] = None):
+        self.logger.warning(message, extra=extra)
+
+    def log_error(self, message: str, extra: Optional[dict] = None):
+        self.logger.error(message, extra=extra)
+
+    def log_critical(self, message: str, extra: Optional[dict] = None):
+        self.logger.critical(message, extra=extra)
+
+    def parse(self, response):
+        pass
+
+
 class SlowSpider(DelaySpider):
     name = "slow"
 

tests/test_utils_log.py

@@ -1,18 +1,26 @@
+import json
 import logging
+import re
 import sys
 import unittest
+from io import StringIO
+from typing import Any, Dict, Mapping, MutableMapping
+from unittest import TestCase
 
+import pytest
 from testfixtures import LogCapture
 from twisted.python.failure import Failure
 
 from scrapy.extensions import telnet
 from scrapy.utils.log import (
     LogCounterHandler,
+    SpiderLoggerAdapter,
     StreamLogger,
     TopLevelFormatter,
     failure_to_exc_info,
 )
 from scrapy.utils.test import get_crawler
+from tests.spiders import LogSpider
 
 
 class FailureToExcInfoTest(unittest.TestCase):
@@ -106,3 +114,180 @@ class StreamLoggerTest(unittest.TestCase):
         with LogCapture() as log:
             print("test log msg")
         log.check(("test", "ERROR", "test log msg"))
+
+
+@pytest.mark.parametrize(
+    ("base_extra", "log_extra", "expected_extra"),
+    (
+        (
+            {"spider": "test"},
+            {"extra": {"log_extra": "info"}},
+            {"extra": {"log_extra": "info", "spider": "test"}},
+        ),
+        (
+            {"spider": "test"},
+            {"extra": None},
+            {"extra": {"spider": "test"}},
+        ),
+        (
+            {"spider": "test"},
+            {"extra": {"spider": "test2"}},
+            {"extra": {"spider": "test"}},
+        ),
+    ),
+)
+def test_spider_logger_adapter_process(
+    base_extra: Mapping[str, Any], log_extra: MutableMapping, expected_extra: Dict
+):
+    logger = logging.getLogger("test")
+    spider_logger_adapter = SpiderLoggerAdapter(logger, base_extra)
+
+    log_message = "test_log_message"
+    result_message, result_kwargs = spider_logger_adapter.process(
+        log_message, log_extra
+    )
+
+    assert result_message == log_message
+    assert result_kwargs == expected_extra
+
+
+class LoggingTestCase(TestCase):
+    def setUp(self):
+        self.log_stream = StringIO()
+        handler = logging.StreamHandler(self.log_stream)
+        logger = logging.getLogger("log_spider")
+        logger.addHandler(handler)
+        logger.setLevel(logging.DEBUG)
+        self.handler = handler
+        self.logger = logger
+        self.spider = LogSpider()
+
+    def tearDown(self):
+        self.logger.removeHandler(self.handler)
+
+    def test_debug_logging(self):
+        log_message = "Foo message"
+        self.spider.log_debug(log_message)
+        log_contents = self.log_stream.getvalue()
+
+        assert log_contents == f"{log_message}\n"
+
+    def test_info_logging(self):
+        log_message = "Bar message"
+        self.spider.log_info(log_message)
+        log_contents = self.log_stream.getvalue()
+
+        assert log_contents == f"{log_message}\n"
+
+    def test_warning_logging(self):
+        log_message = "Baz message"
+        self.spider.log_warning(log_message)
+        log_contents = self.log_stream.getvalue()
+
+        assert log_contents == f"{log_message}\n"
+
+    def test_error_logging(self):
+        log_message = "Foo bar message"
+        self.spider.log_error(log_message)
+        log_contents = self.log_stream.getvalue()
+
+        assert log_contents == f"{log_message}\n"
+
+    def test_critical_logging(self):
+        log_message = "Foo bar baz message"
+        self.spider.log_critical(log_message)
+        log_contents = self.log_stream.getvalue()
+
+        assert log_contents == f"{log_message}\n"
+
+
+class LoggingWithExtraTestCase(TestCase):
+    def setUp(self):
+        self.log_stream = StringIO()
+        handler = logging.StreamHandler(self.log_stream)
+        formatter = logging.Formatter(
+            '{"levelname": "%(levelname)s", "message": "%(message)s", "spider": "%(spider)s", "important_info": "%(important_info)s"}'
+        )
+        handler.setFormatter(formatter)
+        logger = logging.getLogger("log_spider")
+        logger.addHandler(handler)
+        logger.setLevel(logging.DEBUG)
+        self.handler = handler
+        self.logger = logger
+        self.spider = LogSpider()
+        self.regex_pattern = re.compile(r"^<LogSpider\s'log_spider'\sat\s[^>]+>$")
+
+    def tearDown(self):
+        self.logger.removeHandler(self.handler)
+
+    def test_debug_logging(self):
+        log_message = "Foo message"
+        extra = {"important_info": "foo"}
+        self.spider.log_debug(log_message, extra)
+        log_contents = self.log_stream.getvalue()
+        log_contents = json.loads(log_contents)
+
+        assert log_contents["levelname"] == "DEBUG"
+        assert log_contents["message"] == log_message
+        assert self.regex_pattern.match(log_contents["spider"])
+        assert log_contents["important_info"] == extra["important_info"]
+
+    def test_info_logging(self):
+        log_message = "Bar message"
+        extra = {"important_info": "bar"}
+        self.spider.log_info(log_message, extra)
+        log_contents = self.log_stream.getvalue()
+        log_contents = json.loads(log_contents)
+
+        assert log_contents["levelname"] == "INFO"
+        assert log_contents["message"] == log_message
+        assert self.regex_pattern.match(log_contents["spider"])
+        assert log_contents["important_info"] == extra["important_info"]
+
+    def test_warning_logging(self):
+        log_message = "Baz message"
+        extra = {"important_info": "baz"}
+        self.spider.log_warning(log_message, extra)
+        log_contents = self.log_stream.getvalue()
+        log_contents = json.loads(log_contents)
+
+        assert log_contents["levelname"] == "WARNING"
+        assert log_contents["message"] == log_message
+        assert self.regex_pattern.match(log_contents["spider"])
+        assert log_contents["important_info"] == extra["important_info"]
+
+    def test_error_logging(self):
+        log_message = "Foo bar message"
+        extra = {"important_info": "foo bar"}
+        self.spider.log_error(log_message, extra)
+        log_contents = self.log_stream.getvalue()
+        log_contents = json.loads(log_contents)
+
+        assert log_contents["levelname"] == "ERROR"
+        assert log_contents["message"] == log_message
+        assert self.regex_pattern.match(log_contents["spider"])
+        assert log_contents["important_info"] == extra["important_info"]
+
+    def test_critical_logging(self):
+        log_message = "Foo bar baz message"
+        extra = {"important_info": "foo bar baz"}
+        self.spider.log_critical(log_message, extra)
+        log_contents = self.log_stream.getvalue()
+        log_contents = json.loads(log_contents)
+
+        assert log_contents["levelname"] == "CRITICAL"
+        assert log_contents["message"] == log_message
+        assert self.regex_pattern.match(log_contents["spider"])
+        assert log_contents["important_info"] == extra["important_info"]
+
+    def test_overwrite_spider_extra(self):
+        log_message = "Foo message"
+        extra = {"important_info": "foo", "spider": "shouldn't change"}
+        self.spider.log_error(log_message, extra)
+        log_contents = self.log_stream.getvalue()
+        log_contents = json.loads(log_contents)
+
+        assert log_contents["levelname"] == "ERROR"
+        assert log_contents["message"] == log_message
+        assert self.regex_pattern.match(log_contents["spider"])
+        assert log_contents["important_info"] == extra["important_info"]