scrapy/scrapy — pull request #380 by dangra (2013-09-08 03:37:33+00:00)
Title: Dont log IgnoreRequest exception as download failure

This change is motivated by [scrapy-users](https://groups.google.com/forum/#!msg/scrapy-users/XaSMkb2tVsE/gn1t6AN8sAsJ)

It lacks proper tests so I am not merging yet, but I have tested it with spiders in https://github.com/scrapinghub/testspiders and a middleware designed to trigger errors pre/post response download and it works fine.

i.e.: Raising an error in `process_response` hook of a downloader middleware

```
$ scrapy crawl followall -a url=http://scrapinghub.com?x-error-response
2013-09-08 00:35:22-0300 [scrapy] INFO: Scrapy 0.19.0 started (bot: testspiders)
2013-09-08 00:35:22-0300 [scrapy] DEBUG: Optional features available: ssl, http11, boto, django
2013-09-08 00:35:22-0300 [scrapy] DEBUG: Overridden settings: {'NEWSPIDER_MODULE': 'testspiders.spiders', 'RETRY_ENABLED': False, 'SPIDER_MODULES': ['testspiders.spiders'], 'BOT_NAME': 'testspiders', 'CLOSESPIDER_TIMEOUT': 3600, 'COOKIES_ENABLED': False, 'CLOSESPIDER_PAGECOUNT': 1000}
2013-09-08 00:35:22-0300 [scrapy] DEBUG: Enabled extensions: LogStats, TelnetConsole, CloseSpider, WebService, CoreStats, SpiderState
2013-09-08 00:35:23-0300 [scrapy] DEBUG: Enabled downloader middlewares: RandomUserAgent, ErrorMonkeyMiddleware, HttpAuthMiddleware, DownloadTimeoutMiddleware, UserAgentMiddleware, DefaultHeadersMiddleware, MetaRefreshMiddleware, HttpCompressionMiddleware, RedirectMiddleware, ChunkedTransferMiddleware, DownloaderStats
2013-09-08 00:35:23-0300 [scrapy] DEBUG: Enabled spider middlewares: HttpErrorMiddleware, OffsiteMiddleware, RefererMiddleware, UrlLengthMiddleware, DepthMiddleware
2013-09-08 00:35:23-0300 [scrapy] DEBUG: Enabled item pipelines:
2013-09-08 00:35:23-0300 [followall] INFO: Spider opened
2013-09-08 00:35:23-0300 [followall] INFO: Crawled 0 pages (at 0 pages/min), scraped 0 items (at 0 items/min)
2013-09-08 00:35:23-0300 [scrapy] DEBUG: Telnet console listening on 0.0.0.0:6024
2013-09-08 00:35:23-0300 [scrapy] DEBUG: Web service listening on 0.0.0.0:6081
2013-09-08 00:35:24-0300 [followall] ERROR: Error downloading
Traceback (most recent call last):
File "/home/daniel/src/Twisted/twisted/internet/defer.py", line 490, in _startRunCallbacks
self._runCallbacks()
File "/home/daniel/src/Twisted/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/home/daniel/src/Twisted/twisted/internet/defer.py", line 382, in callback
self._startRunCallbacks(result)
File "/home/daniel/src/Twisted/twisted/internet/defer.py", line 490, in _startRunCallbacks
self._runCallbacks()
--- ---
File "/home/daniel/src/Twisted/twisted/internet/defer.py", line 577, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/home/daniel/src/scrapy/scrapy/core/downloader/middleware.py", line 46, in process_response
response = method(request=request, response=response, spider=spider)
File "/home/daniel/src/testspiders/testspiders/middleware.py", line 31, in process_response
_ = 1 / 0
exceptions.ZeroDivisionError: integer division or modulo by zero

2013-09-08 00:35:24-0300 [followall] INFO: Closing spider (finished)
2013-09-08 00:35:24-0300 [followall] INFO: Dumping Scrapy stats:
{'downloader/request_bytes': 297,
'downloader/request_count': 1,
'downloader/request_method_count/GET': 1,
'downloader/response_bytes': 2790,
'downloader/response_count': 1,
'downloader/response_status_count/200': 1,
'finish_reason': 'finished',
'finish_time': datetime.datetime(2013, 9, 8, 3, 35, 24, 264399),
'log_count/DEBUG': 6,
'log_count/ERROR': 1,
'log_count/INFO': 3,
'scheduler/dequeued': 1,
'scheduler/dequeued/memory': 1,
'scheduler/enqueued': 1,
'scheduler/enqueued/memory': 1,
'start_time': datetime.datetime(2013, 9, 8, 3, 35, 23, 529681)}
2013-09-08 00:35:24-0300 [followall] INFO: Spider closed (finished)
```

i.e. Raising `IgnoreRequest` in `process_response` hook of a download middleware
```
$ scrapy crawl followall -a url=http://scrapinghub.com?x-ignore-response
2013-09-08 00:35:36-0300 [scrapy] INFO: Scrapy 0.19.0 started (bot: testspiders)
2013-09-08 00:35:36-0300 [scrapy] DEBUG: Optional features available: ssl, http11, boto, django
2013-09-08 00:35:36-0300 [scrapy] DEBUG: Overridden settings: {'NEWSPIDER_MODULE': 'testspiders.spiders', 'RETRY_ENABLED': False, 'SPIDER_MODULES': ['testspiders.spiders'], 'BOT_NAME': 'testspiders', 'CLOSESPIDER_TIMEOUT': 3600, 'COOKIES_ENABLED': False, 'CLOSESPIDER_PAGECOUNT': 1000}
2013-09-08 00:35:36-0300 [scrapy] DEBUG: Enabled extensions: LogStats, TelnetConsole, CloseSpider, WebService, CoreStats, SpiderState
2013-09-08 00:35:38-0300 [scrapy] DEBUG: Enabled downloader middlewares: RandomUserAgent, ErrorMonkeyMiddleware, HttpAuthMiddleware, DownloadTimeoutMiddleware, UserAgentMiddleware, DefaultHeadersMiddleware, MetaRefreshMiddleware, HttpCompressionMiddleware, RedirectMiddleware, ChunkedTransferMiddleware, DownloaderStats
2013-09-08 00:35:38-0300 [scrapy] DEBUG: Enabled spider middlewares: HttpErrorMiddleware, OffsiteMiddleware, RefererMiddleware, UrlLengthMiddleware, DepthMiddleware
2013-09-08 00:35:38-0300 [scrapy] DEBUG: Enabled item pipelines:
2013-09-08 00:35:38-0300 [followall] INFO: Spider opened
2013-09-08 00:35:38-0300 [followall] INFO: Crawled 0 pages (at 0 pages/min), scraped 0 items (at 0 items/min)
2013-09-08 00:35:38-0300 [scrapy] DEBUG: Telnet console listening on 0.0.0.0:6024
2013-09-08 00:35:38-0300 [scrapy] DEBUG: Web service listening on 0.0.0.0:6081
2013-09-08 00:35:38-0300 [followall] INFO: Closing spider (finished)
2013-09-08 00:35:38-0300 [followall] INFO: Dumping Scrapy stats:
{'downloader/request_bytes': 300,
'downloader/request_count': 1,
'downloader/request_method_count/GET': 1,
'downloader/response_bytes': 2790,
'downloader/response_count': 1,
'downloader/response_status_count/200': 1,
'finish_reason': 'finished',
'finish_time': datetime.datetime(2013, 9, 8, 3, 35, 38, 601033),
'log_count/DEBUG': 6,
'log_count/INFO': 3,
'scheduler/dequeued': 1,
'scheduler/dequeued/memory': 1,
'scheduler/enqueued': 1,
'scheduler/enqueued/memory': 1,
'start_time': datetime.datetime(2013, 9, 8, 3, 35, 38, 58156)}
2013-09-08 00:35:38-0300 [followall] INFO: Spider closed (finished)
```