From b8b7c23258eb1c8c80cde2d161e0e6261dfa96e5 Mon Sep 17 00:00:00 2001 From: Erik Montnemery Date: Tue, 2 Jul 2024 15:48:35 +0200 Subject: [PATCH] Create log files in an executor thread (#120912) --- homeassistant/bootstrap.py | 59 +++++++++++++++++++++----------------- tests/test_bootstrap.py | 28 +++++++++--------- 2 files changed, 47 insertions(+), 40 deletions(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index 8435fe73d40..c5229634053 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -8,7 +8,7 @@ import contextlib from functools import partial from itertools import chain import logging -import logging.handlers +from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler import mimetypes from operator import contains, itemgetter import os @@ -257,12 +257,12 @@ async def async_setup_hass( ) -> core.HomeAssistant | None: """Set up Home Assistant.""" - def create_hass() -> core.HomeAssistant: + async def create_hass() -> core.HomeAssistant: """Create the hass object and do basic setup.""" hass = core.HomeAssistant(runtime_config.config_dir) loader.async_setup(hass) - async_enable_logging( + await async_enable_logging( hass, runtime_config.verbose, runtime_config.log_rotate_days, @@ -287,7 +287,7 @@ async def async_setup_hass( async with hass.timeout.async_timeout(10): await hass.async_stop() - hass = create_hass() + hass = await create_hass() if runtime_config.skip_pip or runtime_config.skip_pip_packages: _LOGGER.warning( @@ -326,13 +326,13 @@ async def async_setup_hass( if config_dict is None: recovery_mode = True await stop_hass(hass) - hass = create_hass() + hass = await create_hass() elif not basic_setup_success: _LOGGER.warning("Unable to set up core integrations. Activating recovery mode") recovery_mode = True await stop_hass(hass) - hass = create_hass() + hass = await create_hass() elif any(domain not in hass.config.components for domain in CRITICAL_INTEGRATIONS): _LOGGER.warning( @@ -345,7 +345,7 @@ async def async_setup_hass( recovery_mode = True await stop_hass(hass) - hass = create_hass() + hass = await create_hass() if old_logging: hass.data[DATA_LOGGING] = old_logging @@ -523,8 +523,7 @@ async def async_from_config_dict( return hass -@core.callback -def async_enable_logging( +async def async_enable_logging( hass: core.HomeAssistant, verbose: bool = False, log_rotate_days: int | None = None, @@ -607,23 +606,9 @@ def async_enable_logging( if (err_path_exists and os.access(err_log_path, os.W_OK)) or ( not err_path_exists and os.access(err_dir, os.W_OK) ): - err_handler: ( - logging.handlers.RotatingFileHandler - | logging.handlers.TimedRotatingFileHandler + err_handler = await hass.async_add_executor_job( + _create_log_file, err_log_path, log_rotate_days ) - if log_rotate_days: - err_handler = logging.handlers.TimedRotatingFileHandler( - err_log_path, when="midnight", backupCount=log_rotate_days - ) - else: - err_handler = _RotatingFileHandlerWithoutShouldRollOver( - err_log_path, backupCount=1 - ) - - try: - err_handler.doRollover() - except OSError as err: - _LOGGER.error("Error rolling over log file: %s", err) err_handler.setLevel(logging.INFO if verbose else logging.WARNING) err_handler.setFormatter(logging.Formatter(fmt, datefmt=FORMAT_DATETIME)) @@ -640,7 +625,29 @@ def async_enable_logging( async_activate_log_queue_handler(hass) -class _RotatingFileHandlerWithoutShouldRollOver(logging.handlers.RotatingFileHandler): +def _create_log_file( + err_log_path: str, log_rotate_days: int | None +) -> RotatingFileHandler | TimedRotatingFileHandler: + """Create log file and do roll over.""" + err_handler: RotatingFileHandler | TimedRotatingFileHandler + if log_rotate_days: + err_handler = TimedRotatingFileHandler( + err_log_path, when="midnight", backupCount=log_rotate_days + ) + else: + err_handler = _RotatingFileHandlerWithoutShouldRollOver( + err_log_path, backupCount=1 + ) + + try: + err_handler.doRollover() + except OSError as err: + _LOGGER.error("Error rolling over log file: %s", err) + + return err_handler + + +class _RotatingFileHandlerWithoutShouldRollOver(RotatingFileHandler): """RotatingFileHandler that does not check if it should roll over on every log.""" def shouldRollover(self, record: logging.LogRecord) -> bool: diff --git a/tests/test_bootstrap.py b/tests/test_bootstrap.py index 7f3793e99e2..7bb5624d112 100644 --- a/tests/test_bootstrap.py +++ b/tests/test_bootstrap.py @@ -69,7 +69,7 @@ def mock_http_start_stop() -> Generator[None]: yield -@patch("homeassistant.bootstrap.async_enable_logging", Mock()) +@patch("homeassistant.bootstrap.async_enable_logging", AsyncMock()) async def test_home_assistant_core_config_validation(hass: HomeAssistant) -> None: """Test if we pass in wrong information for HA conf.""" # Extensive HA conf validation testing is done @@ -93,10 +93,10 @@ async def test_async_enable_logging( side_effect=OSError, ), ): - bootstrap.async_enable_logging(hass) + await bootstrap.async_enable_logging(hass) mock_async_activate_log_queue_handler.assert_called_once() mock_async_activate_log_queue_handler.reset_mock() - bootstrap.async_enable_logging( + await bootstrap.async_enable_logging( hass, log_rotate_days=5, log_file="test.log", @@ -140,7 +140,7 @@ async def test_config_does_not_turn_off_debug(hass: HomeAssistant) -> None: @pytest.mark.parametrize("hass_config", [{"frontend": {}}]) @pytest.mark.usefixtures("mock_hass_config") async def test_asyncio_debug_on_turns_hass_debug_on( - mock_enable_logging: Mock, + mock_enable_logging: AsyncMock, mock_is_virtual_env: Mock, mock_mount_local_lib_path: AsyncMock, mock_ensure_config_exists: AsyncMock, @@ -597,7 +597,7 @@ def mock_is_virtual_env() -> Generator[Mock]: @pytest.fixture -def mock_enable_logging() -> Generator[Mock]: +def mock_enable_logging() -> Generator[AsyncMock]: """Mock enable logging.""" with patch("homeassistant.bootstrap.async_enable_logging") as enable_logging: yield enable_logging @@ -633,7 +633,7 @@ def mock_ensure_config_exists() -> Generator[AsyncMock]: @pytest.mark.parametrize("hass_config", [{"browser": {}, "frontend": {}}]) @pytest.mark.usefixtures("mock_hass_config") async def test_setup_hass( - mock_enable_logging: Mock, + mock_enable_logging: AsyncMock, mock_is_virtual_env: Mock, mock_mount_local_lib_path: AsyncMock, mock_ensure_config_exists: AsyncMock, @@ -686,7 +686,7 @@ async def test_setup_hass( @pytest.mark.parametrize("hass_config", [{"browser": {}, "frontend": {}}]) @pytest.mark.usefixtures("mock_hass_config") async def test_setup_hass_takes_longer_than_log_slow_startup( - mock_enable_logging: Mock, + mock_enable_logging: AsyncMock, mock_is_virtual_env: Mock, mock_mount_local_lib_path: AsyncMock, mock_ensure_config_exists: AsyncMock, @@ -727,7 +727,7 @@ async def test_setup_hass_takes_longer_than_log_slow_startup( async def test_setup_hass_invalid_yaml( - mock_enable_logging: Mock, + mock_enable_logging: AsyncMock, mock_is_virtual_env: Mock, mock_mount_local_lib_path: AsyncMock, mock_ensure_config_exists: AsyncMock, @@ -754,7 +754,7 @@ async def test_setup_hass_invalid_yaml( async def test_setup_hass_config_dir_nonexistent( - mock_enable_logging: Mock, + mock_enable_logging: AsyncMock, mock_is_virtual_env: Mock, mock_mount_local_lib_path: AsyncMock, mock_ensure_config_exists: AsyncMock, @@ -780,7 +780,7 @@ async def test_setup_hass_config_dir_nonexistent( async def test_setup_hass_recovery_mode( - mock_enable_logging: Mock, + mock_enable_logging: AsyncMock, mock_is_virtual_env: Mock, mock_mount_local_lib_path: AsyncMock, mock_ensure_config_exists: AsyncMock, @@ -816,7 +816,7 @@ async def test_setup_hass_recovery_mode( @pytest.mark.usefixtures("mock_hass_config") async def test_setup_hass_safe_mode( - mock_enable_logging: Mock, + mock_enable_logging: AsyncMock, mock_is_virtual_env: Mock, mock_mount_local_lib_path: AsyncMock, mock_ensure_config_exists: AsyncMock, @@ -851,7 +851,7 @@ async def test_setup_hass_safe_mode( @pytest.mark.usefixtures("mock_hass_config") async def test_setup_hass_recovery_mode_and_safe_mode( - mock_enable_logging: Mock, + mock_enable_logging: AsyncMock, mock_is_virtual_env: Mock, mock_mount_local_lib_path: AsyncMock, mock_ensure_config_exists: AsyncMock, @@ -887,7 +887,7 @@ async def test_setup_hass_recovery_mode_and_safe_mode( @pytest.mark.parametrize("hass_config", [{"homeassistant": {"non-existing": 1}}]) @pytest.mark.usefixtures("mock_hass_config") async def test_setup_hass_invalid_core_config( - mock_enable_logging: Mock, + mock_enable_logging: AsyncMock, mock_is_virtual_env: Mock, mock_mount_local_lib_path: AsyncMock, mock_ensure_config_exists: AsyncMock, @@ -926,7 +926,7 @@ async def test_setup_hass_invalid_core_config( ) @pytest.mark.usefixtures("mock_hass_config") async def test_setup_recovery_mode_if_no_frontend( - mock_enable_logging: Mock, + mock_enable_logging: AsyncMock, mock_is_virtual_env: Mock, mock_mount_local_lib_path: AsyncMock, mock_ensure_config_exists: AsyncMock,