Dashboard: scheduled latency check and on_ready fix

bot/ada.py

@@ -17,8 +17,10 @@ async def on_ready():
     logger.info("Ada is up and running!")
 
     if main_channel_id := bot.config.get("main_room", section="bot"):
-        room: Room = bot.get_room(main_channel_id)
-        await room.send("Hey, I'm back online!")
+        room: Room | None = bot.get_room(main_channel_id)
+
+        if room:
+            await room.send("Hey, I'm back online!")
 
 
 @bot.hook

bot/dashboard/latency.py

@@ -7,28 +7,33 @@
 
 @dataclass
 class LatencyHealth:
-    """A running average of latency, weighting recent readings most (EMA)."""
+    """A running average (EMA) of the scheduled latency checks, recent ones weighing most."""
 
     average_ms: float | None = None
 
     async def load(self) -> None:
-        """Rebuild the average from the stored latency readings."""
+        """Rebuild the average from the stored latency checks."""
         self.average_ms = None
 
         for event in await dachshund.default().events.events("latency"):
-            value = event.payload.get("value")
+            value = event.payload.get("check")
 
             if value is not None:
                 self._accumulate(value)
 
         if self.average_ms is not None:
             dachshund.emit("average_latency", value=self.average_ms)
 
-    def record(self, latency_ms: int) -> None:
-        dachshund.emit("latency", value=latency_ms)
+    def record_check(self, latency_ms: int) -> None:
+        """A scheduled round trip to the homeserver, which the health tracks."""
+        dachshund.emit("latency", check=latency_ms, message=None)
         self._accumulate(latency_ms)
         dachshund.emit("average_latency", value=self.average_ms)
 
+    def record_message(self, latency_ms: int) -> None:
+        """A message's delivery delay, shown live but left out of the health."""
+        dachshund.emit("latency", check=None, message=latency_ms)
+
     def _accumulate(self, latency_ms: float) -> None:
         if self.average_ms is None:
             self.average_ms = latency_ms

bot/dashboard/pages/overview.py

@@ -32,9 +32,13 @@
                 "worst_latency",
                 title="Worst Latency (24h)",
                 source="latency",
+                # The scheduled check, not message delivery delays.
+                y="check",
                 aggregate="max",
                 over=timedelta(hours=24),
                 unit="ms",
             )
         )
-    overview_page.add(TimeSeriesChart("latency", title="Live Latency"))
+    overview_page.add(
+        TimeSeriesChart("latency", title="Live Latency", y=["check", "message"])
+    )

bot/dashboard/tests/test_latency.py

@@ -14,26 +14,41 @@ def emit() -> Iterator[MagicMock]:
         yield mock
 
 
-def test_first_reading_is_the_average(emit: MagicMock) -> None:
+def test_first_check_is_the_average(emit: MagicMock) -> None:
     health = LatencyHealth()
-    health.record(100)
+    health.record_check(100)
 
     assert health.average_ms == 100
     emit.assert_has_calls(
-        [call("latency", value=100), call("average_latency", value=100)]
+        [
+            call("latency", check=100, message=None),
+            call("average_latency", value=100),
+        ]
     )
 
 
-def test_later_readings_move_average_by_alpha(emit: MagicMock) -> None:
+def test_later_checks_move_average_by_alpha(emit: MagicMock) -> None:
     health = LatencyHealth()
-    health.record(100)
-    health.record(200)
+    health.record_check(100)
+    health.record_check(200)
 
     assert health.average_ms == pytest.approx(120)
 
 
+def test_message_latency_is_shown_but_left_out_of_health(emit: MagicMock) -> None:
+    health = LatencyHealth(average_ms=100)
+    health.record_message(900)
+
+    assert health.average_ms == 100
+    emit.assert_called_once_with("latency", check=None, message=900)
+
+
 async def test_load_replays_stored_readings(emit: MagicMock) -> None:
-    stored = [SimpleNamespace(payload={"value": v}) for v in (100, None, 200)]
+    stored = [
+        SimpleNamespace(payload={"check": 100, "message": None}),
+        SimpleNamespace(payload={"check": None, "message": 900}),
+        SimpleNamespace(payload={"check": 200, "message": None}),
+    ]
     store = SimpleNamespace(
         events=SimpleNamespace(events=AsyncMock(return_value=stored))
     )

bot/extensions/dashboard/dashboard_extension.py

@@ -1,15 +1,18 @@
+import logging
 import time
 from datetime import date, datetime, timedelta
 from typing import cast
 from zoneinfo import ZoneInfo
 
 import dachshund
+from aiohttp import ClientError
 from matrix import Bot, Context, Extension, Room
-from nio import ReactionEvent, RoomMemberEvent, RoomMessageText
+from nio import ReactionEvent, RoomMemberEvent, RoomMessageText, WhoamiError
 
 from bot.dashboard.latency import LatencyHealth
 from bot.extensions.welcome.welcome_extension import _is_new_join
 
+logger = logging.getLogger(__name__)
 extension = Extension("dashboard")
 
 TIMEZONE = ZoneInfo("America/New_York")
@@ -41,6 +44,7 @@ def setup() -> None:
 @extension.hook
 async def on_ready() -> None:
     await latency_health.load()
+    await _check_latency()
     _report_counts()
 
 
@@ -49,6 +53,11 @@ async def report_counts() -> None:
     _report_counts()
 
 
+@extension.schedule("* * * * *")
+async def check_latency() -> None:
+    await _check_latency()
+
+
 @extension.schedule("5 0 * * *")
 async def trim_daily_charts() -> None:
     _trim_daily_charts()
@@ -83,7 +92,7 @@ async def on_command(ctx: Context) -> None:
 
 
 def _record_message(room: Room, event: RoomMessageText) -> None:
-    latency_health.record(_latency_ms(event.server_timestamp))
+    latency_health.record_message(_latency_ms(event.server_timestamp))
     dachshund.emit(
         "message",
         date=_today(),
@@ -108,6 +117,23 @@ def _record_command(name: str) -> None:
     dachshund.emit("commands_per_day", date=_today(), value=1)
 
 
+async def _check_latency() -> None:
+    """Time a round trip to the homeserver, the bot's equivalent of a ping."""
+    started = time.perf_counter()
+
+    try:
+        response = await cast(Bot, extension.bot).client.whoami()
+    except (ClientError, TimeoutError) as error:
+        logger.warning("Latency check failed: %s", error)
+        return
+
+    if isinstance(response, WhoamiError):
+        logger.warning("Latency check failed: %s", response.message)
+        return
+
+    latency_health.record_check(round((time.perf_counter() - started) * 1000))
+
+
 def _report_counts() -> None:
     rooms = cast(Bot, extension.bot).get_rooms()
 

bot/extensions/dashboard/tests/test_dashboard_extension.py

@@ -3,16 +3,18 @@
 from datetime import date
 from types import SimpleNamespace
 from typing import Any, cast
-from unittest.mock import MagicMock, call, patch
+from unittest.mock import AsyncMock, MagicMock, call, patch
 
 import pytest
+from aiohttp import ClientError
 from matrix import Room
-from nio import RoomMemberEvent, RoomMessageText
+from nio import RoomMemberEvent, RoomMessageText, WhoamiError, WhoamiResponse
 
 from bot.extensions.dashboard import dashboard_extension
 from bot.extensions.dashboard.dashboard_extension import (
     DAILY_SOURCES,
     TRIM_SPAN,
+    _check_latency,
     _is_leave,
     _latency_ms,
     _record_command,
@@ -110,7 +112,7 @@ def test_record_message_emits_latency_and_message(emit: MagicMock) -> None:
     _record_message(_room("invite"), cast(RoomMessageText, event))
 
     assert emit.mock_calls[0].args == ("latency",)
-    assert emit.mock_calls[1].args == ("average_latency",)
+    assert emit.mock_calls[0].kwargs["check"] is None
     emit.assert_called_with(
         "message", date=TODAY, author="@a:x", room="private", value=1
     )
@@ -144,3 +146,38 @@ def test_record_command_emits_name_and_day(emit: MagicMock) -> None:
             call("commands_per_day", date=TODAY, value=1),
         ]
     )
+
+
+def _bot_whoami(**whoami: Any) -> SimpleNamespace:
+    return SimpleNamespace(client=SimpleNamespace(whoami=AsyncMock(**whoami)))
+
+
+async def test_check_latency_records_round_trip(emit: MagicMock) -> None:
+    bot = _bot_whoami(return_value=MagicMock(spec=WhoamiResponse))
+
+    with (
+        patch.object(dashboard_extension.extension, "_bot", bot),
+        patch.object(dashboard_extension.latency_health, "record_check") as record,
+    ):
+        await _check_latency()
+
+    record.assert_called_once()
+    assert record.call_args.args[0] >= 0
+
+
+@pytest.mark.parametrize(
+    "whoami",
+    [
+        {"return_value": WhoamiError("M_UNKNOWN_TOKEN")},
+        {"side_effect": ClientError("connection reset")},
+        {"side_effect": TimeoutError()},
+    ],
+)
+async def test_check_latency_skips_failed_checks(whoami: dict[str, Any]) -> None:
+    with (
+        patch.object(dashboard_extension.extension, "_bot", _bot_whoami(**whoami)),
+        patch.object(dashboard_extension.latency_health, "record_check") as record,
+    ):
+        await _check_latency()
+
+    record.assert_not_called()

config/development.yaml

@@ -19,5 +19,5 @@ extensions:
 
 dashboard:
   host: "${DASHBOARD_HOST|127.0.0.1}"
-  port: "${PORT|4242}"
+  port: "${DASHBOARD_PORT|1212}"
   event_store: "${DACHSHUND_EVENT_STORE_PATH|dachshund.db}"

config/production.yaml

@@ -18,5 +18,5 @@ extensions:
 
 dashboard:
   host: "${DASHBOARD_HOST|0.0.0.0}"
-  port: "${PORT|4242}"
+  port: "${DASHBOARD_PORT|1212}"
   event_store: "${DACHSHUND_EVENT_STORE_PATH|dachshund.db}"

pyproject.toml

@@ -9,7 +9,7 @@ description = "Ada is a Matrix bot built with matrix.py framework. It provides v
 readme = "README.md"
 requires-python = ">=3.12"
 dependencies = [
-    "matrix-python>=1.0.1",
+    "matrix-python>=1.0.2",
     "coloredlogs==15.0.1",
     "click==8.3.2",
     "sqlmodel-toolkit @ git+https://github.com/Code-Society-Lab/sqlmodel-toolkit.git",