From 3a667bce8cb33dc609c4affa51acc87e26b351c1 Mon Sep 17 00:00:00 2001 From: Erik Montnemery Date: Tue, 5 Nov 2024 14:05:04 +0100 Subject: [PATCH] Log go2rtc output with warning level on error (#129882) --- homeassistant/components/go2rtc/server.py | 13 ++++ tests/components/go2rtc/test_server.py | 89 +++++++++++++++++++---- 2 files changed, 88 insertions(+), 14 deletions(-) diff --git a/homeassistant/components/go2rtc/server.py b/homeassistant/components/go2rtc/server.py index 6384cc5d49b..9be02d9a5d6 100644 --- a/homeassistant/components/go2rtc/server.py +++ b/homeassistant/components/go2rtc/server.py @@ -1,6 +1,7 @@ """Go2rtc server.""" import asyncio +from collections import deque from contextlib import suppress import logging from tempfile import NamedTemporaryFile @@ -18,6 +19,7 @@ _TERMINATE_TIMEOUT = 5 _SETUP_TIMEOUT = 30 _SUCCESSFUL_BOOT_MESSAGE = "INF [api] listen addr=" _LOCALHOST_IP = "127.0.0.1" +_LOG_BUFFER_SIZE = 512 _RESPAWN_COOLDOWN = 1 # Default configuration for HA @@ -70,6 +72,7 @@ class Server: """Initialize the server.""" self._hass = hass self._binary = binary + self._log_buffer: deque[str] = deque(maxlen=_LOG_BUFFER_SIZE) self._process: asyncio.subprocess.Process | None = None self._startup_complete = asyncio.Event() self._api_ip = _LOCALHOST_IP @@ -114,6 +117,7 @@ class Server: except TimeoutError as err: msg = "Go2rtc server didn't start correctly" _LOGGER.exception(msg) + self._log_server_output(logging.WARNING) await self._stop() raise Go2RTCServerStartError from err @@ -127,10 +131,17 @@ class Server: async for line in process.stdout: msg = line[:-1].decode().strip() + self._log_buffer.append(msg) _LOGGER.debug(msg) if not self._startup_complete.is_set() and _SUCCESSFUL_BOOT_MESSAGE in msg: self._startup_complete.set() + def _log_server_output(self, loglevel: int) -> None: + """Log captured process output, then clear the log buffer.""" + for line in list(self._log_buffer): # Copy the deque to avoid mutation error + _LOGGER.log(loglevel, line) + self._log_buffer.clear() + async def _watchdog(self) -> None: """Keep respawning go2rtc servers. @@ -158,6 +169,8 @@ class Server: await asyncio.sleep(_RESPAWN_COOLDOWN) try: await self._stop() + _LOGGER.warning("Go2rtc unexpectedly stopped, server log:") + self._log_server_output(logging.WARNING) _LOGGER.debug("Spawning new go2rtc server") with suppress(Go2RTCServerStartError): await self._start() diff --git a/tests/components/go2rtc/test_server.py b/tests/components/go2rtc/test_server.py index 5b430d66641..cda05fc4f2b 100644 --- a/tests/components/go2rtc/test_server.py +++ b/tests/components/go2rtc/test_server.py @@ -38,6 +38,42 @@ def mock_tempfile() -> Generator[Mock]: yield file +def _assert_server_output_logged( + server_stdout: list[str], + caplog: pytest.LogCaptureFixture, + loglevel: int, + expect_logged: bool, +) -> None: + """Check server stdout was logged.""" + for entry in server_stdout: + assert ( + ( + "homeassistant.components.go2rtc.server", + loglevel, + entry, + ) + in caplog.record_tuples + ) is expect_logged + + +def assert_server_output_logged( + server_stdout: list[str], + caplog: pytest.LogCaptureFixture, + loglevel: int, +) -> None: + """Check server stdout was logged.""" + _assert_server_output_logged(server_stdout, caplog, loglevel, True) + + +def assert_server_output_not_logged( + server_stdout: list[str], + caplog: pytest.LogCaptureFixture, + loglevel: int, +) -> None: + """Check server stdout was logged.""" + _assert_server_output_logged(server_stdout, caplog, loglevel, False) + + @pytest.mark.parametrize( ("enable_ui", "api_ip"), [ @@ -83,17 +119,15 @@ webrtc: """.encode() ) - # Check that server read the log lines - for entry in server_stdout: - assert ( - "homeassistant.components.go2rtc.server", - logging.DEBUG, - entry, - ) in caplog.record_tuples + # Verify go2rtc binary stdout was logged with debug level + assert_server_output_logged(server_stdout, caplog, logging.DEBUG) await server.stop() mock_create_subprocess.return_value.terminate.assert_called_once() + # Verify go2rtc binary stdout was not logged with warning level + assert_server_output_not_logged(server_stdout, caplog, logging.WARNING) + @pytest.mark.usefixtures("mock_tempfile") async def test_server_timeout_on_stop( @@ -140,13 +174,9 @@ async def test_server_failed_to_start( ): await server.start() - # Verify go2rtc binary stdout was logged - for entry in server_stdout: - assert ( - "homeassistant.components.go2rtc.server", - logging.DEBUG, - entry, - ) in caplog.record_tuples + # Verify go2rtc binary stdout was logged with debug and warning level + assert_server_output_logged(server_stdout, caplog, logging.DEBUG) + assert_server_output_logged(server_stdout, caplog, logging.WARNING) assert ( "homeassistant.components.go2rtc.server", @@ -169,8 +199,10 @@ async def test_server_failed_to_start( async def test_server_restart_process_exit( hass: HomeAssistant, mock_create_subprocess: AsyncMock, + server_stdout: list[str], rest_client: AsyncMock, server: Server, + caplog: pytest.LogCaptureFixture, ) -> None: """Test that the server is restarted when it exits.""" evt = asyncio.Event() @@ -188,10 +220,16 @@ async def test_server_restart_process_exit( await hass.async_block_till_done() mock_create_subprocess.assert_not_awaited() + # Verify go2rtc binary stdout was not yet logged with warning level + assert_server_output_not_logged(server_stdout, caplog, logging.WARNING) + evt.set() await asyncio.sleep(0.1) mock_create_subprocess.assert_awaited_once() + # Verify go2rtc binary stdout was logged with warning level + assert_server_output_logged(server_stdout, caplog, logging.WARNING) + await server.stop() @@ -199,8 +237,10 @@ async def test_server_restart_process_exit( async def test_server_restart_process_error( hass: HomeAssistant, mock_create_subprocess: AsyncMock, + server_stdout: list[str], rest_client: AsyncMock, server: Server, + caplog: pytest.LogCaptureFixture, ) -> None: """Test that the server is restarted on error.""" mock_create_subprocess.return_value.wait.side_effect = [Exception, None, None, None] @@ -209,10 +249,16 @@ async def test_server_restart_process_error( mock_create_subprocess.assert_awaited_once() mock_create_subprocess.reset_mock() + # Verify go2rtc binary stdout was not yet logged with warning level + assert_server_output_not_logged(server_stdout, caplog, logging.WARNING) + await asyncio.sleep(0.1) await hass.async_block_till_done() mock_create_subprocess.assert_awaited_once() + # Verify go2rtc binary stdout was logged with warning level + assert_server_output_logged(server_stdout, caplog, logging.WARNING) + await server.stop() @@ -220,8 +266,10 @@ async def test_server_restart_process_error( async def test_server_restart_api_error( hass: HomeAssistant, mock_create_subprocess: AsyncMock, + server_stdout: list[str], rest_client: AsyncMock, server: Server, + caplog: pytest.LogCaptureFixture, ) -> None: """Test that the server is restarted on error.""" rest_client.streams.list.side_effect = Exception @@ -230,10 +278,16 @@ async def test_server_restart_api_error( mock_create_subprocess.assert_awaited_once() mock_create_subprocess.reset_mock() + # Verify go2rtc binary stdout was not yet logged with warning level + assert_server_output_not_logged(server_stdout, caplog, logging.WARNING) + await asyncio.sleep(0.1) await hass.async_block_till_done() mock_create_subprocess.assert_awaited_once() + # Verify go2rtc binary stdout was logged with warning level + assert_server_output_logged(server_stdout, caplog, logging.WARNING) + await server.stop() @@ -241,6 +295,7 @@ async def test_server_restart_api_error( async def test_server_restart_error( hass: HomeAssistant, mock_create_subprocess: AsyncMock, + server_stdout: list[str], rest_client: AsyncMock, server: Server, caplog: pytest.LogCaptureFixture, @@ -253,10 +308,16 @@ async def test_server_restart_error( mock_create_subprocess.assert_awaited_once() mock_create_subprocess.reset_mock() + # Verify go2rtc binary stdout was not yet logged with warning level + assert_server_output_not_logged(server_stdout, caplog, logging.WARNING) + await asyncio.sleep(0.1) await hass.async_block_till_done() mock_create_subprocess.assert_awaited_once() + # Verify go2rtc binary stdout was logged with warning level + assert_server_output_logged(server_stdout, caplog, logging.WARNING) + assert "Unexpected error when restarting go2rtc server" in caplog.text await server.stop()