Merge pull request #3989 from elacuesta/logformatter_error_method

LogFormatter improvements

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)

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()

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) <GET http://www.example.com> (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) <GET http://www.example.com> (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) <GET http://www.example.com> (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) <GET http://www.example.com> (referer: None) ['test', 'flag']")
 
 
 class SkipMessagesLogFormatter(LogFormatter):