Move LogCounterHandler into a new extension (#7046)

* Move LogCounterHandler into Crawler.crawl().

* Add the LogCount extension.

* Update test_spider_custom_settings_log_level().

* Typo.

* Update docs.

docs/news.rst

@@ -15,6 +15,14 @@ Backward-incompatible changes
     ``True`` when running Scrapy via :ref:`its command-line tool
     <topics-commands-crawlerprocess>` 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 <abstract
     base class>`. They cannot be instantiated directly and their subclasses
     need to override the abstract methods listed below to be able to be

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
 ~~~~~~~~~~~~~~~~~~~~~~~~
 

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)
 

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/<level>``.
+
+    .. 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

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,

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:

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):

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(

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