diff --git a/scrapy/core/engine.py b/scrapy/core/engine.py index 1033e874f..efac5f71c 100644 --- a/scrapy/core/engine.py +++ b/scrapy/core/engine.py @@ -470,16 +470,17 @@ class ExecutionEngine: """ if self.spider is None: raise RuntimeError(f"No open spider to crawl: {request}") - try: - response_or_request = await maybe_deferred_to_future( - self._download(request) - ) - finally: - assert self._slot is not None - self._slot.remove_request(request) - if isinstance(response_or_request, Request): - return await self.download_async(response_or_request) - return response_or_request + while True: + try: + response_or_request = await maybe_deferred_to_future( + self._download(request) + ) + finally: + assert self._slot is not None + self._slot.remove_request(request) + if not isinstance(response_or_request, Request): + return response_or_request + request = response_or_request @inlineCallbacks def _download( diff --git a/scrapy/downloadermiddlewares/offsite.py b/scrapy/downloadermiddlewares/offsite.py index e03dc040e..db85b62a1 100644 --- a/scrapy/downloadermiddlewares/offsite.py +++ b/scrapy/downloadermiddlewares/offsite.py @@ -61,7 +61,7 @@ class OffsiteMiddleware: ) self.stats.inc_value("offsite/domains") self.stats.inc_value("offsite/filtered") - raise IgnoreRequest + raise IgnoreRequest(f"Filtered offsite request to {domain!r}") def should_follow(self, request: Request, spider: Spider) -> bool: regex = self.host_regex diff --git a/scrapy/pipelines/files.py b/scrapy/pipelines/files.py index 44c422430..6561358c5 100644 --- a/scrapy/pipelines/files.py +++ b/scrapy/pipelines/files.py @@ -79,6 +79,17 @@ class FileException(Exception): """General media error exception""" +class _MediaRequestFiltered(FileException): + """Raised internally by media pipelines when a media request is filtered + out (e.g. as an offsite request) instead of being downloaded. + + It is a subclass of :exc:`FileException` for backward compatibility, but + unlike an actual download error it is logged at the ``DEBUG`` level and + without a traceback, since filtering a request is expected behavior rather + than an error. + """ + + class StatInfo(TypedDict, total=False): checksum: str last_modified: float @@ -597,20 +608,20 @@ class FilesPipeline(MediaPipeline): def media_failed( self, failure: Failure, request: Request, info: MediaPipeline.SpiderInfo ) -> NoReturn: - if not isinstance(failure.value, IgnoreRequest): - referer = referer_str(request) - logger.warning( - "File (unknown-error): Error downloading %(medianame)s from " - "%(request)s referred in <%(referer)s>: %(exception)s", - { - "medianame": self.MEDIA_NAME, - "request": request, - "referer": referer, - "exception": failure.value, - }, + referer = referer_str(request) + if isinstance(failure.value, IgnoreRequest): + logger.debug( + f"File (filtered): Not downloading {self.MEDIA_NAME} from " + f"{request} referred in <{referer}>: {failure.value}", extra={"spider": info.spider}, ) + raise _MediaRequestFiltered(str(failure.value)) from failure.value + logger.warning( + f"File (unknown-error): Error downloading {self.MEDIA_NAME} from " + f"{request} referred in <{referer}>: {failure.value}", + extra={"spider": info.spider}, + ) raise FileException async def media_downloaded( diff --git a/scrapy/pipelines/media.py b/scrapy/pipelines/media.py index 5b5d2dcb2..6e5114daa 100644 --- a/scrapy/pipelines/media.py +++ b/scrapy/pipelines/media.py @@ -55,6 +55,12 @@ FileInfoOrError: TypeAlias = ( logger = logging.getLogger(__name__) +def _media_request_filtered(failure: Failure) -> bool: + from scrapy.pipelines.files import _MediaRequestFiltered # noqa: PLC0415 + + return isinstance(failure.value, _MediaRequestFiltered) + + class MediaPipeline(ABC): LOG_FAILED_RESULTS: bool = True @@ -193,7 +199,8 @@ class MediaPipeline(ABC): result = await self._check_media_to_download(request, info, item=item) except Exception: result = Failure() - logger.exception(result) + if not _media_request_filtered(result): + logger.exception(result) self._cache_result_and_execute_waiters(result, fp, info) return await maybe_deferred_to_future(wad) # it must return wad at last @@ -304,6 +311,8 @@ class MediaPipeline(ABC): for ok, value in results: if not ok: assert isinstance(value, Failure) + if _media_request_filtered(value): + continue logger.error( "%(class)s found errors processing %(item)s", {"class": self.__class__.__name__, "item": item}, diff --git a/tests/test_downloadermiddleware_offsite.py b/tests/test_downloadermiddleware_offsite.py index c0b8dc4dd..78efb0191 100644 --- a/tests/test_downloadermiddleware_offsite.py +++ b/tests/test_downloadermiddleware_offsite.py @@ -1,3 +1,5 @@ +import re + import pytest from scrapy import Request, Spider @@ -231,3 +233,15 @@ def test_repeated_offsite_domain(): mw.process_request(req2) assert crawler.stats.get_value("offsite/domains") == 1 # not incremented again assert crawler.stats.get_value("offsite/filtered") == 2 + + +def test_ignore_request_reason(): + crawler = get_crawler(Spider) + crawler.spider = crawler._create_spider(name="a", allowed_domains=["example.com"]) + mw = OffsiteMiddleware.from_crawler(crawler) + mw.spider_opened(crawler.spider) + request = Request("http://other.org/1") + with pytest.raises( + IgnoreRequest, match=re.escape("Filtered offsite request to 'other.org'") + ): + mw.process_request(request) diff --git a/tests/test_engine.py b/tests/test_engine.py index 2b857d35a..732aa3d23 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -574,6 +574,25 @@ class TestEngineDownloadAsync: [call(original_request), call(redirect_request)] ) + @coroutine_test + async def test_download_async_many_redirects(self, engine): + """A long chain of requests being replaced by new ones is handled + iteratively, without hitting the recursion limit.""" + count = sys.getrecursionlimit() * 2 + requests = [Request(f"http://example.com/{i}") for i in range(count)] + final_response = Response("http://example.com/final", body=b"done") + engine.downloader.fetch.side_effect = [ + *(defer.succeed(request) for request in requests[1:]), + defer.succeed(final_response), + ] + engine.spider = Mock() + engine._slot.add_request = Mock() + engine._slot.remove_request = Mock() + + result = await self._download(engine, requests[0]) + assert result == final_response + assert engine.downloader.fetch.call_count == count + @coroutine_test async def test_download_async_no_spider(self, engine): """Test async download attempt when no spider is available.""" diff --git a/tests/test_pipeline_files.py b/tests/test_pipeline_files.py index 3829a35f5..a4f4f7d59 100644 --- a/tests/test_pipeline_files.py +++ b/tests/test_pipeline_files.py @@ -1,6 +1,7 @@ import dataclasses import os import random +import re import time from abc import ABC, abstractmethod from datetime import datetime @@ -18,17 +19,21 @@ from urllib.parse import urlparse import attr import pytest from itemadapter import ItemAdapter +from testfixtures import LogCapture from twisted.internet.defer import Deferred +from twisted.python.failure import Failure -from scrapy.exceptions import NotConfigured +from scrapy.exceptions import IgnoreRequest, NotConfigured from scrapy.http import Request, Response from scrapy.item import Field, Item from scrapy.pipelines.files import ( + FileException, FilesPipeline, FSFilesStore, FTPFilesStore, GCSFilesStore, S3FilesStore, + _MediaRequestFiltered, ) from scrapy.settings import Settings from scrapy.utils.asyncio import call_later @@ -297,6 +302,65 @@ class TestFilesPipeline: request = Request("http://example.com") assert file_path(request, item=item) == "full/path-to-store-file" + def test_media_failed_filtered_request(self): + """A filtered media request (IgnoreRequest) is reported as a + _MediaRequestFiltered exception and logged at the DEBUG level, instead + of as a download error with a traceback.""" + request = Request("http://example.com/file.pdf") + reason = "Filtered offsite request to 'example.com'" + failure = Failure(IgnoreRequest(reason)) + + with ( + LogCapture() as log, + pytest.raises(_MediaRequestFiltered, match=re.escape(reason)), + ): + self.pipeline.media_failed(failure, request, self.pipeline.spiderinfo) + + assert len(log.records) == 1 + record = log.records[0] + assert record.levelname == "DEBUG" + assert record.exc_info is None + assert reason in record.getMessage() + + def test_media_failed_download_error(self): + """A genuine download error is reported as a FileException and logged as + a warning.""" + request = Request("http://example.com/file.pdf") + failure = Failure(Exception("boom")) + + with LogCapture() as log, pytest.raises(FileException): + self.pipeline.media_failed(failure, request, self.pipeline.spiderinfo) + + assert len(log.records) == 1 + assert log.records[0].levelname == "WARNING" + + @coroutine_test + async def test_process_item_filtered_request(self): + """A filtered (e.g. offsite) media request is processed as a failed + result without being logged as an error with a traceback.""" + item_url = "http://example.com/file.pdf" + item = _create_item_with_files(item_url) + request = Request( + item_url, + meta={ + "response": IgnoreRequest("Filtered offsite request to 'example.com'") + }, + ) + with ( + LogCapture() as log, + mock.patch.object( + FilesPipeline, "get_media_requests", return_value=[request] + ), + ): + result = await self.pipeline.process_item(item) + + assert result["files"] == [] + assert not any(r.levelname in ("WARNING", "ERROR") for r in log.records) + assert any( + "Filtered offsite request to 'example.com'" in r.getMessage() + for r in log.records + ) + @pytest.mark.parametrize( "bad_type", [ diff --git a/tests/test_pipeline_media.py b/tests/test_pipeline_media.py index 8ac949da7..f5f3e0fd1 100644 --- a/tests/test_pipeline_media.py +++ b/tests/test_pipeline_media.py @@ -10,7 +10,7 @@ from scrapy import signals from scrapy.exceptions import ScrapyDeprecationWarning from scrapy.http import Request, Response from scrapy.http.request import NO_CALLBACK -from scrapy.pipelines.files import FileException +from scrapy.pipelines.files import FileException, _MediaRequestFiltered from scrapy.pipelines.media import MediaPipeline from scrapy.utils.defer import _defer_sleep_async from scrapy.utils.log import failure_to_exc_info @@ -162,6 +162,19 @@ class TestBaseMediaPipeline: assert new_item is item assert len(log.records) == 0 + def test_item_completed_filtered_request_not_logged(self): + """Filtered media requests (e.g. offsite ones) are not logged as errors + by item_completed(), as they are not download errors.""" + item = {"name": "name"} + fail = Failure(_MediaRequestFiltered("Filtered offsite request")) + results = [(True, 1), (False, fail)] + + with LogCapture() as log: + new_item = self.pipe.item_completed(results, item, self.info) + + assert new_item is item + assert len(log.records) == 0 + @coroutine_test async def test_default_process_item(self): item = {"name": "name"}