diff --git a/.env.example b/.env.example index ed7a9c2f4..406747282 100644 --- a/.env.example +++ b/.env.example @@ -91,6 +91,39 @@ DB_NAME=switch # every unattributed line look like that tenant's own. # TENANT_ID=default +# ── Observability ──────────────────────────────────────────────────────────── +# Where this deployment reports metrics and logs. Unset — the default — means +# it reports nowhere, and nothing measured leaves the process. Readiness +# checking runs either way: /health/ready answers whether or not this is set. +# +# A base URL with no path. `/v1/metrics` and `/v1/logs` are appended, the same +# convention OTEL_EXPORTER_OTLP_ENDPOINT follows, so pasting a full signal URL +# here is refused at startup rather than posting to /v1/logs/v1/metrics. +# OTLP_ENDPOINT=https://telemetry.example.com +# +# A UUID naming this deployment, stable across restarts. Required whenever the +# endpoint is set: the collector drops payloads it cannot attribute, silently +# and with a 200, so without one the server would report nothing while looking +# correctly configured — which is why it refuses to start instead. Generate it +# once with `uuidgen`; a fresh one per restart makes a single deployment look +# like an endless population of new installs. +# DEPLOYMENT_ID= +# +# Per signal. Metrics are the point and are on as soon as an endpoint is named. +# Logs are off because they already reach this container's output, where a +# cluster's log agent can read them — turning this on sends a second copy over +# the network. Traces are off because the relay Switch reports to does not +# serve /v1/traces yet, so enabling them means every export failing. +# OTLP_METRICS_ENABLED=true +# OTLP_LOGS_ENABLED=false +# OTLP_TRACES_ENABLED=false +# +# `key=value` pairs, comma-separated, on every request. Needed for a collector +# that authenticates; the relay does not. +# OTLP_HEADERS= +# OTLP_TIMEOUT_SECONDS=10 +# OTLP_EXPORT_INTERVAL_SECONDS=60 + # ── Client identity ────────────────────────────────────────────────────────── # The server half of every client's `@localpart:server` id. Nothing is # contacted at it; the ids are stable public handles. diff --git a/CLAUDE.md b/CLAUDE.md index 42cf66082..788d955de 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -238,6 +238,12 @@ Tests live in `core/tests/switch_core/` mirroring the module structure. Uses pyt - `docs/old/LOCAL_DEVELOPMENT.md` — running Switch locally for development: `just` recipes, which port serves what, connecting Switch Console to a local server +- `docs/old/observability.md` — what switch-core reports about itself and how + to turn it on: the metric catalogue and why attributes are declared, the + split between the liveness and readiness routes and why only the database + gates readiness, what the process reports in place of an infrastructure + agent, and what tracing still needs. Dashboards and alerts live in + `deploy/observability/`. - `docs/old/multi-tenancy.md` — why Switch is multi-tenant the way it is: the tenant model, sign-in and onboarding, one official messaging app per platform, and the phased plan the work follows. Phases 0 and 1 are built; diff --git a/core/switch_core/bridges/agent/app.py b/core/switch_core/bridges/agent/app.py index 2b3601b8c..63b813040 100644 --- a/core/switch_core/bridges/agent/app.py +++ b/core/switch_core/bridges/agent/app.py @@ -30,6 +30,7 @@ from switch_core.db.stores.external_user_store import ExternalUserStore from switch_core.db.stores.room_store import RoomStore from switch_core.db.stores.task_store import TaskStore +from switch_core.observability.http import MetricsMiddleware from switch_core.request_context import RequestContextMiddleware from switch_core.room_service import RoomService @@ -160,6 +161,10 @@ async def log_validation_errors( api_key_cache=api_key_cache, session_factory=session_factory, # type: ignore[arg-type] ) + # Outside the bearer middleware, so a request rejected for bad credentials + # is still counted and timed — an authentication failure is traffic, and a + # spike of it is the thing you most want a dashboard to show. + app.add_middleware(MetricsMiddleware) # Added last, so it wraps the bearer middleware: a request rejected for bad # credentials is logged with a request id like any other. app.add_middleware(RequestContextMiddleware) diff --git a/core/switch_core/bridges/collaboration/bridge_core.py b/core/switch_core/bridges/collaboration/bridge_core.py index 1c9f9dbc8..8df311771 100644 --- a/core/switch_core/bridges/collaboration/bridge_core.py +++ b/core/switch_core/bridges/collaboration/bridge_core.py @@ -4,7 +4,8 @@ import logging import re import uuid -from collections.abc import Awaitable, Callable, Mapping +from collections.abc import Awaitable, Callable, Iterator, Mapping +from contextlib import contextmanager from dataclasses import dataclass, field from typing import TYPE_CHECKING, Any, TypeVar @@ -44,6 +45,12 @@ from switch_core.db.tenant_lookup import tenant_of_room from switch_core.events import AgentRuntimeStateEvent from switch_core.logging_context import log_context +from switch_core.observability.catalogue import ( + BRIDGE_ERRORS, + BRIDGE_EVENTS_IN, + BRIDGE_EVENTS_OUT, +) +from switch_core.observability.metrics import metrics from switch_core.provisioning import Provisioning from switch_core.room_service import RoomCreateConfig from switch_core.tenant_context import no_tenant, tenant_scope @@ -228,11 +235,31 @@ def adapter(self) -> CollaborationAdapter: def tenant_id(self) -> str: return self._bridge_tenant_id + @contextmanager + def _counted_outbound(self, kind: str) -> Iterator[None]: + """Count one relay out to the platform, and its failure if it fails. + + Placed around the relay call rather than at the top of the handler: a + handler returns early for a puppet's own echo and for a room with no + channel mapping, and neither of those is a message anybody sent + outwards. + """ + metrics().increment( + BRIDGE_EVENTS_OUT, {"platform": self._bridge_type, "kind": kind} + ) + try: + yield + except Exception: + metrics().increment( + BRIDGE_ERRORS, {"platform": self._bridge_type, "direction": "outbound"} + ) + raise + def _traced( - self, handler: Callable[[_InboundEventT], Awaitable[None]] + self, kind: str, handler: Callable[[_InboundEventT], Awaitable[None]] ) -> Callable[[_InboundEventT], Awaitable[None]]: - """Give each inbound platform event its own id in the logs, and bind - the tenant the event belongs to. + """Give each inbound platform event its own id in the logs, count it, + and bind the tenant the event belongs to. An event fans out across room lookup, identity provisioning and the transport, so without this the lines from two events arriving at once @@ -260,6 +287,9 @@ def _traced( async def traced(event: _InboundEventT) -> None: event_id = uuid.uuid4().hex[:16] with log_context(request_id=f"{self._bridge_type}-{event_id}"): + metrics().increment( + BRIDGE_EVENTS_IN, {"platform": self._bridge_type, "event": kind} + ) room_ids = self._channel_to_room.get(event.channel_id) tenant_id = ( self._bridge_tenant_id @@ -267,7 +297,18 @@ async def traced(event: _InboundEventT) -> None: else await self._room_tenant(room_ids[0]) ) with tenant_scope(tenant_id): - await handler(event) + try: + await handler(event) + except Exception: + # Counted here and re-raised unchanged: whoever handles + # it above still does. An inbound handler that fails is + # a message a person sent and nobody received, which is + # invisible from the platform's side. + metrics().increment( + BRIDGE_ERRORS, + {"platform": self._bridge_type, "direction": "inbound"}, + ) + raise return traced @@ -277,11 +318,15 @@ async def start(self) -> None: self._adapter.set_channel_migration_handler(self._handle_channel_migrated) self._adapter.set_agent_presentation_resolver(self._agent_presentation) await self._adapter.start( - on_message=self._traced(self._handle_inbound_message), - on_command=self._traced(self._handle_inbound_command), - on_agent_joined=self._traced(self._handle_agent_joined_channel), - on_user_joined=self._traced(self._handle_user_joined_channel), - on_app_joined=self._traced(self._handle_app_joined_channel), + on_message=self._traced("message", self._handle_inbound_message), + on_command=self._traced("command", self._handle_inbound_command), + on_agent_joined=self._traced( + "agent_joined", self._handle_agent_joined_channel + ), + on_user_joined=self._traced( + "user_joined", self._handle_user_joined_channel + ), + on_app_joined=self._traced("app_joined", self._handle_app_joined_channel), ) await self._ensure_channel_captures() # Deliberately not awaited. Provisioning is one call per agent against @@ -1478,7 +1523,8 @@ async def handle_outbound_message( room_id, _ = self._channel_to_room[channel_id] with tenant_scope(await self._room_tenant(room_id)): - await self._relay_outbound_message(channel_id, event) + with self._counted_outbound("message"): + await self._relay_outbound_message(channel_id, event) async def _relay_outbound_message( self, channel_id: str, event: TransportMessage @@ -1616,7 +1662,8 @@ async def handle_outbound_media( room_id, _ = self._channel_to_room[channel_id] with tenant_scope(await self._room_tenant(room_id)): - await self._relay_outbound_media(channel_id, event, client) + with self._counted_outbound("media"): + await self._relay_outbound_media(channel_id, event, client) async def _relay_outbound_media( self, channel_id: str, event: TransportMedia, client: ClientBase[Any] diff --git a/core/switch_core/bridges/collaboration/lifecycle_service.py b/core/switch_core/bridges/collaboration/lifecycle_service.py index 0b9697df8..d1e6353f5 100644 --- a/core/switch_core/bridges/collaboration/lifecycle_service.py +++ b/core/switch_core/bridges/collaboration/lifecycle_service.py @@ -90,6 +90,12 @@ def __init__( # (see CollaborationAdapter.exclusive_resource). Lets a second # claimant be refused by name instead of failing on the resource. self._held_resources: dict[str, str] = {} + # Bridges that were started and have not been stopped on purpose. A + # crash removes a bridge from `_bridges` and leaves it here, which is + # what makes "configured but no longer running" answerable at all — + # otherwise a crashed bridge is indistinguishable from one that was + # never set up, and the only evidence is a log line nobody reads. + self._started: set[str] = set() # Serialises registration. The exclusivity check reads the stored # bridges and the winner is not written until several awaits later, # so two concurrent registrations would both see a free resource and @@ -533,6 +539,7 @@ async def start(self, bridge_id: str) -> None: ) self._bridges[bridge_id] = bridge_core self._tasks[bridge_id] = task + self._started.add(bridge_id) if wanted is not None: self._held_resources[bridge_id] = wanted @@ -636,6 +643,7 @@ async def stop(self, bridge_id: str) -> None: self._bridges.pop(bridge_id, None) self._held_resources.pop(bridge_id, None) + self._started.discard(bridge_id) logger.info("Stopped collaboration bridge %s", bridge_id) async def restart(self, bridge_id: str) -> None: @@ -707,6 +715,24 @@ async def remove(self, bridge_id: str) -> None: def get(self, bridge_id: str) -> BridgeCore | None: return self._bridges.get(bridge_id) + def expected_count(self) -> int: + """Bridges that were started and have not been stopped deliberately.""" + return len(self._started) + + def running_count(self) -> int: + """Of those, how many still have a task that has not finished. + + A bridge's task runs until shutdown, so a task that is *done* has + stopped serving whether it raised or returned — both are equally + invisible to anything that only checks membership of `_bridges`. + """ + running = 0 + for bridge_id in self._started: + task = self._tasks.get(bridge_id) + if bridge_id in self._bridges and task is not None and not task.done(): + running += 1 + return running + def bridges_for_tenant(self, tenant_id: str) -> list[BridgeCore]: """Running bridges belonging to `tenant_id`, and none other. diff --git a/core/switch_core/clients/client_lifecycle_service.py b/core/switch_core/clients/client_lifecycle_service.py index 221361046..035342736 100644 --- a/core/switch_core/clients/client_lifecycle_service.py +++ b/core/switch_core/clients/client_lifecycle_service.py @@ -268,6 +268,14 @@ async def remove(self, client_id: str) -> None: def get(self, client_id: str) -> ClientBase[ClientConfig] | None: return self._clients.get(client_id) + def running_count(self) -> int: + """Clients believed to be running right now. + + A crashed client removes itself from the registry, so this falling is + the only signal that one did — there is no failure counter to read. + """ + return len(self._clients) + def get_by_agent_id(self, agent_id: str) -> ClientBase[ClientConfig] | None: for client in self._clients.values(): if isinstance(client, AgentClient) and client._agent is not None: diff --git a/core/switch_core/config.py b/core/switch_core/config.py index ab01ca1f4..95a3bd529 100644 --- a/core/switch_core/config.py +++ b/core/switch_core/config.py @@ -1,5 +1,6 @@ import re import ssl +import uuid from pathlib import Path from urllib.parse import urlsplit @@ -164,6 +165,49 @@ class SwitchConfig(BaseSettings): # `tenant_id`. tenant_id: str = "default" + # ── Observability ──────────────────────────────────────────────────────── + # The OTLP/HTTP collector everything is reported to, as a base URL with no + # path: signals are appended as `/v1/metrics` and `/v1/logs`, which is the + # convention `OTEL_EXPORTER_OTLP_ENDPOINT` follows, so an operator who has + # configured any other OTLP client already knows what to set here. + # + # Unset is the default and means the server reports nothing anywhere. That + # is the whole switch: a deployment opts in by naming a collector, and + # until it does, no measurement leaves the process. + otlp_endpoint: str | None = None + + # Per-signal, because the three do not cost the same and are not equally + # available. Metrics are the point of the exercise and are on as soon as a + # collector is named. Logs are off because they already go to the + # container's output where a cluster's own collector can read them, and + # sending a second copy over the network is a volume decision that belongs + # to whoever pays for it. Traces are off because the relay Switch reports + # to does not serve `/v1/traces` yet — turning them on before it does means + # every export fails, loudly and forever (CHOO-2807). + otlp_metrics_enabled: bool = True + otlp_logs_enabled: bool = False + otlp_traces_enabled: bool = False + + # `key=value` pairs, comma-separated, sent on every OTLP request. The relay + # Switch reports to is unauthenticated and needs none; a deployment + # pointing at its own collector usually needs an API key here. + otlp_headers: str | None = None + + otlp_timeout_seconds: float = 10.0 + otlp_export_interval_seconds: float = 60.0 + + # Which deployment a measurement came from: a UUID, stable across restarts, + # chosen by the operator and set once. + # + # Not optional when reporting is on, and not defaulted. The collector + # requires it and drops payloads that arrive without one — in silence, with + # a 200 — so a deployment that omitted it would look configured, log + # nothing wrong, and appear in no dashboard. Better to refuse to start. + # + # Not generated per process either: a fresh id on every restart would make + # one deployment look like an unbounded population of one-off installs. + deployment_id: str | None = None + server_host: str = "0.0.0.0" server_port: int = 8000 @@ -310,6 +354,85 @@ def _validate_logging(self) -> "SwitchConfig": ) return self + @model_validator(mode="after") + def _validate_observability(self) -> "SwitchConfig": + if self.otlp_endpoint is None: + # Nothing else in the block means anything without a collector, and + # a deployment that has set an interval but no endpoint has not + # half-configured reporting — it has not configured it. + return self + + parts = urlsplit(self.otlp_endpoint) + if parts.scheme not in ("http", "https"): + raise ValueError( + f"OTLP_ENDPOINT must be an http(s) URL, got {self.otlp_endpoint!r}." + ) + if not parts.netloc: + raise ValueError( + f"OTLP_ENDPOINT must include a host, got {self.otlp_endpoint!r}." + ) + if parts.path.strip("/"): + # The signal path is appended, so a value that already carries one + # would be posted to `/v1/logs/v1/metrics`. Worth catching by hand: + # the endpoint most people have seen written down is the full logs + # URL, and pasting it here is the obvious mistake. + raise ValueError( + "OTLP_ENDPOINT is the collector's base URL and the signal path " + "is appended to it, so it must have no path of its own. Got " + f"{self.otlp_endpoint!r} — drop the {parts.path!r}." + ) + + if not self.deployment_id: + raise ValueError( + "DEPLOYMENT_ID must be set when OTLP_ENDPOINT is: the collector " + "drops payloads that do not identify the deployment, and it " + "does so silently, so without one this server would report " + "nothing while looking correctly configured." + ) + try: + uuid.UUID(self.deployment_id) + except ValueError as error: + raise ValueError( + f"DEPLOYMENT_ID must be a UUID, got {self.deployment_id!r}. " + "The collector's guard rejects anything else." + ) from error + + for name, value in ( + ("OTLP_TIMEOUT_SECONDS", self.otlp_timeout_seconds), + ("OTLP_EXPORT_INTERVAL_SECONDS", self.otlp_export_interval_seconds), + ): + if value <= 0: + raise ValueError(f"{name} must be greater than 0, got {value!r}.") + + # Parsed here so a malformed header is a startup error rather than a + # `ValueError` from inside the export loop every interval. + self._parse_otlp_headers() + return self + + def _parse_otlp_headers(self) -> dict[str, str]: + if not self.otlp_headers: + return {} + headers: dict[str, str] = {} + for pair in self.otlp_headers.split(","): + if not pair.strip(): + continue + key, separator, value = pair.partition("=") + if not separator or not key.strip(): + raise ValueError( + "OTLP_HEADERS must be comma-separated key=value pairs, got " + f"{pair!r}." + ) + headers[key.strip()] = value.strip() + return headers + + @property + def otlp_header_map(self) -> dict[str, str]: + return self._parse_otlp_headers() + + @property + def observability_enabled(self) -> bool: + return self.otlp_endpoint is not None + @model_validator(mode="after") def _validate_db_user(self) -> "SwitchConfig": # `db_user` is the runtime role name, and `db/runtime_role.py` builds diff --git a/core/switch_core/main.py b/core/switch_core/main.py index 1c0423e2f..95e049bcc 100644 --- a/core/switch_core/main.py +++ b/core/switch_core/main.py @@ -117,6 +117,13 @@ from switch_core.gateway.auth import hash_password from switch_core.logging_config import configure_logging from switch_core.messages.notify import MessageListener +from switch_core.observability.bootstrap import ( + Observability, + RuntimeProbes, + start_observability, +) +from switch_core.observability.pool import pool_stats +from switch_core.observability.runtime import EventLoopLag from switch_core.provisioning import Provisioning from switch_core.provisioning.postgres import PostgresProvisioning from switch_core.room_service import RoomService @@ -152,7 +159,7 @@ async def _runtime_state_sweep_loop(protocol: ProtocolService) -> None: logger.exception("Runtime-state sweep failed") -async def _connection_sweep_loop(protocol: ProtocolService) -> None: +async def _connection_sweep_loop(protocol: ProtocolService, lag: EventLoopLag) -> None: """Expire connections whose client has stopped beating. Skips a round after the event loop has been blocked. A stall stops us @@ -161,11 +168,16 @@ async def _connection_sweep_loop(protocol: ProtocolService) -> None: leases, then every client reconnects together, which is a worse stall. The clients were never given the chance to beat, so the honest reading is "we were not listening", not "they went away". + + This runs on a fixed short interval and is therefore also the process's + most sensitive witness to the loop being blocked at all, so every round's + oversleep is reported — not only the ones large enough to skip a sweep. """ while True: started = time.monotonic() await asyncio.sleep(_CONNECTION_SWEEP_INTERVAL) overslept = (time.monotonic() - started) - _CONNECTION_SWEEP_INTERVAL + lag.record(overslept) if overslept > HEARTBEAT_TTL_SECONDS / 2: logger.warning( "Connection sweep skipped: the event loop was blocked for %.1fs, " @@ -511,26 +523,61 @@ async def run(config: SwitchConfig) -> None: "telegram", TelegramAdapter, TelegramConnectionConfig ) - # Health check mounted on the agent bridge app + # Liveness. Deliberately unconditional and deliberately cheap: besides the + # kubelet's liveness probe, the gateway Deployment and the setup Job both + # wait on this before they start, so anything it checked would become a + # boot-ordering dependency for them. Readiness is /health/ready below. @agent_bridge_app.get("/health") async def health_check() -> JSONResponse: return JSONResponse({"status": "ok"}) + # Set by the lifespan. Readiness is answerable only once the monitor that + # answers it is running, and before that the honest answer is "no". + observability: Observability | None = None + + @agent_bridge_app.get("/health/ready") + async def readiness_check() -> JSONResponse: + if observability is None: + return JSONResponse( + {"status": "not ready", "checks": {"startup": {"healthy": False}}}, + status_code=503, + ) + report = observability.monitor.current() + return JSONResponse( + report.as_response(), status_code=200 if report.ready else 503 + ) + agent_bridge_app.mount("/gateway", gateway_app) # ── Ensure system clients exist ───────────────────────────────────────── await client_lifecycle.ensure_system_client("admin") + probes = RuntimeProbes( + listener_connected=message_listener.connected.is_set, + bridges_running=collab_lifecycle.running_count, + bridges_configured=collab_lifecycle.expected_count, + clients_running=client_lifecycle.running_count, + agents_connected=lambda: len(connections.live_agent_ids()), + pool_stats=lambda: pool_stats(engine), + ) + # ── Lifespan: start server-side connectors once HTTP is serving ──────── original_lifespan = agent_bridge_app.router.lifespan_context @asynccontextmanager async def lifespan(app: object) -> AsyncIterator[None]: + nonlocal observability async with original_lifespan(app): # type: ignore[arg-type] + observability = start_observability( + config=config, + version=switch_core_version(), + session_factory=session_factory, + probes=probes, + ) asyncio.create_task(connector_lifecycle.start_all()) sweep_task = asyncio.create_task(_runtime_state_sweep_loop(protocol)) connection_sweep_task = asyncio.create_task( - _connection_sweep_loop(protocol) + _connection_sweep_loop(protocol, observability.lag) ) await message_listener.start() try: @@ -539,6 +586,7 @@ async def lifespan(app: object) -> AsyncIterator[None]: sweep_task.cancel() connection_sweep_task.cancel() await message_listener.stop() + await observability.aclose() agent_bridge_app.router.lifespan_context = lifespan # type: ignore[assignment] diff --git a/core/switch_core/observability/__init__.py b/core/switch_core/observability/__init__.py new file mode 100644 index 000000000..57f84eb42 --- /dev/null +++ b/core/switch_core/observability/__init__.py @@ -0,0 +1,26 @@ +"""Operational observability: what this server reports about itself. + +Structured logging already existed (:mod:`switch_core.logging_config` and +:mod:`switch_core.logging_context`); this package adds the measurements and the +path they leave by. Everything is off until ``OTLP_ENDPOINT`` names a +collector — see :class:`switch_core.config.SwitchConfig`. + +Read :mod:`switch_core.observability.catalogue` before adding a metric: nothing +is emitted that is not declared there, attributes included. +""" + +from switch_core.observability.metrics import ( + GaugeReading, + MetricsRegistry, + install, + metrics, + uninstall, +) + +__all__ = [ + "GaugeReading", + "MetricsRegistry", + "install", + "metrics", + "uninstall", +] diff --git a/core/switch_core/observability/bootstrap.py b/core/switch_core/observability/bootstrap.py new file mode 100644 index 000000000..88a188273 --- /dev/null +++ b/core/switch_core/observability/bootstrap.py @@ -0,0 +1,249 @@ +"""Assembles observability from config and the running process's own objects. + +Kept apart from ``main`` so that what is measured, and what it takes to measure +it, can be read and tested without starting a server. + +Note what is *not* conditional on configuration: the health monitor always +runs. Readiness is how Kubernetes decides whether to send this pod traffic, and +it cannot depend on whether anyone happens to be collecting metrics. Only the +export is gated. +""" + +from __future__ import annotations + +import asyncio +import logging +from collections.abc import Callable, Iterator +from dataclasses import dataclass + +import httpx +from sqlalchemy.ext.asyncio import async_sessionmaker + +from switch_core.config import SwitchConfig +from switch_core.logging_context import LogContextFilter +from switch_core.observability.catalogue import ( + AGENTS_CONNECTED, + BRIDGES_RUNNING, + CLIENTS_RUNNING, + DB_POOL_IN_USE, + DB_POOL_OVERFLOW, + DB_POOL_SIZE, +) +from switch_core.observability.exporter import MetricsExporter +from switch_core.observability.health import ( + HealthMonitor, + bridges_check, + database_check, + message_listener_check, +) +from switch_core.observability.logs import ( + DEFAULT_BATCH_SIZE, + DEFAULT_QUEUE_CAPACITY, + LogExporter, + OtlpLogHandler, +) +from switch_core.observability.metrics import ( + GaugeReading, + MetricsRegistry, + install, + uninstall, +) +from switch_core.observability.otlp import OtlpClient, OtlpResource +from switch_core.observability.pool import PoolStats +from switch_core.observability.runtime import ( + EventLoopLag, + RuntimeMetrics, + log_unreadable_sources, +) + +logger = logging.getLogger(__name__) + +# How often the dependency checks are re-run. Matched to the kubelet's probe +# period: a readiness answer older than the interval the kubelet asks on would +# report a fault one probe later than it could have. +HEALTH_REFRESH_INTERVAL_SECONDS = 10.0 + +# Logs ship far more often than metrics. A metric interval is a bucket and +# nothing is lost by making it a minute; a log is read by someone looking at an +# incident right now, and a minute behind is a minute of guessing. +LOG_EXPORT_INTERVAL_SECONDS = 5.0 + + +@dataclass(frozen=True) +class RuntimeProbes: + """Live state, as callables over whatever holds it. + + Callables rather than the services themselves so this module does not + depend on half the application to read four numbers off it — and so a test + can supply the numbers without constructing a bridge. + """ + + listener_connected: Callable[[], bool] + bridges_running: Callable[[], int] + bridges_configured: Callable[[], int] + clients_running: Callable[[], int] + agents_connected: Callable[[], int] + # None when the engine's pool does not keep these — see + # :mod:`switch_core.observability.pool`. + pool_stats: Callable[[], PoolStats | None] + + +@dataclass +class Observability: + """What the server needs to hold on to: the monitor, and how to stop.""" + + monitor: HealthMonitor + lag: EventLoopLag + _tasks: list[asyncio.Task[None]] + _http_client: httpx.AsyncClient | None + _log_handler: OtlpLogHandler | None + + async def aclose(self) -> None: + # Detached first, so nothing logged during shutdown is queued for an + # exporter that is about to stop draining it. + if self._log_handler is not None: + logging.getLogger().removeHandler(self._log_handler) + for task in self._tasks: + task.cancel() + for task in self._tasks: + try: + await task + except asyncio.CancelledError: + pass + except Exception: + logger.exception("An observability task failed on shutdown.") + if self._http_client is not None: + await self._http_client.aclose() + uninstall() + + +def _state_readings(probes: RuntimeProbes) -> Callable[[], Iterator[GaugeReading]]: + def readings() -> Iterator[GaugeReading]: + yield GaugeReading(AGENTS_CONNECTED, float(probes.agents_connected()), {}) + yield GaugeReading(CLIENTS_RUNNING, float(probes.clients_running()), {}) + yield GaugeReading(BRIDGES_RUNNING, float(probes.bridges_running()), {}) + + stats = probes.pool_stats() + if stats is not None: + yield GaugeReading(DB_POOL_IN_USE, float(stats.in_use), {}) + yield GaugeReading(DB_POOL_SIZE, float(stats.size), {}) + yield GaugeReading(DB_POOL_OVERFLOW, float(stats.overflow), {}) + + return readings + + +def start_observability( + config: SwitchConfig, + version: str | None, + session_factory: async_sessionmaker, + probes: RuntimeProbes, +) -> Observability: + """Install the registry, start the loops, and hand back the handle. + + Called once, from the server's lifespan. + """ + monitor = HealthMonitor( + checks=[ + database_check(session_factory), + message_listener_check(probes.listener_connected), + bridges_check(probes.bridges_running, probes.bridges_configured), + ], + interval_seconds=HEALTH_REFRESH_INTERVAL_SECONDS, + ) + lag = EventLoopLag() + tasks: list[asyncio.Task[None]] = [ + asyncio.create_task(monitor.run_forever(), name="health-monitor") + ] + + if not config.observability_enabled: + logger.info( + "No OTLP_ENDPOINT is configured, so nothing is reported off this " + "server. Health checks still run and /health/ready still answers." + ) + return Observability( + monitor=monitor, + lag=lag, + _tasks=tasks, + _http_client=None, + _log_handler=None, + ) + + registry = MetricsRegistry() + install(registry) + + monitor.install(registry) + RuntimeMetrics(lag).install(registry) + registry.register_observer(_state_readings(probes)) + log_unreadable_sources() + + http_client = httpx.AsyncClient() + client = OtlpClient( + # Checked at startup: `observability_enabled` is exactly "this is set". + base_endpoint=str(config.otlp_endpoint), + timeout_seconds=config.otlp_timeout_seconds, + headers=config.otlp_header_map, + client=http_client, + ) + resource = OtlpResource( + service_name=config.service_name, + service_version=version, + environment=config.environment, + deployment_id=str(config.deployment_id), + ) + + if config.otlp_metrics_enabled: + exporter = MetricsExporter( + registry=registry, + client=client, + resource=resource, + interval_seconds=config.otlp_export_interval_seconds, + ) + tasks.append( + asyncio.create_task(exporter.run_forever(), name="metrics-exporter") + ) + logger.info( + "Reporting metrics to %s every %.0fs as service %r.", + client.url_for("metrics"), + config.otlp_export_interval_seconds, + config.service_name, + ) + else: + # Worth saying: an endpoint is configured, so somebody expects data. + logger.warning( + "OTLP_ENDPOINT is set but OTLP_METRICS_ENABLED is false, so no " + "metrics are being reported." + ) + + log_handler: OtlpLogHandler | None = None + if config.otlp_logs_enabled: + log_handler = OtlpLogHandler(capacity=DEFAULT_QUEUE_CAPACITY) + # The same filter the stderr handler carries. Without it a record + # reaching this handler has no tenant, request or agent on it — which + # is the entire reason for shipping logs rather than counting them. + log_handler.addFilter(LogContextFilter(config.tenant_id)) + logging.getLogger().addHandler(log_handler) + tasks.append( + asyncio.create_task( + LogExporter( + handler=log_handler, + client=client, + resource=resource, + interval_seconds=LOG_EXPORT_INTERVAL_SECONDS, + batch_size=DEFAULT_BATCH_SIZE, + ).run_forever(), + name="log-exporter", + ) + ) + logger.info( + "Also shipping logs to %s. They continue to be written to this " + "container's output, which remains the primary copy.", + client.url_for("logs"), + ) + + return Observability( + monitor=monitor, + lag=lag, + _tasks=tasks, + _http_client=http_client, + _log_handler=log_handler, + ) diff --git a/core/switch_core/observability/catalogue.py b/core/switch_core/observability/catalogue.py new file mode 100644 index 000000000..80487ec51 --- /dev/null +++ b/core/switch_core/observability/catalogue.py @@ -0,0 +1,267 @@ +"""Every metric this server emits, and the attributes each may carry. + +Nothing is recorded that is not declared here. The registry rejects an unknown +metric name and an attribute key the spec does not name, which buys two things +that matter more on a server than they did in the desktop app this pattern +comes from: + +**Cardinality.** A metric's cost is the number of distinct attribute +combinations it produces, and the values that feel most natural to attach — +room id, agent id, the raw request path — are unbounded. One of them reaching +a call site is not a slightly noisier dashboard, it is a bill and a collector +that starts dropping. Declaring the permitted keys makes that a test failure +rather than an invoice. + +**Disclosure.** Switch is multi-tenant, and a metric is not the place tenant +data is allowed to surface: metrics are read by whoever can see the deployment's +dashboards, which is not the same set of people as those entitled to a given +tenant's rows. Tenant-attributed reporting is a product-events concern +(CHOO-2806) travelling as log records, where it is scoped and consented +separately. + +Every attribute VALUE must come from a fixed set the code controls — a platform +name, a route template, a status class. When that cannot be guaranteed at the +call site, it does not belong in a metric. +""" + +from __future__ import annotations + +from dataclasses import dataclass, field +from typing import Literal + +MetricKind = Literal["sum", "gauge", "histogram"] + +# How many distinct attribute combinations one metric may produce before the +# registry stops accepting new ones. A ceiling rather than a target: crossing +# it means a call site is passing something unbounded, and the registry says so +# out loud rather than absorbing it. +MAX_SERIES_PER_METRIC = 500 + + +@dataclass(frozen=True) +class MetricSpec: + name: str + kind: MetricKind + unit: str + description: str + attributes: frozenset[str] = field(default_factory=frozenset) + + +def _spec( + name: str, + kind: MetricKind, + unit: str, + description: str, + *attributes: str, +) -> MetricSpec: + return MetricSpec( + name=name, + kind=kind, + unit=unit, + description=description, + attributes=frozenset(attributes), + ) + + +# ── HTTP ───────────────────────────────────────────────────────────────────── +# `route` is the route *template* ("/agents/{agent_id}/rooms"), never the +# resolved path: the resolved path carries an id per request and is precisely +# the unbounded value this catalogue exists to keep out. `status_class` is +# "2xx"/"4xx"/"5xx" rather than the code, because the question a dashboard asks +# is "are we failing", and the exact code is in the logs. +HTTP_REQUESTS = _spec( + "switch.http.requests", + "sum", + "{request}", + "HTTP requests served, by route and outcome.", + "route", + "method", + "status_class", +) +HTTP_REQUEST_DURATION = _spec( + "switch.http.request.duration", + "histogram", + "ms", + "Wall time to serve an HTTP request.", + "route", + "method", +) + +# ── Database ───────────────────────────────────────────────────────────────── +DB_POOL_IN_USE = _spec( + "switch.db.pool.in_use", + "gauge", + "{connection}", + "Connections checked out of the pool right now.", +) +DB_POOL_SIZE = _spec( + "switch.db.pool.size", + "gauge", + "{connection}", + "Connections the pool is holding.", +) +DB_POOL_OVERFLOW = _spec( + "switch.db.pool.overflow", + "gauge", + "{connection}", + "Connections open beyond the pool's nominal size.", +) + +# ── Message transport ──────────────────────────────────────────────────────── +MESSAGES_SENT = _spec( + "switch.messages.sent", + "sum", + "{message}", + "Messages written to the message store.", + "kind", +) +MESSAGES_DELIVERED = _spec( + "switch.messages.delivered", + "sum", + "{message}", + "Messages handed to a client's handler.", + "kind", +) +DELIVERY_FAILURES = _spec( + "switch.messages.delivery_failures", + "sum", + "{failure}", + "Delivery-loop iterations that raised. The loop survives these by design, " + "so they are invisible without this counter.", +) +DELIVERY_LAG = _spec( + "switch.messages.delivery_lag", + "histogram", + "ms", + "Age of a message when it reached a client's handler. The number that " + "says whether the room is keeping up, measured per delivery rather than " + "inferred from a queue depth.", + "kind", +) + +# ── Collaboration bridges ──────────────────────────────────────────────────── +# `platform` is one of the five registered adapter types, so it is bounded by +# the code rather than by what a caller passes. +BRIDGE_EVENTS_IN = _spec( + "switch.bridge.events_in", + "sum", + "{event}", + "Events accepted from a collaboration platform.", + "platform", + "event", +) +BRIDGE_EVENTS_OUT = _spec( + "switch.bridge.events_out", + "sum", + "{event}", + "Messages and media relayed out to a collaboration platform.", + "platform", + "kind", +) +BRIDGE_ERRORS = _spec( + "switch.bridge.errors", + "sum", + "{error}", + "Bridge operations that raised, by direction.", + "platform", + "direction", +) +BRIDGES_RUNNING = _spec( + "switch.bridges.running", + "gauge", + "{bridge}", + "Collaboration bridges with a live task. A configured bridge missing here " + "has crashed.", +) + +# ── Agents and clients ─────────────────────────────────────────────────────── +AGENTS_CONNECTED = _spec( + "switch.agents.connected", + "gauge", + "{agent}", + "Agents holding a live protocol connection.", +) +CLIENTS_RUNNING = _spec( + "switch.clients.running", + "gauge", + "{client}", + "Room clients with a live task.", +) + +# ── Process and runtime ────────────────────────────────────────────────────── +# What an infrastructure agent would otherwise report. Switch has no Datadog +# agent deployed, so the process reports on itself; these stay useful even +# once one exists, because the app knows things the node does not. +RUNTIME_MEMORY_RSS = _spec( + "switch.runtime.memory_rss", + "gauge", + "By", + "Resident set size of the server process.", +) +RUNTIME_CPU_SECONDS = _spec( + "switch.runtime.cpu_seconds", + "sum", + "s", + "CPU time consumed by the server process.", + "mode", +) +RUNTIME_OPEN_FDS = _spec( + "switch.runtime.open_fds", + "gauge", + "{file}", + "Open file descriptors. Climbing without bound is a leak.", +) +RUNTIME_EVENT_LOOP_LAG = _spec( + "switch.runtime.event_loop_lag", + "gauge", + "ms", + "How far past its deadline a fixed-interval task woke. The server is " + "single-threaded and cooperative, so this is the one number that says " + "whether anything is being starved.", +) +RUNTIME_GC_COLLECTIONS = _spec( + "switch.runtime.gc_collections", + "sum", + "{collection}", + "Garbage collections, by generation.", + "generation", +) + +# ── Health ─────────────────────────────────────────────────────────────────── +# One series per dependency, 1 when that dependency answered and 0 when it did +# not — so a dashboard shows *which* one broke, and an alert on the readiness +# route does not have to guess. +HEALTH_CHECK = _spec( + "switch.health.check", + "gauge", + "{status}", + "1 when a readiness dependency passed its last check, 0 when it failed.", + "check", +) + +CATALOGUE: dict[str, MetricSpec] = { + spec.name: spec + for spec in ( + HTTP_REQUESTS, + HTTP_REQUEST_DURATION, + DB_POOL_IN_USE, + DB_POOL_SIZE, + DB_POOL_OVERFLOW, + MESSAGES_SENT, + MESSAGES_DELIVERED, + DELIVERY_FAILURES, + DELIVERY_LAG, + BRIDGE_EVENTS_IN, + BRIDGE_EVENTS_OUT, + BRIDGE_ERRORS, + BRIDGES_RUNNING, + AGENTS_CONNECTED, + CLIENTS_RUNNING, + RUNTIME_MEMORY_RSS, + RUNTIME_CPU_SECONDS, + RUNTIME_OPEN_FDS, + RUNTIME_EVENT_LOOP_LAG, + RUNTIME_GC_COLLECTIONS, + HEALTH_CHECK, + ) +} diff --git a/core/switch_core/observability/exporter.py b/core/switch_core/observability/exporter.py new file mode 100644 index 000000000..e4e81b88c --- /dev/null +++ b/core/switch_core/observability/exporter.py @@ -0,0 +1,108 @@ +"""The loop that drains the registry and posts an interval to the collector.""" + +from __future__ import annotations + +import asyncio +import logging + +from switch_core.observability.metrics import MetricsRegistry +from switch_core.observability.otlp import ( + OtlpClient, + OtlpResource, + OtlpSendError, + build_metrics_payload, + now_nanos, +) + +logger = logging.getLogger(__name__) + +# Consecutive failed exports before the complaint is escalated. One failure is +# a flaky network and says nothing; a run of them means the dashboards have +# been blank for long enough that somebody is about to be misled by them. +_FAILURES_BEFORE_ERROR = 3 + + +class MetricsExporter: + """Collects and posts on a fixed interval until cancelled.""" + + def __init__( + self, + registry: MetricsRegistry, + client: OtlpClient, + resource: OtlpResource, + interval_seconds: float, + ) -> None: + self._registry = registry + self._client = client + self._resource = resource + self._interval_seconds = interval_seconds + self._interval_start_nanos = now_nanos() + self._consecutive_failures = 0 + + async def flush_once(self) -> None: + """Post everything recorded since the previous flush. + + The interval window is closed before the request is made, not after it + succeeds: a failed post loses that interval rather than folding it into + the next one, which would otherwise report a minute's traffic as though + it had happened in a second. + """ + end_nanos = now_nanos() + start_nanos = self._interval_start_nanos + self._interval_start_nanos = end_nanos + + payloads = self._registry.collect() + if not payloads: + return + + body = build_metrics_payload(payloads, self._resource, start_nanos, end_nanos) + try: + await self._client.post("metrics", body) + except OtlpSendError as error: + self._consecutive_failures += 1 + if self._consecutive_failures >= _FAILURES_BEFORE_ERROR: + logger.error( + "Metrics export has failed %d times in a row; this " + "deployment's dashboards are stale. Last error: %s", + self._consecutive_failures, + error, + ) + else: + logger.warning( + "Metrics export failed, dropping the interval: %s", error + ) + return + + if self._consecutive_failures: + logger.info( + "Metrics export recovered after %d failed interval(s).", + self._consecutive_failures, + ) + self._consecutive_failures = 0 + + async def run_forever(self) -> None: + """Flush on the interval. Survives everything but cancellation. + + A metrics exporter that can take the server down with it is worse than + no metrics exporter, so the only exception it re-raises is the one that + means "stop". + """ + while True: + try: + await asyncio.sleep(self._interval_seconds) + await self.flush_once() + except asyncio.CancelledError: + # One last window, so a clean shutdown reports what it did + # rather than discarding its final minute. + await self._flush_on_shutdown() + raise + except Exception: + logger.exception("Metrics export loop raised; continuing.") + + async def _flush_on_shutdown(self) -> None: + try: + await self.flush_once() + except Exception: + # Already shutting down; a failure here has nowhere useful to go + # and must not displace whatever is actually stopping the process. + logger.warning("Final metrics flush failed.", exc_info=True) diff --git a/core/switch_core/observability/health.py b/core/switch_core/observability/health.py new file mode 100644 index 000000000..b4354d681 --- /dev/null +++ b/core/switch_core/observability/health.py @@ -0,0 +1,287 @@ +"""Readiness: what has to be true for this server to be worth sending traffic to. + +Two routes, because they answer different questions and Kubernetes does +different things with the answers. + +``/health`` is liveness, and it stays exactly what it was — a cheap, always-ok +reply. It is not only the kubelet's liveness probe: the gateway Deployment and +the setup Job both wait on it before they start, so tightening it would change +boot ordering and could deadlock a deploy on a dependency that is not up yet. + +``/health/ready`` is readiness, and it is new. + +**What gates readiness is deliberately narrow.** switch-core runs as a single +replica with a `Recreate` strategy, because it holds live sessions in memory and +cannot be scaled out. So a failing readiness probe does not shift traffic to a +healthy pod — there is no other pod. It empties the Service and takes the whole +deployment off the air. That makes readiness worth failing only where *not* +serving is genuinely better than serving: the database, without which every +request is an error anyway. + +A crashed collaboration bridge is a real fault, and it is reported here and +alerted on — but it must not fail readiness. Taking Switch offline entirely +because Slack's adapter died would turn one broken bridge into every broken +bridge. + +The checks run on their own schedule rather than per request. The kubelet asks +every ten seconds and the metrics exporter asks once a minute; both read the +same cached answer, so neither adds a database round trip to the other's +budget. The cache carries the time it was taken, and a cache that has stopped +being refreshed is itself reported as a failure — which is also how a wedged +event loop shows up here. +""" + +from __future__ import annotations + +import asyncio +import logging +import time +from collections.abc import Awaitable, Callable, Iterator, Sequence +from dataclasses import dataclass + +from sqlalchemy import text +from sqlalchemy.ext.asyncio import async_sessionmaker + +from switch_core.observability.catalogue import HEALTH_CHECK +from switch_core.observability.metrics import GaugeReading, MetricsRegistry + +logger = logging.getLogger(__name__) + +# How long a database round trip may take before the database counts as +# unreachable. Generous next to a healthy `SELECT 1`, and well under the +# kubelet's own probe timeout, so a slow answer is reported by us rather than +# cut off by the probe with no detail at all. +DATABASE_TIMEOUT_SECONDS = 5.0 + +# A cached result older than this is treated as no result. Set against the +# refresh interval rather than the probe interval: it has to allow a refresh to +# be slow without the answer flapping, while still catching a refresher that +# has stopped entirely. +_STALENESS_MULTIPLIER = 4 + + +@dataclass(frozen=True) +class CheckOutcome: + name: str + healthy: bool + # What is wrong, in a sentence an operator reading a 503 can act on. Empty + # when the check passed — there is nothing to say about a working thing. + detail: str + + +@dataclass(frozen=True) +class HealthCheck: + name: str + # Whether a failure should take the server out of service. See the module + # docstring: on a single-replica deployment this is a much bigger decision + # than it looks. + gates_readiness: bool + probe: Callable[[], Awaitable[CheckOutcome]] + + +@dataclass(frozen=True) +class ReadinessReport: + ready: bool + checks: Sequence[CheckOutcome] + taken_at: float + + def as_response(self) -> dict[str, object]: + return { + "status": "ready" if self.ready else "not ready", + "checks": { + check.name: { + "healthy": check.healthy, + **({"detail": check.detail} if check.detail else {}), + } + for check in self.checks + }, + } + + +def database_check(session_factory: async_sessionmaker) -> HealthCheck: + """One round trip, on an unbound session. + + `SELECT 1` deliberately, rather than counting a real table. Every scoped + table is behind row-level security, and a read with no tenant bound raises + under the restricted runtime role while passing in development — so a + health check written against real data would be the one thing that works + everywhere except production. + """ + + async def probe() -> CheckOutcome: + try: + async with asyncio.timeout(DATABASE_TIMEOUT_SECONDS): + async with session_factory() as session: + await session.execute(text("SELECT 1")) + except TimeoutError: + return CheckOutcome( + name="database", + healthy=False, + detail=( + f"No answer within {DATABASE_TIMEOUT_SECONDS:.0f}s. The " + "database is unreachable, or the pool is exhausted and " + "every connection is held." + ), + ) + except Exception as error: + return CheckOutcome( + name="database", + healthy=False, + detail=f"{type(error).__name__}: {error}", + ) + return CheckOutcome(name="database", healthy=True, detail="") + + return HealthCheck(name="database", gates_readiness=True, probe=probe) + + +def message_listener_check(is_connected: Callable[[], bool]) -> HealthCheck: + """Whether room delivery is actually happening. + + The listener holds a Postgres `LISTEN`, and every room's fan-out is woken + through it. When it is down nothing is delivered to anyone — the API still + answers, rooms still accept writes, and no message moves. It reconnects + itself with backoff, which is why this does not gate readiness: restarting + the pod would not fix it any faster, and would drop every live session to + find that out. + """ + + async def probe() -> CheckOutcome: + if is_connected(): + return CheckOutcome(name="message_listener", healthy=True, detail="") + return CheckOutcome( + name="message_listener", + healthy=False, + detail=( + "The Postgres LISTEN connection is down, so no room message is " + "being delivered. It retries with backoff; if this persists, " + "the database is refusing connections." + ), + ) + + return HealthCheck(name="message_listener", gates_readiness=False, probe=probe) + + +def bridges_check( + running: Callable[[], int], configured: Callable[[], int] +) -> HealthCheck: + """Whether every configured collaboration bridge still has a live task. + + A bridge that raises is dropped from the running set and its exception is + logged and discarded, so without this the only evidence is a line in a log + nobody is reading. Reported, never gating — see the module docstring. + """ + + async def probe() -> CheckOutcome: + live = running() + expected = configured() + if live >= expected: + return CheckOutcome(name="bridges", healthy=True, detail="") + return CheckOutcome( + name="bridges", + healthy=False, + detail=( + f"{expected - live} of {expected} configured collaboration " + "bridge(s) have crashed and are no longer running. The " + "platforms they serve are cut off; the rest of Switch is not." + ), + ) + + return HealthCheck(name="bridges", gates_readiness=False, probe=probe) + + +class HealthMonitor: + """Runs the checks on an interval and holds the latest answer.""" + + def __init__(self, checks: Sequence[HealthCheck], interval_seconds: float) -> None: + self._checks = checks + self._interval_seconds = interval_seconds + self._latest: ReadinessReport | None = None + + async def refresh(self) -> ReadinessReport: + outcomes = [] + for check in self._checks: + try: + outcomes.append(await check.probe()) + except Exception as error: + # A check that raises is a failed check. Swallowing it would + # report the dependency as healthy on the grounds that we could + # not find out, which is the exact inversion of the point. + logger.exception("Health check %s raised", check.name) + outcomes.append( + CheckOutcome( + name=check.name, + healthy=False, + detail=f"The check itself failed: {type(error).__name__}: {error}", + ) + ) + + gating = {check.name for check in self._checks if check.gates_readiness} + ready = all(outcome.healthy for outcome in outcomes if outcome.name in gating) + report = ReadinessReport( + ready=ready, checks=outcomes, taken_at=time.monotonic() + ) + self._latest = report + return report + + def current(self) -> ReadinessReport: + """The last answer, or a failing one when there is not a fresh answer. + + Never optimistic. "Nobody has checked" and "the checker has stopped" + both mean the server cannot vouch for itself, and a probe that answers + ok on that basis is worse than no probe. + """ + latest = self._latest + if latest is None: + return ReadinessReport( + ready=False, + checks=[ + CheckOutcome( + name="startup", + healthy=False, + detail="No health check has completed yet.", + ) + ], + taken_at=time.monotonic(), + ) + + age = time.monotonic() - latest.taken_at + if age > self._interval_seconds * _STALENESS_MULTIPLIER: + return ReadinessReport( + ready=False, + checks=[ + CheckOutcome( + name="health_monitor", + healthy=False, + detail=( + f"The last health check was {age:.0f}s ago and the " + "refresher runs every " + f"{self._interval_seconds:.0f}s. It has stopped, or " + "the event loop is blocked." + ), + ), + *latest.checks, + ], + taken_at=latest.taken_at, + ) + return latest + + async def run_forever(self) -> None: + while True: + try: + await self.refresh() + except asyncio.CancelledError: + raise + except Exception: + # `refresh` already handles a failing check; reaching here means + # the monitor itself is broken, and it must not stop looping. + logger.exception("Health monitor refresh raised; continuing.") + await asyncio.sleep(self._interval_seconds) + + def install(self, registry: MetricsRegistry) -> None: + registry.register_observer(self._readings) + + def _readings(self) -> Iterator[GaugeReading]: + for outcome in self.current().checks: + yield GaugeReading( + HEALTH_CHECK, 1.0 if outcome.healthy else 0.0, {"check": outcome.name} + ) diff --git a/core/switch_core/observability/http.py b/core/switch_core/observability/http.py new file mode 100644 index 000000000..891ba8722 --- /dev/null +++ b/core/switch_core/observability/http.py @@ -0,0 +1,122 @@ +"""ASGI middleware counting and timing every request. + +Plain ASGI rather than ``BaseHTTPMiddleware``, for the same reason +:mod:`switch_core.request_context` is: that one runs the rest of the app in a +separate task, and this needs to see what the router resolved in the scope the +endpoint actually ran in. + +The one thing worth being careful about is the label. A metric keyed by the +request *path* is keyed by an unbounded value — every room id, every agent id, +one series each — which is the cardinality failure the catalogue exists to +prevent, and an HTTP middleware is where it would happen first. So the label is +the route *template* the router matched, and anything unmatched is folded into +a single bucket rather than reported by the path someone happened to ask for. +That also closes the obvious griefing route: an unauthenticated 404 loop would +otherwise mint a series per request. +""" + +from __future__ import annotations + +import time + +from starlette.types import ASGIApp, Message, Receive, Scope, Send + +from switch_core.observability.catalogue import HTTP_REQUEST_DURATION, HTTP_REQUESTS +from switch_core.observability.metrics import metrics + +# Every request the router could not place, under one label. The path is +# deliberately discarded: it is attacker-chosen on a public endpoint. +UNMATCHED_ROUTE = "unmatched" + +# A request whose response never started — the client went away mid-flight, or +# the app raised before sending anything. +NO_STATUS = "none" + + +def route_label(scope: Scope) -> str: + """The matched route template, or a single bucket for everything else. + + Starlette records what it matched in the scope, and for a request that + entered a mounted sub-app (the gateway is mounted under ``/gateway``) the + inner router overwrites it with its own route — whose ``path`` is relative + to the mount. The mount's own prefix is in ``root_path``, so the two are + concatenated here; without that, the gateway's ``/rooms`` and the agent + bridge's ``/rooms`` would be counted as one route. + + Concatenated unconditionally rather than after checking whether the path + already carries the prefix. That check reads as a safe guard and is not + one: a route's path is always relative to its mount, so the prefix is never + already there — but an inner route whose name merely *starts with* the + mount's own string ("/gatewayish" under "/gateway") satisfies a + ``startswith`` test and loses its prefix, which is precisely the collision + this function exists to prevent. + """ + route = scope.get("route") + path = getattr(route, "path", None) + if not isinstance(path, str) or not path: + return UNMATCHED_ROUTE + + return f"{scope.get('root_path') or ''}{path}" + + +def status_class(status_code: int) -> str: + """ "2xx", "4xx", … — the question is "are we failing", not which code. + + The exact code is in the access log and the trace. Keeping it out of the + metric divides the series count by however many codes a route can return, + for an answer no dashboard was asking. + """ + return f"{status_code // 100}xx" + + +class MetricsMiddleware: + def __init__(self, app: ASGIApp) -> None: + self.app = app + + async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None: + if scope["type"] != "http": + await self.app(scope, receive, send) + return + + registry = metrics() + if not registry.enabled: + # Nothing configured: not even the clock is read. + await self.app(scope, receive, send) + return + + started = time.perf_counter() + seen_status: list[int] = [] + + async def send_wrapper(message: Message) -> None: + if message["type"] == "http.response.start": + seen_status.append(message["status"]) + await send(message) + + # Starlette's error handler sits *outside* this middleware, so a request + # that raises past the app never sends a response through `send` here — + # the 500 is written above us. Without catching it, the one outcome a + # dashboard most needs would be the one recorded as "no status". + outcome = NO_STATUS + try: + await self.app(scope, receive, send_wrapper) + if seen_status: + outcome = status_class(seen_status[0]) + except Exception: + outcome = "5xx" + raise + finally: + # `finally` rather than the two branches, so a cancelled request — + # the client hung up mid-response — is still counted, as the + # unfinished thing it was. + elapsed_ms = (time.perf_counter() - started) * 1000.0 + method = scope.get("method", "GET") + # Read after the call: the router fills this in as it dispatches. + route = route_label(scope) + + registry.increment( + HTTP_REQUESTS, + {"route": route, "method": method, "status_class": outcome}, + ) + registry.observe( + HTTP_REQUEST_DURATION, {"route": route, "method": method}, elapsed_ms + ) diff --git a/core/switch_core/observability/logs.py b/core/switch_core/observability/logs.py new file mode 100644 index 000000000..2cd3f020a --- /dev/null +++ b/core/switch_core/observability/logs.py @@ -0,0 +1,238 @@ +"""Shipping log records to the collector, alongside writing them to stderr. + +The server has always written Datadog-shaped JSON to its own output, and in +this deployment nothing collects it: there is no log agent in the cluster, so +those lines reach the container and stop. This is the other end of that. + +**stderr is not replaced.** The handler installed here is additional. `kubectl +logs` keeps working, a log agent added later still reads the same stream, and +a collector outage costs a copy rather than the record. + +Three things make a log exporter different from a metrics one: + +**It must never block.** `logger.info` is called from anywhere, including the +OS thread the Mattermost adapter dispatches on, and a network write inside it +would stall whatever was logging. So the handler only enqueues, and a task +drains. + +**It must never grow without bound.** A collector that stops answering while +the server keeps logging is a memory leak in the observability of the thing it +is observing. The queue is capped and drops the oldest, and says how many it +dropped — a gap that announces itself, rather than one nobody can see. + +**It must not feed itself.** Export failures are logged, and if those lines +were themselves queued for export a failing collector would generate exactly +the traffic that is failing. Two things are therefore written to stderr and +never shipped: records from this package, and anything logged while an export +is in flight — which is how the HTTP client underneath the exporter is kept +out, since it logs a line per connection at a level a deployment may well be +running at. +""" + +from __future__ import annotations + +import asyncio +import logging +import threading +from collections import deque + +from switch_core.logging_context import CONTEXT_FIELDS +from switch_core.observability.otlp import ( + AttributeValue, + LogRecord, + OtlpClient, + OtlpResource, + OtlpSendError, + build_logs_payload, + exporting_now, +) + +logger = logging.getLogger(__name__) + +# Records from this package are never shipped; see the module docstring. +_SELF = "switch_core.observability" + +# OTLP's severity numbers. Python's levels are a different scale, and a +# receiver that filters on severity is filtering on this one. +_SEVERITY = ( + (logging.CRITICAL, 21, "FATAL"), + (logging.ERROR, 17, "ERROR"), + (logging.WARNING, 13, "WARN"), + (logging.INFO, 9, "INFO"), + (logging.DEBUG, 5, "DEBUG"), +) + +# How many records may wait to be sent. Roughly a minute of a busy server at +# the interval below; past that the collector is not keeping up and the +# alternative to dropping is growing. +DEFAULT_QUEUE_CAPACITY = 10_000 + +# Records per request. Large enough that a busy interval is one or two posts, +# small enough that a single payload stays a reasonable size. +DEFAULT_BATCH_SIZE = 500 + + +def severity_of(level: int) -> tuple[int, str]: + for threshold, number, text in _SEVERITY: + if level >= threshold: + return number, text + return 1, "TRACE" + + +def _is_own_traffic(record: logging.LogRecord) -> bool: + """Whether shipping this record would help generate the next one. + + Two sources, and the second is the one that bites. This package's own + loggers are the obvious case — an "export failed" line must not be queued + for the export that is failing. Matched on a dotted-name boundary rather + than a bare prefix, so a future ``switch_core.observability_extras`` is not + silently swallowed along with it. + + The other source is the HTTP client underneath the exporter. `httpcore` + logs a line per connection at DEBUG, and DEBUG is a level a deployment may + legitimately be running at, so every export would manufacture the records + the next export has to send. Anything logged inside an export's own window + is dropped; see :func:`switch_core.observability.otlp.exporting_now`. + """ + if record.name == _SELF or record.name.startswith(f"{_SELF}."): + return True + return exporting_now() + + +class OtlpLogHandler(logging.Handler): + """Enqueues records. Sends nothing itself. + + A `logging.Handler` runs on whatever thread called `logger.info`, so this + one does the least it can: format, and append under a lock. + """ + + def __init__(self, capacity: int) -> None: + super().__init__() + self._capacity = capacity + self._lock = threading.Lock() + self._records: deque[LogRecord] = deque() + self._dropped = 0 + + def emit(self, record: logging.LogRecord) -> None: + if _is_own_traffic(record): + return + try: + entry = self._convert(record) + except Exception: + # `handleError` respects `logging.raiseExceptions` and writes to + # stderr rather than recursing through this handler. + self.handleError(record) + return + + with self._lock: + while len(self._records) >= self._capacity: + self._records.popleft() + self._dropped += 1 + self._records.append(entry) + + def _convert(self, record: logging.LogRecord) -> LogRecord: + number, text = severity_of(record.levelno) + attributes: dict[str, AttributeValue] = { + # Datadog's standard attribute for the source logger, matching what + # the JSON written to stderr already uses. + "logger.name": record.name, + "logger.thread_name": record.threadName or "", + } + # The fields the log context stamps — tenant, request, agent, user. + # They are the reason shipping logs is worth anything: without them a + # line cannot be tied to the request or the customer it belongs to. + for field in CONTEXT_FIELDS: + value = getattr(record, field, None) + if value is not None: + attributes[field] = str(value) + + if record.exc_info: + exc_type, exc_value, _ = record.exc_info + attributes["error.kind"] = ( + exc_type.__name__ if exc_type is not None else "Exception" + ) + attributes["error.message"] = str(exc_value) + attributes["error.stack"] = self.format_exception(record) + + return LogRecord( + body=record.getMessage(), + severity_text=text, + severity_number=number, + time_nanos=int(record.created * 1_000_000_000), + attributes=attributes, + ) + + def format_exception(self, record: logging.LogRecord) -> str: + formatter = self.formatter or logging.Formatter() + return formatter.formatException(record.exc_info) # type: ignore[arg-type] + + def take(self, limit: int) -> tuple[list[LogRecord], int]: + """Up to `limit` records, and how many were dropped since the last take.""" + with self._lock: + batch = [ + self._records.popleft() for _ in range(min(limit, len(self._records))) + ] + dropped = self._dropped + self._dropped = 0 + return batch, dropped + + def pending(self) -> int: + with self._lock: + return len(self._records) + + +class LogExporter: + """Drains the handler on an interval and posts what it found.""" + + def __init__( + self, + handler: OtlpLogHandler, + client: OtlpClient, + resource: OtlpResource, + interval_seconds: float, + batch_size: int, + ) -> None: + self._handler = handler + self._client = client + self._resource = resource + self._interval_seconds = interval_seconds + self._batch_size = batch_size + + async def flush_once(self) -> None: + batch, dropped = self._handler.take(self._batch_size) + if dropped: + # Loud, and carried in the log stream that is still working. A + # dropped record is a hole in the evidence, and the one thing worse + # than the hole is not knowing it is there. + logger.error( + "Dropped %d log record(s) waiting to be exported: the collector " + "is not keeping up with this server's log volume. Those lines " + "are in the container's output and nowhere else.", + dropped, + ) + if not batch: + return + + try: + await self._client.post("logs", build_logs_payload(batch, self._resource)) + except OtlpSendError as error: + logger.warning( + "Log export failed, dropping %d record(s): %s", len(batch), error + ) + + async def run_forever(self) -> None: + while True: + try: + await asyncio.sleep(self._interval_seconds) + await self.flush_once() + except asyncio.CancelledError: + await self._flush_on_shutdown() + raise + except Exception: + logger.exception("Log export loop raised; continuing.") + + async def _flush_on_shutdown(self) -> None: + try: + await self.flush_once() + except Exception: + logger.warning("Final log flush failed.", exc_info=True) diff --git a/core/switch_core/observability/metrics.py b/core/switch_core/observability/metrics.py new file mode 100644 index 000000000..0093c492d --- /dev/null +++ b/core/switch_core/observability/metrics.py @@ -0,0 +1,368 @@ +"""In-process metric aggregation, flushed to OTLP one interval at a time. + +**Why this is a module-level registry and not an injected service.** The house +rule is that services are injected, and it holds for anything a request path +depends on. Instrumentation is the exception, for the same reason logging is +one: the points worth measuring are deep — a transport delivery loop, a bridge +dispatch chokepoint, a pool event handler — and threading a registry through +every constructor between here and there would change the shape of code that +has nothing to do with observability, which is how instrumentation ends up not +being added at all. :func:`install` is called once at startup, exactly like +``configure_logging``, and :func:`metrics` returns whatever is installed. + +Nothing is installed by default, so an uninstrumented process — every test, and +every deployment that has not configured an endpoint — gets a registry that +records nothing and allocates nothing. + +Aggregation is **delta**: each collection returns what happened since the last +one and resets. A restart therefore loses at most one interval instead of +resetting a cumulative series to zero, which downstream reads as a counter +rollback. + +Recording is guarded by a lock because not every caller is on the event loop — +the Mattermost adapter dispatches inbound events from an OS thread via +``run_coroutine_threadsafe``, and a dict mutated from two threads mid-resize is +the kind of bug that appears once a month in production and never in a test. +""" + +from __future__ import annotations + +import bisect +import logging +import threading +from collections.abc import Callable, Iterable, Mapping, Sequence +from dataclasses import dataclass + +from switch_core.observability.catalogue import ( + CATALOGUE, + MAX_SERIES_PER_METRIC, + MetricSpec, +) +from switch_core.observability.otlp import ( + DEFAULT_LATENCY_BOUNDS_MS, + AttributeValue, + HistogramPoint, + MetricPayload, + NumberPoint, +) + +logger = logging.getLogger(__name__) + +# The attribute map, frozen into something hashable so it can key a series. +SeriesKey = tuple[tuple[str, AttributeValue], ...] + + +@dataclass(frozen=True) +class GaugeReading: + """One gauge value, produced at collection time by an observer.""" + + spec: MetricSpec + value: float + attributes: Mapping[str, AttributeValue] + + +# An observer is asked for its readings on every collection, rather than +# pushing them when they change. A pushed gauge keeps reporting its last value +# after whatever was setting it has stopped — so a crashed bridge would go on +# reporting the count it had when it died. A pulled one reports what is true +# now, or is absent. +GaugeObserver = Callable[[], Iterable[GaugeReading]] + +# Run just before a collection, to record anything that must be sampled on the +# collection's own schedule. See `MetricsRegistry.register_pre_collect`. +PreCollectHook = Callable[[], None] + + +def _series_key(attributes: Mapping[str, AttributeValue]) -> SeriesKey: + return tuple(sorted(attributes.items())) + + +def _validate(spec: MetricSpec, attributes: Mapping[str, AttributeValue]) -> None: + """The catalogue is a contract; a call site that breaks it is a bug. + + Raised rather than logged. A wrong attribute set is not a runtime condition + to degrade through — it is a typo or a copied call site, and it should fail + in the test that covers that code rather than quietly produce a series + nobody can group by. + """ + if spec.name not in CATALOGUE: + raise ValueError( + f"{spec.name!r} is not in the metric catalogue. Declare it in " + "switch_core.observability.catalogue before recording it." + ) + keys = set(attributes) + if keys != set(spec.attributes): + missing = sorted(set(spec.attributes) - keys) + unknown = sorted(keys - set(spec.attributes)) + raise ValueError( + f"{spec.name!r} takes attributes {sorted(spec.attributes)}; " + f"missing {missing}, unexpected {unknown}." + ) + + +class _Histogram: + """Counts per bucket for one series, reset each collection.""" + + __slots__ = ("bounds", "buckets", "count", "total") + + def __init__(self, bounds: Sequence[float]) -> None: + self.bounds = bounds + # One more bucket than bounds: the last holds everything above the + # highest bound, which is where a pathological latency shows up. + self.buckets = [0] * (len(bounds) + 1) + self.count = 0 + self.total = 0.0 + + def record(self, value: float) -> None: + self.buckets[bisect.bisect_left(self.bounds, value)] += 1 + self.count += 1 + self.total += value + + +class MetricsRegistry: + """Accumulates one interval's measurements.""" + + def __init__(self) -> None: + self._lock = threading.Lock() + self._sums: dict[str, dict[SeriesKey, float]] = {} + self._histograms: dict[str, dict[SeriesKey, _Histogram]] = {} + self._observers: list[GaugeObserver] = [] + self._pre_collect: list[PreCollectHook] = [] + # Metrics that have already been reported as over the series ceiling, + # so the warning is emitted once per interval rather than per call. + self._over_capacity: set[str] = set() + + @property + def enabled(self) -> bool: + return True + + def increment( + self, + spec: MetricSpec, + attributes: Mapping[str, AttributeValue], + amount: float = 1.0, + ) -> None: + _validate(spec, attributes) + key = _series_key(attributes) + with self._lock: + series = self._sums.setdefault(spec.name, {}) + if key not in series and not self._admits(spec.name, series): + return + series[key] = series.get(key, 0.0) + amount + + def observe( + self, + spec: MetricSpec, + attributes: Mapping[str, AttributeValue], + value: float, + ) -> None: + """Record one measurement into a histogram.""" + _validate(spec, attributes) + key = _series_key(attributes) + with self._lock: + series = self._histograms.setdefault(spec.name, {}) + if key not in series and not self._admits(spec.name, series): + return + histogram = series.get(key) + if histogram is None: + histogram = _Histogram(DEFAULT_LATENCY_BOUNDS_MS) + series[key] = histogram + histogram.record(value) + + def register_observer(self, observer: GaugeObserver) -> None: + """Add a source of gauge readings, polled on every collection.""" + with self._lock: + self._observers.append(observer) + + def register_pre_collect(self, hook: PreCollectHook) -> None: + """Add a callback run immediately before each collection. + + For the counters whose source is itself cumulative — process CPU time, + garbage collections — where the delta this interval is only knowable by + differencing against the last reading. Such a source has to be sampled + on the collection's own schedule or the delta it reports covers a + different window than the interval it is attributed to. + """ + with self._lock: + self._pre_collect.append(hook) + + def _admits(self, name: str, series: Mapping[SeriesKey, object]) -> bool: + """Whether a new series may be added, complaining once if not. + + Called with the lock held. Refusing loses the measurement, which is bad + — but accepting an unbounded attribute value is worse, and the warning + names the metric so the offending call site is one grep away. + """ + if len(series) < MAX_SERIES_PER_METRIC: + return True + if name not in self._over_capacity: + self._over_capacity.add(name) + logger.warning( + "Metric %s has reached %d distinct attribute combinations and is " + "dropping new ones. A call site is passing an unbounded value; " + "check what it puts in the attributes declared for it in " + "switch_core.observability.catalogue.", + name, + MAX_SERIES_PER_METRIC, + ) + return False + + def collect(self) -> list[MetricPayload]: + """Take everything recorded since the last call, and reset. + + Gauges are read here rather than stored, so an observer that raises + takes out its own readings and not the interval's. It is logged at + error: a gauge that has stopped reporting is a broken dashboard panel, + not a broken server. + """ + # Outside the lock: a hook records through the public methods, which + # take it themselves. + with self._lock: + hooks = list(self._pre_collect) + for hook in hooks: + try: + hook() + except Exception: + logger.exception( + "A metrics pre-collect hook raised; the counters it feeds " + "are missing from this interval." + ) + + with self._lock: + sums = self._sums + histograms = self._histograms + observers = list(self._observers) + self._sums = {} + self._histograms = {} + self._over_capacity = set() + + payloads: list[MetricPayload] = [] + + for name, series in sums.items(): + spec = CATALOGUE[name] + payloads.append( + MetricPayload( + name=spec.name, + unit=spec.unit, + description=spec.description, + kind="sum", + numbers=[ + NumberPoint(attributes=dict(key), value=value) + for key, value in series.items() + ], + histograms=(), + ) + ) + + for name, buckets in histograms.items(): + spec = CATALOGUE[name] + payloads.append( + MetricPayload( + name=spec.name, + unit=spec.unit, + description=spec.description, + kind="histogram", + numbers=(), + histograms=[ + HistogramPoint( + attributes=dict(key), + count=histogram.count, + total=histogram.total, + bucket_counts=list(histogram.buckets), + bounds=list(histogram.bounds), + ) + for key, histogram in buckets.items() + ], + ) + ) + + payloads.extend(_collect_gauges(observers)) + return payloads + + +def _collect_gauges(observers: Sequence[GaugeObserver]) -> list[MetricPayload]: + grouped: dict[str, list[NumberPoint]] = {} + for observer in observers: + try: + readings = list(observer()) + except Exception: + logger.exception( + "A metrics gauge observer raised; its readings are missing from " + "this interval." + ) + continue + for reading in readings: + _validate(reading.spec, reading.attributes) + grouped.setdefault(reading.spec.name, []).append( + NumberPoint(attributes=dict(reading.attributes), value=reading.value) + ) + + return [ + MetricPayload( + name=CATALOGUE[name].name, + unit=CATALOGUE[name].unit, + description=CATALOGUE[name].description, + kind="gauge", + numbers=points, + histograms=(), + ) + for name, points in grouped.items() + ] + + +class NullMetricsRegistry(MetricsRegistry): + """What an unconfigured process gets: every call a no-op. + + A subclass rather than a separate protocol so that ``metrics()`` has one + return type and no call site needs a ``None`` check — the thing the house + rule about optional parameters is getting at. + """ + + @property + def enabled(self) -> bool: + return False + + def increment( + self, + spec: MetricSpec, + attributes: Mapping[str, AttributeValue], + amount: float = 1.0, + ) -> None: + return + + def observe( + self, + spec: MetricSpec, + attributes: Mapping[str, AttributeValue], + value: float, + ) -> None: + return + + def register_observer(self, observer: GaugeObserver) -> None: + return + + def register_pre_collect(self, hook: PreCollectHook) -> None: + return + + def collect(self) -> list[MetricPayload]: + return [] + + +_registry: MetricsRegistry = NullMetricsRegistry() + + +def metrics() -> MetricsRegistry: + """The installed registry, or the no-op one when nothing was installed.""" + return _registry + + +def install(registry: MetricsRegistry) -> None: + """Make `registry` the process's metrics sink. Called once, at startup.""" + global _registry + _registry = registry + + +def uninstall() -> None: + """Restore the no-op registry. For tests, and for a clean shutdown.""" + global _registry + _registry = NullMetricsRegistry() diff --git a/core/switch_core/observability/otlp.py b/core/switch_core/observability/otlp.py new file mode 100644 index 000000000..375a8ab17 --- /dev/null +++ b/core/switch_core/observability/otlp.py @@ -0,0 +1,425 @@ +"""The OTLP/HTTP wire format, and the one place anything leaves the deployment. + +Hand-built JSON posted with ``httpx`` rather than the OpenTelemetry SDK, for +the same reason Switch Console hand-builds its own (see +``console/.../telemetry/relay-client.ts``): everything this deployment sends is +visible in one file, and an SDK brings its own batching, retry and identity +behaviour that would then have to be argued down. Switch is self-hosted by +people who are entitled to read exactly what their server reports and to whom. +The cost is that the wire format is ours to keep correct, which is what +``test_otlp.py`` is for. + +The encoding is protobuf's canonical JSON mapping, and its one sharp edge is +that 64-bit integers are **strings** — timestamps, histogram counts and bucket +counts. A receiver that parses strictly rejects a payload that sends them as +numbers, and the relay answers 200 either way, so nothing here would ever see +it happen. Doubles stay numbers. +""" + +from __future__ import annotations + +import logging +import time +from collections.abc import Iterator, Mapping, Sequence +from contextlib import contextmanager +from contextvars import ContextVar +from dataclasses import dataclass +from typing import Any +from urllib.parse import urljoin + +import httpx + +logger = logging.getLogger(__name__) + +# True while this task is inside an export request. +# +# Sending anything costs an HTTP call, and an HTTP client logs — `httpcore` +# emits a line per connection at DEBUG, which is a supported log level here. +# Shipping those lines would mean each export generating the records the next +# export has to send, for ever. The log handler reads this and declines to +# queue anything emitted inside the window. +# +# A context variable rather than a flag because it has to be exactly this +# task's window: another request logging at the same moment is in its own +# context and must still be shipped. +_exporting: ContextVar[bool] = ContextVar("switch_otlp_exporting", default=False) + + +def exporting_now() -> bool: + return _exporting.get() + + +@contextmanager +def _exporting_window() -> Iterator[None]: + token = _exporting.set(True) + try: + yield + finally: + _exporting.reset(token) + +# OTLP's own enum, sent as an integer. Delta rather than cumulative: Datadog +# reads delta sums and histograms directly, whereas a cumulative series has to +# be differenced at query time and reads as a permanently climbing line until +# it is. Delta also means this process keeps no running totals, so a restart +# loses one interval rather than resetting every counter to zero. +AGGREGATION_TEMPORALITY_DELTA = 1 + +# OpenTelemetry's default explicit bucket boundaries, in milliseconds. Kept as +# the library's defaults rather than tuned to Switch: a bound set chosen for +# today's latencies silently stops answering the question the day they change, +# and these already straddle the range that matters (a fast local query to a +# request nobody should be waiting on). +DEFAULT_LATENCY_BOUNDS_MS: tuple[float, ...] = ( + 5.0, + 10.0, + 25.0, + 50.0, + 75.0, + 100.0, + 250.0, + 500.0, + 750.0, + 1000.0, + 2500.0, + 5000.0, + 7500.0, + 10000.0, +) + +AttributeValue = str | bool | int | float + + +class OtlpSendError(RuntimeError): + """A payload did not reach the collector.""" + + +def _otlp_value(value: AttributeValue) -> dict[str, Any]: + # `bool` before the numbers: it is a subclass of `int` and would otherwise + # serialise as 1/0, turning a yes/no into something a receiver will average. + if isinstance(value, bool): + return {"boolValue": value} + if isinstance(value, int | float): + return {"doubleValue": float(value)} + return {"stringValue": value} + + +def otlp_attributes(values: Mapping[str, AttributeValue]) -> list[dict[str, Any]]: + """Attributes in OTLP's key/value shape, ordered so payloads are comparable. + + Sorted by key because an unordered dict makes two identical payloads + compare unequal, which is only ever felt in a test diff — but it is felt + there constantly. + """ + return [{"key": key, "value": _otlp_value(values[key])} for key in sorted(values)] + + +@dataclass(frozen=True) +class OtlpResource: + """What this process calls itself to the collector, and to Datadog beyond it. + + ``service_version`` is ``None`` when switch-core cannot read its own + version (see :mod:`switch_core.version`); it is then omitted rather than + sent as a placeholder, so a dashboard filtered by version shows the record + missing instead of attributing it to a release nobody built. + """ + + service_name: str + service_version: str | None + environment: str | None + deployment_id: str + + def attributes(self) -> dict[str, AttributeValue]: + values: dict[str, AttributeValue] = { + "service.name": self.service_name, + # The relay's guard. It requires a canonical UUID on every payload + # and drops what arrives without one, in silence and with a 200 — + # so an absent id is not a degraded send, it is no send at all. + # `SwitchConfig` refuses to start with export on and this unset. + "flint.client_id": self.deployment_id, + } + if self.service_version: + values["service.version"] = self.service_version + if self.environment: + # Datadog's unified service tagging reads `deployment.environment` + # from OTLP and maps it onto `env`. + values["deployment.environment"] = self.environment + return values + + +@dataclass(frozen=True) +class NumberPoint: + attributes: Mapping[str, AttributeValue] + value: float + + +@dataclass(frozen=True) +class HistogramPoint: + attributes: Mapping[str, AttributeValue] + count: int + total: float + bucket_counts: Sequence[int] + bounds: Sequence[float] + + +@dataclass(frozen=True) +class MetricPayload: + """One metric's points, ready to encode.""" + + name: str + unit: str + description: str + kind: str # "sum" | "gauge" | "histogram" + numbers: Sequence[NumberPoint] + histograms: Sequence[HistogramPoint] + + +def _number_data_point( + point: NumberPoint, start_nanos: int, end_nanos: int +) -> dict[str, Any]: + return { + "attributes": otlp_attributes(point.attributes), + "startTimeUnixNano": str(start_nanos), + "timeUnixNano": str(end_nanos), + # `asDouble` rather than `asInt`: OTLP's int64 is a JSON string, which + # invites a receiver to treat a count as text and makes it useless to + # average. Every value here is exact as a double. + "asDouble": point.value, + } + + +def _histogram_data_point( + point: HistogramPoint, start_nanos: int, end_nanos: int +) -> dict[str, Any]: + return { + "attributes": otlp_attributes(point.attributes), + "startTimeUnixNano": str(start_nanos), + "timeUnixNano": str(end_nanos), + # fixed64 on the wire, so strings in JSON. + "count": str(point.count), + "sum": point.total, + "bucketCounts": [str(count) for count in point.bucket_counts], + "explicitBounds": list(point.bounds), + } + + +def _encode_metric( + metric: MetricPayload, start_nanos: int, end_nanos: int +) -> dict[str, Any]: + encoded: dict[str, Any] = { + "name": metric.name, + "unit": metric.unit, + "description": metric.description, + } + if metric.kind == "gauge": + # A gauge is the current reading and carries no interval, so it gets no + # start time and no temporality. + encoded["gauge"] = { + "dataPoints": [ + { + "attributes": otlp_attributes(point.attributes), + "timeUnixNano": str(end_nanos), + "asDouble": point.value, + } + for point in metric.numbers + ] + } + elif metric.kind == "sum": + encoded["sum"] = { + "dataPoints": [ + _number_data_point(point, start_nanos, end_nanos) + for point in metric.numbers + ], + "aggregationTemporality": AGGREGATION_TEMPORALITY_DELTA, + "isMonotonic": True, + } + elif metric.kind == "histogram": + encoded["histogram"] = { + "dataPoints": [ + _histogram_data_point(point, start_nanos, end_nanos) + for point in metric.histograms + ], + "aggregationTemporality": AGGREGATION_TEMPORALITY_DELTA, + } + else: + raise ValueError(f"Unknown metric kind {metric.kind!r} for {metric.name!r}.") + return encoded + + +def build_metrics_payload( + metrics: Sequence[MetricPayload], + resource: OtlpResource, + start_nanos: int, + end_nanos: int, +) -> dict[str, Any]: + """One export interval's metrics as a single OTLP request body.""" + return { + "resourceMetrics": [ + { + "resource": {"attributes": otlp_attributes(resource.attributes())}, + "scopeMetrics": [ + { + "scope": { + "name": resource.service_name, + **( + {"version": resource.service_version} + if resource.service_version + else {} + ), + }, + "metrics": [ + _encode_metric(metric, start_nanos, end_nanos) + for metric in metrics + ], + } + ], + } + ] + } + + +@dataclass(frozen=True) +class LogRecord: + """One log line, on its way to the collector.""" + + body: str + severity_text: str + severity_number: int + time_nanos: int + attributes: Mapping[str, AttributeValue] + # Set when the record was emitted inside a span, so Datadog can pivot from + # the log to the trace it belongs to. Hex strings, as OTLP JSON wants them. + trace_id: str | None = None + span_id: str | None = None + + +def build_logs_payload( + records: Sequence[LogRecord], resource: OtlpResource +) -> dict[str, Any]: + """A batch of log records as a single OTLP request body.""" + encoded: list[dict[str, Any]] = [] + for record in records: + entry: dict[str, Any] = { + "timeUnixNano": str(record.time_nanos), + "observedTimeUnixNano": str(record.time_nanos), + "severityNumber": record.severity_number, + "severityText": record.severity_text, + "body": {"stringValue": record.body}, + "attributes": otlp_attributes(record.attributes), + } + if record.trace_id: + entry["traceId"] = record.trace_id + if record.span_id: + entry["spanId"] = record.span_id + encoded.append(entry) + + return { + "resourceLogs": [ + { + "resource": {"attributes": otlp_attributes(resource.attributes())}, + "scopeLogs": [ + { + "scope": { + "name": resource.service_name, + **( + {"version": resource.service_version} + if resource.service_version + else {} + ), + }, + "logRecords": encoded, + } + ], + } + ] + } + + +def now_nanos() -> int: + return time.time_ns() + + +class OtlpClient: + """Posts payloads to an OTLP/HTTP collector. One client, reused. + + No retry, deliberately. A metric interval lost to a flaky network is lost; + retrying would queue work behind a collector that is already struggling and + turn an observability outage into a memory leak in the thing being + observed. The loss is visible — the series has a hole — which is the + property that matters. + """ + + def __init__( + self, + base_endpoint: str, + timeout_seconds: float, + headers: Mapping[str, str], + client: httpx.AsyncClient, + ) -> None: + self._base_endpoint = base_endpoint + self._timeout_seconds = timeout_seconds + self._headers = { + "Content-Type": "application/json", + # Sent in place of whatever httpx would otherwise volunteer, so the + # collector's operators can see which client their traffic is from. + "User-Agent": "switch-core", + **headers, + } + self._client = client + + def url_for(self, signal: str) -> str: + """The endpoint for a signal, by OTLP's own base-plus-path convention. + + The same rule ``OTEL_EXPORTER_OTLP_ENDPOINT`` follows, so an operator + who has configured any other OTLP client already knows what to set. + """ + return urljoin(self._base_endpoint.rstrip("/") + "/", f"v1/{signal}") + + async def post(self, signal: str, payload: Mapping[str, Any]) -> None: + """Send one payload. Raises :class:`OtlpSendError` on any failure.""" + url = self.url_for(signal) + with _exporting_window(): + try: + response = await self._client.post( + url, + json=payload, + headers=self._headers, + timeout=self._timeout_seconds, + ) + except httpx.HTTPError as error: + raise OtlpSendError(f"POST {url} failed: {error}") from error + + if response.status_code >= 400: + raise OtlpSendError( + f"POST {url} answered {response.status_code}: {response.text[:200]}" + ) + + _raise_on_partial_rejection(url, response) + + +def _raise_on_partial_rejection(url: str, response: httpx.Response) -> None: + """OTLP allows a 200 to carry a count of records the receiver would not take. + + It is the only channel through which a rejection becomes visible at all — + a collector that drops a record for failing its own guard still answers + 200 — so the small body is worth one parse. A response that is not JSON is + not worth a second failure on top of the first. + """ + try: + body = response.json() + except ValueError: + return + if not isinstance(body, dict): + return + + partial = body.get("partialSuccess") + if not isinstance(partial, dict): + return + + rejected = partial.get("rejectedDataPoints") or partial.get("rejectedLogRecords") + if not rejected or int(rejected) == 0: + return + + raise OtlpSendError( + f"POST {url} rejected {rejected} record(s): " + f"{partial.get('errorMessage') or 'no reason given'}" + ) diff --git a/core/switch_core/observability/pool.py b/core/switch_core/observability/pool.py new file mode 100644 index 000000000..b961b8ad2 --- /dev/null +++ b/core/switch_core/observability/pool.py @@ -0,0 +1,39 @@ +"""Connection-pool readings, for the pools that have them. + +Pool exhaustion is the failure this exists for: every request waits, the health +check times out, and from the outside it looks exactly like a slow database. +The difference between the two is here. + +``AsyncEngine.pool`` is typed as the base ``Pool``, which declares none of these +— they belong to ``QueuePool``, the one the application engine actually uses. +The unpooled engine behind the notification listener is a ``NullPool`` and +genuinely has nothing to report. So this asks rather than assumes, and a pool +that cannot answer produces no reading at all instead of a zero, which would +otherwise draw a flat line that looks like an idle pool rather than an absent +one. +""" + +from __future__ import annotations + +from dataclasses import dataclass + +from sqlalchemy.ext.asyncio import AsyncEngine + + +@dataclass(frozen=True) +class PoolStats: + in_use: int + size: int + overflow: int + + +def pool_stats(engine: AsyncEngine) -> PoolStats | None: + pool = engine.pool + try: + return PoolStats( + in_use=pool.checkedout(), # type: ignore[attr-defined] + size=pool.size(), # type: ignore[attr-defined] + overflow=pool.overflow(), # type: ignore[attr-defined] + ) + except AttributeError: + return None diff --git a/core/switch_core/observability/runtime.py b/core/switch_core/observability/runtime.py new file mode 100644 index 000000000..fa9753696 --- /dev/null +++ b/core/switch_core/observability/runtime.py @@ -0,0 +1,181 @@ +"""What the process can tell you about itself. + +This is the part an infrastructure agent would normally report, and Switch has +none deployed. Most of it is cheap to read from inside the process anyway, and +two of the numbers here are ones no external agent could produce: event-loop +lag, and the count of descriptors this process in particular is holding. + +Nothing here reaches outside the process — no ``psutil``, no subprocess, no new +dependency. On Linux that is ``/proc/self``, which is what production runs on; +off Linux the readings that have no source are simply absent, because a +fabricated memory figure on a developer's laptop is worse than a missing one. +""" + +from __future__ import annotations + +import gc +import logging +import os +import resource +import sys +import threading +from collections.abc import Iterator + +from switch_core.observability.catalogue import ( + RUNTIME_CPU_SECONDS, + RUNTIME_EVENT_LOOP_LAG, + RUNTIME_GC_COLLECTIONS, + RUNTIME_MEMORY_RSS, + RUNTIME_OPEN_FDS, +) +from switch_core.observability.metrics import GaugeReading, MetricsRegistry, metrics + +logger = logging.getLogger(__name__) + +_PROC_STATM = "/proc/self/statm" +_PROC_FD = "/proc/self/fd" + + +class EventLoopLag: + """The worst oversleep seen since the last reading. + + The server is single-threaded and cooperative: one synchronous call that + blocks stalls every room, every bridge and every heartbeat at once, and + from the outside that looks like an unrelated timeout somewhere else. This + is the number that names the real cause. + + The maximum rather than the latest, because a stall is rare and brief by + nature — sampling the current value on a one-minute interval would miss + almost all of them. Reading it resets it, so each interval reports its own + worst case rather than the worst case ever seen. + """ + + def __init__(self) -> None: + self._lock = threading.Lock() + self._worst_ms = 0.0 + + def record(self, lag_seconds: float) -> None: + # A task woken early (or on time) contributes nothing; only lateness is + # lag, and a negative reading would otherwise drag the maximum down. + lag_ms = max(0.0, lag_seconds * 1000.0) + with self._lock: + self._worst_ms = max(self._worst_ms, lag_ms) + + def take(self) -> float: + with self._lock: + worst = self._worst_ms + self._worst_ms = 0.0 + return worst + + +def _resident_bytes() -> int | None: + """Current resident set size, or None where it cannot be read. + + ``/proc/self/statm`` reports pages, and its second field is the resident + count. Deliberately not ``getrusage``, whose ``ru_maxrss`` is the *peak* + and never falls — a process that briefly spiked would report that spike + forever, which reads on a graph as a leak that is not there. + """ + try: + with open(_PROC_STATM) as handle: + fields = handle.read().split() + except OSError: + return None + if len(fields) < 2: + return None + try: + pages = int(fields[1]) + except ValueError: + return None + return pages * os.sysconf("SC_PAGE_SIZE") + + +def _open_descriptors() -> int | None: + try: + return len(os.listdir(_PROC_FD)) + except OSError: + return None + + +class RuntimeMetrics: + """Samples the process and feeds the registry. + + CPU time and collection counts are cumulative at the source, so they are + differenced against the previous reading and recorded as the interval's + delta through a pre-collect hook. The rest are read at collection time. + """ + + def __init__(self, lag: EventLoopLag) -> None: + self._lag = lag + usage = resource.getrusage(resource.RUSAGE_SELF) + self._last_user = usage.ru_utime + self._last_system = usage.ru_stime + self._last_collections = self._collection_counts() + + def install(self, registry: MetricsRegistry) -> None: + registry.register_pre_collect(self._record_cumulative) + registry.register_observer(self._readings) + + @staticmethod + def _collection_counts() -> list[int]: + return [generation["collections"] for generation in gc.get_stats()] + + def _record_cumulative(self) -> None: + registry = metrics() + + usage = resource.getrusage(resource.RUSAGE_SELF) + for mode, previous, current in ( + ("user", self._last_user, usage.ru_utime), + ("system", self._last_system, usage.ru_stime), + ): + delta = current - previous + if delta > 0: + registry.increment(RUNTIME_CPU_SECONDS, {"mode": mode}, delta) + self._last_user = usage.ru_utime + self._last_system = usage.ru_stime + + counts = self._collection_counts() + for generation, current in enumerate(counts): + previous = ( + self._last_collections[generation] + if generation < len(self._last_collections) + else 0 + ) + delta = current - previous + if delta > 0: + registry.increment( + RUNTIME_GC_COLLECTIONS, {"generation": str(generation)}, delta + ) + self._last_collections = counts + + def _readings(self) -> Iterator[GaugeReading]: + resident = _resident_bytes() + if resident is not None: + yield GaugeReading(RUNTIME_MEMORY_RSS, float(resident), {}) + + descriptors = _open_descriptors() + if descriptors is not None: + yield GaugeReading(RUNTIME_OPEN_FDS, float(descriptors), {}) + + yield GaugeReading(RUNTIME_EVENT_LOOP_LAG, self._lag.take(), {}) + + +def log_unreadable_sources() -> None: + """Say once, at startup, which process readings this platform will not give. + + A missing panel on a dashboard is otherwise indistinguishable from a + healthy process that happens to be reporting nothing. + """ + missing = [] + if _resident_bytes() is None: + missing.append("memory") + if _open_descriptors() is None: + missing.append("open file descriptors") + if missing: + logger.warning( + "Process %s cannot be read on this platform (%s), so those metrics " + "will be absent. Expected off Linux; on a deployment it means " + "/proc is not mounted.", + " and ".join(missing), + sys.platform, + ) diff --git a/core/switch_core/transport/postgres.py b/core/switch_core/transport/postgres.py index fe4574647..283e9138b 100644 --- a/core/switch_core/transport/postgres.py +++ b/core/switch_core/transport/postgres.py @@ -45,6 +45,13 @@ from switch_core.db.session_scope import tenant_session from switch_core.messages.recorded_types import EPHEMERAL from switch_core.messages.row import attachments_in, text_field, thread_root_of +from switch_core.observability.catalogue import ( + DELIVERY_FAILURES, + DELIVERY_LAG, + MESSAGES_DELIVERED, + MESSAGES_SENT, +) +from switch_core.observability.metrics import metrics from switch_core.tenant_context import no_tenant, tenant_scope from switch_core.transport.content import media_content, message_content from switch_core.transport.ephemeral import EphemeralBus @@ -80,6 +87,53 @@ # delivered in bounded steps instead of one unbounded read. _DELIVERY_PAGE = 200 +# The msgtypes that make an `m.room.message` a file rather than text. Used only +# to label a metric, so a msgtype nobody listed is counted as a message — which +# is what it is. +_MEDIA_MSGTYPES = frozenset({"m.image", "m.file", "m.video", "m.audio"}) + + +def _sent_kind(event_type: str, content: dict[str, object]) -> str: + """A bounded label for what was sent. + + Four values, from a field that is not bounded at all: `send_event` takes + whatever event type its caller passes, and putting that straight into an + attribute would let a caller mint metric series. + """ + if event_type in EPHEMERAL: + return "ephemeral" + if event_type != "m.room.message": + return "event" + return "media" if content.get("msgtype") in _MEDIA_MSGTYPES else "message" + + +def _delivered_kind(event: InboundEvent) -> str: + if isinstance(event, InboundMedia): + return "media" + if isinstance(event, InboundMembership): + return "membership" + if isinstance(event, InboundCustomEvent): + return "custom" + return "message" + + +def _age_ms(sent_at: object) -> float | None: + """How long ago a row was written, in milliseconds. + + None when the value is not a datetime this can subtract, rather than a + guess: a wrong lag reading is worse than a missing one, because it is the + number an alert would fire on. + + Clamped at zero. The timestamp is the database's `now()` and the + subtraction is against this process's clock, so a small negative is + ordinary clock skew rather than a message delivered before it was sent. + """ + if not isinstance(sent_at, datetime): + return None + when = sent_at if sent_at.tzinfo is not None else sent_at.replace(tzinfo=UTC) + return max(0.0, (datetime.now(UTC) - when).total_seconds() * 1000.0) + + MEMBERSHIP_EVENT_TYPE = "m.room.member" @@ -239,6 +293,10 @@ async def _deliver_forever_unbound(self) -> None: except Exception: # One room's failure is not the other rooms' problem, # and this loop is the only delivery this client has. + # Counted as well as logged: swallowing is what keeps + # the loop alive, and it is also what makes a room that + # has stopped delivering invisible. + metrics().increment(DELIVERY_FAILURES, {}) logger.error( "Delivery failed for client %s in room %s", self.user_id, @@ -400,6 +458,11 @@ async def _deliver( handler = self._handler_for(event) if handler is None: return + kind = _delivered_kind(event) + metrics().increment(MESSAGES_DELIVERED, {"kind": kind}) + lag_ms = _age_ms(row.sent_at) + if lag_ms is not None: + metrics().observe(DELIVERY_LAG, {"kind": kind}, lag_ms) await handler(room, event) def _handler_for(self, event: InboundEvent) -> Handler | None: @@ -482,6 +545,7 @@ async def _send( row as part of it, so no subscriber can be woken for a row that a later rollback removes. """ + metrics().increment(MESSAGES_SENT, {"kind": _sent_kind(event_type, content)}) result = SendResult( event_id=new_event_id(), event_type=event_type, content=content ) diff --git a/core/tests/switch_core/bridges/collaboration/test_bridge_inbound_tenant_binding.py b/core/tests/switch_core/bridges/collaboration/test_bridge_inbound_tenant_binding.py index 9920a25ef..0b8289b4b 100644 --- a/core/tests/switch_core/bridges/collaboration/test_bridge_inbound_tenant_binding.py +++ b/core/tests/switch_core/bridges/collaboration/test_bridge_inbound_tenant_binding.py @@ -79,7 +79,7 @@ async def test_a_room_created_after_the_bridge_started_resolves_its_tenant() -> async def _handler(event: object) -> None: seen.append(current_tenant_id()) - traced = bridge._traced(_handler) + traced = bridge._traced("message", _handler) # Exactly what room creation does once the room exists (room_service), # long after `_load_channel_map` ran. @@ -101,7 +101,7 @@ async def test_an_unmapped_channel_binds_the_bridges_own_tenant() -> None: async def _handler(event: object) -> None: seen.append(current_tenant_id()) - await bridge._traced(_handler)(_event("C-unknown")) + await bridge._traced("message", _handler)(_event("C-unknown")) assert seen == [BRIDGE_TENANT] @@ -113,7 +113,7 @@ async def test_the_binding_does_not_outlive_the_event() -> None: async def _handler(event: object) -> None: assert current_tenant_id() == ROOM_TENANT - await bridge._traced(_handler)(_event("C1")) + await bridge._traced("message", _handler)(_event("C1")) assert current_tenant_id() is None @@ -154,7 +154,7 @@ async def test_the_dispatch_style_cannot_change_the_tenant() -> None: async def _handler(event: object) -> None: seen.append(current_tenant_id()) - traced = bridge._traced(_handler) + traced = bridge._traced("message", _handler) loop = asyncio.get_running_loop() from_thread: list[concurrent.futures.Future[None]] = [] diff --git a/core/tests/switch_core/bridges/collaboration/test_bridge_metrics.py b/core/tests/switch_core/bridges/collaboration/test_bridge_metrics.py new file mode 100644 index 000000000..67c3be8a3 --- /dev/null +++ b/core/tests/switch_core/bridges/collaboration/test_bridge_metrics.py @@ -0,0 +1,152 @@ +"""What a bridge reports about its own traffic (CHOO-2807). + +Inbound is counted at `_traced`, the one choke point every platform event goes +through, and outbound at the relay call rather than at the top of the handler — +a handler returns early for a puppet's own echo and for a room with no channel +mapping, and neither is something anybody sent. + +The failure counters matter more than the volume ones. A bridge handler that +raises is a message a person sent that nobody received, and from the platform's +side it looks exactly like a message nobody answered. +""" + +from __future__ import annotations + +from collections.abc import Iterator +from types import SimpleNamespace +from typing import Any + +import pytest + +from switch_core.bridges.collaboration.bridge_core import BridgeCore +from switch_core.observability.metrics import MetricsRegistry, install, uninstall + +BRIDGE_TENANT = "tenant-bridge" + + +@pytest.fixture +def registry() -> Iterator[MetricsRegistry]: + registry = MetricsRegistry() + install(registry) + yield registry + uninstall() + + +def _bridge() -> BridgeCore: + bridge = BridgeCore.__new__(BridgeCore) + bridge._bridge_id = "bridge-1" + bridge._bridge_tenant_id = BRIDGE_TENANT + bridge._bridge_type = "slack" + bridge._channel_to_room = {} + bridge._room_to_channel = {} + bridge._room_tenants = {} + return bridge + + +def _event(channel_id: str = "C1") -> SimpleNamespace: + return SimpleNamespace(channel_id=channel_id) + + +def _collect(registry: MetricsRegistry) -> dict[str, dict[tuple, float]]: + """Every counter this interval, by name. One call: collecting resets.""" + return { + payload.name: { + tuple(sorted(point.attributes.items())): point.value + for point in payload.numbers + } + for payload in registry.collect() + } + + +def _points(registry: MetricsRegistry, name: str) -> dict[tuple, float]: + return _collect(registry).get(name, {}) + + +async def test_each_inbound_event_kind_is_counted_separately(registry) -> None: + bridge = _bridge() + + async def _handler(event: object) -> None: + return None + + await bridge._traced("message", _handler)(_event()) + await bridge._traced("message", _handler)(_event()) + await bridge._traced("command", _handler)(_event()) + + assert _points(registry, "switch.bridge.events_in") == { + (("event", "message"), ("platform", "slack")): 2.0, + (("event", "command"), ("platform", "slack")): 1.0, + } + + +async def test_a_failing_inbound_handler_is_counted_and_still_raises( + registry, +) -> None: + bridge = _bridge() + + async def _handler(event: object) -> None: + raise RuntimeError("the handler is broken") + + with pytest.raises(RuntimeError, match="broken"): + await bridge._traced("message", _handler)(_event()) + + # Counted and re-raised unchanged: whoever handled it before still does. + assert _points(registry, "switch.bridge.errors") == { + (("direction", "inbound"), ("platform", "slack")): 1.0 + } + + +def test_an_outbound_relay_is_counted(registry) -> None: + bridge = _bridge() + + with bridge._counted_outbound("message"): + pass + + assert _points(registry, "switch.bridge.events_out") == { + (("kind", "message"), ("platform", "slack")): 1.0 + } + + +def test_a_failing_outbound_relay_is_counted_and_still_raises(registry) -> None: + bridge = _bridge() + + with pytest.raises(RuntimeError, match="slack is down"): + with bridge._counted_outbound("media"): + raise RuntimeError("slack is down") + + collected = _collect(registry) + assert collected["switch.bridge.errors"] == { + (("direction", "outbound"), ("platform", "slack")): 1.0 + } + # Still counted as attempted: the rate of attempts is what the failure + # rate is a fraction of. + assert collected["switch.bridge.events_out"] == { + (("kind", "media"), ("platform", "slack")): 1.0 + } + + +async def test_nothing_is_recorded_when_observability_is_off() -> None: + uninstall() + bridge = _bridge() + + async def _handler(event: object) -> None: + return None + + # The no-op registry has to accept the same calls, or an unconfigured + # deployment breaks where a configured one works. + await bridge._traced("message", _handler)(_event()) + with bridge._counted_outbound("message"): + pass + + +def test_the_platform_label_comes_from_the_bridge_not_the_caller(registry) -> None: + """Bounded by the code: five registered adapter types, not a free string.""" + bridge = _bridge() + bridge._bridge_type = "telegram" + + with bridge._counted_outbound("message"): + pass + + attributes: dict[str, Any] = dict( + next(iter(_points(registry, "switch.bridge.events_out"))) + ) + assert attributes["platform"] == "telegram" diff --git a/core/tests/switch_core/bridges/collaboration/test_bridge_outbound_admin_rendering.py b/core/tests/switch_core/bridges/collaboration/test_bridge_outbound_admin_rendering.py index 97156798f..fe4c2a7ed 100644 --- a/core/tests/switch_core/bridges/collaboration/test_bridge_outbound_admin_rendering.py +++ b/core/tests/switch_core/bridges/collaboration/test_bridge_outbound_admin_rendering.py @@ -66,6 +66,7 @@ async def send_message( def _bridge(adapter: _RecordingAdapter) -> BridgeCore: core = object.__new__(BridgeCore) + core._bridge_type = "slack" # type: ignore[attr-defined] core._adapter = adapter # type: ignore[assignment] core._puppet_matrix_ids = set() # type: ignore[assignment] core._bridge_client_matrix_user_id = "@bridge:switch.local" # type: ignore[assignment] diff --git a/core/tests/switch_core/bridges/collaboration/test_bridge_outbound_media.py b/core/tests/switch_core/bridges/collaboration/test_bridge_outbound_media.py index 7b9ab498c..d53cfbb6a 100644 --- a/core/tests/switch_core/bridges/collaboration/test_bridge_outbound_media.py +++ b/core/tests/switch_core/bridges/collaboration/test_bridge_outbound_media.py @@ -138,6 +138,7 @@ async def _room_tenant(room_id: str) -> str: return "tenant-1" ns = SimpleNamespace( + _bridge_type="slack", _adapter=adapter, _puppet_matrix_ids={"@puppet:s"}, _bridge_client_matrix_user_id="@bridge:s", @@ -164,6 +165,7 @@ async def _room_tenant(room_id: str) -> str: ) ns._relay_outbound_group = BridgeCore._relay_outbound_group.__get__(ns) ns._relay_outbound_media = BridgeCore._relay_outbound_media.__get__(ns) + ns._counted_outbound = BridgeCore._counted_outbound.__get__(ns) ns._move_indicator_for_sender = BridgeCore._move_indicator_for_sender.__get__(ns) ns._schedule_indicator_move = BridgeCore._schedule_indicator_move.__get__(ns) ns._flush_incomplete_outbound_group = ( diff --git a/core/tests/switch_core/bridges/collaboration/test_bridge_outbound_platform_rendering.py b/core/tests/switch_core/bridges/collaboration/test_bridge_outbound_platform_rendering.py index 5ee6ccb36..68bf04682 100644 --- a/core/tests/switch_core/bridges/collaboration/test_bridge_outbound_platform_rendering.py +++ b/core/tests/switch_core/bridges/collaboration/test_bridge_outbound_platform_rendering.py @@ -57,6 +57,7 @@ async def _tenant(*_args: Any, **_kwargs: Any) -> str: def _bridge(adapter: _RecordingAdapter) -> BridgeCore: core = object.__new__(BridgeCore) + core._bridge_type = "slack" # type: ignore[attr-defined] core._adapter = adapter # type: ignore[assignment] core._puppet_matrix_ids = set() # type: ignore[assignment] core._bridge_client_matrix_user_id = "@bridge:switch.local" # type: ignore[assignment] diff --git a/core/tests/switch_core/db/test_tenant_exemption_allowlist.py b/core/tests/switch_core/db/test_tenant_exemption_allowlist.py index 64c129911..baa79ec0f 100644 --- a/core/tests/switch_core/db/test_tenant_exemption_allowlist.py +++ b/core/tests/switch_core/db/test_tenant_exemption_allowlist.py @@ -116,6 +116,12 @@ # on purpose and touches only the seven functions above, which are the one # thing a session with nothing bound may read. "switch_core.db.tenant_lookup", + # ── The readiness check, which issues `SELECT 1` and reads no table at + # all. Unbound on purpose: binding a tenant would make the health of the + # database a question about one customer's rows, and reading a scoped + # table here would be the one check that passes in development and raises + # under the restricted runtime role in production. + "switch_core.observability.health", # `switch_core.transport.postgres` and `switch_core.bridges.agent.auth` # came off this list with the runtime role: the transport learned its own # tenant from its client row and the middleware learned a credential's diff --git a/core/tests/switch_core/observability/__init__.py b/core/tests/switch_core/observability/__init__.py new file mode 100644 index 000000000..e69de29bb diff --git a/core/tests/switch_core/observability/test_bootstrap.py b/core/tests/switch_core/observability/test_bootstrap.py new file mode 100644 index 000000000..e996f78d3 --- /dev/null +++ b/core/tests/switch_core/observability/test_bootstrap.py @@ -0,0 +1,252 @@ +"""Wiring: what actually starts, what it reports, and what it does when off.""" + +from __future__ import annotations + +import asyncio +import json +from contextlib import asynccontextmanager + +import pytest + +from switch_core.config import SwitchConfig +from switch_core.observability.bootstrap import RuntimeProbes, start_observability +from switch_core.observability.metrics import metrics, uninstall +from switch_core.observability.pool import PoolStats + +BASE_ENV = { + "DB_HOST": "localhost", + "DB_PORT": "5432", + "DB_USER": "postgres", + "DB_PASSWORD": "secret", + "DB_NAME": "switch", + "MATRIX_SERVER_NAME": "switch.local", + "AGENT_REGISTRATION_TOKEN": "token", + "JWT_SECRET_KEY": "jwt", + "GATEWAY_ADMIN_EMAIL": "admin@example.com", + "GATEWAY_ADMIN_PASSWORD": "pw", +} + +DEPLOYMENT_ID = "0e5d1b3a-6c1f-4c22-9a4c-3a9f5a2b7d10" + +OBSERVABILITY_KEYS = ( + "OTLP_ENDPOINT", + "OTLP_METRICS_ENABLED", + "OTLP_LOGS_ENABLED", + "OTLP_TRACES_ENABLED", + "OTLP_HEADERS", + "OTLP_TIMEOUT_SECONDS", + "OTLP_EXPORT_INTERVAL_SECONDS", + "DEPLOYMENT_ID", +) + + +def _config(monkeypatch: pytest.MonkeyPatch, **overrides: str) -> SwitchConfig: + for key in (*BASE_ENV, *OBSERVABILITY_KEYS): + monkeypatch.delenv(key, raising=False) + for key, value in {**BASE_ENV, **overrides}.items(): + monkeypatch.setenv(key.upper(), value) + return SwitchConfig() # type: ignore[call-arg] + + +class _FakeSession: + def __init__(self, fail: bool) -> None: + self._fail = fail + + async def execute(self, statement: object) -> None: + if self._fail: + raise ConnectionRefusedError("the database is not there") + + +def _session_factory(fail: bool = False): + @asynccontextmanager + async def factory(): + yield _FakeSession(fail) + + return factory + + +def _probes(**overrides) -> RuntimeProbes: + defaults = dict( + listener_connected=lambda: True, + bridges_running=lambda: 2, + bridges_configured=lambda: 2, + clients_running=lambda: 5, + agents_connected=lambda: 3, + pool_stats=lambda: PoolStats(in_use=4, size=30, overflow=0), + ) + return RuntimeProbes(**{**defaults, **overrides}) + + +@pytest.fixture(autouse=True) +def _clean_registry(): + yield + uninstall() + + +@pytest.mark.asyncio +async def test_health_runs_even_with_nothing_configured(monkeypatch): + """Readiness is how Kubernetes routes traffic; it cannot be opt-in.""" + observability = start_observability( + config=_config(monkeypatch), + version="1.0.0", + session_factory=_session_factory(), + probes=_probes(), + ) + try: + report = await observability.monitor.refresh() + assert report.ready is True + # ...but nothing is being reported anywhere. + assert metrics().enabled is False + finally: + await observability.aclose() + + +@pytest.mark.asyncio +async def test_a_dead_database_fails_readiness(monkeypatch): + observability = start_observability( + config=_config(monkeypatch), + version="1.0.0", + session_factory=_session_factory(fail=True), + probes=_probes(), + ) + try: + report = await observability.monitor.refresh() + assert report.ready is False + assert "ConnectionRefusedError" in str(report.as_response()) + finally: + await observability.aclose() + + +@pytest.mark.asyncio +async def test_a_crashed_bridge_is_reported_without_taking_the_server_down( + monkeypatch, +): + observability = start_observability( + config=_config(monkeypatch), + version="1.0.0", + session_factory=_session_factory(), + probes=_probes(bridges_running=lambda: 1, bridges_configured=lambda: 3), + ) + try: + report = await observability.monitor.refresh() + # Single replica: failing readiness here would turn one dead adapter + # into a total outage. + assert report.ready is True + assert report.as_response()["checks"]["bridges"]["healthy"] is False + finally: + await observability.aclose() + + +@pytest.mark.asyncio +async def test_an_endpoint_installs_the_registry_and_reports_state(monkeypatch): + observability = start_observability( + config=_config( + monkeypatch, + OTLP_ENDPOINT="https://collector.example", + DEPLOYMENT_ID=DEPLOYMENT_ID, + OTLP_EXPORT_INTERVAL_SECONDS="3600", + ), + version="1.0.0", + session_factory=_session_factory(), + probes=_probes(), + ) + try: + await observability.monitor.refresh() + payloads = {p.name: p for p in metrics().collect()} + + assert metrics().enabled is True + values = { + name: payload.numbers[0].value + for name, payload in payloads.items() + if payload.numbers and not payload.numbers[0].attributes + } + assert values["switch.agents.connected"] == 3.0 + assert values["switch.clients.running"] == 5.0 + assert values["switch.bridges.running"] == 2.0 + assert values["switch.db.pool.in_use"] == 4.0 + assert values["switch.db.pool.size"] == 30.0 + finally: + await observability.aclose() + + +@pytest.mark.asyncio +async def test_a_pool_that_reports_nothing_produces_no_reading(monkeypatch): + """A zero would draw an idle pool; absence draws nothing, which is true.""" + observability = start_observability( + config=_config( + monkeypatch, + OTLP_ENDPOINT="https://collector.example", + DEPLOYMENT_ID=DEPLOYMENT_ID, + OTLP_EXPORT_INTERVAL_SECONDS="3600", + ), + version="1.0.0", + session_factory=_session_factory(), + probes=_probes(pool_stats=lambda: None), + ) + try: + names = {p.name for p in metrics().collect()} + assert "switch.db.pool.in_use" not in names + assert "switch.agents.connected" in names + finally: + await observability.aclose() + + +@pytest.mark.asyncio +async def test_metrics_reach_the_collector(monkeypatch): + """End to end: a recorded measurement becomes a posted OTLP payload.""" + posted: list[dict] = [] + + async def fake_post(self, signal: str, payload: dict) -> None: + posted.append({"signal": signal, "payload": payload}) + + observability = start_observability( + config=_config( + monkeypatch, + OTLP_ENDPOINT="https://collector.example", + DEPLOYMENT_ID=DEPLOYMENT_ID, + OTLP_EXPORT_INTERVAL_SECONDS="0.05", + ), + version="9.9.9", + session_factory=_session_factory(), + probes=_probes(), + ) + try: + monkeypatch.setattr("switch_core.observability.otlp.OtlpClient.post", fake_post) + await asyncio.sleep(0.2) + finally: + await observability.aclose() + + assert posted, "the exporter never posted anything" + assert posted[0]["signal"] == "metrics" + body = posted[0]["payload"] + # It has to survive serialisation, and it has to name the deployment. + json.dumps(body) + attributes = { + entry["key"]: entry["value"] + for entry in body["resourceMetrics"][0]["resource"]["attributes"] + } + assert attributes["flint.client_id"] == {"stringValue": DEPLOYMENT_ID} + assert attributes["service.version"] == {"stringValue": "9.9.9"} + + +@pytest.mark.asyncio +async def test_closing_stops_the_loops_and_uninstalls(monkeypatch): + observability = start_observability( + config=_config( + monkeypatch, + OTLP_ENDPOINT="https://collector.example", + DEPLOYMENT_ID=DEPLOYMENT_ID, + OTLP_EXPORT_INTERVAL_SECONDS="3600", + ), + version="1.0.0", + session_factory=_session_factory(), + probes=_probes(), + ) + monkeypatch.setattr( + "switch_core.observability.otlp.OtlpClient.post", + lambda self, signal, payload: asyncio.sleep(0), + ) + await observability.aclose() + + assert metrics().enabled is False + assert all(task.done() for task in observability._tasks) diff --git a/core/tests/switch_core/observability/test_health.py b/core/tests/switch_core/observability/test_health.py new file mode 100644 index 000000000..75f286e47 --- /dev/null +++ b/core/tests/switch_core/observability/test_health.py @@ -0,0 +1,191 @@ +import asyncio + +import pytest + +from switch_core.observability.catalogue import HEALTH_CHECK +from switch_core.observability.health import ( + CheckOutcome, + HealthCheck, + HealthMonitor, + bridges_check, + message_listener_check, +) +from switch_core.observability.metrics import MetricsRegistry + + +def _check(name: str, healthy: bool, gates: bool) -> HealthCheck: + async def probe() -> CheckOutcome: + return CheckOutcome(name=name, healthy=healthy, detail="" if healthy else "no") + + return HealthCheck(name=name, gates_readiness=gates, probe=probe) + + +@pytest.mark.asyncio +async def test_all_healthy_is_ready(): + monitor = HealthMonitor([_check("database", True, True)], interval_seconds=1.0) + report = await monitor.refresh() + + assert report.ready is True + assert report.as_response()["status"] == "ready" + + +@pytest.mark.asyncio +async def test_a_failing_gating_check_fails_readiness(): + monitor = HealthMonitor([_check("database", False, True)], interval_seconds=1.0) + report = await monitor.refresh() + + assert report.ready is False + assert report.as_response()["checks"]["database"]["detail"] == "no" + + +@pytest.mark.asyncio +async def test_a_failing_non_gating_check_is_reported_but_stays_ready(): + """switch-core is a single replica: failing readiness is a total outage. + + A dead Slack adapter must not take the whole server off the air. + """ + monitor = HealthMonitor( + [_check("database", True, True), _check("bridges", False, False)], + interval_seconds=1.0, + ) + report = await monitor.refresh() + + assert report.ready is True + assert report.as_response()["checks"]["bridges"]["healthy"] is False + + +@pytest.mark.asyncio +async def test_a_check_that_raises_counts_as_failed(): + async def explode() -> CheckOutcome: + raise RuntimeError("boom") + + monitor = HealthMonitor( + [HealthCheck(name="database", gates_readiness=True, probe=explode)], + interval_seconds=1.0, + ) + report = await monitor.refresh() + + # Reporting healthy because we could not find out is the exact inversion of + # what a health check is for. + assert report.ready is False + assert "RuntimeError" in report.as_response()["checks"]["database"]["detail"] + + +@pytest.mark.asyncio +async def test_healthy_checks_carry_no_detail(): + monitor = HealthMonitor([_check("database", True, True)], interval_seconds=1.0) + await monitor.refresh() + + assert monitor.current().as_response()["checks"]["database"] == {"healthy": True} + + +def test_before_the_first_check_the_server_is_not_ready(): + monitor = HealthMonitor([_check("database", True, True)], interval_seconds=1.0) + report = monitor.current() + + assert report.ready is False + assert "No health check has completed" in str(report.as_response()) + + +@pytest.mark.asyncio +async def test_a_stale_answer_is_not_a_good_answer(monkeypatch): + """A refresher that has stopped means the server cannot vouch for itself.""" + monitor = HealthMonitor([_check("database", True, True)], interval_seconds=1.0) + await monitor.refresh() + assert monitor.current().ready is True + + clock = [monitor.current().taken_at + 100.0] + monkeypatch.setattr( + "switch_core.observability.health.time.monotonic", lambda: clock[0] + ) + + report = monitor.current() + assert report.ready is False + assert "health_monitor" in report.as_response()["checks"] + + +@pytest.mark.asyncio +async def test_the_stale_report_still_shows_what_was_last_known(monkeypatch): + monitor = HealthMonitor( + [_check("database", True, True), _check("bridges", False, False)], + interval_seconds=1.0, + ) + await monitor.refresh() + clock = [monitor.current().taken_at + 100.0] + monkeypatch.setattr( + "switch_core.observability.health.time.monotonic", lambda: clock[0] + ) + + checks = monitor.current().as_response()["checks"] + assert set(checks) == {"health_monitor", "database", "bridges"} + + +@pytest.mark.asyncio +async def test_message_listener_check_follows_the_connection(): + connected = [True] + check = message_listener_check(lambda: connected[0]) + + assert (await check.probe()).healthy is True + connected[0] = False + outcome = await check.probe() + assert outcome.healthy is False + assert "LISTEN" in outcome.detail + # Reconnects itself with backoff, so restarting the pod would not help. + assert check.gates_readiness is False + + +@pytest.mark.asyncio +async def test_bridges_check_counts_the_missing_ones(): + check = bridges_check(running=lambda: 1, configured=lambda: 3) + outcome = await check.probe() + + assert outcome.healthy is False + assert "2 of 3" in outcome.detail + assert check.gates_readiness is False + + +@pytest.mark.asyncio +async def test_bridges_check_is_healthy_when_none_are_configured(): + check = bridges_check(running=lambda: 0, configured=lambda: 0) + assert (await check.probe()).healthy is True + + +@pytest.mark.asyncio +async def test_checks_become_a_gauge_per_dependency(): + monitor = HealthMonitor( + [_check("database", True, True), _check("bridges", False, False)], + interval_seconds=1.0, + ) + await monitor.refresh() + + registry = MetricsRegistry() + monitor.install(registry) + payload = next(p for p in registry.collect() if p.name == HEALTH_CHECK.name) + + values = {point.attributes["check"]: point.value for point in payload.numbers} + # One series per dependency, so an alert says which one broke. + assert values == {"database": 1.0, "bridges": 0.0} + + +@pytest.mark.asyncio +async def test_run_forever_keeps_going_after_a_broken_refresh(monkeypatch): + calls = [0] + + async def flaky() -> CheckOutcome: + calls[0] += 1 + if calls[0] == 1: + raise RuntimeError("first one fails") + return CheckOutcome(name="database", healthy=True, detail="") + + monitor = HealthMonitor( + [HealthCheck(name="database", gates_readiness=True, probe=flaky)], + interval_seconds=0.01, + ) + task = asyncio.create_task(monitor.run_forever()) + try: + await asyncio.sleep(0.1) + finally: + task.cancel() + + assert calls[0] > 1 + assert monitor.current().ready is True diff --git a/core/tests/switch_core/observability/test_http_metrics.py b/core/tests/switch_core/observability/test_http_metrics.py new file mode 100644 index 000000000..8acbac770 --- /dev/null +++ b/core/tests/switch_core/observability/test_http_metrics.py @@ -0,0 +1,144 @@ +import pytest +from fastapi import FastAPI +from starlette.testclient import TestClient + +from switch_core.observability.catalogue import HTTP_REQUEST_DURATION, HTTP_REQUESTS +from switch_core.observability.http import MetricsMiddleware +from switch_core.observability.metrics import MetricsRegistry, install, uninstall + + +@pytest.fixture +def registry(): + registry = MetricsRegistry() + install(registry) + yield registry + uninstall() + + +def _app() -> FastAPI: + app = FastAPI() + inner = FastAPI() + + @app.get("/rooms/{room_id}") + async def room(room_id: str) -> dict[str, str]: + return {"id": room_id} + + @app.get("/boom") + async def boom() -> None: + raise RuntimeError("boom") + + @inner.get("/rooms") + async def gateway_rooms() -> list[str]: + return [] + + app.mount("/gateway", inner) + app.add_middleware(MetricsMiddleware) + return app + + +def _counts(registry: MetricsRegistry) -> dict[tuple, float]: + payload = next(p for p in registry.collect() if p.name == HTTP_REQUESTS.name) + return { + tuple(sorted(point.attributes.items())): point.value + for point in payload.numbers + } + + +def test_a_path_parameter_does_not_become_a_series(registry): + with TestClient(_app()) as client: + for room_id in ("a", "b", "c"): + client.get(f"/rooms/{room_id}") + + counts = _counts(registry) + # Three requests, one series: keyed by the template, not the id. + assert len(counts) == 1 + assert next(iter(counts.values())) == 3.0 + assert dict(next(iter(counts))) == { + "route": "/rooms/{room_id}", + "method": "GET", + "status_class": "2xx", + } + + +def test_an_unmatched_path_is_folded_into_one_bucket(registry): + with TestClient(_app()) as client: + for index in range(5): + client.get(f"/nope/{index}") + + counts = _counts(registry) + # Otherwise an unauthenticated 404 loop mints a series per request. + assert len(counts) == 1 + attributes = dict(next(iter(counts))) + assert attributes["route"] == "unmatched" + assert attributes["status_class"] == "4xx" + + +def test_a_mounted_route_keeps_its_prefix(registry): + with TestClient(_app()) as client: + client.get("/gateway/rooms") + + routes = {dict(key)["route"] for key in _counts(registry)} + # The gateway's /rooms and the bridge's /rooms are different routes and + # must not be counted as one. + assert routes == {"/gateway/rooms"} + + +def test_an_unhandled_exception_is_still_counted(registry): + client = TestClient(_app(), raise_server_exceptions=False) + client.get("/boom") + + counts = _counts(registry) + attributes = dict(next(iter(counts))) + assert attributes["route"] == "/boom" + assert attributes["status_class"] == "5xx" + + +def test_duration_is_recorded_per_route(registry): + with TestClient(_app()) as client: + client.get("/rooms/a") + + payload = next( + p for p in registry.collect() if p.name == HTTP_REQUEST_DURATION.name + ) + point = payload.histograms[0] + assert point.count == 1 + assert point.attributes == {"route": "/rooms/{room_id}", "method": "GET"} + + +def test_nothing_is_recorded_when_no_registry_is_installed(): + uninstall() + with TestClient(_app()) as client: + response = client.get("/rooms/a") + # The middleware must be transparent when observability is off, which is + # every test and every unconfigured deployment. + assert response.status_code == 200 + + +def test_an_inner_route_sharing_the_mounts_name_keeps_its_prefix(registry): + """The collision a `startswith` check silently allowed. + + `/gatewayish` under a `/gateway` mount starts with the mount's own string, + so a prefix test that asked "is it already prefixed?" answered yes and + dropped it — losing exactly the distinction this label exists to keep. + """ + app = FastAPI() + inner = FastAPI() + + @inner.get("/gatewayish") + async def inner_route() -> dict[str, str]: + return {} + + app.mount("/gateway", inner) + app.add_middleware(MetricsMiddleware) + + with TestClient(app) as client: + client.get("/gateway/gatewayish") + + assert {dict(key)["route"] for key in _counts(registry)} == {"/gateway/gatewayish"} + + +def test_an_unmounted_route_is_not_given_a_prefix(registry): + with TestClient(_app()) as client: + client.get("/rooms/a") + + assert {dict(key)["route"] for key in _counts(registry)} == {"/rooms/{room_id}"} diff --git a/core/tests/switch_core/observability/test_logs.py b/core/tests/switch_core/observability/test_logs.py new file mode 100644 index 000000000..d33d638cc --- /dev/null +++ b/core/tests/switch_core/observability/test_logs.py @@ -0,0 +1,228 @@ +import logging + +import pytest + +from switch_core.logging_context import LogContextFilter, log_context +from switch_core.observability.logs import ( + LogExporter, + OtlpLogHandler, + severity_of, +) +from switch_core.observability.otlp import OtlpResource, OtlpSendError + +RESOURCE = OtlpResource( + service_name="switch-core", + service_version="1.0.0", + environment="pilot", + deployment_id="0e5d1b3a-6c1f-4c22-9a4c-3a9f5a2b7d10", +) + + +def _record( + name: str = "switch_core.rooms", + level: int = logging.INFO, + message: str = "hello %s", + args: tuple = (), + exc_info=None, +) -> logging.LogRecord: + return logging.LogRecord( + name=name, + level=level, + pathname=__file__, + lineno=1, + msg=message, + args=args, + exc_info=exc_info, + ) + + +@pytest.mark.parametrize( + ("level", "number", "text"), + [ + (logging.DEBUG, 5, "DEBUG"), + (logging.INFO, 9, "INFO"), + (logging.WARNING, 13, "WARN"), + (logging.ERROR, 17, "ERROR"), + (logging.CRITICAL, 21, "FATAL"), + (1, 1, "TRACE"), + ], +) +def test_python_levels_map_onto_otlp_severity(level, number, text): + """A receiver filtering by severity is filtering on OTLP's scale, not ours.""" + assert severity_of(level) == (number, text) + + +def test_a_record_becomes_a_formatted_body(): + handler = OtlpLogHandler(capacity=10) + handler.emit(_record(args=("world",))) + + batch, dropped = handler.take(10) + assert dropped == 0 + assert batch[0].body == "hello world" + assert batch[0].severity_text == "INFO" + assert batch[0].attributes["logger.name"] == "switch_core.rooms" + + +def test_the_log_context_travels_with_the_record(): + """The whole reason to ship logs: a line you can tie to a tenant.""" + handler = OtlpLogHandler(capacity=10) + handler.addFilter(LogContextFilter("default")) + + with log_context(request_id="req-1", agent_id="agent-7"): + record = _record(args=("world",)) + for filter_ in handler.filters: + filter_.filter(record) + handler.emit(record) + + attributes = handler.take(10)[0][0].attributes + assert attributes["request_id"] == "req-1" + assert attributes["agent_id"] == "agent-7" + assert attributes["tenant_id"] == "default" + + +def test_an_exception_becomes_datadog_error_attributes(): + handler = OtlpLogHandler(capacity=10) + try: + raise ValueError("it broke") + except ValueError: + import sys + + handler.emit( + _record(level=logging.ERROR, args=("world",), exc_info=sys.exc_info()) + ) + + attributes = handler.take(10)[0][0].attributes + assert attributes["error.kind"] == "ValueError" + assert attributes["error.message"] == "it broke" + assert "ValueError: it broke" in str(attributes["error.stack"]) + + +def test_the_exporters_own_records_are_never_shipped(): + """Otherwise a failing collector generates the traffic that is failing.""" + handler = OtlpLogHandler(capacity=10) + handler.emit(_record(name="switch_core.observability.logs", message="failed")) + handler.emit(_record(name="switch_core.observability.exporter", message="failed")) + handler.emit(_record(name="switch_core.rooms", message="kept")) + + batch, _ = handler.take(10) + assert [entry.body for entry in batch] == ["kept"] + + +def test_a_full_queue_drops_the_oldest_and_counts_it(): + handler = OtlpLogHandler(capacity=3) + for index in range(5): + handler.emit(_record(message="line %d", args=(index,))) + + batch, dropped = handler.take(10) + # A bounded queue is the difference between losing records and losing the + # server; the count is what stops the loss being silent. + assert [entry.body for entry in batch] == ["line 2", "line 3", "line 4"] + assert dropped == 2 + + +def test_the_dropped_count_resets_once_reported(): + handler = OtlpLogHandler(capacity=1) + handler.emit(_record(message="a")) + handler.emit(_record(message="b")) + assert handler.take(10)[1] == 1 + assert handler.take(10)[1] == 0 + + +def test_take_is_bounded_by_the_batch_size(): + handler = OtlpLogHandler(capacity=100) + for index in range(10): + handler.emit(_record(message="line %d", args=(index,))) + + batch, _ = handler.take(4) + assert len(batch) == 4 + assert handler.pending() == 6 + + +class _Client: + def __init__(self, fail: bool = False) -> None: + self.posted: list[tuple[str, dict]] = [] + self._fail = fail + + async def post(self, signal: str, payload: dict) -> None: + if self._fail: + raise OtlpSendError("collector is down") + self.posted.append((signal, payload)) + + +@pytest.mark.asyncio +async def test_a_flush_posts_the_batch_as_logs(): + handler = OtlpLogHandler(capacity=10) + handler.emit(_record(message="one")) + handler.emit(_record(message="two")) + client = _Client() + + await LogExporter(handler, client, RESOURCE, 1.0, 500).flush_once() + + signal, payload = client.posted[0] + assert signal == "logs" + records = payload["resourceLogs"][0]["scopeLogs"][0]["logRecords"] + assert [entry["body"]["stringValue"] for entry in records] == ["one", "two"] + + +@pytest.mark.asyncio +async def test_an_empty_queue_posts_nothing(): + client = _Client() + await LogExporter(OtlpLogHandler(10), client, RESOURCE, 1.0, 500).flush_once() + assert client.posted == [] + + +@pytest.mark.asyncio +async def test_a_failed_post_is_reported_and_does_not_raise(caplog): + handler = OtlpLogHandler(capacity=10) + handler.emit(_record(message="one")) + exporter = LogExporter(handler, _Client(fail=True), RESOURCE, 1.0, 500) + + with caplog.at_level(logging.WARNING): + await exporter.flush_once() + + assert "Log export failed" in caplog.text + + +@pytest.mark.asyncio +async def test_dropped_records_are_reported_at_error(caplog): + handler = OtlpLogHandler(capacity=1) + handler.emit(_record(message="a")) + handler.emit(_record(message="b")) + exporter = LogExporter(handler, _Client(), RESOURCE, 1.0, 500) + + with caplog.at_level(logging.ERROR): + await exporter.flush_once() + + assert "Dropped 1 log record" in caplog.text + + +def test_records_logged_during_an_export_are_not_queued(): + """The feedback loop: the exporter's own HTTP client logs. + + `httpcore` emits a line per connection at DEBUG, and DEBUG is a level a + deployment may be running at — so without this each export manufactures + the records the next export has to send, for ever. + """ + from switch_core.observability.otlp import _exporting_window + + handler = OtlpLogHandler(capacity=10) + + with _exporting_window(): + handler.emit(_record(name="httpcore.connection", message="connect_tcp")) + handler.emit(_record(name="httpcore.connection", message="a real request")) + + batch, _ = handler.take(10) + # Outside the window the same logger is shipped normally: this suppresses + # the exporter's own traffic, not a whole library. + assert [entry.body for entry in batch] == ["a real request"] + + +def test_the_self_exclusion_is_anchored_on_a_name_boundary(): + handler = OtlpLogHandler(capacity=10) + handler.emit(_record(name="switch_core.observability", message="dropped")) + handler.emit(_record(name="switch_core.observability.logs", message="dropped")) + # A bare prefix test would swallow this one too, and it is not ours. + handler.emit(_record(name="switch_core.observability_extras", message="kept")) + + batch, _ = handler.take(10) + assert [entry.body for entry in batch] == ["kept"] diff --git a/core/tests/switch_core/observability/test_metrics.py b/core/tests/switch_core/observability/test_metrics.py new file mode 100644 index 000000000..87f90e70f --- /dev/null +++ b/core/tests/switch_core/observability/test_metrics.py @@ -0,0 +1,188 @@ +import logging + +import pytest + +from switch_core.observability.catalogue import ( + HTTP_REQUEST_DURATION, + HTTP_REQUESTS, + MAX_SERIES_PER_METRIC, + MetricSpec, +) +from switch_core.observability.metrics import ( + GaugeReading, + MetricsRegistry, + NullMetricsRegistry, + install, + metrics, + uninstall, +) + +AGENTS = MetricSpec( + name="switch.agents.connected", + kind="gauge", + unit="{agent}", + description="Agents connected.", +) + +REQUEST_ATTRS = {"route": "/health", "method": "GET", "status_class": "2xx"} + + +@pytest.fixture +def registry() -> MetricsRegistry: + return MetricsRegistry() + + +def _by_name(payloads) -> dict[str, object]: + return {payload.name: payload for payload in payloads} + + +def test_counter_accumulates_then_resets(registry: MetricsRegistry): + registry.increment(HTTP_REQUESTS, REQUEST_ATTRS) + registry.increment(HTTP_REQUESTS, REQUEST_ATTRS) + + first = _by_name(registry.collect())[HTTP_REQUESTS.name] + assert first.numbers[0].value == 2.0 + assert first.kind == "sum" + + # Delta: the next interval starts at nothing, so a restart loses one + # interval instead of reading downstream as a counter rollback. + assert registry.collect() == [] + + +def test_counters_are_kept_apart_by_attributes(registry: MetricsRegistry): + registry.increment(HTTP_REQUESTS, REQUEST_ATTRS) + registry.increment(HTTP_REQUESTS, {**REQUEST_ATTRS, "status_class": "5xx"}) + + points = _by_name(registry.collect())[HTTP_REQUESTS.name].numbers + classes = {point.attributes["status_class"]: point.value for point in points} + assert classes == {"2xx": 1.0, "5xx": 1.0} + + +def test_unknown_attribute_is_a_bug_and_raises(registry: MetricsRegistry): + with pytest.raises(ValueError, match="unexpected \\['room_id'\\]"): + registry.increment(HTTP_REQUESTS, {**REQUEST_ATTRS, "room_id": "r1"}) + + +def test_missing_attribute_is_a_bug_and_raises(registry: MetricsRegistry): + with pytest.raises(ValueError, match="missing \\['status_class'\\]"): + registry.increment(HTTP_REQUESTS, {"route": "/health", "method": "GET"}) + + +def test_histogram_buckets_by_upper_bound(registry: MetricsRegistry): + for value in (1.0, 7.0, 7.5, 999_999.0): + registry.observe(HTTP_REQUEST_DURATION, {"route": "/x", "method": "GET"}, value) + + point = _by_name(registry.collect())[HTTP_REQUEST_DURATION.name].histograms[0] + assert point.count == 4 + assert point.total == pytest.approx(1_000_014.5) + # Bounds start (5, 10, ...): 1.0 falls in the first bucket, 7.0 and 7.5 in + # the second, and the outlier in the overflow bucket at the end. + assert point.bucket_counts[0] == 1 + assert point.bucket_counts[1] == 2 + assert point.bucket_counts[-1] == 1 + assert sum(point.bucket_counts) == point.count + + +def test_histogram_resets_between_intervals(registry: MetricsRegistry): + registry.observe(HTTP_REQUEST_DURATION, {"route": "/x", "method": "GET"}, 1.0) + registry.collect() + assert registry.collect() == [] + + +def test_gauges_are_pulled_at_collection_not_pushed(registry: MetricsRegistry): + current = [1.0] + registry.register_observer(lambda: [GaugeReading(AGENTS, current[0], {})]) + + assert _by_name(registry.collect())[AGENTS.name].numbers[0].value == 1.0 + current[0] = 4.0 + # Pulled, so the second interval reports what is true then — a pushed gauge + # would still be reporting 1.0 until something set it again. + assert _by_name(registry.collect())[AGENTS.name].numbers[0].value == 4.0 + + +def test_a_broken_observer_loses_only_its_own_readings( + registry: MetricsRegistry, caplog +): + def broken(): + raise RuntimeError("no") + + registry.register_observer(broken) + registry.register_observer(lambda: [GaugeReading(AGENTS, 2.0, {})]) + + with caplog.at_level(logging.ERROR): + payloads = _by_name(registry.collect()) + + assert payloads[AGENTS.name].numbers[0].value == 2.0 + assert "gauge observer raised" in caplog.text + + +def test_pre_collect_hooks_run_before_the_drain(registry: MetricsRegistry): + registry.register_pre_collect( + lambda: registry.increment(HTTP_REQUESTS, REQUEST_ATTRS, 5.0) + ) + # The hook's counter must appear in the interval it was recorded for, not + # the one after it. + assert _by_name(registry.collect())[HTTP_REQUESTS.name].numbers[0].value == 5.0 + + +def test_a_broken_pre_collect_hook_does_not_lose_the_interval( + registry: MetricsRegistry, caplog +): + def broken(): + raise RuntimeError("no") + + registry.register_pre_collect(broken) + registry.increment(HTTP_REQUESTS, REQUEST_ATTRS) + + with caplog.at_level(logging.ERROR): + payloads = _by_name(registry.collect()) + + assert payloads[HTTP_REQUESTS.name].numbers[0].value == 1.0 + assert "pre-collect hook raised" in caplog.text + + +def test_series_ceiling_drops_and_complains_once(registry: MetricsRegistry, caplog): + with caplog.at_level(logging.WARNING): + for index in range(MAX_SERIES_PER_METRIC + 10): + registry.increment( + HTTP_REQUESTS, {**REQUEST_ATTRS, "route": f"/room/{index}"} + ) + + points = _by_name(registry.collect())[HTTP_REQUESTS.name].numbers + assert len(points) == MAX_SERIES_PER_METRIC + # Loud, but once — a warning per dropped call would bury the log it is + # trying to draw attention to. + assert caplog.text.count("distinct attribute combinations") == 1 + + +def test_an_existing_series_still_records_at_the_ceiling(registry: MetricsRegistry): + for index in range(MAX_SERIES_PER_METRIC): + registry.increment(HTTP_REQUESTS, {**REQUEST_ATTRS, "route": f"/r/{index}"}) + registry.increment(HTTP_REQUESTS, {**REQUEST_ATTRS, "route": "/r/0"}) + + points = _by_name(registry.collect())[HTTP_REQUESTS.name].numbers + first = next(p for p in points if p.attributes["route"] == "/r/0") + assert first.value == 2.0 + + +def test_nothing_is_installed_by_default(): + assert metrics().enabled is False + # The no-op has to accept every call the real one does, or an uninstrumented + # process crashes where an instrumented one works. + metrics().increment(HTTP_REQUESTS, REQUEST_ATTRS) + metrics().observe(HTTP_REQUEST_DURATION, {"route": "/x", "method": "GET"}, 1.0) + metrics().register_observer(lambda: []) + metrics().register_pre_collect(lambda: None) + assert metrics().collect() == [] + + +def test_install_and_uninstall_swap_the_sink(): + registry = MetricsRegistry() + install(registry) + try: + assert metrics() is registry + assert metrics().enabled is True + finally: + uninstall() + + assert isinstance(metrics(), NullMetricsRegistry) diff --git a/core/tests/switch_core/observability/test_otlp.py b/core/tests/switch_core/observability/test_otlp.py new file mode 100644 index 000000000..d67892a9f --- /dev/null +++ b/core/tests/switch_core/observability/test_otlp.py @@ -0,0 +1,283 @@ +"""The OTLP wire format is ours to keep correct, so it is tested directly. + +The encoding's sharp edge is protobuf JSON's rule that 64-bit integers travel +as strings. A receiver that parses strictly rejects a payload that sends them +as numbers, and the relay answers 200 either way — so nothing but a test will +ever notice. +""" + +import json + +import httpx +import pytest + +from switch_core.observability.otlp import ( + AGGREGATION_TEMPORALITY_DELTA, + HistogramPoint, + LogRecord, + MetricPayload, + NumberPoint, + OtlpClient, + OtlpResource, + OtlpSendError, + build_logs_payload, + build_metrics_payload, + otlp_attributes, +) + +RESOURCE = OtlpResource( + service_name="switch-core", + service_version="1.2.3", + environment="pilot", + deployment_id="0e5d1b3a-6c1f-4c22-9a4c-3a9f5a2b7d10", +) + +START_NANOS = 1_700_000_000_000_000_000 +END_NANOS = 1_700_000_060_000_000_000 + + +def _sum_metric() -> MetricPayload: + return MetricPayload( + name="switch.http.requests", + unit="{request}", + description="HTTP requests served.", + kind="sum", + numbers=[NumberPoint(attributes={"route": "/health"}, value=3.0)], + histograms=(), + ) + + +def test_attribute_values_keep_their_type(): + encoded = otlp_attributes({"text": "a", "flag": True, "count": 2}) + by_key = {entry["key"]: entry["value"] for entry in encoded} + + assert by_key["text"] == {"stringValue": "a"} + # bool is a subclass of int; encoding it as a number would turn a yes/no + # into something a receiver will happily average. + assert by_key["flag"] == {"boolValue": True} + assert by_key["count"] == {"doubleValue": 2.0} + + +def test_attributes_are_ordered_by_key(): + encoded = otlp_attributes({"b": "1", "a": "2"}) + assert [entry["key"] for entry in encoded] == ["a", "b"] + + +def test_resource_carries_the_deployment_id_the_relay_guards_on(): + attributes = RESOURCE.attributes() + assert attributes["flint.client_id"] == RESOURCE.deployment_id + assert attributes["service.name"] == "switch-core" + assert attributes["deployment.environment"] == "pilot" + + +def test_unknown_version_is_omitted_rather_than_placeheld(): + resource = OtlpResource( + service_name="switch-core", + service_version=None, + environment=None, + deployment_id=RESOURCE.deployment_id, + ) + attributes = resource.attributes() + + assert "service.version" not in attributes + assert "deployment.environment" not in attributes + + +def test_sum_points_are_delta_and_monotonic(): + payload = build_metrics_payload([_sum_metric()], RESOURCE, START_NANOS, END_NANOS) + metric = payload["resourceMetrics"][0]["scopeMetrics"][0]["metrics"][0] + + assert metric["sum"]["aggregationTemporality"] == AGGREGATION_TEMPORALITY_DELTA + assert metric["sum"]["isMonotonic"] is True + + point = metric["sum"]["dataPoints"][0] + assert point["asDouble"] == 3.0 + # The whole point of the test file. + assert point["startTimeUnixNano"] == str(START_NANOS) + assert point["timeUnixNano"] == str(END_NANOS) + assert isinstance(point["startTimeUnixNano"], str) + + +def test_gauge_points_carry_no_interval(): + gauge = MetricPayload( + name="switch.agents.connected", + unit="{agent}", + description="Agents connected.", + kind="gauge", + numbers=[NumberPoint(attributes={}, value=7.0)], + histograms=(), + ) + payload = build_metrics_payload([gauge], RESOURCE, START_NANOS, END_NANOS) + metric = payload["resourceMetrics"][0]["scopeMetrics"][0]["metrics"][0] + + point = metric["gauge"]["dataPoints"][0] + assert point["asDouble"] == 7.0 + # A reading, not an interval: a start time would claim the value held for + # the whole window, which is exactly what a gauge does not say. + assert "startTimeUnixNano" not in point + assert "aggregationTemporality" not in metric["gauge"] + + +def test_histogram_counts_are_strings_and_bounds_are_numbers(): + histogram = MetricPayload( + name="switch.http.request.duration", + unit="ms", + description="Request duration.", + kind="histogram", + numbers=(), + histograms=[ + HistogramPoint( + attributes={"route": "/health"}, + count=2, + total=12.5, + bucket_counts=[1, 1, 0], + bounds=[5.0, 10.0], + ) + ], + ) + payload = build_metrics_payload([histogram], RESOURCE, START_NANOS, END_NANOS) + metric = payload["resourceMetrics"][0]["scopeMetrics"][0]["metrics"][0] + point = metric["histogram"]["dataPoints"][0] + + assert point["count"] == "2" + assert point["bucketCounts"] == ["1", "1", "0"] + # Doubles stay numbers; only the 64-bit integers become strings. + assert point["explicitBounds"] == [5.0, 10.0] + assert point["sum"] == 12.5 + + +def test_unknown_metric_kind_is_refused(): + broken = MetricPayload( + name="switch.bogus", + unit="1", + description="", + kind="summary", + numbers=(), + histograms=(), + ) + with pytest.raises(ValueError, match="Unknown metric kind"): + build_metrics_payload([broken], RESOURCE, START_NANOS, END_NANOS) + + +def test_metrics_payload_is_json_serialisable(): + payload = build_metrics_payload([_sum_metric()], RESOURCE, START_NANOS, END_NANOS) + # A payload that cannot be serialised fails inside httpx, one layer below + # anything that could report it usefully. + json.dumps(payload) + + +def test_log_records_carry_trace_ids_only_when_present(): + records = [ + LogRecord( + body="hello", + severity_text="INFO", + severity_number=9, + time_nanos=END_NANOS, + attributes={"logger.name": "switch_core.test"}, + ), + LogRecord( + body="traced", + severity_text="ERROR", + severity_number=17, + time_nanos=END_NANOS, + attributes={}, + trace_id="4bf92f3577b34da6a3ce929d0e0e4736", + span_id="00f067aa0ba902b7", + ), + ] + payload = build_logs_payload(records, RESOURCE) + encoded = payload["resourceLogs"][0]["scopeLogs"][0]["logRecords"] + + assert "traceId" not in encoded[0] + assert encoded[1]["traceId"] == "4bf92f3577b34da6a3ce929d0e0e4736" + assert encoded[1]["spanId"] == "00f067aa0ba902b7" + assert encoded[0]["timeUnixNano"] == str(END_NANOS) + + +def _client(handler) -> OtlpClient: + transport = httpx.MockTransport(handler) + return OtlpClient( + base_endpoint="https://collector.example", + timeout_seconds=1.0, + headers={}, + client=httpx.AsyncClient(transport=transport), + ) + + +def test_signal_url_follows_the_otlp_base_convention(): + client = _client(lambda request: httpx.Response(200, json={})) + assert client.url_for("metrics") == "https://collector.example/v1/metrics" + + trailing = OtlpClient( + base_endpoint="https://collector.example/", + timeout_seconds=1.0, + headers={}, + client=httpx.AsyncClient(), + ) + assert trailing.url_for("logs") == "https://collector.example/v1/logs" + + +@pytest.mark.asyncio +async def test_post_sends_headers_and_body(): + seen: dict[str, object] = {} + + def handler(request: httpx.Request) -> httpx.Response: + seen["url"] = str(request.url) + seen["auth"] = request.headers.get("dd-api-key") + seen["agent"] = request.headers.get("user-agent") + seen["body"] = json.loads(request.content) + return httpx.Response(200, json={"partialSuccess": {}}) + + client = OtlpClient( + base_endpoint="https://collector.example", + timeout_seconds=1.0, + headers={"dd-api-key": "k"}, + client=httpx.AsyncClient(transport=httpx.MockTransport(handler)), + ) + await client.post("metrics", {"resourceMetrics": []}) + + assert seen["url"] == "https://collector.example/v1/metrics" + assert seen["auth"] == "k" + assert seen["agent"] == "switch-core" + assert seen["body"] == {"resourceMetrics": []} + + +@pytest.mark.asyncio +async def test_http_error_is_raised_not_swallowed(): + client = _client(lambda request: httpx.Response(503, text="unavailable")) + with pytest.raises(OtlpSendError, match="503"): + await client.post("metrics", {}) + + +@pytest.mark.asyncio +async def test_network_failure_is_raised(): + def handler(request: httpx.Request) -> httpx.Response: + raise httpx.ConnectError("refused") + + client = _client(handler) + with pytest.raises(OtlpSendError, match="failed"): + await client.post("metrics", {}) + + +@pytest.mark.asyncio +async def test_partial_rejection_inside_a_200_is_raised(): + """A 200 does not prove the records were kept, so the body is read.""" + body = { + "partialSuccess": {"rejectedDataPoints": "4", "errorMessage": "bad resource"} + } + client = _client(lambda request: httpx.Response(200, json=body)) + + with pytest.raises(OtlpSendError, match="rejected 4"): + await client.post("metrics", {}) + + +@pytest.mark.asyncio +async def test_empty_partial_success_is_not_a_failure(): + client = _client(lambda request: httpx.Response(200, json={"partialSuccess": {}})) + await client.post("metrics", {}) + + +@pytest.mark.asyncio +async def test_non_json_success_body_is_tolerated(): + client = _client(lambda request: httpx.Response(200, text="OK")) + await client.post("metrics", {}) diff --git a/core/tests/switch_core/test_config_observability.py b/core/tests/switch_core/test_config_observability.py new file mode 100644 index 000000000..50a295b2f --- /dev/null +++ b/core/tests/switch_core/test_config_observability.py @@ -0,0 +1,156 @@ +import pytest + +from switch_core.config import SwitchConfig + +BASE_ENV = { + "DB_HOST": "localhost", + "DB_PORT": "5432", + "DB_USER": "postgres", + "DB_PASSWORD": "secret", + "DB_NAME": "switch", + "MATRIX_SERVER_NAME": "switch.local", + "AGENT_REGISTRATION_TOKEN": "token", + "JWT_SECRET_KEY": "jwt", + "GATEWAY_ADMIN_EMAIL": "admin@example.com", + "GATEWAY_ADMIN_PASSWORD": "pw", +} + +DEPLOYMENT_ID = "0e5d1b3a-6c1f-4c22-9a4c-3a9f5a2b7d10" + +OBSERVABILITY_KEYS = ( + "OTLP_ENDPOINT", + "OTLP_METRICS_ENABLED", + "OTLP_LOGS_ENABLED", + "OTLP_TRACES_ENABLED", + "OTLP_HEADERS", + "OTLP_TIMEOUT_SECONDS", + "OTLP_EXPORT_INTERVAL_SECONDS", + "DEPLOYMENT_ID", +) + + +def _config(monkeypatch: pytest.MonkeyPatch, **overrides: str) -> SwitchConfig: + for key in (*BASE_ENV, *OBSERVABILITY_KEYS): + monkeypatch.delenv(key, raising=False) + for key, value in {**BASE_ENV, **overrides}.items(): + monkeypatch.setenv(key.upper(), value) + return SwitchConfig() # type: ignore[call-arg] + + +def test_reporting_is_off_until_a_collector_is_named(monkeypatch): + config = _config(monkeypatch) + assert config.observability_enabled is False + assert config.otlp_endpoint is None + + +def test_an_endpoint_turns_metrics_on_but_not_logs_or_traces(monkeypatch): + config = _config( + monkeypatch, + OTLP_ENDPOINT="https://collector.example", + DEPLOYMENT_ID=DEPLOYMENT_ID, + ) + assert config.observability_enabled is True + assert config.otlp_metrics_enabled is True + # Logs already reach the container's output; a second copy over the network + # costs money somebody has to choose to spend. + assert config.otlp_logs_enabled is False + # The relay Switch reports to does not serve /v1/traces, so defaulting this + # on would mean every export failing forever. + assert config.otlp_traces_enabled is False + + +def test_an_endpoint_without_a_deployment_id_refuses_to_start(monkeypatch): + """The collector drops unidentified payloads silently, with a 200. + + Starting anyway would give a deployment that looks configured, logs nothing + wrong, and appears on no dashboard. + """ + with pytest.raises(ValueError, match="DEPLOYMENT_ID must be set"): + _config(monkeypatch, OTLP_ENDPOINT="https://collector.example") + + +def test_deployment_id_must_be_a_uuid(monkeypatch): + with pytest.raises(ValueError, match="DEPLOYMENT_ID must be a UUID"): + _config( + monkeypatch, + OTLP_ENDPOINT="https://collector.example", + DEPLOYMENT_ID="pilot-cluster", + ) + + +def test_a_deployment_id_alone_is_not_partial_configuration(monkeypatch): + # Nothing is reported, so nothing is wrong: an id without a collector has + # not half-configured reporting, it has not configured it. + config = _config(monkeypatch, DEPLOYMENT_ID=DEPLOYMENT_ID) + assert config.observability_enabled is False + + +def test_the_endpoint_is_a_base_url_and_says_so(monkeypatch): + """Pasting the full logs URL is the obvious mistake, so it is named.""" + with pytest.raises(ValueError, match="drop the '/v1/logs'"): + _config( + monkeypatch, + OTLP_ENDPOINT="https://collector.example/v1/logs", + DEPLOYMENT_ID=DEPLOYMENT_ID, + ) + + +def test_endpoint_must_be_http(monkeypatch): + with pytest.raises(ValueError, match="must be an http"): + _config( + monkeypatch, + OTLP_ENDPOINT="collector.example", + DEPLOYMENT_ID=DEPLOYMENT_ID, + ) + + +def test_endpoint_must_have_a_host(monkeypatch): + with pytest.raises(ValueError, match="must include a host"): + _config(monkeypatch, OTLP_ENDPOINT="https://", DEPLOYMENT_ID=DEPLOYMENT_ID) + + +def test_a_trailing_slash_is_not_a_path(monkeypatch): + config = _config( + monkeypatch, + OTLP_ENDPOINT="https://collector.example/", + DEPLOYMENT_ID=DEPLOYMENT_ID, + ) + assert config.otlp_endpoint == "https://collector.example/" + + +@pytest.mark.parametrize( + "name", ["OTLP_TIMEOUT_SECONDS", "OTLP_EXPORT_INTERVAL_SECONDS"] +) +def test_intervals_must_be_positive(monkeypatch, name): + with pytest.raises(ValueError, match=f"{name} must be greater than 0"): + _config( + monkeypatch, + OTLP_ENDPOINT="https://collector.example", + DEPLOYMENT_ID=DEPLOYMENT_ID, + **{name: "0"}, + ) + + +def test_headers_parse_into_pairs(monkeypatch): + config = _config( + monkeypatch, + OTLP_ENDPOINT="https://collector.example", + DEPLOYMENT_ID=DEPLOYMENT_ID, + OTLP_HEADERS="dd-api-key=abc, x-tag = two ", + ) + assert config.otlp_header_map == {"dd-api-key": "abc", "x-tag": "two"} + + +def test_malformed_headers_fail_at_startup_not_every_interval(monkeypatch): + with pytest.raises(ValueError, match="key=value"): + _config( + monkeypatch, + OTLP_ENDPOINT="https://collector.example", + DEPLOYMENT_ID=DEPLOYMENT_ID, + OTLP_HEADERS="just-a-key", + ) + + +def test_no_headers_is_an_empty_map(monkeypatch): + config = _config(monkeypatch) + assert config.otlp_header_map == {} diff --git a/core/tests/switch_core/transport/test_postgres_transport.py b/core/tests/switch_core/transport/test_postgres_transport.py index 96e6542d9..fdfa80298 100644 --- a/core/tests/switch_core/transport/test_postgres_transport.py +++ b/core/tests/switch_core/transport/test_postgres_transport.py @@ -25,6 +25,7 @@ from switch_core.db.stores.media_store import MediaStore from switch_core.db.stores.message_store import MessageStore from switch_core.db.stores.room_store import RoomStore +from switch_core.observability.metrics import MetricsRegistry, install, uninstall from switch_core.tenant_context import current_tenant_id, tenant_scope from switch_core.transport import ( InboundCustomEvent, @@ -1320,3 +1321,128 @@ async def test_the_schema_forbids_a_client_row_in_another_tenants_room( ) with pytest.raises(IntegrityError): await session.commit() + + +class TestWhatIsMeasured: + """The counters, against a real database round trip (CHOO-2807). + + A real delivery rather than a hand-built event: asserting on the latter + would prove the arithmetic and nothing about whether the instrumentation is + actually on the path a message takes. + """ + + @pytest.fixture(autouse=True) + def _registry(self) -> Iterator[MetricsRegistry]: + registry = MetricsRegistry() + install(registry) + self._tasks: list[asyncio.Task] = [] + yield registry + for task in self._tasks: + task.cancel() + uninstall() + + async def _receiving( + self, + session_factory: async_sessionmaker[AsyncSession], + handlers: TransportHandlers | None = None, + ) -> tuple[PostgresTransport, _FakeListener, str]: + async with session_factory() as session: + _, transport_room_id, client_id, user_id = await _make_room(session) + await session.commit() + + listener = _FakeListener() + transport = _transport( + session_factory, client_id=client_id, user_id=user_id, listener=listener + ) + transport.register_handlers(handlers or _Received().handlers()) + await transport.join_room(transport_room_id) + self._tasks.append(asyncio.create_task(transport.receive_forever())) + await _watched_room(transport) + return transport, listener, transport_room_id + + @staticmethod + def _kinds(payloads: dict, name: str) -> dict[str, float]: + return { + str(point.attributes["kind"]): point.value + for point in payloads[name].numbers + } + + async def test_a_send_and_its_delivery_are_both_counted( + self, session_factory: async_sessionmaker[AsyncSession], _registry + ) -> None: + transport, listener, room = await self._receiving(session_factory) + + await transport.send_message(room, "hello", sender_name="agent one") + await listener.announce(await _watched_room(transport)) + + payloads = {p.name: p for p in _registry.collect()} + assert self._kinds(payloads, "switch.messages.sent") == {"message": 1.0} + assert self._kinds(payloads, "switch.messages.delivered") == {"message": 1.0} + + async def test_media_is_counted_apart_from_text( + self, session_factory: async_sessionmaker[AsyncSession], _registry + ) -> None: + transport, listener, room = await self._receiving(session_factory) + + await transport.send_media( + room, + uri="mxc://test/abc", + filename="a.png", + mimetype="image/png", + size=3, + sender_name="agent one", + msgtype="m.image", + ) + await listener.announce(await _watched_room(transport)) + + payloads = {p.name: p for p in _registry.collect()} + # Both travel as `m.room.message`, so without reading the msgtype these + # would be one undifferentiated number. + assert self._kinds(payloads, "switch.messages.sent") == {"media": 1.0} + assert self._kinds(payloads, "switch.messages.delivered") == {"media": 1.0} + + async def test_delivery_lag_is_measured_per_message( + self, session_factory: async_sessionmaker[AsyncSession], _registry + ) -> None: + transport, listener, room = await self._receiving(session_factory) + + await transport.send_message(room, "hello", sender_name="agent one") + await listener.announce(await _watched_room(transport)) + + payload = next( + p for p in _registry.collect() if p.name == "switch.messages.delivery_lag" + ) + point = payload.histograms[0] + assert point.count == 1 + assert point.attributes == {"kind": "message"} + # Never negative: the row's timestamp comes from the database's clock + # and the subtraction happens on this process's, so skew is ordinary. + assert 0.0 <= point.total < 60_000.0 + + async def test_a_failing_handler_is_counted_not_just_logged( + self, session_factory: async_sessionmaker[AsyncSession], _registry + ) -> None: + async def explode(_room, _event) -> None: + raise RuntimeError("handler is broken") + + transport, listener, room = await self._receiving( + session_factory, + TransportHandlers( + on_message=explode, + on_media=explode, + on_member_event=explode, + on_custom_event=explode, + ), + ) + + await transport.send_message(room, "hello", sender_name="agent one") + await listener.announce(await _watched_room(transport)) + + # Swallowing the exception is what keeps the delivery loop alive for + # every other room; the counter is what stops that being invisible. + payload = next( + p + for p in _registry.collect() + if p.name == "switch.messages.delivery_failures" + ) + assert payload.numbers[0].value >= 1.0 diff --git a/deploy/observability/README.md b/deploy/observability/README.md new file mode 100644 index 000000000..f61d5b79d --- /dev/null +++ b/deploy/observability/README.md @@ -0,0 +1,76 @@ +# Dashboards and alerts + +Datadog definitions for what `switch-core` reports (CHOO-2807). They are kept +here rather than clicked together in the UI so that a change to a metric and a +change to the panel reading it land in the same review. + +Nothing here contains an account, an API key, a team handle or a URL. The +monitors carry `@REPLACE-WITH-NOTIFICATION-HANDLE` where a destination belongs; +fill it in when importing, not here. + +## What the server has to be doing first + +Reporting is off until a collector is named. See `OTLP_ENDPOINT` and +`DEPLOYMENT_ID` in `.env.example`, or `switchCore.observability` in the Helm +chart. With neither set these panels are empty and the monitors below will +report no data — which is a correct reading, not a broken dashboard. + +Every metric this server can emit is declared in +`core/switch_core/observability/catalogue.py`, with the attributes each may +carry. That file is the reference; this directory is one view of it. + +## Importing + +```bash +# Dashboard +curl -X POST "https://api./api/v1/dashboard" \ + -H "DD-API-KEY: $DD_API_KEY" -H "DD-APPLICATION-KEY: $DD_APP_KEY" \ + -H "Content-Type: application/json" \ + --data @dashboard.json + +# Monitors, one at a time — the API takes a single monitor per call +jq -c '.[]' monitors.json | while read -r monitor; do + curl -X POST "https://api./api/v1/monitor" \ + -H "DD-API-KEY: $DD_API_KEY" -H "DD-APPLICATION-KEY: $DD_APP_KEY" \ + -H "Content-Type: application/json" --data "$monitor" +done +``` + +## Two things to check on first import + +**Histogram panels depend on how the collector maps them.** Request latency and +delivery lag are OTLP histograms. A collector exporting to Datadog in +`distributions` mode makes them distributions, which is what the `p95:` and +`p99:` queries here assume. In the default `histograms` mode they arrive as +separate `.count`, `.sum`, `.min` and `.max` series instead, and those panels +will be empty until either the collector's mode or the queries are changed. +Empty is the honest outcome; a panel is not silently switched to a different +statistic. + +**The environment tag depends on `ENVIRONMENT` being set.** It is emitted as +OTLP's `deployment.environment`, which Datadog reads as `env`. A deployment +that has not set it appears with no environment, and the template variable on +the dashboard will have nothing to filter by. + +## The odd-looking first monitor + +`[Switch] switch-core has stopped reporting` queries event-loop lag with a +threshold of `< 0`, which no real reading can satisfy. That is deliberate and +is Datadog's idiom for a no-data monitor: the threshold never fires, and +`notify_no_data` does the work. Event-loop lag is the metric used because it is +emitted every interval unconditionally — a request counter would read zero on a +quiet night and a heartbeat that can legitimately be absent is not a heartbeat. + +## What is deliberately not alerted on + +**Latency.** Switch holds long-poll connections open on purpose, so a slow +request is its normal mode and a duration threshold would page on healthy +traffic. The dashboard shows it; nothing wakes anyone for it. + +**Bridge event volume.** It follows whatever the humans in the channels are +doing. A quiet Sunday is not an incident, and an alert that fires every +weekend is one nobody reads by the time something real happens. + +**Readiness itself, from inside.** If the pod is not ready, Kubernetes already +knows and the deployment is already out of service. What is alerted on is the +dependency that caused it, which is the part that says what to go and fix. diff --git a/deploy/observability/dashboard.json b/deploy/observability/dashboard.json new file mode 100644 index 000000000..fa0033990 --- /dev/null +++ b/deploy/observability/dashboard.json @@ -0,0 +1,398 @@ +{ + "title": "Switch — core service health", + "description": "What switch-core reports about itself. Metric definitions live in core/switch_core/observability/catalogue.py; this dashboard is checked into deploy/observability/ in the switch repository, so edit it there rather than here.", + "layout_type": "ordered", + "reflow_type": "fixed", + "template_variables": [ + { + "name": "env", + "prefix": "env", + "available_values": [], + "default": "*" + }, + { + "name": "service", + "prefix": "service", + "available_values": [], + "default": "switch-core" + } + ], + "widgets": [ + { + "definition": { + "type": "note", + "content": "**Is it working?** Each dependency reports 1 when its last check passed and 0 when it failed. Only the database takes the server out of service — switch-core runs as a single replica, so failing readiness empties the service rather than shifting traffic. A crashed bridge is a real fault that is deliberately not fatal.", + "background_color": "blue", + "font_size": "14", + "text_align": "left", + "vertical_align": "top", + "show_tick": false, + "tick_pos": "50%", + "tick_edge": "left", + "has_padding": true + }, + "layout": { "x": 0, "y": 0, "width": 12, "height": 2 } + }, + { + "definition": { + "type": "timeseries", + "title": "Dependency checks (1 = passing)", + "show_legend": true, + "legend_layout": "horizontal", + "requests": [ + { + "q": "min:switch.health.check{$env,$service} by {check}", + "display_type": "line", + "style": { "palette": "green", "line_type": "solid", "line_width": "normal" } + } + ], + "yaxis": { "min": "0", "max": "1.2" } + }, + "layout": { "x": 0, "y": 2, "width": 8, "height": 4 } + }, + { + "definition": { + "type": "query_value", + "title": "Agents connected", + "requests": [ + { + "q": "avg:switch.agents.connected{$env,$service}", + "aggregator": "last" + } + ], + "autoscale": true, + "precision": 0 + }, + "layout": { "x": 8, "y": 2, "width": 2, "height": 2 } + }, + { + "definition": { + "type": "query_value", + "title": "Bridges running", + "requests": [ + { + "q": "avg:switch.bridges.running{$env,$service}", + "aggregator": "last" + } + ], + "autoscale": true, + "precision": 0 + }, + "layout": { "x": 10, "y": 2, "width": 2, "height": 2 } + }, + { + "definition": { + "type": "query_value", + "title": "Room clients running", + "requests": [ + { + "q": "avg:switch.clients.running{$env,$service}", + "aggregator": "last" + } + ], + "autoscale": true, + "precision": 0 + }, + "layout": { "x": 8, "y": 4, "width": 2, "height": 2 } + }, + { + "definition": { + "type": "query_value", + "title": "Event-loop lag (ms, worst)", + "requests": [ + { + "q": "max:switch.runtime.event_loop_lag{$env,$service}", + "aggregator": "max", + "conditional_formats": [ + { "comparator": "<", "value": 100, "palette": "white_on_green" }, + { "comparator": "<", "value": 1000, "palette": "white_on_yellow" }, + { "comparator": ">=", "value": 1000, "palette": "white_on_red" } + ] + } + ], + "autoscale": true, + "precision": 0 + }, + "layout": { "x": 10, "y": 4, "width": 2, "height": 2 } + }, + + { + "definition": { + "type": "note", + "content": "**HTTP.** Routes are templates, never resolved paths — a path carries an id per request and would be a new series each time. Anything the router could not place is folded into `unmatched`.", + "background_color": "gray", + "font_size": "14", + "text_align": "left", + "vertical_align": "top", + "show_tick": false, + "tick_pos": "50%", + "tick_edge": "left", + "has_padding": true + }, + "layout": { "x": 0, "y": 6, "width": 12, "height": 1 } + }, + { + "definition": { + "type": "timeseries", + "title": "Requests per second, by outcome", + "show_legend": true, + "requests": [ + { + "q": "sum:switch.http.requests{$env,$service} by {status_class}.as_rate()", + "display_type": "bars" + } + ] + }, + "layout": { "x": 0, "y": 7, "width": 6, "height": 4 } + }, + { + "definition": { + "type": "timeseries", + "title": "Server errors per second, by route", + "show_legend": true, + "requests": [ + { + "q": "sum:switch.http.requests{$env,$service,status_class:5xx} by {route}.as_rate()", + "display_type": "bars", + "style": { "palette": "warm" } + } + ] + }, + "layout": { "x": 6, "y": 7, "width": 6, "height": 4 } + }, + { + "definition": { + "type": "timeseries", + "title": "Request duration p95 by route (ms) — needs distribution mapping, see README", + "show_legend": true, + "requests": [ + { + "q": "p95:switch.http.request.duration{$env,$service} by {route}", + "display_type": "line" + } + ] + }, + "layout": { "x": 0, "y": 11, "width": 12, "height": 4 } + }, + + { + "definition": { + "type": "note", + "content": "**Rooms.** Delivery lag is the age of a message when it reached a recipient, measured per delivery. Delivery failures are the exceptions the delivery loop swallows on purpose so one bad room cannot stop the others — which is also what makes them invisible without this.", + "background_color": "gray", + "font_size": "14", + "text_align": "left", + "vertical_align": "top", + "show_tick": false, + "tick_pos": "50%", + "tick_edge": "left", + "has_padding": true + }, + "layout": { "x": 0, "y": 15, "width": 12, "height": 1 } + }, + { + "definition": { + "type": "timeseries", + "title": "Messages per second, sent and delivered", + "show_legend": true, + "requests": [ + { + "q": "sum:switch.messages.sent{$env,$service}.as_rate()", + "display_type": "line" + }, + { + "q": "sum:switch.messages.delivered{$env,$service}.as_rate()", + "display_type": "line" + } + ] + }, + "layout": { "x": 0, "y": 16, "width": 6, "height": 4 } + }, + { + "definition": { + "type": "timeseries", + "title": "Delivery failures per second", + "show_legend": false, + "requests": [ + { + "q": "sum:switch.messages.delivery_failures{$env,$service}.as_rate()", + "display_type": "bars", + "style": { "palette": "warm" } + } + ] + }, + "layout": { "x": 6, "y": 16, "width": 6, "height": 4 } + }, + { + "definition": { + "type": "timeseries", + "title": "Delivery lag p95 / p99 (ms) — needs distribution mapping, see README", + "show_legend": true, + "requests": [ + { + "q": "p95:switch.messages.delivery_lag{$env,$service}", + "display_type": "line" + }, + { + "q": "p99:switch.messages.delivery_lag{$env,$service}", + "display_type": "line" + } + ] + }, + "layout": { "x": 0, "y": 20, "width": 12, "height": 4 } + }, + + { + "definition": { + "type": "note", + "content": "**Bridges.** Inbound is counted where every platform event already funnels through; outbound at the relay, so a puppet's own echo and a room with no channel are not counted as traffic nobody sent.", + "background_color": "gray", + "font_size": "14", + "text_align": "left", + "vertical_align": "top", + "show_tick": false, + "tick_pos": "50%", + "tick_edge": "left", + "has_padding": true + }, + "layout": { "x": 0, "y": 24, "width": 12, "height": 1 } + }, + { + "definition": { + "type": "timeseries", + "title": "Inbound platform events per second, by platform", + "show_legend": true, + "requests": [ + { + "q": "sum:switch.bridge.events_in{$env,$service} by {platform}.as_rate()", + "display_type": "area" + } + ] + }, + "layout": { "x": 0, "y": 25, "width": 4, "height": 4 } + }, + { + "definition": { + "type": "timeseries", + "title": "Outbound relays per second, by platform", + "show_legend": true, + "requests": [ + { + "q": "sum:switch.bridge.events_out{$env,$service} by {platform}.as_rate()", + "display_type": "area" + } + ] + }, + "layout": { "x": 4, "y": 25, "width": 4, "height": 4 } + }, + { + "definition": { + "type": "timeseries", + "title": "Bridge errors per second, by platform and direction", + "show_legend": true, + "requests": [ + { + "q": "sum:switch.bridge.errors{$env,$service} by {platform,direction}.as_rate()", + "display_type": "bars", + "style": { "palette": "warm" } + } + ] + }, + "layout": { "x": 8, "y": 25, "width": 4, "height": 4 } + }, + + { + "definition": { + "type": "note", + "content": "**Resources.** Reported by the process about itself — there is no infrastructure agent in this cluster. Event-loop lag is the one no agent could produce: the server is single-threaded, so one blocking call stalls every room and bridge at once, and from outside that looks like an unrelated timeout somewhere else.", + "background_color": "gray", + "font_size": "14", + "text_align": "left", + "vertical_align": "top", + "show_tick": false, + "tick_pos": "50%", + "tick_edge": "left", + "has_padding": true + }, + "layout": { "x": 0, "y": 29, "width": 12, "height": 1 } + }, + { + "definition": { + "type": "timeseries", + "title": "Database pool: in use vs size", + "show_legend": true, + "requests": [ + { + "q": "avg:switch.db.pool.in_use{$env,$service}", + "display_type": "area" + }, + { + "q": "avg:switch.db.pool.size{$env,$service}", + "display_type": "line" + }, + { + "q": "avg:switch.db.pool.overflow{$env,$service}", + "display_type": "line" + } + ] + }, + "layout": { "x": 0, "y": 30, "width": 6, "height": 4 } + }, + { + "definition": { + "type": "timeseries", + "title": "Event-loop lag (ms)", + "show_legend": false, + "requests": [ + { + "q": "max:switch.runtime.event_loop_lag{$env,$service}", + "display_type": "bars" + } + ] + }, + "layout": { "x": 6, "y": 30, "width": 6, "height": 4 } + }, + { + "definition": { + "type": "timeseries", + "title": "Process memory (bytes)", + "show_legend": false, + "requests": [ + { + "q": "avg:switch.runtime.memory_rss{$env,$service}", + "display_type": "area" + } + ] + }, + "layout": { "x": 0, "y": 34, "width": 4, "height": 3 } + }, + { + "definition": { + "type": "timeseries", + "title": "CPU seconds per second, by mode", + "show_legend": true, + "requests": [ + { + "q": "sum:switch.runtime.cpu_seconds{$env,$service} by {mode}.as_rate()", + "display_type": "area" + } + ] + }, + "layout": { "x": 4, "y": 34, "width": 4, "height": 3 } + }, + { + "definition": { + "type": "timeseries", + "title": "Open file descriptors", + "show_legend": false, + "requests": [ + { + "q": "avg:switch.runtime.open_fds{$env,$service}", + "display_type": "line" + } + ] + }, + "layout": { "x": 8, "y": 34, "width": 4, "height": 3 } + } + ] +} diff --git a/deploy/observability/monitors.json b/deploy/observability/monitors.json new file mode 100644 index 000000000..8a9d60115 --- /dev/null +++ b/deploy/observability/monitors.json @@ -0,0 +1,120 @@ +[ + { + "name": "[Switch] switch-core has stopped reporting", + "type": "metric alert", + "query": "max(last_15m):avg:switch.runtime.event_loop_lag{service:switch-core} < 0", + "message": "No metrics have arrived from switch-core for 15 minutes.\n\nThis is a no-data alert, and it cannot tell you which of three things happened: the server is down, it cannot reach the collector, or someone turned reporting off. Check the pod first — if it is serving, the other two are the ones left.\n\nNote that every other monitor in this set goes quiet at the same time, so treat this one as the reason the rest went silent rather than as an outage on its own.\n\n@REPLACE-WITH-NOTIFICATION-HANDLE", + "tags": ["service:switch-core", "team:switch", "source:CHOO-2807"], + "options": { + "notify_no_data": true, + "no_data_timeframe": 15, + "renotify_interval": 60, + "thresholds": { "critical": 0 }, + "include_tags": true + } + }, + { + "name": "[Switch] the database is unreachable", + "type": "metric alert", + "query": "min(last_5m):min:switch.health.check{service:switch-core,check:database} by {env} < 1", + "message": "switch-core's readiness check cannot reach the database.\n\nThis is the one dependency that takes the server out of service, so Kubernetes has already emptied the Service — and because switch-core runs as a single replica there is nothing else serving. Every request is failing.\n\nCheck the database before the pod: the pod is reporting the fault, not causing it.\n\n@REPLACE-WITH-NOTIFICATION-HANDLE", + "tags": ["service:switch-core", "team:switch", "source:CHOO-2807"], + "options": { + "notify_no_data": false, + "renotify_interval": 30, + "thresholds": { "critical": 1 }, + "include_tags": true + } + }, + { + "name": "[Switch] no room messages are being delivered", + "type": "metric alert", + "query": "min(last_10m):min:switch.health.check{service:switch-core,check:message_listener} by {env} < 1", + "message": "The Postgres LISTEN connection that wakes every room's delivery is down.\n\nThe API still answers and rooms still accept writes, so from outside Switch looks healthy — and no message reaches anybody. That combination is why this is alerted separately from the database check.\n\nIt reconnects itself with backoff, which is why it does not fail readiness: restarting the pod would drop every live session without fixing it any faster. Ten minutes of this means the backoff is not winning.\n\n@REPLACE-WITH-NOTIFICATION-HANDLE", + "tags": ["service:switch-core", "team:switch", "source:CHOO-2807"], + "options": { + "notify_no_data": false, + "renotify_interval": 60, + "thresholds": { "critical": 1 }, + "include_tags": true + } + }, + { + "name": "[Switch] a collaboration bridge has crashed", + "type": "metric alert", + "query": "min(last_10m):min:switch.health.check{service:switch-core,check:bridges} by {env} < 1", + "message": "A configured collaboration bridge is no longer running.\n\nThe platform it serves is cut off — messages from that Slack, Mattermost, Discord, Teams or Telegram channel reach nobody, and nothing Switch sends reaches it. The rest of Switch is unaffected, deliberately: a dead adapter must not take the whole server off the air.\n\nA bridge that crashes removes itself and does not retry, so this needs a restart of that bridge rather than waiting.\n\n@REPLACE-WITH-NOTIFICATION-HANDLE", + "tags": ["service:switch-core", "team:switch", "source:CHOO-2807"], + "options": { + "notify_no_data": false, + "renotify_interval": 120, + "thresholds": { "critical": 1 }, + "include_tags": true + } + }, + { + "name": "[Switch] messages are being dropped on delivery", + "type": "metric alert", + "query": "sum(last_10m):sum:switch.messages.delivery_failures{service:switch-core}.as_count() by {env} > 5", + "message": "The delivery loop has failed to deliver {{value}} time(s) in ten minutes.\n\nEach one is a message written to a room that a client never received. The loop swallows these on purpose so one bad room cannot stop the others, so nothing else will surface them — the counter is the only evidence.\n\nThe logs carry the room and the client for each: search for \"Delivery failed for client\".\n\n@REPLACE-WITH-NOTIFICATION-HANDLE", + "tags": ["service:switch-core", "team:switch", "source:CHOO-2807"], + "options": { + "notify_no_data": false, + "renotify_interval": 60, + "thresholds": { "critical": 5, "warning": 1 }, + "include_tags": true + } + }, + { + "name": "[Switch] the event loop is stalling", + "type": "metric alert", + "query": "avg(last_10m):max:switch.runtime.event_loop_lag{service:switch-core} by {env} > 1000", + "message": "A fixed-interval task is waking more than a second late.\n\nswitch-core is single-threaded and cooperative, so this is not one slow thing — it is everything at once. Room delivery, bridge dispatch and agent heartbeats are all waiting on the same loop, and heartbeats arriving late make live agent connections look lapsed through no fault of their own.\n\nA synchronous call on the event loop is the usual cause. The stall itself is the bug; whatever timed out because of it is a symptom.\n\n@REPLACE-WITH-NOTIFICATION-HANDLE", + "tags": ["service:switch-core", "team:switch", "source:CHOO-2807"], + "options": { + "notify_no_data": false, + "renotify_interval": 60, + "thresholds": { "critical": 1000, "warning": 250 }, + "include_tags": true + } + }, + { + "name": "[Switch] the database pool is nearly exhausted", + "type": "metric alert", + "query": "avg(last_10m):avg:switch.db.pool.in_use{service:switch-core} by {env} / avg:switch.db.pool.size{service:switch-core} by {env} > 0.9", + "message": "More than 90% of the connection pool has been checked out for ten minutes.\n\nWhat happens next is that requests start waiting for a connection rather than failing, so the symptom is latency everywhere and then a readiness check that times out — which reads as \"the database is down\" when the database is fine and this server is holding all of it.\n\nLook for a query holding a connection longer than it should before raising the pool size.\n\n@REPLACE-WITH-NOTIFICATION-HANDLE", + "tags": ["service:switch-core", "team:switch", "source:CHOO-2807"], + "options": { + "notify_no_data": false, + "renotify_interval": 60, + "thresholds": { "critical": 0.9, "warning": 0.75 }, + "include_tags": true + } + }, + { + "name": "[Switch] server errors are elevated", + "type": "metric alert", + "query": "sum(last_10m):sum:switch.http.requests{service:switch-core,status_class:5xx}.as_count() by {env} / sum:switch.http.requests{service:switch-core}.as_count() by {env} > 0.05", + "message": "More than 5% of requests answered 5xx over ten minutes.\n\nA ratio rather than a count, so a quiet period does not page and a busy one is not held to the same absolute number. Break it down by route on the dashboard: one failing endpoint and everything failing want different responses.\n\n@REPLACE-WITH-NOTIFICATION-HANDLE", + "tags": ["service:switch-core", "team:switch", "source:CHOO-2807"], + "options": { + "notify_no_data": false, + "renotify_interval": 60, + "thresholds": { "critical": 0.05, "warning": 0.01 }, + "include_tags": true + } + }, + { + "name": "[Switch] a bridge is failing to relay", + "type": "metric alert", + "query": "sum(last_15m):sum:switch.bridge.errors{service:switch-core}.as_count() by {env,platform,direction} > 10", + "message": "{{platform.name}} has failed {{value}} time(s) {{direction.name}} in fifteen minutes.\n\nInbound failures are messages a person sent that nobody received; from the platform's side that is indistinguishable from being ignored. Outbound failures are Switch's replies not arriving.\n\nThe bridge is still running — a crashed one is a different alert. This is usually the platform rate-limiting, an expired token, or a channel the app was removed from.\n\n@REPLACE-WITH-NOTIFICATION-HANDLE", + "tags": ["service:switch-core", "team:switch", "source:CHOO-2807"], + "options": { + "notify_no_data": false, + "renotify_interval": 120, + "thresholds": { "critical": 10, "warning": 3 }, + "include_tags": true + } + } +] diff --git a/deploy/remote/helm/switch/templates/_helpers.tpl b/deploy/remote/helm/switch/templates/_helpers.tpl index eac995c80..787d08178 100644 --- a/deploy/remote/helm/switch/templates/_helpers.tpl +++ b/deploy/remote/helm/switch/templates/_helpers.tpl @@ -454,6 +454,29 @@ error rather than a crash loop. {{- end -}} {{- end }} +{{/* +Refuse to render an observability config that would report nothing. + +The collector drops payloads that do not identify the deployment, silently and +with a 200, so a chart that shipped without an id would produce a pod that +looks configured and appears on no dashboard. switch-core refuses to start in +that state too; failing here means the operator finds out at `helm upgrade` +rather than from a CrashLoopBackOff. +*/}} +{{- define "switch.validateObservability" -}} +{{- with .Values.switchCore.observability }} +{{- if and .otlpEndpoint (not .deploymentId) -}} +{{- fail "switchCore.observability.deploymentId must be set when otlpEndpoint is: the collector drops payloads it cannot attribute to a deployment, so this server would report nothing while looking correctly configured. Use a UUID, and keep it stable across upgrades." -}} +{{- end -}} +{{- if and .deploymentId (not .otlpEndpoint) -}} +{{- fail "switchCore.observability.deploymentId is set but otlpEndpoint is not, so nothing is reported anywhere. Set the endpoint, or remove the id." -}} +{{- end -}} +{{- if and .logs (not .otlpEndpoint) -}} +{{- fail "switchCore.observability.logs is on but no otlpEndpoint is set." -}} +{{- end -}} +{{- end -}} +{{- end }} + {{/* switch-core container env. Shared by the switch-core Deployment and the pre-upgrade migration Job so they always run against the same configuration @@ -590,6 +613,26 @@ Include with `nindent 12`. - name: ENVIRONMENT value: {{ . | quote }} {{- end }} +{{- with .Values.switchCore.observability }} +{{- if .otlpEndpoint }} +- name: OTLP_ENDPOINT + value: {{ .otlpEndpoint | quote }} +- name: DEPLOYMENT_ID + value: {{ .deploymentId | quote }} +- name: OTLP_METRICS_ENABLED + value: {{ .metrics | quote }} +- name: OTLP_LOGS_ENABLED + value: {{ .logs | quote }} +- name: OTLP_TRACES_ENABLED + value: {{ .traces | quote }} +- name: OTLP_EXPORT_INTERVAL_SECONDS + value: {{ .exportIntervalSeconds | quote }} +{{- with .headers }} +- name: OTLP_HEADERS + value: {{ . | quote }} +{{- end }} +{{- end }} +{{- end }} # switch-core sits behind the cluster/ALB and enforces its own # BearerAuthMiddleware, so fastmcp's browser-oriented DNS-rebinding # Host/Origin guard (default-on since mcp 1.28) only rejects the diff --git a/deploy/remote/helm/switch/templates/switch-core/deployment.yaml b/deploy/remote/helm/switch/templates/switch-core/deployment.yaml index 95873ebaf..fb192ff91 100644 --- a/deploy/remote/helm/switch/templates/switch-core/deployment.yaml +++ b/deploy/remote/helm/switch/templates/switch-core/deployment.yaml @@ -3,6 +3,7 @@ {{- end }} {{- include "switch.validateDbTls" . }} {{- include "switch.validateLogging" . }} +{{- include "switch.validateObservability" . }} apiVersion: apps/v1 kind: Deployment metadata: @@ -46,12 +47,21 @@ spec: {{- end }} env: {{- include "switch.coreEnv" . | nindent 12 }} + # Readiness checks the database; liveness deliberately does not. + # There is one replica, so a failing readiness probe empties the + # Service rather than shifting traffic — which is right while the + # database is unreachable, and would be catastrophic as a restart + # trigger. `/health` stays the cheap always-ok reply that liveness + # and the other workloads' boot waits use. readinessProbe: httpGet: - path: /health + path: /health/ready port: 8000 initialDelaySeconds: 10 periodSeconds: 10 + # Six failures at ten seconds: long enough to ride out a database + # failover, short enough that a real outage stops being served. + failureThreshold: 6 livenessProbe: httpGet: path: /health diff --git a/deploy/remote/helm/switch/values.yaml b/deploy/remote/helm/switch/values.yaml index 75fffe8dc..c219c5bde 100644 --- a/deploy/remote/helm/switch/values.yaml +++ b/deploy/remote/helm/switch/values.yaml @@ -117,6 +117,35 @@ switchCore: environment: "" serviceName: switch-core + # Where this deployment reports metrics and logs (CHOO-2807). + # + # Empty endpoint means it reports nowhere, which is the default: nothing + # leaves the deployment until an operator names a collector. Readiness + # checking is unaffected either way — /health/ready works regardless. + observability: + # Base URL of an OTLP/HTTP collector, with no path: `/v1/metrics` and + # `/v1/logs` are appended, the same convention every other OTLP client + # follows. Setting this is what turns reporting on. + otlpEndpoint: "" + # A UUID identifying this deployment, stable across restarts and upgrades. + # Required when otlpEndpoint is set — the collector drops what it cannot + # attribute, so without one this reports nothing while looking configured. + # Generate once with `uuidgen` and leave it alone; a new id per install + # makes one deployment look like a population of them. + deploymentId: "" + metrics: true + # Off by default: logs already go to the container's output, where a + # cluster log agent can read them. Turning this on sends a second copy + # over the network, which costs money somebody has to choose to spend. + logs: false + # Off because the relay Switch reports to does not serve /v1/traces yet. + # Turning it on before it does means every export fails. + traces: false + exportIntervalSeconds: 60 + # `key=value` pairs, comma-separated, sent on every request. The relay + # needs none; a private collector usually wants an API key. + headers: "" + # Public base URL the gateway is served on (used for links / OIDC redirects). frontendBaseUrl: "" # Public origin (scheme + host, no path) of the gateway HTTP API itself, used diff --git a/docs/old/observability.md b/docs/old/observability.md new file mode 100644 index 000000000..6b31cd249 --- /dev/null +++ b/docs/old/observability.md @@ -0,0 +1,145 @@ +# Observability + +What `switch-core` reports about itself, where it goes, and how to turn it on. + +Structured logging came first and is older than the rest of this +(`logging_config.py`, `logging_context.py`). Metrics, readiness and the export +path are CHOO-2807. + +## The short version + +Nothing leaves the deployment until `OTLP_ENDPOINT` names a collector. Set it, +set `DEPLOYMENT_ID` to a UUID, and the server reports metrics. Logs are a +second switch because they cost more. + +```bash +OTLP_ENDPOINT=https://telemetry.example.com +DEPLOYMENT_ID=0e5d1b3a-6c1f-4c22-9a4c-3a9f5a2b7d10 # `uuidgen`, once, then leave it +OTLP_LOGS_ENABLED=true # optional +``` + +In Helm the same settings are `switchCore.observability.*`. Dashboards and +alerts are checked in under [`deploy/observability/`](../../deploy/observability/). + +## The three things it emits + +**Logs** have always been written to the container's output as JSON, keyed for +Datadog, with `tenant_id`, `request_id`, `agent_id` and `user_id` stamped on +every line by a filter on the handler — so records from libraries carry them +too. With `OTLP_LOGS_ENABLED` the same records are *also* posted to the +collector. The stderr copy is never replaced: `kubectl logs` keeps working, and +a collector outage costs a copy rather than the record. + +**Metrics** are declared in +[`core/switch_core/observability/catalogue.py`](../../core/switch_core/observability/catalogue.py), +which is the reference for what exists. Nothing not declared there can be +recorded — the registry rejects an unknown name and an attribute the spec does +not list. + +**Traces** are not implemented. See "What is missing" below. + +## Why there is a catalogue + +A metric's cost is the number of distinct attribute combinations it produces, +and the values that feel most natural to attach are unbounded: a room id, an +agent id, the raw request path. One of those reaching a call site is not a +noisier dashboard, it is a bill and a collector that starts dropping. + +On a multi-tenant server it is also a disclosure question. Dashboards are read +by whoever can see them, which is not the same set of people as those entitled +to a given tenant's rows, so tenant attribution stays out of metrics. Product +events that *are* tenant-attributed are CHOO-2806's concern and travel as log +records, where they are scoped separately. + +So every attribute value must come from a fixed set the code controls — a +platform name, a route template, a status class. Where that cannot be +guaranteed at the call site, it does not belong in a metric. Two examples in +the tree: the HTTP middleware labels by route template and folds everything +unmatched into one bucket, because a 404 path is attacker-chosen; and the +transport classifies `send_event`'s arbitrary event type into four values +rather than passing it through. + +## Health: two routes, on purpose + +| Route | Answers | Used by | +| --- | --- | --- | +| `/health` | Always `ok`, checks nothing | Liveness probe; the gateway Deployment and setup Job wait on it at boot | +| `/health/ready` | Each dependency, and 503 when a gating one fails | Readiness probe | + +`/health` could not simply be made stricter. Two other workloads block on it +during a deploy, so anything it checked would become a boot-ordering +dependency for them. + +**What gates readiness is deliberately narrow.** `switch-core` is pinned to one +replica with a `Recreate` strategy, because it holds live sessions in memory. +A failing readiness probe therefore does not move traffic to a healthy pod — +there is no other pod. It empties the Service. So only the database gates: +without it every request is an error anyway. + +Everything else is reported and alertable but never fatal. A crashed Slack +adapter is a real fault; taking Switch off the air over it would turn one +broken bridge into every broken bridge. + +The checks run on a timer rather than per request, and the kubelet and the +metrics exporter read the same cached answer. The cache carries its own age, +and one nobody is refreshing reports itself as a failure — which is also how a +blocked event loop shows up. + +## What the process reports about itself + +There is no Datadog agent in the cluster, so `switch-core` reports its own +memory, CPU, descriptors and garbage collections, read from `/proc/self` with +no extra dependency. Off Linux those readings are absent rather than +fabricated, and a warning at startup says which. + +**Event-loop lag is the one no external agent could produce.** The server is +single-threaded and cooperative: one blocking call stalls every room, every +bridge and every heartbeat at once, and from the outside that looks like an +unrelated timeout somewhere else. The connection sweep already measured its own +oversleep to avoid expiring connections it had simply failed to hear from; that +number is now reported instead of discarded. + +## What you still do not get without an agent + +Pod and node facts the process cannot see: container restarts, OOM kills, +evictions, node pressure, and Datadog's Kubernetes views. Application health +does not depend on any of it, but capacity planning eventually does. That is +infrastructure work, separate from this. + +## What is missing + +**Tracing.** The export path is signal-agnostic and `OTLP_TRACES_ENABLED` +exists, but nothing produces spans yet, and the relay Switch reports to does +not serve `/v1/traces` — a POST there returns 404. Enabling the flag today +would mean every export failing, which is why it defaults off. Two things have +to happen: the collector must accept the signal, and the server must produce +spans. + +When it does, the log records already carry `traceId` and `spanId` fields +wherever they are set, so log-to-trace correlation needs no further change to +the log path. + +**Per-route trace sampling** will matter when it arrives. Switch's agent +polling endpoints (`/events`, `/room-history`, per-agent reads) are very high +volume and are already filtered out of the uvicorn access log for that reason; +tracing them at full rate would swamp APM and cost more than it tells anyone. + +## Failure behaviour + +Everything here follows the repository's rule that a visible failure beats a +silent fallback. + +- A collector that rejects a payload raises rather than being ignored, + including a partial rejection inside a `200` — the collector answers `200` + for a payload it drops, so the body is read. +- Repeated export failures escalate from a warning to an error naming how many + intervals were lost, because by then the dashboards are stale and somebody is + about to be misled by them. +- The log queue is bounded and drops the oldest, and says how many it dropped. + A gap that announces itself beats one nobody can see. +- `DEPLOYMENT_ID` is required whenever an endpoint is set, and the server + refuses to start without it. The collector drops unattributed payloads + silently, with a `200`, so the alternative is a deployment that looks + configured and appears on no dashboard. +- An export failure never takes the server down. A metrics exporter that can + kill the thing it measures is worse than no metrics exporter.