diff --git a/scrapy/core/scraper.py b/scrapy/core/scraper.py index facbd8b73..7b62068f5 100644 --- a/scrapy/core/scraper.py +++ b/scrapy/core/scraper.py @@ -16,7 +16,7 @@ from scrapy import signals from scrapy.http import Request, Response from scrapy.item import BaseItem from scrapy.core.spidermw import SpiderMiddlewareManager -from scrapy.utils.request import referer_str + logger = logging.getLogger(__name__) @@ -158,9 +158,9 @@ class Scraper(object): if isinstance(exc, CloseSpider): self.crawler.engine.close_spider(spider, exc.reason or 'cancelled') return - logger.error( - "Spider error processing %(request)s (referer: %(referer)s)", - {'request': request, 'referer': referer_str(request)}, + logkws = self.logformatter.spider_error(_failure, request, response, spider) + logger.log( + *logformatter_adapter(logkws), exc_info=failure_to_exc_info(_failure), extra={'spider': spider} ) @@ -208,16 +208,21 @@ class Scraper(object): """ if isinstance(download_failure, Failure) and not download_failure.check(IgnoreRequest): if download_failure.frames: - logger.error('Error downloading %(request)s', - {'request': request}, - exc_info=failure_to_exc_info(download_failure), - extra={'spider': spider}) + logkws = self.logformatter.download_error(download_failure, request, spider) + logger.log( + *logformatter_adapter(logkws), + extra={'spider': spider}, + exc_info=failure_to_exc_info(download_failure), + ) else: errmsg = download_failure.getErrorMessage() if errmsg: - logger.error('Error downloading %(request)s: %(errmsg)s', - {'request': request, 'errmsg': errmsg}, - extra={'spider': spider}) + logkws = self.logformatter.download_error( + download_failure, request, spider, errmsg) + logger.log( + *logformatter_adapter(logkws), + extra={'spider': spider}, + ) if spider_failure is not download_failure: return spider_failure @@ -236,7 +241,7 @@ class Scraper(object): signal=signals.item_dropped, item=item, response=response, spider=spider, exception=output.value) else: - logkws = self.logformatter.error(item, ex, response, spider) + logkws = self.logformatter.item_error(item, ex, response, spider) logger.log(*logformatter_adapter(logkws), extra={'spider': spider}, exc_info=failure_to_exc_info(output)) return self.signals.send_catch_log_deferred( diff --git a/scrapy/logformatter.py b/scrapy/logformatter.py index 4e5963e99..194013642 100644 --- a/scrapy/logformatter.py +++ b/scrapy/logformatter.py @@ -5,10 +5,13 @@ from twisted.python.failure import Failure from scrapy.utils.request import referer_str -SCRAPEDMSG = u"Scraped from %(src)s" + os.linesep + "%(item)s" -DROPPEDMSG = u"Dropped: %(exception)s" + os.linesep + "%(item)s" -CRAWLEDMSG = u"Crawled (%(status)s) %(request)s%(request_flags)s (referer: %(referer)s)%(response_flags)s" -ERRORMSG = u"'Error processing %(item)s'" +SCRAPEDMSG = "Scraped from %(src)s" + os.linesep + "%(item)s" +DROPPEDMSG = "Dropped: %(exception)s" + os.linesep + "%(item)s" +CRAWLEDMSG = "Crawled (%(status)s) %(request)s%(request_flags)s (referer: %(referer)s)%(response_flags)s" +ITEMERRORMSG = "Error processing %(item)s" +SPIDERERRORMSG = "Spider error processing %(request)s (referer: %(referer)s)" +DOWNLOADERRORMSG_SHORT = "Error downloading %(request)s" +DOWNLOADERRORMSG_LONG = "Error downloading %(request)s: %(errmsg)s" class LogFormatter(object): @@ -93,16 +96,41 @@ class LogFormatter(object): } } - def error(self, item, exception, response, spider): + def item_error(self, item, exception, response, spider): """Logs a message when an item causes an error while it is passing through the item pipeline.""" return { 'level': logging.ERROR, - 'msg': ERRORMSG, + 'msg': ITEMERRORMSG, 'args': { 'item': item, } } + def spider_error(self, failure, request, response, spider): + """Logs an error message from a spider.""" + return { + 'level': logging.ERROR, + 'msg': SPIDERERRORMSG, + 'args': { + 'request': request, + 'referer': referer_str(request), + } + } + + def download_error(self, failure, request, spider, errmsg=None): + """Logs a download error message from a spider (typically coming from the engine).""" + args = {'request': request} + if errmsg: + msg = DOWNLOADERRORMSG_LONG + args['errmsg'] = errmsg + else: + msg = DOWNLOADERRORMSG_SHORT + return { + 'level': logging.ERROR, + 'msg': msg, + 'args': args, + } + @classmethod def from_crawler(cls, crawler): return cls() diff --git a/tests/test_logformatter.py b/tests/test_logformatter.py index 7d8c6ec7f..bf9fbe5e4 100644 --- a/tests/test_logformatter.py +++ b/tests/test_logformatter.py @@ -2,6 +2,7 @@ import unittest from testfixtures import LogCapture from twisted.internet import defer +from twisted.python.failure import Failure from twisted.trial.unittest import TestCase as TwistedTestCase from scrapy.crawler import CrawlerRunner @@ -62,15 +63,46 @@ class LogFormatterTestCase(unittest.TestCase): assert all(isinstance(x, str) for x in lines) self.assertEqual(lines, [u"Dropped: \u2018", '{}']) - def test_error(self): + def test_item_error(self): # In practice, the complete traceback is shown by passing the # 'exc_info' argument to the logging function item = {'key': 'value'} exception = Exception() response = Response("http://www.example.com") - logkws = self.formatter.error(item, exception, response, self.spider) + logkws = self.formatter.item_error(item, exception, response, self.spider) logline = logkws['msg'] % logkws['args'] - self.assertEqual(logline, u"'Error processing {'key': 'value'}'") + self.assertEqual(logline, u"Error processing {'key': 'value'}") + + def test_spider_error(self): + # In practice, the complete traceback is shown by passing the + # 'exc_info' argument to the logging function + failure = Failure(Exception()) + request = Request("http://www.example.com", headers={'Referer': 'http://example.org'}) + response = Response("http://www.example.com", request=request) + logkws = self.formatter.spider_error(failure, request, response, self.spider) + logline = logkws['msg'] % logkws['args'] + self.assertEqual( + logline, + "Spider error processing (referer: http://example.org)" + ) + + def test_download_error_short(self): + # In practice, the complete traceback is shown by passing the + # 'exc_info' argument to the logging function + failure = Failure(Exception()) + request = Request("http://www.example.com") + logkws = self.formatter.download_error(failure, request, self.spider) + logline = logkws['msg'] % logkws['args'] + self.assertEqual(logline, "Error downloading ") + + def test_download_error_long(self): + # In practice, the complete traceback is shown by passing the + # 'exc_info' argument to the logging function + failure = Failure(Exception()) + request = Request("http://www.example.com") + logkws = self.formatter.download_error(failure, request, self.spider, "Some message") + logline = logkws['msg'] % logkws['args'] + self.assertEqual(logline, "Error downloading : Some message") def test_scraped(self): item = CustomItem()