Allow higher threshold for loggers during startup

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

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