Log a warning for modules that log too often (#139708)

* Log a warning for modules that log too often

* Improve var naming

* Increase time window; improve log info

* Fix zha type

* Fix typo

* Ignore debug logs

* Use timer to avoid now() calls

* Switch to async_track_time_interval

* Allow using base QueueLister

* Add test for counters reset

* Make var names consistent; reduce message/time ratio

* Use log times instead of timer

* Simplify reset test

* Warn only once per module

* Remove uneeded counter reset

homeassistant/util/logging.py

@@ -2,14 +2,16 @@
 
 from __future__ import annotations
 
+from collections import defaultdict
 from collections.abc import Callable, Coroutine
 from functools import partial, wraps
 import inspect
 import logging
 import logging.handlers
-import queue
+from queue import SimpleQueue
+import time
 import traceback
-from typing import Any, cast, overload
+from typing import Any, cast, overload, override
 
 from homeassistant.core import (
     HassJobType,
@@ -18,6 +20,59 @@ from homeassistant.core import (
     get_hassjob_callable_job_type,
 )
 
+_LOGGER = logging.getLogger(__name__)
+
+
+class HomeAssistantQueueListener(logging.handlers.QueueListener):
+    """Custom QueueListener to watch for noisy loggers."""
+
+    LOG_COUNTS_RESET_INTERVAL = 300
+    MAX_LOGS_COUNT = 200
+
+    _last_reset: float
+    _log_counts: dict[str, int]
+    _warned_modules: set[str]
+
+    def __init__(
+        self, queue: SimpleQueue[logging.Handler], *handlers: logging.Handler
+    ) -> None:
+        """Initialize the handler."""
+        super().__init__(queue, *handlers)
+        self._warned_modules = set()
+        self._reset_counters(time.time())
+
+    @override
+    def handle(self, record: logging.LogRecord) -> None:
+        """Handle the record."""
+        super().handle(record)
+
+        if record.levelno < logging.INFO:
+            return
+
+        if (record.created - self._last_reset) > self.LOG_COUNTS_RESET_INTERVAL:
+            self._reset_counters(record.created)
+
+        module_name = record.name
+        if module_name == __name__ or module_name in self._warned_modules:
+            return
+
+        self._log_counts[module_name] += 1
+        module_count = self._log_counts[module_name]
+        if module_count < self.MAX_LOGS_COUNT:
+            return
+
+        _LOGGER.warning(
+            "Module %s is logging too frequently. %d messages since last count",
+            module_name,
+            module_count,
+        )
+        self._warned_modules.add(module_name)
+
+    def _reset_counters(self, time_sec: float) -> None:
+        _LOGGER.debug("Resetting log counters")
+        self._last_reset = time_sec
+        self._log_counts = defaultdict(int)
+
 
 class HomeAssistantQueueHandler(logging.handlers.QueueHandler):
     """Process the log in another thread."""
@@ -60,7 +115,7 @@ def async_activate_log_queue_handler(hass: HomeAssistant) -> None:
     This allows us to avoid blocking I/O and formatting messages
     in the event loop as log messages are written in another thread.
     """
-    simple_queue: queue.SimpleQueue[logging.Handler] = queue.SimpleQueue()
+    simple_queue: SimpleQueue[logging.Handler] = SimpleQueue()
     queue_handler = HomeAssistantQueueHandler(simple_queue)
     logging.root.addHandler(queue_handler)
 
@@ -71,7 +126,7 @@ def async_activate_log_queue_handler(hass: HomeAssistant) -> None:
         logging.root.removeHandler(handler)
         migrated_handlers.append(handler)
 
-    listener = logging.handlers.QueueListener(simple_queue, *migrated_handlers)
+    listener = HomeAssistantQueueListener(simple_queue, *migrated_handlers)
     queue_handler.listener = listener
 
     listener.start()

tests/util/test_logging.py

@@ -6,6 +6,7 @@ import logging
 import queue
 from unittest.mock import patch
 
+from freezegun.api import FrozenDateTimeFactory
 import pytest
 
 from homeassistant.core import (
@@ -17,6 +18,13 @@ from homeassistant.core import (
 from homeassistant.util import logging as logging_util
 
 
+async def empty_log_queue() -> None:
+    """Empty the log queue."""
+    log_queue: queue.SimpleQueue = logging.root.handlers[0].queue
+    while not log_queue.empty():
+        await asyncio.sleep(0)
+
+
 async def test_logging_with_queue_handler() -> None:
     """Test logging with HomeAssistantQueueHandler."""
 
@@ -149,3 +157,115 @@ async def test_catch_log_exception_catches_and_logs() -> None:
     func("failure sync passed")
 
     assert saved_args == [("failure sync passed",)]
+
+
+@patch("homeassistant.util.logging.HomeAssistantQueueListener.MAX_LOGS_COUNT", 5)
+@pytest.mark.parametrize(
+    (
+        "logger1_count",
+        "logger1_expected_notices",
+        "logger2_count",
+        "logger2_expected_notices",
+    ),
+    [(4, 0, 0, 0), (5, 1, 1, 0), (11, 1, 5, 1), (20, 1, 20, 1)],
+)
+async def test_noisy_loggers(
+    hass: HomeAssistant,
+    caplog: pytest.LogCaptureFixture,
+    logger1_count: int,
+    logger1_expected_notices: int,
+    logger2_count: int,
+    logger2_expected_notices: int,
+) -> None:
+    """Test that noisy loggers all logged as warnings."""
+
+    logging_util.async_activate_log_queue_handler(hass)
+    logger1 = logging.getLogger("noisy1")
+    logger2 = logging.getLogger("noisy2.module")
+
+    for _ in range(logger1_count):
+        logger1.info("This is a log")
+
+    for _ in range(logger2_count):
+        logger2.info("This is another log")
+
+    await empty_log_queue()
+
+    assert (
+        caplog.text.count(
+            "Module noisy1 is logging too frequently. 5 messages since last count"
+        )
+        == logger1_expected_notices
+    )
+    assert (
+        caplog.text.count(
+            "Module noisy2.module is logging too frequently. 5 messages since last count"
+        )
+        == logger2_expected_notices
+    )
+
+    # close the handler so the queue thread stops
+    logging.root.handlers[0].close()
+
+
+@patch("homeassistant.util.logging.HomeAssistantQueueListener.MAX_LOGS_COUNT", 5)
+async def test_noisy_loggers_ignores_lower_than_info(
+    hass: HomeAssistant, caplog: pytest.LogCaptureFixture
+) -> None:
+    """Test that noisy loggers all logged as warnings, except for levels lower than INFO."""
+
+    logging_util.async_activate_log_queue_handler(hass)
+    logger = logging.getLogger("noisy_module")
+
+    for _ in range(5):
+        logger.debug("This is a log")
+
+    await empty_log_queue()
+    expected_warning = "Module noisy_module is logging too frequently"
+    assert caplog.text.count(expected_warning) == 0
+
+    logger.info("This is a log")
+    logger.info("This is a log")
+    logger.warning("This is a log")
+    logger.error("This is a log")
+    logger.critical("This is a log")
+
+    await empty_log_queue()
+    assert caplog.text.count(expected_warning) == 1
+
+    # close the handler so the queue thread stops
+    logging.root.handlers[0].close()
+
+
+@patch("homeassistant.util.logging.HomeAssistantQueueListener.MAX_LOGS_COUNT", 3)
+async def test_noisy_loggers_counters_reset(
+    hass: HomeAssistant,
+    caplog: pytest.LogCaptureFixture,
+    freezer: FrozenDateTimeFactory,
+) -> None:
+    """Test that noisy logger counters reset periodically."""
+
+    logging_util.async_activate_log_queue_handler(hass)
+    logger = logging.getLogger("noisy_module")
+
+    expected_warning = "Module noisy_module is logging too frequently"
+
+    # Do multiple iterations to ensure the reset is periodic
+    for _ in range(logging_util.HomeAssistantQueueListener.MAX_LOGS_COUNT * 2):
+        logger.info("This is log 0")
+        await empty_log_queue()
+
+        freezer.tick(
+            logging_util.HomeAssistantQueueListener.LOG_COUNTS_RESET_INTERVAL + 1
+        )
+
+        logger.info("This is log 1")
+        await empty_log_queue()
+        assert caplog.text.count(expected_warning) == 0
+
+    logger.info("This is log 2")
+    logger.info("This is log 3")
+    await empty_log_queue()
+    assert caplog.text.count(expected_warning) == 1
+    # close the handler so the queue thread stops
+    logging.root.handlers[0].close()