From ef04cfd237ec3d072a487f92e217bad68195f2d8 Mon Sep 17 00:00:00 2001 From: Konstantin Lopuhin Date: Tue, 21 Feb 2017 19:55:52 +0300 Subject: [PATCH] Respect log settings in custom_settings: fixes GH-1612 A new root logger is installed when a crawler is created if one was already installed before. This allows to respect custom settings related to logging, such as LOG_LEVEL, LOG_FILE, etc. --- scrapy/crawler.py | 9 +++++++-- scrapy/utils/log.py | 22 ++++++++++++++++++--- tests/test_crawl.py | 4 ++-- tests/test_crawler.py | 46 +++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 74 insertions(+), 7 deletions(-) diff --git a/scrapy/crawler.py b/scrapy/crawler.py index 443a9aa2f..7b8518832 100644 --- a/scrapy/crawler.py +++ b/scrapy/crawler.py @@ -16,7 +16,9 @@ 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 LogCounterHandler, configure_logging, log_scrapy_info +from scrapy.utils.log import ( + LogCounterHandler, configure_logging, log_scrapy_info, + get_scrapy_root_handler, install_scrapy_root_handler) from scrapy import signals logger = logging.getLogger(__name__) @@ -35,8 +37,11 @@ class Crawler(object): self.signals = SignalManager(self) self.stats = load_object(self.settings['STATS_CLASS'])(self) - handler = LogCounterHandler(self, level=settings.get('LOG_LEVEL')) + handler = LogCounterHandler(self, level=self.settings.get('LOG_LEVEL')) logging.root.addHandler(handler) + if get_scrapy_root_handler() is not None: + # scrapy root handler alread installed: update it with new settings + install_scrapy_root_handler(self.settings) # lambda is assigned to Crawler attribute because this way it is not # garbage collected after leaving __init__ scope self.__remove_handler = lambda: logging.root.removeHandler(handler) diff --git a/scrapy/utils/log.py b/scrapy/utils/log.py index f33ce7017..6ceb61a82 100644 --- a/scrapy/utils/log.py +++ b/scrapy/utils/log.py @@ -96,9 +96,25 @@ def configure_logging(settings=None, install_root_handler=True): sys.stdout = StreamLogger(logging.getLogger('stdout')) if install_root_handler: - logging.root.setLevel(logging.NOTSET) - handler = _get_handler(settings) - logging.root.addHandler(handler) + install_scrapy_root_handler(settings) + + +def install_scrapy_root_handler(settings): + global _scrapy_root_handler + + if (_scrapy_root_handler is not None + and _scrapy_root_handler in logging.root.handlers): + logging.root.removeHandler(_scrapy_root_handler) + logging.root.setLevel(logging.NOTSET) + _scrapy_root_handler = _get_handler(settings) + logging.root.addHandler(_scrapy_root_handler) + + +def get_scrapy_root_handler(): + return _scrapy_root_handler + + +_scrapy_root_handler = None def _get_handler(settings): diff --git a/tests/test_crawl.py b/tests/test_crawl.py index d5babdded..3c5d9b958 100644 --- a/tests/test_crawl.py +++ b/tests/test_crawl.py @@ -97,8 +97,8 @@ class CrawlTestCase(TestCase): @defer.inlineCallbacks def test_start_requests_bug_before_yield(self): + crawler = self.runner.create_crawler(BrokenStartRequestsSpider) with LogCapture('scrapy', level=logging.ERROR) as l: - crawler = self.runner.create_crawler(BrokenStartRequestsSpider) yield crawler.crawl(fail_before_yield=1) self.assertEqual(len(l.records), 1) @@ -108,8 +108,8 @@ class CrawlTestCase(TestCase): @defer.inlineCallbacks def test_start_requests_bug_yielding(self): + crawler = self.runner.create_crawler(BrokenStartRequestsSpider) with LogCapture('scrapy', level=logging.ERROR) as l: - crawler = self.runner.create_crawler(BrokenStartRequestsSpider) yield crawler.crawl(fail_yielding=1) self.assertEqual(len(l.records), 1) diff --git a/tests/test_crawler.py b/tests/test_crawler.py index 53a1202e3..ba0d709ff 100644 --- a/tests/test_crawler.py +++ b/tests/test_crawler.py @@ -1,3 +1,6 @@ +import logging +import os +import tempfile import warnings import unittest @@ -5,6 +8,7 @@ import scrapy from scrapy.crawler import Crawler, CrawlerRunner, CrawlerProcess from scrapy.settings import Settings, default_settings from scrapy.spiderloader import SpiderLoader +from scrapy.utils.log import configure_logging, get_scrapy_root_handler from scrapy.utils.spider import DefaultSpider from scrapy.utils.misc import load_object from scrapy.extensions.throttle import AutoThrottle @@ -74,6 +78,48 @@ class SpiderSettingsTestCase(unittest.TestCase): self.assertIn(AutoThrottle, enabled_exts) +class CrawlerLoggingTestCase(unittest.TestCase): + def test_no_root_handler_installed(self): + handler = get_scrapy_root_handler() + if handler is not None: + logging.root.removeHandler(handler) + + class MySpider(scrapy.Spider): + name = 'spider' + + crawler = Crawler(MySpider, {}) + assert get_scrapy_root_handler() is None + + def test_spider_custom_settings_log_level(self): + with tempfile.NamedTemporaryFile() as log_file: + class MySpider(scrapy.Spider): + name = 'spider' + custom_settings = { + 'LOG_LEVEL': 'INFO', + 'LOG_FILE': log_file.name, + } + + configure_logging() + self.assertEqual(get_scrapy_root_handler().level, logging.DEBUG) + crawler = Crawler(MySpider, {}) + self.assertEqual(get_scrapy_root_handler().level, logging.INFO) + info_count = crawler.stats.get_value('log_count/INFO') + logging.debug('debug message') + logging.info('info message') + logging.warning('warning message') + logging.error('error message') + logged = log_file.read().decode('utf8') + self.assertNotIn('debug message', logged) + self.assertIn('info message', logged) + self.assertIn('warning message', logged) + self.assertIn('error message', logged) + self.assertEqual(crawler.stats.get_value('log_count/ERROR'), 1) + self.assertEqual(crawler.stats.get_value('log_count/WARNING'), 1) + self.assertEqual( + crawler.stats.get_value('log_count/INFO') - info_count, 1) + self.assertEqual(crawler.stats.get_value('log_count/DEBUG', 0), 0) + + class SpiderLoaderWithWrongInterface(object): def unneeded_method(self):