Log go2rtc output with warning level on error (#129882)

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

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
+    # Verify go2rtc binary stdout was logged with debug level
-    for entry in server_stdout:
+    assert_server_output_logged(server_stdout, caplog, logging.DEBUG)
-        assert (
-            "homeassistant.components.go2rtc.server",
-            logging.DEBUG,
-            entry,
-        ) in caplog.record_tuples
 
     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
+    # Verify go2rtc binary stdout was logged with debug and warning level
-    for entry in server_stdout:
+    assert_server_output_logged(server_stdout, caplog, logging.DEBUG)
-        assert (
+    assert_server_output_logged(server_stdout, caplog, logging.WARNING)
-            "homeassistant.components.go2rtc.server",
-            logging.DEBUG,
-            entry,
-        ) in caplog.record_tuples
 
     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()