diff --git a/homeassistant/util/logging.py b/homeassistant/util/logging.py index 1e516742bfe..26f5298f936 100644 --- a/homeassistant/util/logging.py +++ b/homeassistant/util/logging.py @@ -13,7 +13,9 @@ import time import traceback from typing import Any, cast, overload, override +from homeassistant.const import EVENT_HOMEASSISTANT_STARTED from homeassistant.core import ( + Event, HassJobType, HomeAssistant, callback, @@ -27,6 +29,7 @@ class HomeAssistantQueueListener(logging.handlers.QueueListener): """Custom QueueListener to watch for noisy loggers.""" LOG_COUNTS_RESET_INTERVAL = 300 + MAX_LOGS_COUNT_HA_STARTING = 500 MAX_LOGS_COUNT = 200 _last_reset: float @@ -39,6 +42,7 @@ class HomeAssistantQueueListener(logging.handlers.QueueListener): """Initialize the handler.""" super().__init__(queue, *handlers) self._warned_modules = set() + self._max_logs_count = self.MAX_LOGS_COUNT_HA_STARTING self._reset_counters(time.time()) @override @@ -58,7 +62,7 @@ class HomeAssistantQueueListener(logging.handlers.QueueListener): self._log_counts[module_name] += 1 module_count = self._log_counts[module_name] - if module_count < self.MAX_LOGS_COUNT: + if module_count < self._max_logs_count: return _LOGGER.warning( @@ -68,6 +72,11 @@ class HomeAssistantQueueListener(logging.handlers.QueueListener): ) self._warned_modules.add(module_name) + def use_default_max_logs_count(self) -> None: + """Use the default max logs count.""" + self._reset_counters(time.time()) + self._max_logs_count = self.MAX_LOGS_COUNT + def _reset_counters(self, time_sec: float) -> None: _LOGGER.debug("Resetting log counters") self._last_reset = time_sec @@ -129,6 +138,13 @@ def async_activate_log_queue_handler(hass: HomeAssistant) -> None: listener = HomeAssistantQueueListener(simple_queue, *migrated_handlers) queue_handler.listener = listener + @callback + def on_hass_started(event: Event) -> None: + """Switch to normal log count after HA has started.""" + listener.use_default_max_logs_count() + + hass.bus.async_listen_once(EVENT_HOMEASSISTANT_STARTED, on_hass_started) + listener.start() diff --git a/tests/util/test_logging.py b/tests/util/test_logging.py index d213a68d7f2..25dcd35ca46 100644 --- a/tests/util/test_logging.py +++ b/tests/util/test_logging.py @@ -180,6 +180,9 @@ async def test_noisy_loggers( """Test that noisy loggers all logged as warnings.""" logging_util.async_activate_log_queue_handler(hass) + await hass.async_start() + await hass.async_block_till_done() + logger1 = logging.getLogger("noisy1") logger2 = logging.getLogger("noisy2.module") @@ -215,6 +218,9 @@ async def test_noisy_loggers_ignores_lower_than_info( """Test that noisy loggers all logged as warnings, except for levels lower than INFO.""" logging_util.async_activate_log_queue_handler(hass) + await hass.async_start() + await hass.async_block_till_done() + logger = logging.getLogger("noisy_module") for _ in range(5): @@ -246,6 +252,9 @@ async def test_noisy_loggers_counters_reset( """Test that noisy logger counters reset periodically.""" logging_util.async_activate_log_queue_handler(hass) + await hass.async_start() + await hass.async_block_till_done() + logger = logging.getLogger("noisy_module") expected_warning = "Module noisy_module is logging too frequently" @@ -269,3 +278,42 @@ async def test_noisy_loggers_counters_reset( 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", 2) +@patch( + "homeassistant.util.logging.HomeAssistantQueueListener.MAX_LOGS_COUNT_HA_STARTING", + 3, +) +async def test_noisy_loggers_max_while_ha_starting( + hass: HomeAssistant, caplog: pytest.LogCaptureFixture +) -> None: + """Test that the threshold for warning about noisy loggers is higher during HomeAssistant startup.""" + + logging_util.async_activate_log_queue_handler(hass) + + logger_startup = logging.getLogger("startup") + logger_startup.info("This is a log") + logger_startup.info("This is a log") + + await empty_log_queue() + expected_warning = "logging too frequently" + assert caplog.text.count(expected_warning) == 0 + + logger_startup.info("This is a log") + logger_startup.info("This is a log") + await empty_log_queue() + assert caplog.text.count(expected_warning) == 1 + + await hass.async_start() + await hass.async_block_till_done() + + logger = logging.getLogger("noisy_module") + logger.info("This is a log") + logger.info("This is a log") + await empty_log_queue() + expected_warning = "logging too frequently" + assert caplog.text.count(expected_warning) == 2 + + # close the handler so the queue thread stops + logging.root.handlers[0].close()