Add endpoint for complete logs of the latest container startup (#6163)

* Add endpoint for complete logs of the latest container startup

Add endpoint that returns complete logs of the latest startup of
container, which can be used for downloading Core logs in the frontend.

Realtime filtering header is used for the Journal API and StartedAt
parameter from the Docker API is used as the reference point. This means
that any other Range header is ignored for this parameter, yet the
"lines" query argument can be used to limit the number of lines. By
default "infinite" number of lines is returned.

Closes #6147

* Implement fallback for latest logs for OS older than 16.0

Implement fallback which uses the internal CONTAINER_LOG_EPOCH metadata
added to logs created by the Docker logger. Still prefer the time-based
method, as it has lower overhead and using public APIs.

* Address review comments

* Only use CONTAINER_LOG_EPOCH for latest logs

As pointed out in the review comments, we might not be able to get the
StartedAt for add-ons that are not running. Thus we need to use the only
reliable mechanism available now, which is the container log epoch.

* Remove dead code for 'Range: realtime' header handling

supervisor/api/__init__.py

@@ -146,6 +146,14 @@ class RestAPI(CoreSysAttributes):
                         follow=True,
                     ),
                 ),
+                web.get(
+                    f"{path}/logs/latest",
+                    partial(
+                        self._api_host.advanced_logs,
+                        identifier=syslog_identifier,
+                        latest=True,
+                    ),
+                ),
                 web.get(
                     f"{path}/logs/boots/{{bootid}}",
                     partial(self._api_host.advanced_logs, identifier=syslog_identifier),
@@ -440,6 +448,7 @@ class RestAPI(CoreSysAttributes):
                     # is known and reported to the user using the resolution center.
                     await async_capture_exception(err)
                 kwargs.pop("follow", None)  # Follow is not supported for Docker logs
+                kwargs.pop("latest", None)  # Latest is not supported for Docker logs
                 return await api_supervisor.logs(*args, **kwargs)
 
         self.webapp.add_routes(
@@ -449,6 +458,10 @@ class RestAPI(CoreSysAttributes):
                     "/supervisor/logs/follow",
                     partial(get_supervisor_logs, follow=True),
                 ),
+                web.get(
+                    "/supervisor/logs/latest",
+                    partial(get_supervisor_logs, latest=True),
+                ),
                 web.get("/supervisor/logs/boots/{bootid}", get_supervisor_logs),
                 web.get(
                     "/supervisor/logs/boots/{bootid}/follow",
@@ -561,6 +574,10 @@ class RestAPI(CoreSysAttributes):
                     "/addons/{addon}/logs/follow",
                     partial(get_addon_logs, follow=True),
                 ),
+                web.get(
+                    "/addons/{addon}/logs/latest",
+                    partial(get_addon_logs, latest=True),
+                ),
                 web.get("/addons/{addon}/logs/boots/{bootid}", get_addon_logs),
                 web.get(
                     "/addons/{addon}/logs/boots/{bootid}/follow",

supervisor/api/host.py

@@ -2,10 +2,17 @@
 
 import asyncio
 from contextlib import suppress
+import json
 import logging
 from typing import Any
 
-from aiohttp import ClientConnectionResetError, ClientPayloadError, web
+from aiohttp import (
+    ClientConnectionResetError,
+    ClientError,
+    ClientPayloadError,
+    ClientTimeout,
+    web,
+)
 from aiohttp.hdrs import ACCEPT, RANGE
 import voluptuous as vol
 from voluptuous.error import CoerceInvalid
@@ -194,7 +201,11 @@ class APIHost(CoreSysAttributes):
         return possible_offset
 
     async def advanced_logs_handler(
-        self, request: web.Request, identifier: str | None = None, follow: bool = False
+        self,
+        request: web.Request,
+        identifier: str | None = None,
+        follow: bool = False,
+        latest: bool = False,
     ) -> web.StreamResponse:
         """Return systemd-journald logs."""
         log_formatter = LogFormatter.PLAIN
@@ -213,6 +224,20 @@ class APIHost(CoreSysAttributes):
         if follow:
             params[PARAM_FOLLOW] = ""
 
+        if latest:
+            if not identifier:
+                raise APIError(
+                    "Latest logs can only be fetched for a specific identifier."
+                )
+
+            try:
+                epoch = await self._get_container_last_epoch(identifier)
+                params["CONTAINER_LOG_EPOCH"] = epoch
+            except HostLogError as err:
+                raise APIError(
+                    f"Cannot determine CONTAINER_LOG_EPOCH of {identifier}, latest logs not available."
+                ) from err
+
         if ACCEPT in request.headers and request.headers[ACCEPT] not in [
             CONTENT_TYPE_TEXT,
             CONTENT_TYPE_X_LOG,
@@ -241,6 +266,8 @@ class APIHost(CoreSysAttributes):
                 lines = max(2, lines)
             # entries=cursor[[:num_skip]:num_entries]
             range_header = f"entries=:-{lines - 1}:{SYSTEMD_JOURNAL_GATEWAYD_LINES_MAX if follow else lines}"
+        elif latest:
+            range_header = f"entries=0:{SYSTEMD_JOURNAL_GATEWAYD_LINES_MAX}"
         elif RANGE in request.headers:
             range_header = request.headers[RANGE]
         else:
@@ -286,10 +313,14 @@ class APIHost(CoreSysAttributes):
 
     @api_process_raw(CONTENT_TYPE_TEXT, error_type=CONTENT_TYPE_TEXT)
     async def advanced_logs(
-        self, request: web.Request, identifier: str | None = None, follow: bool = False
+        self,
+        request: web.Request,
+        identifier: str | None = None,
+        follow: bool = False,
+        latest: bool = False,
     ) -> web.StreamResponse:
         """Return systemd-journald logs. Wrapped as standard API handler."""
-        return await self.advanced_logs_handler(request, identifier, follow)
+        return await self.advanced_logs_handler(request, identifier, follow, latest)
 
     @api_process
     async def disk_usage(self, request: web.Request) -> dict:
@@ -336,3 +367,27 @@ class APIHost(CoreSysAttributes):
                 *known_paths,
             ],
         }
+
+    async def _get_container_last_epoch(self, identifier: str) -> str | None:
+        """Get Docker's internal log epoch of the latest log entry for the given identifier."""
+        try:
+            async with self.sys_host.logs.journald_logs(
+                params={"CONTAINER_NAME": identifier},
+                range_header="entries=:-1:2",  # -1 = next to the last entry
+                accept=LogFormat.JSON,
+                timeout=ClientTimeout(total=10),
+            ) as resp:
+                text = await resp.text()
+        except (ClientError, TimeoutError) as err:
+            raise HostLogError(
+                "Could not get last container epoch from systemd-journal-gatewayd",
+                _LOGGER.error,
+            ) from err
+
+        try:
+            return json.loads(text.strip().split("\n")[-1])["CONTAINER_LOG_EPOCH"]
+        except (json.JSONDecodeError, KeyError, IndexError) as err:
+            raise HostLogError(
+                f"Failed to parse CONTAINER_LOG_EPOCH of {identifier} container, got: {text}",
+                _LOGGER.error,
+            ) from err

tests/api/__init__.py

@@ -1,9 +1,10 @@
 """Test for API calls."""
 
-from unittest.mock import MagicMock
+from unittest.mock import AsyncMock, MagicMock
 
 from aiohttp.test_utils import TestClient
 
+from supervisor.coresys import CoreSys
 from supervisor.host.const import LogFormat
 
 DEFAULT_LOG_RANGE = "entries=:-99:100"
@@ -15,6 +16,8 @@ async def common_test_api_advanced_logs(
     syslog_identifier: str,
     api_client: TestClient,
     journald_logs: MagicMock,
+    coresys: CoreSys,
+    os_available: None,
 ):
     """Template for tests of endpoints using advanced logs."""
     resp = await api_client.get(f"{path_prefix}/logs")
@@ -41,6 +44,30 @@ async def common_test_api_advanced_logs(
 
     journald_logs.reset_mock()
 
+    mock_response = MagicMock()
+    mock_response.text = AsyncMock(
+        return_value='{"CONTAINER_LOG_EPOCH": "12345"}\n{"CONTAINER_LOG_EPOCH": "12345"}\n'
+    )
+    journald_logs.return_value.__aenter__.return_value = mock_response
+
+    resp = await api_client.get(f"{path_prefix}/logs/latest")
+    assert resp.status == 200
+
+    assert journald_logs.call_count == 2
+
+    # Check the first call for getting epoch
+    epoch_call = journald_logs.call_args_list[0]
+    assert epoch_call[1]["params"] == {"CONTAINER_NAME": syslog_identifier}
+    assert epoch_call[1]["range_header"] == "entries=:-1:2"
+
+    # Check the second call for getting logs with the epoch
+    logs_call = journald_logs.call_args_list[1]
+    assert logs_call[1]["params"]["SYSLOG_IDENTIFIER"] == syslog_identifier
+    assert logs_call[1]["params"]["CONTAINER_LOG_EPOCH"] == "12345"
+    assert logs_call[1]["range_header"] == "entries=0:18446744073709551615"
+
+    journald_logs.reset_mock()
+
     resp = await api_client.get(f"{path_prefix}/logs/boots/0")
     assert resp.status == 200
     assert resp.content_type == "text/plain"

tests/api/test_addons.py

@@ -72,11 +72,20 @@ async def test_addons_info_not_installed(
 
 
 async def test_api_addon_logs(
-    api_client: TestClient, journald_logs: MagicMock, install_addon_ssh: Addon
+    api_client: TestClient,
+    journald_logs: MagicMock,
+    coresys: CoreSys,
+    os_available,
+    install_addon_ssh: Addon,
 ):
     """Test addon logs."""
     await common_test_api_advanced_logs(
-        "/addons/local_ssh", "addon_local_ssh", api_client, journald_logs
+        "/addons/local_ssh",
+        "addon_local_ssh",
+        api_client,
+        journald_logs,
+        coresys,
+        os_available,
     )
 
 

tests/api/test_audio.py

@@ -4,11 +4,15 @@ from unittest.mock import MagicMock
 
 from aiohttp.test_utils import TestClient
 
+from supervisor.coresys import CoreSys
+
 from tests.api import common_test_api_advanced_logs
 
 
-async def test_api_audio_logs(api_client: TestClient, journald_logs: MagicMock):
+async def test_api_audio_logs(
+    api_client: TestClient, journald_logs: MagicMock, coresys: CoreSys, os_available
+):
     """Test audio logs."""
     await common_test_api_advanced_logs(
-        "/audio", "hassio_audio", api_client, journald_logs
+        "/audio", "hassio_audio", api_client, journald_logs, coresys, os_available
     )

tests/api/test_dns.py

@@ -66,6 +66,15 @@ async def test_options(api_client: TestClient, coresys: CoreSys):
         restart.assert_called_once()
 
 
-async def test_api_dns_logs(api_client: TestClient, journald_logs: MagicMock):
+async def test_api_dns_logs(
+    api_client: TestClient, journald_logs: MagicMock, coresys: CoreSys, os_available
+):
     """Test dns logs."""
-    await common_test_api_advanced_logs("/dns", "hassio_dns", api_client, journald_logs)
+    await common_test_api_advanced_logs(
+        "/dns",
+        "hassio_dns",
+        api_client,
+        journald_logs,
+        coresys,
+        os_available,
+    )

tests/api/test_homeassistant.py

@@ -21,7 +21,11 @@ from tests.common import load_json_fixture
 
 @pytest.mark.parametrize("legacy_route", [True, False])
 async def test_api_core_logs(
-    api_client: TestClient, journald_logs: MagicMock, legacy_route: bool
+    api_client: TestClient,
+    journald_logs: MagicMock,
+    coresys: CoreSys,
+    os_available,
+    legacy_route: bool,
 ):
     """Test core logs."""
     await common_test_api_advanced_logs(
@@ -29,6 +33,8 @@ async def test_api_core_logs(
         "homeassistant",
         api_client,
         journald_logs,
+        coresys,
+        os_available,
     )
 
 

tests/api/test_host.py

@@ -243,6 +243,10 @@ async def test_advanced_logs(
         accept=LogFormat.JOURNAL,
     )
 
+    # Host logs don't have a /latest endpoint
+    resp = await api_client.get("/host/logs/latest")
+    assert resp.status == 404
+
 
 async def test_advaced_logs_query_parameters(
     api_client: TestClient,

tests/api/test_multicast.py

@@ -4,11 +4,20 @@ from unittest.mock import MagicMock
 
 from aiohttp.test_utils import TestClient
 
+from supervisor.coresys import CoreSys
+
 from tests.api import common_test_api_advanced_logs
 
 
-async def test_api_multicast_logs(api_client: TestClient, journald_logs: MagicMock):
+async def test_api_multicast_logs(
+    api_client: TestClient, journald_logs: MagicMock, coresys: CoreSys, os_available
+):
     """Test multicast logs."""
     await common_test_api_advanced_logs(
-        "/multicast", "hassio_multicast", api_client, journald_logs
+        "/multicast",
+        "hassio_multicast",
+        api_client,
+        journald_logs,
+        coresys,
+        os_available,
     )

tests/api/test_supervisor.py

@@ -148,10 +148,17 @@ async def test_api_supervisor_options_diagnostics(
     assert coresys.dbus.agent.diagnostics is False
 
 
-async def test_api_supervisor_logs(api_client: TestClient, journald_logs: MagicMock):
+async def test_api_supervisor_logs(
+    api_client: TestClient, journald_logs: MagicMock, coresys: CoreSys, os_available
+):
     """Test supervisor logs."""
     await common_test_api_advanced_logs(
-        "/supervisor", "hassio_supervisor", api_client, journald_logs
+        "/supervisor",
+        "hassio_supervisor",
+        api_client,
+        journald_logs,
+        coresys,
+        os_available,
     )
 
 
@@ -175,7 +182,7 @@ async def test_api_supervisor_fallback(
         b"\x1b[36m22-10-11 14:04:23 DEBUG (MainThread) [supervisor.utils.dbus] D-Bus call - org.freedesktop.DBus.Properties.call_get_all on /io/hass/os/AppArmor\x1b[0m",
     ]
 
-    # check fallback also works for the follow endpoint (no mock reset needed)
+    # check fallback also works for the /follow endpoint (no mock reset needed)
 
     with patch("supervisor.api._LOGGER.exception") as logger:
         resp = await api_client.get("/supervisor/logs/follow")
@@ -186,7 +193,16 @@ async def test_api_supervisor_fallback(
     assert resp.status == 200
     assert resp.content_type == "text/plain"
 
-    journald_logs.reset_mock()
+    # check the /latest endpoint as well
+
+    with patch("supervisor.api._LOGGER.exception") as logger:
+        resp = await api_client.get("/supervisor/logs/latest")
+        logger.assert_called_once_with(
+            "Failed to get supervisor logs using advanced_logs API"
+        )
+
+    assert resp.status == 200
+    assert resp.content_type == "text/plain"
 
     # also check generic Python error
     journald_logs.side_effect = OSError("Something bad happened!")

tests/conftest.py

@@ -804,7 +804,7 @@ async def os_available(request: pytest.FixtureRequest) -> None:
     version = (
         AwesomeVersion(request.param)
         if hasattr(request, "param")
-        else AwesomeVersion("10.2")
+        else AwesomeVersion("16.2")
     )
     with (
         patch.object(OSManager, "available", new=PropertyMock(return_value=True)),