diff --git a/scrapy/core/engine.py b/scrapy/core/engine.py index 7e330af1c..a978d3c08 100644 --- a/scrapy/core/engine.py +++ b/scrapy/core/engine.py @@ -10,7 +10,7 @@ from time import time from twisted.internet import defer from twisted.python.failure import Failure -from scrapy import log, signals +from scrapy import signals from scrapy.core.scraper import Scraper from scrapy.exceptions import DontCloseSpider from scrapy.http import Response, Request @@ -204,7 +204,7 @@ class ExecutionEngine(object): if isinstance(response, Response): response.request = request # tie request to response received logkws = self.logformatter.crawled(request, response, spider) - log.msg(spider=spider, **logkws) + logger._log(extra={'spider': spider}, **logkws) self.signals.send_catch_log(signal=signals.response_received, \ response=response, request=request, spider=spider) return response diff --git a/scrapy/core/scraper.py b/scrapy/core/scraper.py index 4a961f8e8..196f5392d 100644 --- a/scrapy/core/scraper.py +++ b/scrapy/core/scraper.py @@ -15,7 +15,6 @@ from scrapy import signals from scrapy.http import Request, Response from scrapy.item import BaseItem from scrapy.core.spidermw import SpiderMiddlewareManager -from scrapy import log logger = logging.getLogger('scrapy') @@ -221,7 +220,7 @@ class Scraper(object): ex = output.value if isinstance(ex, DropItem): logkws = self.logformatter.dropped(item, ex, response, spider) - log.msg(spider=spider, **logkws) + logger._log(extra={'spider': spider}, **logkws) return self.signals.send_catch_log_deferred( signal=signals.item_dropped, item=item, response=response, spider=spider, exception=output.value) @@ -230,7 +229,7 @@ class Scraper(object): extra={'spider': spider, 'failure': output}) else: logkws = self.logformatter.scraped(output, response, spider) - log.msg(spider=spider, **logkws) + logger._log(extra={'spider': spider}, **logkws) return self.signals.send_catch_log_deferred( signal=signals.item_scraped, item=output, response=response, spider=spider) diff --git a/scrapy/logformatter.py b/scrapy/logformatter.py index d03d2d07f..a0508e0b7 100644 --- a/scrapy/logformatter.py +++ b/scrapy/logformatter.py @@ -1,46 +1,67 @@ import os +import logging from twisted.python.failure import Failure -from scrapy import log +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 (referer: %(referer)s)%(flags)s" -SCRAPEDFMT = u"Scraped from %(src)s" + os.linesep + "%(item)s" -DROPPEDFMT = u"Dropped: %(exception)s" + os.linesep + "%(item)s" -CRAWLEDFMT = u"Crawled (%(status)s) %(request)s (referer: %(referer)s)%(flags)s" class LogFormatter(object): - """Class for generating log messages for different actions. All methods - must return a plain string which doesn't include the log level or the - timestamp + """Class for generating log messages for different actions. + + All methods must return a dictionary listing the parameters `level`, `msg` + and `args` which are going to be used for constructing the log message when + calling logging.log. + + Dictionary keys for the method outputs: + * `level` should be the log level for that action, you can use those + from the python logging library: logging.DEBUG, logging.INFO, + logging.WARNING, logging.ERROR and logging.CRITICAL. + + * `msg` should be a string that can contain different formatting + placeholders. This string, formatted with the provided `args`, is going + to be the log message for that action. + + * `args` should be a tuple or dict with the formatting placeholders for + `msg`. The final log message is computed as output['msg'] % + output['args']. """ def crawled(self, request, response, spider): flags = ' %s' % str(response.flags) if response.flags else '' return { - 'level': log.DEBUG, - 'format': CRAWLEDFMT, - 'status': response.status, - 'request': request, - 'referer': request.headers.get('Referer'), - 'flags': flags, + 'level': logging.DEBUG, + 'msg': CRAWLEDMSG, + 'args': { + 'status': response.status, + 'request': request, + 'referer': request.headers.get('Referer'), + 'flags': flags, + } } def scraped(self, item, response, spider): src = response.getErrorMessage() if isinstance(response, Failure) else response return { - 'level': log.DEBUG, - 'format': SCRAPEDFMT, - 'src': src, - 'item': item, + 'level': logging.DEBUG, + 'msg': SCRAPEDMSG, + 'args': { + 'src': src, + 'item': item, + } } def dropped(self, item, exception, response, spider): return { - 'level': log.WARNING, - 'format': DROPPEDFMT, - 'exception': exception, - 'item': item, + 'level': logging.WARNING, + 'msg': DROPPEDMSG, + 'args': { + 'exception': exception, + 'item': item, + } } @classmethod diff --git a/tests/test_logformatter.py b/tests/test_logformatter.py index adec19afa..8446fd646 100644 --- a/tests/test_logformatter.py +++ b/tests/test_logformatter.py @@ -24,14 +24,14 @@ class LoggingContribTest(unittest.TestCase): req = Request("http://www.example.com") res = Response("http://www.example.com") logkws = self.formatter.crawled(req, res, self.spider) - logline = logkws['format'] % logkws + logline = logkws['msg'] % logkws['args'] self.assertEqual(logline, "Crawled (200) (referer: None)") 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) - logline = logkws['format'] % logkws + logline = logkws['msg'] % logkws['args'] self.assertEqual(logline, "Crawled (200) (referer: http://example.com) ['cached']") @@ -40,7 +40,7 @@ class LoggingContribTest(unittest.TestCase): exception = Exception(u"\u2018") response = Response("http://www.example.com") logkws = self.formatter.dropped(item, exception, response, self.spider) - logline = logkws['format'] % logkws + logline = logkws['msg'] % logkws['args'] lines = logline.splitlines() assert all(isinstance(x, unicode) for x in lines) self.assertEqual(lines, [u"Dropped: \u2018", '{}']) @@ -50,7 +50,7 @@ class LoggingContribTest(unittest.TestCase): item['name'] = u'\xa3' response = Response("http://www.example.com") logkws = self.formatter.scraped(item, response, self.spider) - logline = logkws['format'] % logkws + logline = logkws['msg'] % logkws['args'] lines = logline.splitlines() assert all(isinstance(x, unicode) for x in lines) self.assertEqual(lines, [u"Scraped from <200 http://www.example.com>", u'name: \xa3'])