Go2rtc server start is waiting until we got the api listen stdout line (#129391)

homeassistant/components/go2rtc/server.py

@@ -5,9 +5,12 @@ import logging
 from tempfile import NamedTemporaryFile
 
 from homeassistant.core import HomeAssistant
+from homeassistant.exceptions import HomeAssistantError
 
 _LOGGER = logging.getLogger(__name__)
 _TERMINATE_TIMEOUT = 5
+_SETUP_TIMEOUT = 30
+_SUCCESSFUL_BOOT_MESSAGE = "INF [api] listen addr=127.0.0.1:1984"
 
 # Default configuration for HA
 # - Api is listening only on localhost
@@ -34,14 +37,6 @@ def _create_temp_file() -> str:
         return file.name
 
 
-async def _log_output(process: asyncio.subprocess.Process) -> None:
-    """Log the output of the process."""
-    assert process.stdout is not None
-
-    async for line in process.stdout:
-        _LOGGER.debug(line[:-1].decode().strip())
-
-
 class Server:
     """Go2rtc server."""
 
@@ -50,12 +45,15 @@ class Server:
         self._hass = hass
         self._binary = binary
         self._process: asyncio.subprocess.Process | None = None
+        self._startup_complete = asyncio.Event()
 
     async def start(self) -> None:
         """Start the server."""
         _LOGGER.debug("Starting go2rtc server")
         config_file = await self._hass.async_add_executor_job(_create_temp_file)
 
+        self._startup_complete.clear()
+
         self._process = await asyncio.create_subprocess_exec(
             self._binary,
             "-c",
@@ -66,9 +64,30 @@ class Server:
         )
 
         self._hass.async_create_background_task(
-            _log_output(self._process), "Go2rtc log output"
+            self._log_output(self._process), "Go2rtc log output"
         )
 
+        try:
+            async with asyncio.timeout(_SETUP_TIMEOUT):
+                await self._startup_complete.wait()
+        except TimeoutError as err:
+            msg = "Go2rtc server didn't start correctly"
+            _LOGGER.exception(msg)
+            await self.stop()
+            raise HomeAssistantError("Go2rtc server didn't start correctly") from err
+
+    async def _log_output(self, process: asyncio.subprocess.Process) -> None:
+        """Log the output of the process."""
+        assert process.stdout is not None
+
+        async for line in process.stdout:
+            msg = line[:-1].decode().strip()
+            _LOGGER.debug(msg)
+            if not self._startup_complete.is_set() and msg.endswith(
+                _SUCCESSFUL_BOOT_MESSAGE
+            ):
+                self._startup_complete.set()
+
     async def stop(self) -> None:
         """Stop the server."""
         if self._process:

tests/components/go2rtc/conftest.py

@@ -35,17 +35,39 @@ def ws_client() -> Generator[Mock]:
 
 
 @pytest.fixture
-def server_start() -> Generator[AsyncMock]:
+def server_stdout() -> list[str]:
-    """Mock start of a go2rtc server."""
+    """Server stdout lines."""
-    with (
+    return [
-        patch(f"{GO2RTC_PATH}.server.asyncio.create_subprocess_exec") as mock_subproc,
+        "09:00:03.466 INF go2rtc platform=linux/amd64 revision=780f378 version=1.9.5",
-        patch(
+        "09:00:03.466 INF config path=/tmp/go2rtc.yaml",
-            f"{GO2RTC_PATH}.server.Server.start", wraps=Server.start, autospec=True
+        "09:00:03.467 INF [rtsp] listen addr=:8554",
-        ) as mock_server_start,
+        "09:00:03.467 INF [api] listen addr=127.0.0.1:1984",
-    ):
+        "09:00:03.467 INF [webrtc] listen addr=:8555/tcp",
+    ]
+
+
+@pytest.fixture
+def mock_create_subprocess(server_stdout: list[str]) -> Generator[AsyncMock]:
+    """Mock create_subprocess_exec."""
+    with patch(f"{GO2RTC_PATH}.server.asyncio.create_subprocess_exec") as mock_subproc:
         subproc = AsyncMock()
         subproc.terminate = Mock()
+        subproc.kill = Mock()
+        subproc.returncode = None
+        # Simulate process output
+        subproc.stdout.__aiter__.return_value = iter(
+            [f"{entry}\n".encode() for entry in server_stdout]
+        )
         mock_subproc.return_value = subproc
+        yield mock_subproc
+
+
+@pytest.fixture
+def server_start(mock_create_subprocess: AsyncMock) -> Generator[AsyncMock]:
+    """Mock start of a go2rtc server."""
+    with patch(
+        f"{GO2RTC_PATH}.server.Server.start", wraps=Server.start, autospec=True
+    ) as mock_server_start:
         yield mock_server_start
 
 
@@ -61,7 +83,7 @@ def server_stop() -> Generator[AsyncMock]:
 
 
 @pytest.fixture
-def server(server_start, server_stop) -> Generator[AsyncMock]:
+def server(server_start: AsyncMock, server_stop: AsyncMock) -> Generator[AsyncMock]:
     """Mock a go2rtc server."""
     with patch(f"{GO2RTC_PATH}.Server", wraps=Server) as mock_server:
         yield mock_server

tests/components/go2rtc/test_server.py

@@ -4,12 +4,13 @@ import asyncio
 from collections.abc import Generator
 import logging
 import subprocess
-from unittest.mock import MagicMock, Mock, patch
+from unittest.mock import AsyncMock, MagicMock, Mock, patch
 
 import pytest
 
 from homeassistant.components.go2rtc.server import Server
 from homeassistant.core import HomeAssistant
+from homeassistant.exceptions import HomeAssistantError
 
 TEST_BINARY = "/bin/go2rtc"
 
@@ -31,37 +32,18 @@ def mock_tempfile() -> Generator[Mock]:
         yield file
 
 
-@pytest.fixture
-def mock_process() -> Generator[MagicMock]:
-    """Fixture to mock subprocess.Popen."""
-    with patch(
-        "homeassistant.components.go2rtc.server.asyncio.create_subprocess_exec"
-    ) as mock_popen:
-        mock_popen.return_value.terminate = MagicMock()
-        mock_popen.return_value.kill = MagicMock()
-        mock_popen.return_value.returncode = None
-        yield mock_popen
-
-
 async def test_server_run_success(
-    mock_process: MagicMock,
+    mock_create_subprocess: AsyncMock,
+    server_stdout: list[str],
     server: Server,
     caplog: pytest.LogCaptureFixture,
     mock_tempfile: Mock,
 ) -> None:
     """Test that the server runs successfully."""
-    # Simulate process output
-    mock_process.return_value.stdout.__aiter__.return_value = iter(
-        [
-            b"log line 1\n",
-            b"log line 2\n",
-        ]
-    )
-
     await server.start()
 
     # Check that Popen was called with the right arguments
-    mock_process.assert_called_once_with(
+    mock_create_subprocess.assert_called_once_with(
         TEST_BINARY,
         "-c",
         "test.yaml",
@@ -83,7 +65,7 @@ webrtc:
 """)
 
     # Check that server read the log lines
-    for entry in ("log line 1", "log line 2"):
+    for entry in server_stdout:
         assert (
             "homeassistant.components.go2rtc.server",
             logging.DEBUG,
@@ -91,31 +73,74 @@ webrtc:
         ) in caplog.record_tuples
 
     await server.stop()
-    mock_process.return_value.terminate.assert_called_once()
+    mock_create_subprocess.return_value.terminate.assert_called_once()
 
 
 @pytest.mark.usefixtures("mock_tempfile")
-async def test_server_run_process_timeout(
+async def test_server_timeout_on_stop(
-    mock_process: MagicMock, server: Server
+    mock_create_subprocess: MagicMock, server: Server
 ) -> None:
     """Test server run where the process takes too long to terminate."""
-    mock_process.return_value.stdout.__aiter__.return_value = iter(
+    # Start server thread
-        [
+    await server.start()
-            b"log line 1\n",
-        ]
-    )
 
     async def sleep() -> None:
         await asyncio.sleep(1)
 
     # Simulate timeout
-    mock_process.return_value.wait.side_effect = sleep
+    mock_create_subprocess.return_value.wait.side_effect = sleep
 
     with patch("homeassistant.components.go2rtc.server._TERMINATE_TIMEOUT", new=0.1):
-        # Start server thread
-        await server.start()
         await server.stop()
 
     # Ensure terminate and kill were called due to timeout
-    mock_process.return_value.terminate.assert_called_once()
+    mock_create_subprocess.return_value.terminate.assert_called_once()
-    mock_process.return_value.kill.assert_called_once()
+    mock_create_subprocess.return_value.kill.assert_called_once()
+
+
+@pytest.mark.parametrize(
+    "server_stdout",
+    [
+        [
+            "09:00:03.466 INF go2rtc platform=linux/amd64 revision=780f378 version=1.9.5",
+            "09:00:03.466 INF config path=/tmp/go2rtc.yaml",
+        ]
+    ],
+)
+@pytest.mark.usefixtures("mock_tempfile")
+async def test_server_failed_to_start(
+    mock_create_subprocess: MagicMock,
+    server_stdout: list[str],
+    server: Server,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    """Test server, where an exception is raised if the expected log entry was not received until the timeout."""
+    with (
+        patch("homeassistant.components.go2rtc.server._SETUP_TIMEOUT", new=0.1),
+        pytest.raises(HomeAssistantError, match="Go2rtc server didn't start correctly"),
+    ):
+        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
+
+    assert (
+        "homeassistant.components.go2rtc.server",
+        logging.ERROR,
+        "Go2rtc server didn't start correctly",
+    ) in caplog.record_tuples
+
+    # Check that Popen was called with the right arguments
+    mock_create_subprocess.assert_called_once_with(
+        TEST_BINARY,
+        "-c",
+        "test.yaml",
+        stdout=subprocess.PIPE,
+        stderr=subprocess.STDOUT,
+        close_fds=False,
+    )