Add backward compatibility to LogFormatter

scrapy/core/engine.py

@@ -16,6 +16,7 @@ from scrapy.exceptions import DontCloseSpider
 from scrapy.http import Response, Request
 from scrapy.utils.misc import load_object
 from scrapy.utils.reactor import CallLaterOnce
+from scrapy.utils.log import logformatter_adapter
 
 logger = logging.getLogger(__name__)
 
@@ -204,7 +205,7 @@ class ExecutionEngine(object):
             if isinstance(response, Response):
                 response.request = request # tie request to response received
                 logkws = self.logformatter.crawled(request, response, spider)
-                logger._log(extra={'spider': spider}, **logkws)
+                logger.log(*logformatter_adapter(logkws), extra={'spider': spider})
                 self.signals.send_catch_log(signal=signals.response_received, \
                     response=response, request=request, spider=spider)
             return response

scrapy/core/scraper.py

@@ -10,6 +10,7 @@ from twisted.internet import defer
 from scrapy.utils.defer import defer_result, defer_succeed, parallel, iter_errback
 from scrapy.utils.spider import iterate_spider_output
 from scrapy.utils.misc import load_object
+from scrapy.utils.log import logformatter_adapter
 from scrapy.exceptions import CloseSpider, DropItem, IgnoreRequest
 from scrapy import signals
 from scrapy.http import Request, Response
@@ -220,7 +221,7 @@ class Scraper(object):
             ex = output.value
             if isinstance(ex, DropItem):
                 logkws = self.logformatter.dropped(item, ex, response, spider)
-                logger._log(extra={'spider': spider}, **logkws)
+                logger.log(*logformatter_adapter(logkws), extra={'spider': spider})
                 return self.signals.send_catch_log_deferred(
                     signal=signals.item_dropped, item=item, response=response,
                     spider=spider, exception=output.value)
@@ -229,7 +230,7 @@ class Scraper(object):
                              extra={'spider': spider, 'failure': output})
         else:
             logkws = self.logformatter.scraped(output, response, spider)
-            logger._log(extra={'spider': spider}, **logkws)
+            logger.log(*logformatter_adapter(logkws), extra={'spider': spider})
             return self.signals.send_catch_log_deferred(
                 signal=signals.item_scraped, item=output, response=response,
                 spider=spider)

scrapy/utils/log.py

@@ -3,6 +3,7 @@
 import os
 import sys
 import logging
+import warnings
 from logging.config import dictConfig
 
 from twisted.python.failure import Failure
@@ -10,6 +11,7 @@ from twisted.python import log as twisted_log
 
 import scrapy
 from scrapy.settings import overridden_settings
+from scrapy.exceptions import ScrapyDeprecationWarning
 
 logger = logging.getLogger(__name__)
 
@@ -153,3 +155,27 @@ class LogCounterHandler(logging.Handler):
     def emit(self, record):
         sname = 'log_count/{}'.format(record.levelname)
         self.crawler.stats.inc_value(sname)
+
+
+def logformatter_adapter(logkws):
+    """
+    Helper that takes the dictionary output from the methods in LogFormatter
+    and adapts it into a tuple of positional arguments for logger.log calls,
+    handling backward compatibility as well.
+    """
+    if not {'level', 'msg', 'args'} <= set(logkws):
+        warnings.warn('Missing keys in LogFormatter method',
+                      ScrapyDeprecationWarning)
+
+    if 'format' in logkws:
+        warnings.warn('`format` key in LogFormatter methods has been '
+                      'deprecated, use `msg` instead',
+                      ScrapyDeprecationWarning)
+
+    level = logkws.get('level', logging.INFO)
+    message = logkws.get('format', logkws.get('msg'))
+    # NOTE: This also handles 'args' being an empty dict, that case doesn't
+    # play well in logger.log calls
+    args = logkws if not logkws.get('args') else logkws['args']
+
+    return (level, message, args)