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

pull/129887/head
Erik Montnemery 2024-11-05 14:05:04 +01:00 committed by GitHub
parent 4c86102daf
commit 3a667bce8c
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
2 changed files with 88 additions and 14 deletions

View File

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

View File

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