From 7a7d13b1122dac397ee0bb8edd4e6fd61665e232 Mon Sep 17 00:00:00 2001 From: Eugenio Lacuesta Date: Sat, 23 Nov 2019 19:04:02 -0300 Subject: [PATCH 1/4] Rename LogFormatter.error to item_error --- scrapy/core/scraper.py | 2 +- scrapy/logformatter.py | 6 +++--- tests/test_logformatter.py | 4 ++-- 3 files changed, 6 insertions(+), 6 deletions(-) diff --git a/scrapy/core/scraper.py b/scrapy/core/scraper.py index db463f989..c5bb48ea6 100644 --- a/scrapy/core/scraper.py +++ b/scrapy/core/scraper.py @@ -231,7 +231,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 5189d7cfa..79c752da4 100644 --- a/scrapy/logformatter.py +++ b/scrapy/logformatter.py @@ -8,7 +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'" +ITEMERRORMSG = u"'Error processing %(item)s'" class LogFormatter(object): @@ -93,11 +93,11 @@ 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, } diff --git a/tests/test_logformatter.py b/tests/test_logformatter.py index d0b23a8c4..f2f8c0464 100644 --- a/tests/test_logformatter.py +++ b/tests/test_logformatter.py @@ -63,13 +63,13 @@ class LogFormatterTestCase(unittest.TestCase): assert all(isinstance(x, six.text_type) 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'}'") From facb9265421ead8afb839323af2e18f81dda560b Mon Sep 17 00:00:00 2001 From: Eugenio Lacuesta Date: Sat, 23 Nov 2019 19:16:41 -0300 Subject: [PATCH 2/4] Remove quotes from item_error message --- scrapy/logformatter.py | 8 ++++---- tests/test_logformatter.py | 2 +- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/scrapy/logformatter.py b/scrapy/logformatter.py index 79c752da4..9e038160f 100644 --- a/scrapy/logformatter.py +++ b/scrapy/logformatter.py @@ -5,10 +5,10 @@ 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" -ITEMERRORMSG = 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" class LogFormatter(object): diff --git a/tests/test_logformatter.py b/tests/test_logformatter.py index f2f8c0464..990927f71 100644 --- a/tests/test_logformatter.py +++ b/tests/test_logformatter.py @@ -71,7 +71,7 @@ class LogFormatterTestCase(unittest.TestCase): response = Response("http://www.example.com") 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_scraped(self): item = CustomItem() From 4756e7c587880997a54d9abf94b9a4c0b5bab71c Mon Sep 17 00:00:00 2001 From: Eugenio Lacuesta Date: Sat, 23 Nov 2019 19:33:29 -0300 Subject: [PATCH 3/4] LogFormatter.spider_error --- scrapy/core/scraper.py | 8 ++++---- scrapy/logformatter.py | 12 ++++++++++++ tests/test_logformatter.py | 14 ++++++++++++++ 3 files changed, 30 insertions(+), 4 deletions(-) diff --git a/scrapy/core/scraper.py b/scrapy/core/scraper.py index c5bb48ea6..21820e988 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__) @@ -152,9 +152,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} ) diff --git a/scrapy/logformatter.py b/scrapy/logformatter.py index 9e038160f..d87f685d5 100644 --- a/scrapy/logformatter.py +++ b/scrapy/logformatter.py @@ -9,6 +9,7 @@ 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)" class LogFormatter(object): @@ -103,6 +104,17 @@ class LogFormatter(object): } } + 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), + } + } + @classmethod def from_crawler(cls, crawler): return cls() diff --git a/tests/test_logformatter.py b/tests/test_logformatter.py index 990927f71..47d2747c2 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 import six @@ -73,6 +74,19 @@ class LogFormatterTestCase(unittest.TestCase): logline = logkws['msg'] % logkws['args'] 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_scraped(self): item = CustomItem() item['name'] = u'\xa3' From 03af8885ff475dc47a3de89517b1a5d627bd49c4 Mon Sep 17 00:00:00 2001 From: Eugenio Lacuesta Date: Sat, 23 Nov 2019 20:02:44 -0300 Subject: [PATCH 4/4] LogFormatter.download_error --- scrapy/core/scraper.py | 22 +++++++++++++--------- scrapy/logformatter.py | 16 ++++++++++++++++ tests/test_logformatter.py | 18 ++++++++++++++++++ 3 files changed, 47 insertions(+), 9 deletions(-) diff --git a/scrapy/core/scraper.py b/scrapy/core/scraper.py index 21820e988..427969f30 100644 --- a/scrapy/core/scraper.py +++ b/scrapy/core/scraper.py @@ -200,19 +200,23 @@ class Scraper(object): """Log and silence errors that come from the engine (typically download errors that got propagated thru here) """ - if (isinstance(download_failure, Failure) and - not download_failure.check(IgnoreRequest)): + 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 diff --git a/scrapy/logformatter.py b/scrapy/logformatter.py index d87f685d5..99bd5cfac 100644 --- a/scrapy/logformatter.py +++ b/scrapy/logformatter.py @@ -10,6 +10,8 @@ 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): @@ -115,6 +117,20 @@ class LogFormatter(object): } } + 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 47d2747c2..697ac1d15 100644 --- a/tests/test_logformatter.py +++ b/tests/test_logformatter.py @@ -87,6 +87,24 @@ class LogFormatterTestCase(unittest.TestCase): "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() item['name'] = u'\xa3'