diff --git a/scrapy/core/engine.py b/scrapy/core/engine.py index 1033e874f..6848ea952 100644 --- a/scrapy/core/engine.py +++ b/scrapy/core/engine.py @@ -41,7 +41,7 @@ from scrapy.utils.defer import ( maybe_deferred_to_future, ) from scrapy.utils.deprecate import argument_is_required -from scrapy.utils.log import failure_to_exc_info, logformatter_adapter +from scrapy.utils.log import failure_to_exc_info, log_crawler, logformatter_adapter from scrapy.utils.misc import build_from_crawler, load_object from scrapy.utils.python import global_object_name from scrapy.utils.reactor import CallLaterOnce @@ -274,7 +274,8 @@ class ExecutionEngine: """ assert self._start is not None try: - item_or_request = await anext(self._start) + with log_crawler(self.crawler): + item_or_request = await anext(self._start) except StopAsyncIteration: self._start = None except Exception as exception: diff --git a/scrapy/core/scraper.py b/scrapy/core/scraper.py index 466ce656d..0c8c2a525 100644 --- a/scrapy/core/scraper.py +++ b/scrapy/core/scraper.py @@ -35,7 +35,7 @@ from scrapy.utils.defer import ( parallel_async, ) from scrapy.utils.deprecate import method_is_overridden -from scrapy.utils.log import failure_to_exc_info, logformatter_adapter +from scrapy.utils.log import failure_to_exc_info, log_crawler, logformatter_adapter from scrapy.utils.misc import load_object, warn_on_generator_with_return_value from scrapy.utils.python import global_object_name from scrapy.utils.spider import iterate_spider_output @@ -310,40 +310,43 @@ class Scraper: .. versionadded:: 2.13 """ await _defer_sleep_async() - assert self.crawler.spider - if isinstance(result, Response): - if getattr(result, "request", None) is None: - result.request = request - assert result.request - callback = result.request.callback or self.crawler.spider._parse - warn_on_generator_with_return_value(self.crawler.spider, callback) - output = callback(result, **result.request.cb_kwargs) - if isinstance(output, Deferred): - warnings.warn( - f"{callback} returned a Deferred." - f" Returning Deferreds from spider callbacks is deprecated.", - ScrapyDeprecationWarning, - stacklevel=2, + with log_crawler(self.crawler): + assert self.crawler.spider + if isinstance(result, Response): + if getattr(result, "request", None) is None: + result.request = request + assert result.request + callback = result.request.callback or self.crawler.spider._parse + warn_on_generator_with_return_value(self.crawler.spider, callback) + output = callback(result, **result.request.cb_kwargs) + if isinstance(output, Deferred): + warnings.warn( + f"{callback} returned a Deferred." + f" Returning Deferreds from spider callbacks is deprecated.", + ScrapyDeprecationWarning, + stacklevel=2, + ) + else: # result is a Failure + # TODO: properly type adding this attribute to a Failure + result.request = request # type: ignore[attr-defined] + if not request.errback: + result.raiseException() + warn_on_generator_with_return_value( + self.crawler.spider, request.errback ) - else: # result is a Failure - # TODO: properly type adding this attribute to a Failure - result.request = request # type: ignore[attr-defined] - if not request.errback: - result.raiseException() - warn_on_generator_with_return_value(self.crawler.spider, request.errback) - output = request.errback(result) - if isinstance(output, Failure): - output.raiseException() - # else the errback returned actual output (like a callback), - # which needs to be passed to iterate_spider_output() - if isinstance(output, Deferred): - warnings.warn( - f"{request.errback} returned a Deferred." - f" Returning Deferreds from spider errbacks is deprecated.", - ScrapyDeprecationWarning, - stacklevel=2, - ) - return await ensure_awaitable(iterate_spider_output(output)) + output = request.errback(result) + if isinstance(output, Failure): + output.raiseException() + # else the errback returned actual output (like a callback), + # which needs to be passed to iterate_spider_output() + if isinstance(output, Deferred): + warnings.warn( + f"{request.errback} returned a Deferred." + f" Returning Deferreds from spider errbacks is deprecated.", + ScrapyDeprecationWarning, + stacklevel=2, + ) + return await ensure_awaitable(iterate_spider_output(output)) def handle_spider_error( self, @@ -491,12 +494,13 @@ class Scraper: assert self.crawler.spider is not None # typing self.slot.itemproc_size += 1 try: - if self._itemproc_has_async["process_item"]: - output = await self.itemproc.process_item_async(item) - else: - output = await maybe_deferred_to_future( - self.itemproc.process_item(item, self.crawler.spider) - ) + with log_crawler(self.crawler): + if self._itemproc_has_async["process_item"]: + output = await self.itemproc.process_item_async(item) + else: + output = await maybe_deferred_to_future( + self.itemproc.process_item(item, self.crawler.spider) + ) except DropItem as ex: logkws = self.logformatter.dropped(item, ex, response, self.crawler.spider) if logkws is not None: diff --git a/scrapy/crawler.py b/scrapy/crawler.py index 9828fe6f5..9413d04f3 100644 --- a/scrapy/crawler.py +++ b/scrapy/crawler.py @@ -25,6 +25,7 @@ from scrapy.utils.log import ( configure_logging, get_scrapy_root_handler, install_scrapy_root_handler, + log_crawler, log_reactor_info, log_scrapy_info, ) @@ -184,18 +185,19 @@ class Crawler: ) self.crawling = self._started = True - try: - self.spider = self._create_spider(*args, **kwargs) - self._apply_settings() - self._update_root_log_handler() - self.engine = self._create_engine() - yield deferred_from_coro(self.engine.open_spider_async()) - yield deferred_from_coro(self.engine.start_async()) - except Exception: - self.crawling = False - if self.engine is not None: - yield deferred_from_coro(self.engine.close_async()) - raise + with log_crawler(self): + try: + self.spider = self._create_spider(*args, **kwargs) + self._apply_settings() + self._update_root_log_handler() + self.engine = self._create_engine() + yield deferred_from_coro(self.engine.open_spider_async()) + yield deferred_from_coro(self.engine.start_async()) + except Exception: + self.crawling = False + if self.engine is not None: + yield deferred_from_coro(self.engine.close_async()) + raise async def crawl_async(self, *args: Any, **kwargs: Any) -> None: """Start the crawler by instantiating its spider class with the given @@ -214,18 +216,19 @@ class Crawler: ) self.crawling = self._started = True - try: - self.spider = self._create_spider(*args, **kwargs) - self._apply_settings() - self._update_root_log_handler() - self.engine = self._create_engine() - await self.engine.open_spider_async() - await self.engine.start_async() - except Exception: - self.crawling = False - if self.engine is not None: - await self.engine.close_async() - raise + with log_crawler(self): + try: + self.spider = self._create_spider(*args, **kwargs) + self._apply_settings() + self._update_root_log_handler() + self.engine = self._create_engine() + await self.engine.open_spider_async() + await self.engine.start_async() + except Exception: + self.crawling = False + if self.engine is not None: + await self.engine.close_async() + raise def _create_spider(self, *args: Any, **kwargs: Any) -> Spider: return self.spidercls.from_crawler(self, *args, **kwargs) @@ -248,11 +251,12 @@ class Crawler: .. versionadded:: 2.14 """ - if self.crawling: - self.crawling = False - assert self.engine - if self.engine.running: - await self.engine.stop_async() + with log_crawler(self): + if self.crawling: + self.crawling = False + assert self.engine + if self.engine.running: + await self.engine.stop_async() @staticmethod def _get_component( diff --git a/scrapy/utils/log.py b/scrapy/utils/log.py index b1f1c24d5..6c9996af2 100644 --- a/scrapy/utils/log.py +++ b/scrapy/utils/log.py @@ -3,7 +3,9 @@ from __future__ import annotations import logging import pprint import sys -from collections.abc import MutableMapping +from collections.abc import Iterator, MutableMapping +from contextlib import contextmanager +from contextvars import ContextVar from logging.config import dictConfig from typing import TYPE_CHECKING, Any, cast @@ -23,6 +25,20 @@ if TYPE_CHECKING: logger = logging.getLogger(__name__) +_log_crawler: ContextVar[Crawler | None] = ContextVar("log_crawler", default=None) + + +@contextmanager +def log_crawler(crawler: Crawler) -> Iterator[None]: + token = _log_crawler.set(crawler) + try: + yield + finally: + _log_crawler.reset(token) + + +def get_log_crawler() -> Crawler | None: + return _log_crawler.get() def failure_to_exc_info( @@ -239,14 +255,24 @@ class LogCounterHandler(logging.Handler): def emit(self, record: logging.LogRecord) -> None: record_crawler = getattr(record, "crawler", None) + + record_spider = getattr(record, "spider", None) + if record_crawler is None: + record_crawler = getattr(record_spider, "crawler", None) + + if record_crawler is None: + record_crawler = get_log_crawler() + if record_crawler is not None and record_crawler is not self.crawler: return - record_spider = getattr(record, "spider", None) - record_spider_crawler = getattr(record_spider, "crawler", None) if ( - record_spider_crawler is not None - and record_spider_crawler is not self.crawler + record_crawler is None + and sum( + isinstance(handler, LogCounterHandler) + for handler in logging.root.handlers + ) + > 1 ): return diff --git a/tests/test_crawler.py b/tests/test_crawler.py index 0cddfd0ed..e4dcc9fa6 100644 --- a/tests/test_crawler.py +++ b/tests/test_crawler.py @@ -7,6 +7,7 @@ from pathlib import Path from typing import Any, ClassVar import pytest +from twisted.internet.defer import Deferred from zope.interface.exceptions import MultipleInvalid import scrapy @@ -555,6 +556,126 @@ class TestCrawlerLogging: assert info_count == 1 assert crawler.stats.get_value("log_count/DEBUG", 0) == 0 + @coroutine_test + async def test_log_counter_scope_isolated_between_crawlers(self) -> None: + barrier: Deferred[None] = Deferred() + counts: dict[str, int] = {} + opened = 0 + root_level = logging.root.level + + class BaseSpider(scrapy.Spider): + custom_settings = { + "LOG_LEVEL": "INFO", + "EXTENSIONS": { + "scrapy.extensions.logstats.LogStats": None, + "scrapy.extensions.telnet.TelnetConsole": None, + }, + } + start_urls = ["data:,test"] + + @classmethod + def from_crawler(cls, crawler, *args, **kwargs): + spider = super().from_crawler(crawler, *args, **kwargs) + crawler.signals.connect( + spider.spider_opened, signal=scrapy.signals.spider_opened + ) + return spider + + def spider_opened(self, spider) -> None: + nonlocal opened + opened += 1 + if opened == 2 and not barrier.called: + barrier.callback(None) + + async def parse(self, response): + await maybe_deferred_to_future(barrier) + logging.info("info message") # noqa: LOG015 + assert self.crawler.stats + counts[self.name] = self.crawler.stats.get_value("log_count/INFO") + return [] + + class Spider1(BaseSpider): + name = "spider1" + + class Spider2(BaseSpider): + name = "spider2" + + try: + logging.root.setLevel(logging.INFO) + runner = CrawlerRunner() + crawler1 = runner.create_crawler(Spider1) + crawler2 = runner.create_crawler(Spider2) + d1 = runner.crawl(crawler1) + d2 = runner.crawl(crawler2) + await maybe_deferred_to_future(d1) + await maybe_deferred_to_future(d2) + finally: + logging.root.setLevel(root_level) + + assert counts == {"spider1": 1, "spider2": 1} + + @coroutine_test + async def test_log_counter_scope_isolated_between_crawlers_in_start( + self, + ) -> None: + barrier: Deferred[None] = Deferred() + counts: dict[str, int] = {} + opened = 0 + root_level = logging.root.level + + class BaseSpider(scrapy.Spider): + custom_settings = { + "LOG_LEVEL": "INFO", + "EXTENSIONS": { + "scrapy.extensions.logstats.LogStats": None, + "scrapy.extensions.telnet.TelnetConsole": None, + }, + } + + @classmethod + def from_crawler(cls, crawler, *args, **kwargs): + spider = super().from_crawler(crawler, *args, **kwargs) + crawler.signals.connect( + spider.spider_opened, signal=scrapy.signals.spider_opened + ) + return spider + + def spider_opened(self, spider) -> None: + nonlocal opened + opened += 1 + if opened == 2 and not barrier.called: + barrier.callback(None) + + async def start(self): + await maybe_deferred_to_future(barrier) + logging.info("info message") # noqa: LOG015 + yield scrapy.Request("data:,test", dont_filter=True) + + async def parse(self, response): + assert self.crawler.stats + counts[self.name] = self.crawler.stats.get_value("log_count/INFO") + return [] + + class Spider1(BaseSpider): + name = "spider1" + + class Spider2(BaseSpider): + name = "spider2" + + try: + logging.root.setLevel(logging.INFO) + runner = CrawlerRunner() + crawler1 = runner.create_crawler(Spider1) + crawler2 = runner.create_crawler(Spider2) + d1 = runner.crawl(crawler1) + d2 = runner.crawl(crawler2) + await maybe_deferred_to_future(d1) + await maybe_deferred_to_future(d2) + finally: + logging.root.setLevel(root_level) + + assert counts == {"spider1": 1, "spider2": 1} + def test_spider_custom_settings_log_append(self, tmp_path: Path) -> None: log_file = Path(tmp_path, "log.txt") log_file.write_text("previous message\n", encoding="utf-8") diff --git a/tests/test_utils_log.py b/tests/test_utils_log.py index 2be98606e..2de1bc142 100644 --- a/tests/test_utils_log.py +++ b/tests/test_utils_log.py @@ -17,6 +17,7 @@ from scrapy.utils.log import ( StreamLogger, TopLevelFormatter, failure_to_exc_info, + log_crawler, ) from scrapy.utils.test import get_crawler from tests.spiders import LogSpider @@ -113,6 +114,46 @@ class TestLogCounterHandler: assert crawler.stats assert crawler.stats.get_value("log_count/ERROR") is None + def test_log_crawler_context(self, crawler: Crawler) -> None: + other_crawler = get_crawler(settings_dict={"LOG_LEVEL": "WARNING"}) + logger = logging.getLogger("test") + logger.setLevel(logging.DEBUG) + handler = LogCounterHandler(crawler, level=crawler.settings.get("LOG_LEVEL")) + other_handler = LogCounterHandler( + other_crawler, level=other_crawler.settings.get("LOG_LEVEL") + ) + logging.root.addHandler(handler) + logging.root.addHandler(other_handler) + try: + with log_crawler(crawler): + logger.error("test log msg") + finally: + logging.root.removeHandler(handler) + logging.root.removeHandler(other_handler) + assert crawler.stats + assert crawler.stats.get_value("log_count/ERROR") == 1 + assert other_crawler.stats + assert other_crawler.stats.get_value("log_count/ERROR") is None + + def test_ambiguous_record(self, crawler: Crawler) -> None: + other_crawler = get_crawler(settings_dict={"LOG_LEVEL": "WARNING"}) + logger = logging.getLogger("test") + handler = LogCounterHandler(crawler, level=crawler.settings.get("LOG_LEVEL")) + other_handler = LogCounterHandler( + other_crawler, level=other_crawler.settings.get("LOG_LEVEL") + ) + logging.root.addHandler(handler) + logging.root.addHandler(other_handler) + try: + logger.error("test log msg") + finally: + logging.root.removeHandler(handler) + logging.root.removeHandler(other_handler) + assert crawler.stats + assert crawler.stats.get_value("log_count/ERROR") is None + assert other_crawler.stats + assert other_crawler.stats.get_value("log_count/ERROR") is None + def test_filtered_out_level(self, crawler: Crawler, logger: logging.Logger) -> None: logger.debug("test log msg") assert crawler.stats