Add enhanced logging REST endpoints using systemd-journal-gatewayd (#3291)

* Add enhanced logging REST endpoints using systemd-journal-gatewayd

Add /host/logs/entries and /host/logs/{identifier}/entries to expose log
entries from systemd-journald running on the host. Use
systemd-journal-gatewayd which exposes the logs to the Supervisor via
Unix socket.

Current two query string parameters are allowed: "boot" and "follow".
The first will only return logs since last boot. The second will keep
the HTTP request open and send new log entries as they get added to the
systemd-journal.

* Allow Range header

Forward the Range header to systemd-journal-gatewayd. This allows to
select only a certain amount of log data. The Range header is a standard
header to select only partial amount of data. However, the "entries="
prefix is custom for systemd-journal-gatewayd, denoting that the numbers
following represent log entries (as opposed to bytes or other metrics).

* Avoid connecting if systemd-journal-gatewayd is not available

* Use path for all options

* Add pytests

* Address pylint issues

* Boot ID offsets and slug to identifier

* Fix tests

* API refactor from feedback

* fix tests and add identifiers

* stop isort and pylint fighting

* fix tests

* Update default log identifiers

* Only modify /host/logs endpoints

* Fix bad import

* Load log caches asynchronously at startup

* Allow task to complete in fixture

* Boot IDs and identifiers loaded on demand

* Add suggested identifiers

* Fix tests around boot ids

Co-authored-by: Mike Degatano <michael.degatano@gmail.com>

tests/api/middleware/test_security.py

@@ -1,4 +1,5 @@
 """Test API security layer."""
+from unittest.mock import patch
 
 from aiohttp import web
 import pytest
@@ -15,7 +16,9 @@ async def api_system(aiohttp_client, run_dir, coresys: CoreSys):
     """Fixture for RestAPI client."""
     api = RestAPI(coresys)
     api.webapp = web.Application()
-    await api.load()
+    with patch("supervisor.docker.supervisor.os") as os:
+        os.environ = {"SUPERVISOR_NAME": "hassio_supervisor"}
+        await api.load()
 
     api.webapp.middlewares.append(api.security.system_validation)
     yield await aiohttp_client(api.webapp)

tests/api/test_addons.py

@@ -1,5 +1,9 @@
 """Test addons api."""
 
+from unittest.mock import MagicMock
+
+from aiohttp.test_utils import TestClient
+
 from supervisor.addons.addon import Addon
 from supervisor.const import AddonState
 from supervisor.coresys import CoreSys
@@ -8,7 +12,9 @@ from supervisor.store.repository import Repository
 from ..const import TEST_ADDON_SLUG
 
 
-async def test_addons_info(api_client, coresys: CoreSys, install_addon_ssh: Addon):
+async def test_addons_info(
+    api_client: TestClient, coresys: CoreSys, install_addon_ssh: Addon
+):
     """Test getting addon info."""
     install_addon_ssh.state = AddonState.STOPPED
     install_addon_ssh.ingress_panel = True
@@ -27,7 +33,7 @@ async def test_addons_info(api_client, coresys: CoreSys, install_addon_ssh: Addo
 
 # DEPRECATED - Remove with legacy routing logic on 1/2023
 async def test_addons_info_not_installed(
-    api_client, coresys: CoreSys, repository: Repository
+    api_client: TestClient, coresys: CoreSys, repository: Repository
 ):
     """Test getting addon info for not installed addon."""
     resp = await api_client.get(f"/addons/{TEST_ADDON_SLUG}/info")
@@ -42,3 +48,17 @@ async def test_addons_info_not_installed(
         "password": "",
         "server": {"tcp_forwarding": False},
     }
+
+
+async def test_api_addon_logs(
+    api_client: TestClient, docker_logs: MagicMock, install_addon_ssh: Addon
+):
+    """Test addon logs."""
+    resp = await api_client.get("/addons/local_ssh/logs")
+    assert resp.status == 200
+    assert resp.content_type == "application/octet-stream"
+    content = await resp.text()
+    assert content.split("\n")[0:2] == [
+        "\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\x1b[0m",
+        "\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",
+    ]

tests/api/test_audio.py

@@ -0,0 +1,17 @@
+"""Test audio api."""
+
+from unittest.mock import MagicMock
+
+from aiohttp.test_utils import TestClient
+
+
+async def test_api_audio_logs(api_client: TestClient, docker_logs: MagicMock):
+    """Test audio logs."""
+    resp = await api_client.get("/audio/logs")
+    assert resp.status == 200
+    assert resp.content_type == "application/octet-stream"
+    content = await resp.text()
+    assert content.split("\n")[0:2] == [
+        "\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\x1b[0m",
+        "\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",
+    ]

tests/api/test_dns.py

@@ -1,11 +1,15 @@
 """Test DNS API."""
-from unittest.mock import PropertyMock, patch
+from unittest.mock import MagicMock, PropertyMock, patch
+
+from aiohttp.test_utils import TestClient
 
 from supervisor.coresys import CoreSys
 from supervisor.dbus.const import MulticastProtocolEnabled
 
 
-async def test_llmnr_mdns_info(api_client, coresys: CoreSys, dbus_is_connected):
+async def test_llmnr_mdns_info(
+    api_client: TestClient, coresys: CoreSys, dbus_is_connected: PropertyMock
+):
     """Test llmnr and mdns in info api."""
     coresys.host.sys_dbus.resolved.is_connected = False
 
@@ -38,7 +42,7 @@ async def test_llmnr_mdns_info(api_client, coresys: CoreSys, dbus_is_connected):
     assert result["data"]["mdns"] is True
 
 
-async def test_options(api_client, coresys: CoreSys):
+async def test_options(api_client: TestClient, coresys: CoreSys):
     """Test options api."""
     assert coresys.plugins.dns.servers == []
     assert coresys.plugins.dns.fallback is True
@@ -58,3 +62,15 @@ async def test_options(api_client, coresys: CoreSys):
         assert coresys.plugins.dns.servers == ["dns://8.8.8.8"]
         assert coresys.plugins.dns.fallback is True
         restart.assert_called_once()
+
+
+async def test_api_dns_logs(api_client: TestClient, docker_logs: MagicMock):
+    """Test dns logs."""
+    resp = await api_client.get("/dns/logs")
+    assert resp.status == 200
+    assert resp.content_type == "application/octet-stream"
+    content = await resp.text()
+    assert content.split("\n")[0:2] == [
+        "\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\x1b[0m",
+        "\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",
+    ]

tests/api/test_homeassistant.py

@@ -0,0 +1,21 @@
+"""Test homeassistant api."""
+
+from unittest.mock import MagicMock
+
+from aiohttp.test_utils import TestClient
+import pytest
+
+
+@pytest.mark.parametrize("legacy_route", [True, False])
+async def test_api_core_logs(
+    api_client: TestClient, docker_logs: MagicMock, legacy_route: bool
+):
+    """Test core logs."""
+    resp = await api_client.get(f"/{'homeassistant' if legacy_route else 'core'}/logs")
+    assert resp.status == 200
+    assert resp.content_type == "application/octet-stream"
+    content = await resp.text()
+    assert content.split("\n")[0:2] == [
+        "\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\x1b[0m",
+        "\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",
+    ]

tests/api/test_host.py

@@ -1,9 +1,13 @@
 """Test Host API."""
 
+from unittest.mock import MagicMock
+
+from aiohttp.test_utils import TestClient
 import pytest
 
 from supervisor.coresys import CoreSys
 
+DEFAULT_RANGE = "entries=:-100:"
 # pylint: disable=protected-access
 
 
@@ -19,7 +23,7 @@ async def fixture_coresys_disk_info(coresys: CoreSys) -> CoreSys:
 
 
 @pytest.mark.asyncio
-async def test_api_host_info(api_client, coresys_disk_info: CoreSys):
+async def test_api_host_info(api_client: TestClient, coresys_disk_info: CoreSys):
     """Test host info api."""
     coresys = coresys_disk_info
 
@@ -33,7 +37,7 @@ async def test_api_host_info(api_client, coresys_disk_info: CoreSys):
 
 
 async def test_api_host_features(
-    api_client, coresys_disk_info: CoreSys, dbus_is_connected
+    api_client: TestClient, coresys_disk_info: CoreSys, dbus_is_connected
 ):
     """Test host info features."""
     coresys = coresys_disk_info
@@ -96,7 +100,7 @@ async def test_api_host_features(
 
 
 async def test_api_llmnr_mdns_info(
-    api_client, coresys_disk_info: CoreSys, dbus_is_connected
+    api_client: TestClient, coresys_disk_info: CoreSys, dbus_is_connected
 ):
     """Test llmnr and mdns details in info."""
     coresys = coresys_disk_info
@@ -118,3 +122,132 @@ async def test_api_llmnr_mdns_info(
     assert result["data"]["broadcast_llmnr"] is True
     assert result["data"]["broadcast_mdns"] is False
     assert result["data"]["llmnr_hostname"] == "homeassistant"
+
+
+async def test_api_boot_ids_info(api_client: TestClient, journald_logs: MagicMock):
+    """Test getting boot IDs."""
+    resp = await api_client.get("/host/logs/boots")
+    result = await resp.json()
+    assert result["data"] == {"0": "ccc", "-1": "bbb", "-2": "aaa"}
+
+
+async def test_api_identifiers_info(api_client: TestClient, journald_logs: MagicMock):
+    """Test getting syslog identifiers."""
+    resp = await api_client.get("/host/logs/identifiers")
+    result = await resp.json()
+    assert result["data"] == ["hassio_supervisor", "hassos-config", "kernel"]
+
+
+async def test_advanced_logs(
+    api_client: TestClient, coresys: CoreSys, journald_logs: MagicMock
+):
+    """Test advanced logging API entries with identifier and custom boot."""
+    await api_client.get("/host/logs")
+    journald_logs.assert_called_once_with(
+        params={"SYSLOG_IDENTIFIER": coresys.host.logs.default_identifiers},
+        range_header=DEFAULT_RANGE,
+    )
+
+    journald_logs.reset_mock()
+
+    identifier = "dropbear"
+    await api_client.get(f"/host/logs/identifiers/{identifier}")
+    journald_logs.assert_called_once_with(
+        params={"SYSLOG_IDENTIFIER": identifier}, range_header=DEFAULT_RANGE
+    )
+
+    journald_logs.reset_mock()
+
+    bootid = "798cc03bcd77465482b6a1c43dc6a5fc"
+    await api_client.get(f"/host/logs/boots/{bootid}")
+    journald_logs.assert_called_once_with(
+        params={
+            "_BOOT_ID": bootid,
+            "SYSLOG_IDENTIFIER": coresys.host.logs.default_identifiers,
+        },
+        range_header=DEFAULT_RANGE,
+    )
+
+    journald_logs.reset_mock()
+
+    await api_client.get(f"/host/logs/boots/{bootid}/identifiers/{identifier}")
+    journald_logs.assert_called_once_with(
+        params={"_BOOT_ID": bootid, "SYSLOG_IDENTIFIER": identifier},
+        range_header=DEFAULT_RANGE,
+    )
+
+    journald_logs.reset_mock()
+
+    headers = {"Range": "entries=:-19:10"}
+    await api_client.get("/host/logs", headers=headers)
+    journald_logs.assert_called_once_with(
+        params={"SYSLOG_IDENTIFIER": coresys.host.logs.default_identifiers},
+        range_header=headers["Range"],
+    )
+
+    journald_logs.reset_mock()
+
+    await api_client.get("/host/logs/follow")
+    journald_logs.assert_called_once_with(
+        params={
+            "SYSLOG_IDENTIFIER": coresys.host.logs.default_identifiers,
+            "follow": "",
+        },
+        range_header=DEFAULT_RANGE,
+    )
+
+
+async def test_advanced_logs_boot_id_offset(
+    api_client: TestClient, coresys: CoreSys, journald_logs: MagicMock
+):
+    """Test advanced logging API when using an offset as boot ID."""
+    await api_client.get("/host/logs/boots/0")
+    journald_logs.assert_called_once_with(
+        params={
+            "_BOOT_ID": "ccc",
+            "SYSLOG_IDENTIFIER": coresys.host.logs.default_identifiers,
+        },
+        range_header=DEFAULT_RANGE,
+    )
+
+    journald_logs.reset_mock()
+
+    await api_client.get("/host/logs/boots/-2")
+    journald_logs.assert_called_once_with(
+        params={
+            "_BOOT_ID": "aaa",
+            "SYSLOG_IDENTIFIER": coresys.host.logs.default_identifiers,
+        },
+        range_header=DEFAULT_RANGE,
+    )
+
+    journald_logs.reset_mock()
+
+    await api_client.get("/host/logs/boots/2")
+    journald_logs.assert_called_once_with(
+        params={
+            "_BOOT_ID": "bbb",
+            "SYSLOG_IDENTIFIER": coresys.host.logs.default_identifiers,
+        },
+        range_header=DEFAULT_RANGE,
+    )
+
+    journald_logs.reset_mock()
+
+
+async def test_advanced_logs_errors(api_client: TestClient):
+    """Test advanced logging API errors."""
+    # coresys = coresys_logs_control
+    resp = await api_client.get("/host/logs")
+    result = await resp.json()
+    assert result["result"] == "error"
+    assert result["message"] == "No systemd-journal-gatewayd Unix socket available"
+
+    headers = {"Accept": "application/json"}
+    resp = await api_client.get("/host/logs", headers=headers)
+    result = await resp.json()
+    assert result["result"] == "error"
+    assert (
+        result["message"]
+        == "Invalid content type requested. Only text/plain supported for now."
+    )

tests/api/test_multicast.py

@@ -0,0 +1,17 @@
+"""Test multicast api."""
+
+from unittest.mock import MagicMock
+
+from aiohttp.test_utils import TestClient
+
+
+async def test_api_multicast_logs(api_client: TestClient, docker_logs: MagicMock):
+    """Test multicast logs."""
+    resp = await api_client.get("/multicast/logs")
+    assert resp.status == 200
+    assert resp.content_type == "application/octet-stream"
+    content = await resp.text()
+    assert content.split("\n")[0:2] == [
+        "\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\x1b[0m",
+        "\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",
+    ]

tests/api/test_supervisor.py

@@ -1,7 +1,7 @@
 """Test Supervisor API."""
 # pylint: disable=protected-access
 import asyncio
-from unittest.mock import patch
+from unittest.mock import MagicMock, patch
 
 from aiohttp.test_utils import TestClient
 import pytest
@@ -129,3 +129,15 @@ async def test_api_supervisor_options_diagnostics(
 
     assert response.status == 200
     assert dbus == ["/io/hass/os-io.hass.os.Diagnostics"]
+
+
+async def test_api_supervisor_logs(api_client: TestClient, docker_logs: MagicMock):
+    """Test supervisor logs."""
+    resp = await api_client.get("/supervisor/logs")
+    assert resp.status == 200
+    assert resp.content_type == "application/octet-stream"
+    content = await resp.text()
+    assert content.split("\n")[0:2] == [
+        "\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\x1b[0m",
+        "\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",
+    ]