diff --git a/homeassistant/util/logging.py b/homeassistant/util/logging.py index 2c4eb744614..1e516742bfe 100644 --- a/homeassistant/util/logging.py +++ b/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() diff --git a/tests/util/test_logging.py b/tests/util/test_logging.py index e5b85f35693..d213a68d7f2 100644 --- a/tests/util/test_logging.py +++ b/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()