Restructure LogFormatter to comply with std logging calls

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

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)

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

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) <GET http://www.example.com> (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) <GET http://www.example.com> (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'])