From f6872189b96595625e428331ddd4d1c620047642 Mon Sep 17 00:00:00 2001 From: Eugenio Lacuesta Date: Thu, 29 Aug 2019 10:38:49 -0300 Subject: [PATCH 1/3] Add LogFormatter.error method --- scrapy/core/scraper.py | 6 +++--- scrapy/logformatter.py | 11 +++++++++++ 2 files changed, 14 insertions(+), 3 deletions(-) diff --git a/scrapy/core/scraper.py b/scrapy/core/scraper.py index 1f389cf2e..3273a1506 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 f15940ed1..4437d1106 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() From 27436cbbc9e7331d18d4b63f3c894e6621226efb Mon Sep 17 00:00:00 2001 From: Eugenio Lacuesta Date: Thu, 29 Aug 2019 13:51:42 -0300 Subject: [PATCH 2/3] [test] LogFormatter.error --- tests/test_logformatter.py | 30 ++++++++++++++++++++++-------- 1 file changed, 22 insertions(+), 8 deletions(-) diff --git a/tests/test_logformatter.py b/tests/test_logformatter.py index eb9c4a561..502bc4ccc 100644 --- a/tests/test_logformatter.py +++ b/tests/test_logformatter.py @@ -23,7 +23,7 @@ class CustomItem(Item): return "name: %s" % self['name'] -class LoggingContribTest(unittest.TestCase): +class LoggingFormatterTest(unittest.TestCase): def setUp(self): self.formatter = LogFormatter() @@ -61,6 +61,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 +85,30 @@ 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(unittest.TestCase): def setUp(self): self.formatter = LogFormatterSubclass() self.spider = Spider('default') 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): From 07a31b13db96b2aef3074157808f7ad300780c3d Mon Sep 17 00:00:00 2001 From: Eugenio Lacuesta Date: Tue, 1 Oct 2019 17:55:57 -0300 Subject: [PATCH 3/3] Update LogFormatter tests --- tests/test_logformatter.py | 23 ++++++++++++++++++++--- 1 file changed, 20 insertions(+), 3 deletions(-) diff --git a/tests/test_logformatter.py b/tests/test_logformatter.py index 502bc4ccc..f12ffc11b 100644 --- a/tests/test_logformatter.py +++ b/tests/test_logformatter.py @@ -23,13 +23,13 @@ class CustomItem(Item): return "name: %s" % self['name'] -class LoggingFormatterTest(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 LoggingFormatterTest(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) @@ -98,11 +99,27 @@ class LogFormatterSubclass(LogFormatter): } -class LogformatterSubclassTest(unittest.TestCase): +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): req = Request("http://www.example.com", flags=['test','flag']) res = Response("http://www.example.com")