diff --git a/docs/news.rst b/docs/news.rst index 6a019e2fb..2a769bc1c 100644 --- a/docs/news.rst +++ b/docs/news.rst @@ -15,6 +15,14 @@ Backward-incompatible changes ``True`` when running Scrapy via :ref:`its command-line tool ` to avoid a reactor mismatch exception. +- The ``log_count/*`` stats no longer count some of the early messages that + they counted before. While the earliest log messages, emitted before the + counter is initialized, were never counted, the counter initialization now + happens later than in previous Scrapy versions. You may need to adjust + expected values if you retrieve and compare values of these stats in your + code. + (:issue:`7046`) + - The classes listed below are now :term:`abstract base classes `. They cannot be instantiated directly and their subclasses need to override the abstract methods listed below to be able to be diff --git a/docs/topics/extensions.rst b/docs/topics/extensions.rst index e1e3dd6b4..d2ddde207 100644 --- a/docs/topics/extensions.rst +++ b/docs/topics/extensions.rst @@ -138,6 +138,14 @@ enabled (see :ref:`topics-stats`). .. _topics-extensions-ref-telnetconsole: +Log Count extension +~~~~~~~~~~~~~~~~~~~ + +.. module:: scrapy.extensions.logcount + :synopsis: Basic stats logging + +.. autoclass:: LogCount + Telnet console extension ~~~~~~~~~~~~~~~~~~~~~~~~ diff --git a/scrapy/crawler.py b/scrapy/crawler.py index ef658e9b5..ffbebe152 100644 --- a/scrapy/crawler.py +++ b/scrapy/crawler.py @@ -11,7 +11,7 @@ from typing import TYPE_CHECKING, Any, TypeVar from twisted.internet.defer import Deferred, DeferredList, inlineCallbacks -from scrapy import Spider, signals +from scrapy import Spider from scrapy.addons import AddonManager from scrapy.core.engine import ExecutionEngine from scrapy.exceptions import ScrapyDeprecationWarning @@ -22,7 +22,6 @@ from scrapy.spiderloader import SpiderLoaderProtocol, get_spider_loader from scrapy.utils.asyncio import is_asyncio_available from scrapy.utils.defer import deferred_from_coro from scrapy.utils.log import ( - LogCounterHandler, configure_logging, get_scrapy_root_handler, install_scrapy_root_handler, @@ -97,13 +96,6 @@ class Crawler: self.addons.load_settings(self.settings) self.stats = load_object(self.settings["STATS_CLASS"])(self) - handler = LogCounterHandler(self, level=self.settings.get("LOG_LEVEL")) - logging.root.addHandler(handler) - # lambda is assigned to Crawler attribute because this way it is not - # garbage collected after leaving the scope - self.__remove_handler = lambda: logging.root.removeHandler(handler) - self.signals.connect(self.__remove_handler, signals.engine_stopped) - lf_cls: type[LogFormatter] = load_object(self.settings["LOG_FORMATTER"]) self.logformatter = lf_cls.from_crawler(self) diff --git a/scrapy/extensions/logcount.py b/scrapy/extensions/logcount.py new file mode 100644 index 000000000..04e570bbf --- /dev/null +++ b/scrapy/extensions/logcount.py @@ -0,0 +1,48 @@ +from __future__ import annotations + +import logging +from typing import TYPE_CHECKING + +from scrapy import Spider, signals +from scrapy.utils.log import LogCounterHandler + +if TYPE_CHECKING: + # typing.Self requires Python 3.11 + from typing_extensions import Self + + from scrapy.crawler import Crawler + + +logger = logging.getLogger(__name__) + + +class LogCount: + """Install a log handler that counts log messages by level. + + The handler installed is :class:`scrapy.utils.log.LogCounterHandler`. + The counts are stored in stats as ``log_count/``. + + .. versionadded:: VERSION + """ + + def __init__(self, crawler: Crawler): + self.crawler: Crawler = crawler + self.handler: LogCounterHandler | None = None + + @classmethod + def from_crawler(cls, crawler: Crawler) -> Self: + o = cls(crawler) + crawler.signals.connect(o.spider_opened, signal=signals.spider_opened) + crawler.signals.connect(o.spider_closed, signal=signals.spider_closed) + return o + + def spider_opened(self, spider: Spider) -> None: + self.handler = LogCounterHandler( + self.crawler, level=self.crawler.settings.get("LOG_LEVEL") + ) + logging.root.addHandler(self.handler) + + def spider_closed(self, spider: Spider, reason: str) -> None: + if self.handler: + logging.root.removeHandler(self.handler) + self.handler = None diff --git a/scrapy/settings/default_settings.py b/scrapy/settings/default_settings.py index f306569e4..624e71774 100644 --- a/scrapy/settings/default_settings.py +++ b/scrapy/settings/default_settings.py @@ -308,6 +308,7 @@ if sys.platform == "win32": EXTENSIONS = {} EXTENSIONS_BASE = { "scrapy.extensions.corestats.CoreStats": 0, + "scrapy.extensions.logcount.LogCount": 0, "scrapy.extensions.telnet.TelnetConsole": 0, "scrapy.extensions.memusage.MemoryUsage": 0, "scrapy.extensions.memdebug.MemoryDebugger": 0, diff --git a/tests/test_crawl.py b/tests/test_crawl.py index 255a03a2a..47bed925a 100644 --- a/tests/test_crawl.py +++ b/tests/test_crawl.py @@ -401,7 +401,7 @@ with multiples lines assert "Got response 200" in str(log) @inlineCallbacks - def test_crawl_multiple(self): + def test_crawl_multiple(self, caplog: pytest.LogCaptureFixture): runner = CrawlerRunner(get_reactor_settings()) runner.crawl( SimpleSpider, @@ -414,11 +414,11 @@ with multiples lines mockserver=self.mockserver, ) - with LogCapture() as log: + with caplog.at_level(logging.DEBUG): yield runner.join() - self._assert_retried(log) - assert "Got response 200" in str(log) + self._assert_retried(caplog.text) + assert "Got response 200" in caplog.text class TestCrawlSpider: diff --git a/tests/test_crawler.py b/tests/test_crawler.py index de20d6b90..66383b92b 100644 --- a/tests/test_crawler.py +++ b/tests/test_crawler.py @@ -516,10 +516,13 @@ class TestCrawlerLogging: get_crawler(MySpider) assert get_scrapy_root_handler() is None - def test_spider_custom_settings_log_level(self, tmp_path): + @deferred_f_from_coro_f + async def test_spider_custom_settings_log_level(self, tmp_path): log_file = Path(tmp_path, "log.txt") log_file.write_text("previous message\n", encoding="utf-8") + info_count = None + class MySpider(scrapy.Spider): name = "spider" custom_settings = { @@ -527,15 +530,24 @@ class TestCrawlerLogging: "LOG_FILE": str(log_file), } + async def start(self): + info_count_start = crawler.stats.get_value("log_count/INFO") + logging.debug("debug message") # noqa: LOG015 + logging.info("info message") # noqa: LOG015 + logging.warning("warning message") # noqa: LOG015 + logging.error("error message") # noqa: LOG015 + nonlocal info_count + info_count = ( + crawler.stats.get_value("log_count/INFO") - info_count_start + ) + return + yield + configure_logging() assert get_scrapy_root_handler().level == logging.DEBUG crawler = get_crawler(MySpider) assert get_scrapy_root_handler().level == logging.INFO - info_count = crawler.stats.get_value("log_count/INFO") - logging.debug("debug message") # noqa: LOG015 - logging.info("info message") # noqa: LOG015 - logging.warning("warning message") # noqa: LOG015 - logging.error("error message") # noqa: LOG015 + await maybe_deferred_to_future(crawler.crawl()) logged = log_file.read_text(encoding="utf-8") @@ -546,7 +558,7 @@ class TestCrawlerLogging: assert "error message" in logged assert crawler.stats.get_value("log_count/ERROR") == 1 assert crawler.stats.get_value("log_count/WARNING") == 1 - assert crawler.stats.get_value("log_count/INFO") - info_count == 1 + assert info_count == 1 assert crawler.stats.get_value("log_count/DEBUG", 0) == 0 def test_spider_custom_settings_log_append(self, tmp_path): diff --git a/tests/test_downloadermiddleware.py b/tests/test_downloadermiddleware.py index a4233d447..03b941e4f 100644 --- a/tests/test_downloadermiddleware.py +++ b/tests/test_downloadermiddleware.py @@ -32,8 +32,10 @@ class TestManagerBase: mwman = DownloaderMiddlewareManager.from_crawler(crawler) crawler.engine = crawler._create_engine() await crawler.engine.open_spider_async() - yield mwman - await crawler.engine.close_spider_async() + try: + yield mwman + finally: + await crawler.engine.close_spider_async() @staticmethod async def _download( diff --git a/tests/test_zz_resources.py b/tests/test_zz_resources.py new file mode 100644 index 000000000..84b2910db --- /dev/null +++ b/tests/test_zz_resources.py @@ -0,0 +1,16 @@ +"""Test that certain resources are not leaked during earlier tests.""" + +from __future__ import annotations + +import logging + +from scrapy.utils.log import LogCounterHandler + + +def test_counter_handler() -> None: + """Test that LogCounterHandler is always properly removed. + + It's added in Crawler.crawl{,_async}() and removed on engine_stopped. + """ + c = sum(1 for h in logging.root.handlers if isinstance(h, LogCounterHandler)) + assert c == 0