diff --git a/scrapy/core/scraper.py b/scrapy/core/scraper.py index 40de6b87a..db463f989 100644 --- a/scrapy/core/scraper.py +++ b/scrapy/core/scraper.py @@ -231,9 +231,9 @@ class Scraper(object): signal=signals.item_dropped, item=item, response=response, spider=spider, exception=output.value) else: - logger.error('Error processing %(item)s', {'item': item}, - exc_info=failure_to_exc_info(output), - extra={'spider': spider}) + logkws = self.logformatter.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( signal=signals.item_error, item=item, response=response, spider=spider, failure=output) diff --git a/scrapy/logformatter.py b/scrapy/logformatter.py index 3c61ed7e0..5189d7cfa 100644 --- a/scrapy/logformatter.py +++ b/scrapy/logformatter.py @@ -8,6 +8,7 @@ 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'" class LogFormatter(object): @@ -92,6 +93,16 @@ class LogFormatter(object): } } + def 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, + 'args': { + 'item': item, + } + } + @classmethod def from_crawler(cls, crawler): return cls() diff --git a/tests/test_logformatter.py b/tests/test_logformatter.py index b4ea30bb7..5b5d68f4f 100644 --- a/tests/test_logformatter.py +++ b/tests/test_logformatter.py @@ -23,13 +23,13 @@ class CustomItem(Item): return "name: %s" % self['name'] -class LoggingContribTest(unittest.TestCase): +class LogFormatterTestCase(unittest.TestCase): def setUp(self): self.formatter = LogFormatter() self.spider = Spider('default') - def test_crawled(self): + def test_crawled_with_referer(self): req = Request("http://www.example.com") res = Response("http://www.example.com") logkws = self.formatter.crawled(req, res, self.spider) @@ -37,6 +37,7 @@ class LoggingContribTest(unittest.TestCase): self.assertEqual(logline, "Crawled (200) (referer: None)") + def test_crawled_without_referer(self): req = Request("http://www.example.com", headers={'referer': 'http://example.com'}) res = Response("http://www.example.com", flags=['cached']) logkws = self.formatter.crawled(req, res, self.spider) @@ -61,6 +62,16 @@ class LoggingContribTest(unittest.TestCase): lines = logline.splitlines() assert all(isinstance(x, six.text_type) for x in lines) self.assertEqual(lines, [u"Dropped: \u2018", '{}']) + + def test_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) + logline = logkws['msg'] % logkws['args'] + self.assertEqual(logline, u"'Error processing {'key': 'value'}'") def test_scraped(self): item = CustomItem() @@ -75,26 +86,46 @@ class LoggingContribTest(unittest.TestCase): class LogFormatterSubclass(LogFormatter): def crawled(self, request, response, spider): - kwargs = super(LogFormatterSubclass, self).crawled( - request, response, spider) + kwargs = super(LogFormatterSubclass, self).crawled(request, response, spider) CRAWLEDMSG = ( - u"Crawled (%(status)s) %(request)s (referer: " - u"%(referer)s)%(flags)s" + u"Crawled (%(status)s) %(request)s (referer: %(referer)s) %(flags)s" ) + log_args = kwargs['args'] + log_args['flags'] = str(request.flags) return { 'level': kwargs['level'], 'msg': CRAWLEDMSG, - 'args': kwargs['args'] + 'args': log_args, } -class LogformatterSubclassTest(LoggingContribTest): +class LogformatterSubclassTest(LogFormatterTestCase): def setUp(self): self.formatter = LogFormatterSubclass() self.spider = Spider('default') + def test_crawled_with_referer(self): + req = Request("http://www.example.com") + res = Response("http://www.example.com") + logkws = self.formatter.crawled(req, res, self.spider) + logline = logkws['msg'] % logkws['args'] + self.assertEqual(logline, + "Crawled (200) (referer: None) []") + + def test_crawled_without_referer(self): + req = Request("http://www.example.com", headers={'referer': 'http://example.com'}, flags=['cached']) + res = Response("http://www.example.com") + logkws = self.formatter.crawled(req, res, self.spider) + logline = logkws['msg'] % logkws['args'] + self.assertEqual(logline, + "Crawled (200) (referer: http://example.com) ['cached']") + def test_flags_in_request(self): - pass + req = Request("http://www.example.com", flags=['test','flag']) + res = Response("http://www.example.com") + logkws = self.formatter.crawled(req, res, self.spider) + logline = logkws['msg'] % logkws['args'] + self.assertEqual(logline, "Crawled (200) (referer: None) ['test', 'flag']") class SkipMessagesLogFormatter(LogFormatter):