Custom handler to count log level occurrences in a crawler

scrapy/commands/shell.py

@@ -53,7 +53,6 @@ class Command(ScrapyCommand):
         # The crawler is created this way since the Shell manually handles the
         # crawling engine, so the set up in the crawl method won't work
         crawler = self.crawler_process._create_crawler(spidercls)
-        self.crawler_process._setup_crawler_logging(crawler)
         # The Shell class needs a persistent engine in the crawler
         crawler.engine = crawler._create_engine()
         crawler.engine.start()

scrapy/crawler.py

@@ -15,7 +15,7 @@ from scrapy.signalmanager import SignalManager
 from scrapy.exceptions import ScrapyDeprecationWarning
 from scrapy.utils.ossignal import install_shutdown_handlers, signal_names
 from scrapy.utils.misc import load_object
-from scrapy.utils.log import configure_logging, log_scrapy_info
+from scrapy.utils.log import LogCounterHandler, configure_logging, log_scrapy_info
 from scrapy import signals
 
 logger = logging.getLogger('scrapy')
@@ -32,6 +32,12 @@ class Crawler(object):
 
         self.signals = SignalManager(self)
         self.stats = load_object(self.settings['STATS_CLASS'])(self)
+
+        handler = LogCounterHandler(self, level=settings.get('LOG_LEVEL'))
+        logging.root.addHandler(handler)
+        self.signals.connect(lambda: logging.root.removeHandler(handler),
+                             signals.engine_stopped)
+
         lf_cls = load_object(self.settings['LOG_FORMATTER'])
         self.logformatter = lf_cls.from_crawler(self)
         self.extensions = ExtensionManager.from_crawler(self)
@@ -103,7 +109,6 @@ class CrawlerRunner(object):
         crawler = crawler_or_spidercls
         if not isinstance(crawler_or_spidercls, Crawler):
             crawler = self._create_crawler(crawler_or_spidercls)
-            self._setup_crawler_logging(crawler)
 
         self.crawlers.add(crawler)
         d = crawler.crawl(*args, **kwargs)
@@ -121,11 +126,6 @@ class CrawlerRunner(object):
             spidercls = self.spider_loader.load(spidercls)
         return Crawler(spidercls, self.settings)
 
-    def _setup_crawler_logging(self, crawler):
-        log_observer = log.start_from_crawler(crawler)
-        if log_observer:
-            crawler.signals.connect(log_observer.stop, signals.engine_stopped)
-
     def stop(self):
         return defer.DeferredList([c.stop() for c in list(self.crawlers)])
 

scrapy/utils/log.py

@@ -72,3 +72,15 @@ def log_scrapy_info(settings):
 
     d = dict(overridden_settings(settings))
     logger.info("Overridden settings: %(settings)r", {'settings': d})
+
+
+class LogCounterHandler(logging.Handler):
+    """Record log levels count into a crawler stats"""
+
+    def __init__(self, crawler, *args, **kwargs):
+        super(LogCounterHandler, self).__init__(*args, **kwargs)
+        self.crawler = crawler
+
+    def emit(self, record):
+        sname = 'log_count/{}'.format(record.levelname)
+        self.crawler.stats.inc_value(sname)

tests/py3-ignores.txt

@@ -59,6 +59,7 @@ tests/test_stats.py
 tests/test_utils_defer.py
 tests/test_utils_iterators.py
 tests/test_utils_jsonrpc.py
+tests/test_utils_log.py
 tests/test_utils_python.py
 tests/test_utils_reqser.py
 tests/test_utils_request.py

tests/test_utils_log.py

@@ -6,7 +6,8 @@ import unittest
 from testfixtures import LogCapture
 from twisted.python.failure import Failure
 
-from scrapy.utils.log import FailureFormatter
+from scrapy.utils.log import FailureFormatter, LogCounterHandler
+from scrapy.utils.test import get_crawler
 
 
 class FailureFormatterTest(unittest.TestCase):
@@ -44,3 +45,33 @@ class FailureFormatterTest(unittest.TestCase):
         self.assertEqual(len(l.records), 1)
         self.assertMultiLineEqual(l.records[0].getMessage(),
                                   'test log msg' + os.linesep + '3')
+
+
+class LogCounterHandlerTest(unittest.TestCase):
+
+    def setUp(self):
+        self.logger = logging.getLogger('test')
+        self.logger.setLevel(logging.NOTSET)
+        self.logger.propagate = False
+        self.crawler = get_crawler(settings_dict={'LOG_LEVEL': 'WARNING'})
+        self.handler = LogCounterHandler(self.crawler)
+        self.logger.addHandler(self.handler)
+
+    def tearDown(self):
+        self.logger.propagate = True
+        self.logger.removeHandler(self.handler)
+
+    def test_init(self):
+        self.assertIsNone(self.crawler.stats.get_value('log_count/DEBUG'))
+        self.assertIsNone(self.crawler.stats.get_value('log_count/INFO'))
+        self.assertIsNone(self.crawler.stats.get_value('log_count/WARNING'))
+        self.assertIsNone(self.crawler.stats.get_value('log_count/ERROR'))
+        self.assertIsNone(self.crawler.stats.get_value('log_count/CRITICAL'))
+
+    def test_accepted_level(self):
+        self.logger.error('test log msg')
+        self.assertEqual(self.crawler.stats.get_value('log_count/ERROR'), 1)
+
+    def test_filtered_out_level(self):
+        self.logger.debug('test log msg')
+        self.assertIsNone(self.crawler.stats.get_value('log_count/INFO'))