Repository: scrapy/scrapy
Pull request: MediaPipeline: log media_to_download errors before stripping them
Fixes #5067

To do:

- [x] Make sure that existing tests pass
- [x] Add a test for the issue being fixed here

Problem statement:
MediaPipeline exceptions passed silently
### Description

MediaPipeline exceptions passed silently both for method body or method signature errors.

### Steps to Reproduce

```
from scrapy.pipelines.files import FilesPipeline
class BuggyFilesPipeline(FilesPipeline):
    def file_path(self, request, response=None, info=None, *, item=None):
        return 1 / 0
```
**Expected behavior:** Exception logged

**Actual behavior:** Exception passed silently

**Reproduces how often:** 100%

### Versions

Scrapy 2.4

Hints from issue discussion:
Can you share the log? I would expect something to get logged based on the [implementation](https://github.com/scrapy/scrapy/blob/2.4.1/scrapy/pipelines/files.py). I have doubts about `media_to_download`, but I think even that should generate something in the log.
<details>
 <summary>spider.py</summary>

```python
from scrapy import Spider


class ExampleSpider(Spider):
    name = 'example'
    start_urls = ['http://example.com/']

    def parse(self, response):
        yield {'file_urls': [response.url]}
```

</details>

<details>
 <summary>pipelines.py</summary>

```python
from scrapy.pipelines.files import FilesPipeline


class BuggyFilesPipeline(FilesPipeline):
    def file_path(self, request, response=None, info=None, *, item=None):
        return 1 / 0
```

</details>

<details>
 <summary>settings.py</summary>

```python
BOT_NAME = 'example'

SPIDER_MODULES = ['example.spiders']
NEWSPIDER_MODULE = 'example.spiders'

ITEM_PIPELINES = {
    #'scrapy.pipelines.files.FilesPipeline': 1,
    'example.pipelines.BuggyFilesPipeline': 1,
}

FILES_STORE = 'files'
```

</details>

<details>
 <summary>Log with 'scrapy.pipelines.files.FilesPipeline' selected</summary>

```
2021-03-26 15:45:35 [scrapy.utils.log] INFO: Scrapy 2.4.1 started (bot: example)
2021-03-26 15:45:35 [scrapy.utils.log] INFO: Versions: lxml 4.6.3.0, libxml2 2.9.5, cssselect 1.1.0, parsel 1.6.0, w3lib 1.22.0, Twisted 21.2.0, Python 3.8.8 (tags/v3.8.8:024d805, Feb 19 2021, 13:18:16) [MSC v.1928 64 bit (AMD64)], pyOpenSSL 20.0.1 (OpenSSL 1.1.1k  25 Mar 2021), cryptography 3.4.7, Platform Windows-10-10.0.19041-SP0
2021-03-26 15:45:35 [scrapy.utils.log] DEBUG: Using reactor: twisted.internet.selectreactor.SelectReactor
2021-03-26 15:45:35 [scrapy.crawler] INFO: Overridden settings:
{'BOT_NAME': 'example',
 'EDITOR': 'micro',
 'NEWSPIDER_MODULE': 'example.spiders',
 'SPIDER_MODULES': ['example.spiders']}
2021-03-26 15:45:35 [scrapy.extensions.telnet] INFO: Telnet Password: a6f05877a1cbaf1a
2021-03-26 15:45:35 [scrapy.middleware] INFO: Enabled extensions:
['scrapy.extensions.corestats.CoreStats',
 'scrapy.extensions.telnet.TelnetConsole',
 'scrapy.extensions.logstats.LogStats']
2021-03-26 15:45:35 [scrapy.middleware] INFO: Enabled downloader middlewares:
['scrapy.downloadermiddlewares.httpauth.HttpAuthMiddleware',
 'scrapy.downloadermiddlewares.downloadtimeout.DownloadTimeoutMiddleware',
 'scrapy.downloadermiddlewares.defaultheaders.DefaultHeadersMiddleware',
 'scrapy.downloadermiddlewares.useragent.UserAgentMiddleware',
 'scrapy.downloadermiddlewares.retry.RetryMiddleware',
 'scrapy.downloadermiddlewares.redirect.MetaRefreshMiddleware',
 'scrapy.downloadermiddlewares.httpcompression.HttpCompressionMiddleware',
 'scrapy.downloadermiddlewares.redirect.RedirectMiddleware',
 'scrapy.downloadermiddlewares.cookies.CookiesMiddleware',
 'scrapy.downloadermiddlewares.httpproxy.HttpProxyMiddleware',
 'scrapy.downloadermiddlewares.stats.DownloaderStats']
2021-03-26 15:45:35 [scrapy.middleware] INFO: Enabled spider middlewares:
['scrapy.spidermiddlewares.httperror.HttpErrorMiddleware',
 'scrapy.spidermiddlewares.offsite.OffsiteMiddleware',
 'scrapy.spidermiddlewares.referer.RefererMiddleware',
 'scrapy.spidermiddlewares.urllength.UrlLengthMiddleware',
 'scrapy.spidermiddlewares.depth.DepthMiddleware']
2021-03-26 15:45:35 [scrapy.middleware] INFO: Enabled item pipelines:
['scrapy.pipelines.files.FilesPipeline']
2021-03-26 15:45:35 [scrapy.core.engine] INFO: Spider opened
2021-03-26 15:45:35 [scrapy.extensions.logstats] INFO: Crawled 0 pages (at 0 pages/min), scraped 0 items (at 0 items/min)
2021-03-26 15:45:35 [scrapy.extensions.telnet] INFO: Telnet console listening on 127.0.0.1:6023
2021-03-26 15:45:36 [scrapy.core.engine] DEBUG: Crawled (200) <GET http://example.com/> (referer: None)
2021-03-26 15:45:36 [scrapy.core.engine] DEBUG: Crawled (200) <GET http://example.com/> (referer: None)
2021-03-26 15:45:36 [scrapy.pipelines.files] DEBUG: File (downloaded): Downloaded file from <GET http://example.com/> referred in <None>
2021-03-26 15:45:36 [scrapy.core.scraper] DEBUG: Scraped from <200 http://example.com/>
{'file_urls': ['http://example.com/'], 'files': [{'url': 'http://example.com/', 'path': 'full/9c17e047f58f9220a7008d4f18152fee4d111d14', 'checksum': '84238dfc8092e5d9c0dac8ef93371a07', 'status': 'downloaded'}]}
2021-03-26 15:45:36 [scrapy.core.engine] INFO: Closing spider (finished)
2021-03-26 15:45:36 [scrapy.statscollectors] INFO: Dumping Scrapy stats:
{'downloader/request_bytes': 422,
 'downloader/request_count': 2,
 'downloader/request_method_count/GET': 2,
 'downloader/response_bytes': 2002,
 'downloader/response_count': 2,
 'downloader/response_status_count/200': 2,
 'elapsed_time_seconds': 0.555499,
 'file_count': 1,
 'file_status_count/downloaded': 1,
 'finish_reason': 'finished',
 'finish_time': datetime.datetime(2021, 3, 26, 13, 45, 36, 512893),
 'item_scraped_count': 1,
 'log_count/DEBUG': 4,
 'log_count/INFO': 10,
 'response_received_count': 2,
 'scheduler/dequeued': 1,
 'scheduler/dequeued/memory': 1,
 'scheduler/enqueued': 1,
 'scheduler/enqueued/memory': 1,
 'start_time': datetime.datetime(2021, 3, 26, 13, 45, 35, 957394)}
2021-03-26 15:45:36 [scrapy.core.engine] INFO: Spider closed (finished)
```

</details>

<details>
 <summary>Log with 'example.pipelines.BuggyFilesPipeline' selected</summary>

```
2021-03-26 15:47:10 [scrapy.utils.log] INFO: Scrapy 2.4.1 started (bot: example)
2021-03-26 15:47:10 [scrapy.utils.log] INFO: Versions: lxml 4.6.3.0, libxml2 2.9.5, cssselect 1.1.0, parsel 1.6.0, w3lib 1.22.0, Twisted 21.2.0, Python 3.8.8 (tags/v3.8.8:024d805, Feb 19 2021, 13:18:16) [MSC v.1928 64 bit (AMD64)], pyOpenSSL 20.0.1 (OpenSSL 1.1.1k  25 Mar 2021), cryptography 3.4.7, Platform Windows-10-10.0.19041-SP0
2021-03-26 15:47:10 [scrapy.utils.log] DEBUG: Using reactor: twisted.internet.selectreactor.SelectReactor
2021-03-26 15:47:10 [scrapy.crawler] INFO: Overridden settings:
{'BOT_NAME': 'example',
 'EDITOR': 'micro',
 'NEWSPIDER_MODULE': 'example.spiders',
 'SPIDER_MODULES': ['example.spiders']}
2021-03-26 15:47:10 [scrapy.extensions.telnet] INFO: Telnet Password: 3d23010f41375347
2021-03-26 15:47:10 [scrapy.middleware] INFO: Enabled extensions:
['scrapy.extensions.corestats.CoreStats',
 'scrapy.extensions.telnet.TelnetConsole',
 'scrapy.extensions.logstats.LogStats']
2021-03-26 15:47:11 [scrapy.middleware] INFO: Enabled downloader middlewares:
['scrapy.downloadermiddlewares.httpauth.HttpAuthMiddleware',
 'scrapy.downloadermiddlewares.downloadtimeout.DownloadTimeoutMiddleware',
 'scrapy.downloadermiddlewares.defaultheaders.DefaultHeadersMiddleware',
 'scrapy.downloadermiddlewares.useragent.UserAgentMiddleware',
 'scrapy.downloadermiddlewares.retry.RetryMiddleware',
 'scrapy.downloadermiddlewares.redirect.MetaRefreshMiddleware',
 'scrapy.downloadermiddlewares.httpcompression.HttpCompressionMiddleware',
 'scrapy.downloadermiddlewares.redirect.RedirectMiddleware',
 'scrapy.downloadermiddlewares.cookies.CookiesMiddleware',
 'scrapy.downloadermiddlewares.httpproxy.HttpProxyMiddleware',
 'scrapy.downloadermiddlewares.stats.DownloaderStats']
2021-03-26 15:47:11 [scrapy.middleware] INFO: Enabled spider middlewares:
['scrapy.spidermiddlewares.httperror.HttpErrorMiddleware',
 'scrapy.spidermiddlewares.offsite.OffsiteMiddleware',
 'scrapy.spidermiddlewares.referer.RefererMiddleware',
 'scrapy.spidermiddlewares.urllength.UrlLengthMiddleware',
 'scrapy.spidermiddlewares.depth.DepthMiddleware']
2021-03-26 15:47:11 [scrapy.middleware] INFO: Enabled item pipelines:
['example.pipelines.BuggyFilesPipeline']
2021-03-26 15:47:11 [scrapy.core.engine] INFO: Spider opened
2021-03-26 15:47:11 [scrapy.extensions.logstats] INFO: Crawled 0 pages (at 0 pages/min), scraped 0 items (at 0 items/min)
2021-03-26 15:47:11 [scrapy.extensions.telnet] INFO: Telnet console listening on 127.0.0.1:6023
2021-03-26 15:47:11 [scrapy.core.engine] DEBUG: Crawled (200) <GET http://example.com/> (referer: None)
2021-03-26 15:47:11 [scrapy.core.scraper] DEBUG: Scraped from <200 http://example.com/>
{'file_urls': ['http://example.com/'], 'files': []}
2021-03-26 15:47:11 [scrapy.core.engine] INFO: Closing spider (finished)
2021-03-26 15:47:11 [scrapy.statscollectors] INFO: Dumping Scrapy stats:
{'downloader/request_bytes': 211,
 'downloader/request_count': 1,
 'downloader/request_method_count/GET': 1,
 'downloader/response_bytes': 983,
 'downloader/response_count': 1,
 'downloader/response_status_count/200': 1,
 'elapsed_time_seconds': 0.567943,
 'finish_reason': 'finished',
 'finish_time': datetime.datetime(2021, 3, 26, 13, 47, 11, 655970),
 'item_scraped_count': 1,
 'log_count/DEBUG': 2,
 'log_count/INFO': 10,
 'response_received_count': 1,
 'scheduler/dequeued': 1,
 'scheduler/dequeued/memory': 1,
 'scheduler/enqueued': 1,
 'scheduler/enqueued/memory': 1,
 'start_time': datetime.datetime(2021, 3, 26, 13, 47, 11, 88027)}
2021-03-26 15:47:11 [scrapy.core.engine] INFO: Spider closed (finished)
```

</details>

Commit message: MediaPipeline: log media_to_download errors before striping them

Patch to review:
diff --git a/scrapy/pipelines/media.py b/scrapy/pipelines/media.py
index 0c2ee685688..7fb16b6251f 100644
--- a/scrapy/pipelines/media.py
+++ b/scrapy/pipelines/media.py
@@ -112,12 +112,18 @@ def _process_request(self, request, info, item):
         info.downloading.add(fp)
         dfd = mustbe_deferred(self.media_to_download, request, info, item=item)
         dfd.addCallback(self._check_media_to_download, request, info, item=item)
+        dfd.addErrback(self._log_error, info)
         dfd.addBoth(self._cache_result_and_execute_waiters, fp, info)
-        dfd.addErrback(lambda f: logger.error(
-            f.value, exc_info=failure_to_exc_info(f), extra={'spider': info.spider})
-        )
         return dfd.addBoth(lambda _: wad)  # it must return wad at last
 
+    def _log_error(self, result, info):
+        logger.error(
+            result.value,
+            exc_info=failure_to_exc_info(result),
+            extra={'spider': info.spider}
+        )
+        return result
+
     def _make_compatible(self):
         """Make overridable methods of MediaPipeline and subclasses backwards compatible"""
         methods = [


Code review comments:
diff_hunk: @@ -112,12 +112,18 @@ def _process_request(self, request, info, item):
         info.downloading.add(fp)
         dfd = mustbe_deferred(self.media_to_download, request, info, item=item)
         dfd.addCallback(self._check_media_to_download, request, info, item=item)
+        dfd.addErrback(self._log_error, info)
         dfd.addBoth(self._cache_result_and_execute_waiters, fp, info)
-        dfd.addErrback(lambda f: logger.error(
-            f.value, exc_info=failure_to_exc_info(f), extra={'spider': info.spider})
-        )
         return dfd.addBoth(lambda _: wad)  # it must return wad at last
 
+    def _log_error(self, result, info):
+        logger.error(
+            result.value,
+            exc_info=failure_to_exc_info(result),
+            extra={'spider': info.spider}
+        )
+        return result
path: scrapy/pipelines/media.py
text: @user1:
Is this the only actual change?

@author:
Well, the main change is actually moving the `addErrback` 1 line above. Returning `result` here is just so that the line move does not break the `addBoth` line that now goes afterwards.

@user1:
Oh, I see.

@author:
The reason for the line move is that `_cache_result_and_execute_waiters` removes the failure information to save memory. So we were basically removing an error and then logging it, now we should be logging it and _then_ removing it.