Add a logging filter to mimic Twisted's log.err formating for Failures

scrapy/utils/log.py

@@ -1,9 +1,11 @@
 # -*- coding: utf-8 -*-
 
+import os
 import sys
 import logging
 from logging.config import dictConfig
 
+from twisted.python.failure import Failure
 from twisted.python import log as twisted_log
 
 import scrapy
@@ -12,12 +14,36 @@ from scrapy.settings import overridden_settings
 logger = logging.getLogger('scrapy')
 
 
+class FailureFormatter(logging.Filter):
+    """Extract exc_info from Failure instances provided as contextual data
+
+    This filter mimics Twisted log.err formatting for its first `_stuff`
+    argument, which means that reprs of non Failure objects are appended to the
+    log messages.
+    """
+
+    def filter(self, record):
+        failure = record.__dict__.get('failure')
+        if failure:
+            if isinstance(failure, Failure):
+                record.exc_info = (failure.type, failure.value, failure.tb)
+            else:
+                record.msg += os.linesep + repr(failure)
+        return True
+
+
 DEFAULT_LOGGING = {
     'version': 1,
     'disable_existing_loggers': False,
+    'filters': {
+        'failure_formatter': {
+            '()': 'scrapy.utils.log.FailureFormatter',
+        },
+    },
     'loggers': {
         'scrapy': {
             'level': 'DEBUG',
+            'filters': ['failure_formatter'],
         },
         'twisted': {
             'level': 'ERROR',

tests/test_utils_log.py

@@ -0,0 +1,46 @@
+# -*- coding: utf-8 -*-
+import os
+import logging
+import unittest
+
+from testfixtures import LogCapture
+from twisted.python.failure import Failure
+
+from scrapy.utils.log import FailureFormatter
+
+
+class FailureFormatterTest(unittest.TestCase):
+
+    def setUp(self):
+        self.logger = logging.getLogger('test')
+        self.filter = FailureFormatter()
+        self.logger.addFilter(self.filter)
+
+    def tearDown(self):
+        self.logger.removeFilter(self.filter)
+
+    def test_failure_format(self):
+        with LogCapture() as l:
+            try:
+                0/0
+            except ZeroDivisionError:
+                self.logger.exception('test log msg')
+                failure = Failure()
+
+            self.logger.error('test log msg', extra={'failure': failure})
+
+        self.assertEqual(len(l.records), 2)
+        exc_record, failure_record = l.records
+        self.assertTupleEqual(failure_record.exc_info, exc_record.exc_info)
+
+        formatter = logging.Formatter()
+        self.assertMultiLineEqual(formatter.format(failure_record),
+                                  formatter.format(exc_record))
+
+    def test_non_failure_format(self):
+        with LogCapture() as l:
+            self.logger.error('test log msg', extra={'failure': 3})
+
+        self.assertEqual(len(l.records), 1)
+        self.assertMultiLineEqual(l.records[0].getMessage(),
+                                  'test log msg' + os.linesep + '3')