375 lines
14 KiB
Python
375 lines
14 KiB
Python
"""OpenTelemetry metrics and log export beyond kaya-otel.
|
|
|
|
kaya-otel instruments HTTP requests and websockets with traces and HTTP
|
|
metrics; this module adds what it does not cover, all behind the optional
|
|
``otel`` extra (OpenTelemetry imports are lazy, so default installs and
|
|
the test suite never need them):
|
|
|
|
* application gauges: ``tavolo.active_users`` (sessions held in the
|
|
session store) and ``tavolo.ongoing_games`` (live matches that have not
|
|
finished yet);
|
|
* process metrics through ``opentelemetry-instrumentation-system-metrics``:
|
|
CPU time/utilization, memory usage and CPython garbage-collection
|
|
counters;
|
|
* OTLP log export through a stdlib :class:`logging.Handler` attached to
|
|
the root logger, mirroring what the console sees;
|
|
* session/user tagging of request and websocket spans through
|
|
:func:`session_tag_hook` (kaya-otel's response/close hooks), so traces
|
|
can be correlated with a session (hashed id) and an OIDC user.
|
|
|
|
The store counts are asynchronous while OpenTelemetry instrument
|
|
callbacks are synchronous, so :class:`TelemetryMixin` polls the stores on
|
|
a background task and its callbacks report the cached values.
|
|
"""
|
|
from __future__ import annotations
|
|
|
|
import asyncio
|
|
import hashlib
|
|
import logging
|
|
from dataclasses import dataclass
|
|
from logging import getLogger
|
|
from typing import TYPE_CHECKING, Any, Dict, Mapping, Optional, Union
|
|
|
|
from kaya.core import KayaApp, KayaMixin
|
|
from kaya.session import InMemorySessionStore, SessionStore
|
|
from kaya.session.redis import RedisSessionStore
|
|
from redis.asyncio import Redis
|
|
from tavolo.platform.store import GameStore
|
|
|
|
from .config import Settings
|
|
|
|
if TYPE_CHECKING:
|
|
from opentelemetry.sdk._logs import LoggerProvider
|
|
from opentelemetry.sdk.metrics import MeterProvider
|
|
from opentelemetry.sdk.trace import TracerProvider
|
|
|
|
log = getLogger(__name__)
|
|
|
|
# Session keys live under kaya's default prefix. Keeping it explicit here
|
|
# makes the Redis count scan exact and preserves existing sessions.
|
|
SESSION_KEY_PREFIX = "kaya:session:"
|
|
|
|
# The interpreter metrics to export. The instrumentation package can also
|
|
# emit host-level ``system.*`` metrics; those are deliberately left off:
|
|
# the application cares about its own process, and per-CPU host metrics
|
|
# add cardinality without context.
|
|
#
|
|
# ``process.cpu.utilization`` ignores its configuration value upstream
|
|
# (the callback always emits one aggregate observation), so its ``None``
|
|
# is only for readability.
|
|
PROCESS_METRICS_CONFIG: Dict[str, Optional[list]] = {
|
|
"process.cpu.time": ["user", "system"],
|
|
"process.cpu.utilization": None,
|
|
"process.memory.usage": None,
|
|
"process.memory.virtual": None,
|
|
"cpython.gc.collections": None,
|
|
"cpython.gc.collected_objects": None,
|
|
"cpython.gc.uncollectable_objects": None,
|
|
}
|
|
|
|
|
|
def otel_headers(settings: Settings) -> Optional[Dict[str, str]]:
|
|
"""Parse ``OTEL_EXPORTER_OTLP_HEADERS`` into a mapping (or ``None``)."""
|
|
headers = dict(
|
|
pair.split("=", 1)
|
|
for pair in (settings.otel_exporter_headers or ())
|
|
if "=" in pair
|
|
)
|
|
return headers or None
|
|
|
|
|
|
def _signal_endpoint(base: Optional[str], signal: str) -> Optional[str]:
|
|
"""``{base}/v1/<signal>``, or ``None`` for the exporter's own default."""
|
|
return f"{base}/{signal}" if base else None
|
|
|
|
|
|
def session_tag_hook(span: Any, carrier: Any) -> None:
|
|
"""Tag an HTTP request/websocket span with the request's session/user.
|
|
|
|
Wired into kaya-otel as its ``server_response_hook`` and
|
|
``websocket_close_hook``: those run after the session mixin's after
|
|
hook has persisted (and, at login, minted) the session, so the final
|
|
session id is visible here.
|
|
|
|
The session id is the session cookie, i.e. a credential, so only a
|
|
truncated SHA-256 of it is exported; session ids are
|
|
``secrets.token_urlsafe(32)`` (256 bits), which makes the digest
|
|
irreversible in practice. The OIDC ``sub`` is a pseudonymous
|
|
identifier already persisted in Postgres and served by the API, so it
|
|
is exported verbatim as ``user.id`` (OpenTelemetry's current end-user
|
|
attribute; ``enduser.id`` is PII-flagged and being superseded).
|
|
"""
|
|
session = getattr(carrier, "session", None)
|
|
if session is None:
|
|
return
|
|
session_id = getattr(session, "id", None)
|
|
if session_id:
|
|
span.set_attribute(
|
|
"session.id",
|
|
hashlib.sha256(session_id.encode()).hexdigest()[:16],
|
|
)
|
|
user = session.get("oidc_user")
|
|
if isinstance(user, Mapping):
|
|
sub = user.get("sub")
|
|
if sub:
|
|
span.set_attribute("user.id", str(sub))
|
|
|
|
|
|
class _NoOtelLogs(logging.Filter):
|
|
"""Drop OpenTelemetry's own log records.
|
|
|
|
Export failures are logged by the SDK; forwarding those through the
|
|
same exporter would feed an endless retry loop.
|
|
"""
|
|
|
|
def filter(self, record: logging.LogRecord) -> bool:
|
|
return not record.name.startswith("opentelemetry")
|
|
|
|
|
|
class CountingInMemorySessionStore(InMemorySessionStore):
|
|
"""In-memory session store that can report its live session count."""
|
|
|
|
async def count(self) -> int:
|
|
now = self._clock()
|
|
return sum(
|
|
1
|
|
for session_id in self._data
|
|
if session_id not in self._expires
|
|
or self._expires[session_id] > now
|
|
)
|
|
|
|
|
|
class CountingRedisSessionStore(RedisSessionStore):
|
|
"""Redis session store that can report its live session count."""
|
|
|
|
def __init__(self, client: Redis, prefix: str = SESSION_KEY_PREFIX) -> None:
|
|
super().__init__(client, prefix=prefix)
|
|
|
|
async def count(self) -> int:
|
|
total = 0
|
|
async for _ in self._client.scan_iter(match=f"{self._prefix}*", count=500):
|
|
total += 1
|
|
return total
|
|
|
|
|
|
# The session stores the application builds: both expose ``count()`` on top
|
|
# of kaya's ``SessionStore`` interface. Game stores need no alias — the
|
|
# platform's ``GameStore`` declares ``count_ongoing()`` itself.
|
|
CountableSessionStore = Union[CountingInMemorySessionStore, CountingRedisSessionStore]
|
|
|
|
|
|
class TelemetryMixin(KayaMixin):
|
|
"""Application gauges, DB instrumentation and log export.
|
|
|
|
The meter, tracer and logger providers are built by
|
|
:func:`telemetry_from_settings` and injected: kaya-otel only shuts
|
|
down providers it created itself, so this mixin owns their shutdown
|
|
(and uninstruments the database clients it instrumented).
|
|
"""
|
|
|
|
def __init__(
|
|
self,
|
|
*,
|
|
meter_provider: "MeterProvider",
|
|
tracer_provider: "TracerProvider",
|
|
logger_provider: Optional["LoggerProvider"],
|
|
log_handler: Optional[logging.Handler],
|
|
session_store: CountableSessionStore,
|
|
game_store: GameStore,
|
|
poll_interval_seconds: float,
|
|
) -> None:
|
|
self._meter_provider = meter_provider
|
|
self._tracer_provider = tracer_provider
|
|
self._logger_provider = logger_provider
|
|
self._log_handler = log_handler
|
|
self._session_store = session_store
|
|
self._game_store = game_store
|
|
self._poll_interval = poll_interval_seconds
|
|
self._active_users: Optional[int] = None
|
|
self._ongoing_games: Optional[int] = None
|
|
self._poll_task: Optional[asyncio.Task] = None
|
|
self._instrumentor: Optional[Any] = None
|
|
self._db_instrumentors: list = []
|
|
|
|
def apply(self, app: KayaApp) -> None:
|
|
from opentelemetry.instrumentation.asyncpg import AsyncPGInstrumentor
|
|
from opentelemetry.instrumentation.redis import RedisInstrumentor
|
|
from opentelemetry.instrumentation.system_metrics import (
|
|
SystemMetricsInstrumentor,
|
|
)
|
|
from opentelemetry.metrics import CallbackOptions, Observation
|
|
|
|
instrumentor = SystemMetricsInstrumentor(config=PROCESS_METRICS_CONFIG)
|
|
self._instrumentor = instrumentor
|
|
instrumentor.instrument(meter_provider=self._meter_provider)
|
|
|
|
# Query spans for the Postgres (asyncpg, used by Tortoise) and Redis
|
|
# clients. Redis command values are redacted by the instrumentation
|
|
# (``SET ? ?``); asyncpg spans carry the parameterized SQL only.
|
|
self._db_instrumentors = [
|
|
AsyncPGInstrumentor(capture_parameters=False),
|
|
RedisInstrumentor(),
|
|
]
|
|
for db_instrumentor in self._db_instrumentors:
|
|
db_instrumentor.instrument(tracer_provider=self._tracer_provider)
|
|
|
|
meter = self._meter_provider.get_meter(__name__)
|
|
|
|
def active_users(options: CallbackOptions):
|
|
if self._active_users is not None:
|
|
yield Observation(self._active_users)
|
|
|
|
def ongoing_games(options: CallbackOptions):
|
|
if self._ongoing_games is not None:
|
|
yield Observation(self._ongoing_games)
|
|
|
|
meter.create_observable_gauge(
|
|
"tavolo.active_users",
|
|
callbacks=[active_users],
|
|
unit="{user}",
|
|
description="Sessions currently held in the session store.",
|
|
)
|
|
meter.create_observable_gauge(
|
|
"tavolo.ongoing_games",
|
|
callbacks=[ongoing_games],
|
|
unit="{game}",
|
|
description="Live games that have not finished yet.",
|
|
)
|
|
|
|
# -- lifecycle ----------------------------------------------------------
|
|
|
|
def setup(self, loop: asyncio.AbstractEventLoop) -> None:
|
|
self._poll_task = loop.create_task(self._poll())
|
|
|
|
def shutdown(self, loop: asyncio.AbstractEventLoop) -> None:
|
|
if self._poll_task is not None:
|
|
self._poll_task.cancel()
|
|
self._poll_task = None
|
|
for db_instrumentor in self._db_instrumentors:
|
|
db_instrumentor.uninstrument()
|
|
self._db_instrumentors = []
|
|
if self._log_handler is not None:
|
|
logging.getLogger().removeHandler(self._log_handler)
|
|
self._log_handler.close()
|
|
self._log_handler = None
|
|
if self._logger_provider is not None:
|
|
self._logger_provider.shutdown()
|
|
self._tracer_provider.shutdown()
|
|
self._meter_provider.shutdown()
|
|
|
|
async def _poll(self) -> None:
|
|
while True:
|
|
await self.refresh_counts()
|
|
await asyncio.sleep(self._poll_interval)
|
|
|
|
async def refresh_counts(self) -> None:
|
|
"""Refresh the cached store counts (the poll loop calls this)."""
|
|
try:
|
|
self._active_users = await self._session_store.count()
|
|
except Exception:
|
|
log.warning("active_users refresh failed", exc_info=True)
|
|
try:
|
|
self._ongoing_games = await self._game_store.count_ongoing()
|
|
except Exception:
|
|
log.warning("ongoing_games refresh failed", exc_info=True)
|
|
|
|
|
|
@dataclass
|
|
class Telemetry:
|
|
"""The providers and mixin built from the ``OTEL_*`` settings."""
|
|
|
|
meter_provider: "MeterProvider"
|
|
tracer_provider: "TracerProvider"
|
|
logger_provider: Optional["LoggerProvider"]
|
|
log_handler: Optional[logging.Handler]
|
|
mixin: TelemetryMixin
|
|
|
|
|
|
def telemetry_from_settings(
|
|
settings: Settings,
|
|
session_store: CountableSessionStore,
|
|
game_store: GameStore,
|
|
) -> Optional[Telemetry]:
|
|
"""Build the metric/trace/log providers, or ``None`` when telemetry is off.
|
|
|
|
Only called when ``OTEL_ENABLED`` is set; the OpenTelemetry imports
|
|
are lazy so the default install does not need the ``otel`` extra.
|
|
"""
|
|
if not settings.otel_enabled:
|
|
return None
|
|
try:
|
|
from opentelemetry.exporter.otlp.proto.http._log_exporter import (
|
|
OTLPLogExporter,
|
|
)
|
|
from opentelemetry.exporter.otlp.proto.http.metric_exporter import (
|
|
OTLPMetricExporter,
|
|
)
|
|
from opentelemetry.exporter.otlp.proto.http.trace_exporter import (
|
|
OTLPSpanExporter,
|
|
)
|
|
from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler
|
|
from opentelemetry.sdk._logs.export import BatchLogRecordProcessor
|
|
from opentelemetry.sdk.metrics import MeterProvider
|
|
from opentelemetry.sdk.metrics.export import PeriodicExportingMetricReader
|
|
from opentelemetry.sdk.resources import Resource
|
|
from opentelemetry.sdk.trace import TracerProvider
|
|
from opentelemetry.sdk.trace.export import BatchSpanProcessor
|
|
except ImportError as exc:
|
|
raise RuntimeError(
|
|
"OTEL_ENABLED is set but the OpenTelemetry dependencies are not "
|
|
"installed; install tavolo-app with the 'otel' extra"
|
|
) from exc
|
|
|
|
endpoint = settings.otel_exporter_endpoint
|
|
headers = otel_headers(settings)
|
|
resource = Resource.create({"service.name": settings.otel_service_name})
|
|
tracer_provider = TracerProvider(resource=resource)
|
|
tracer_provider.add_span_processor(
|
|
BatchSpanProcessor(
|
|
OTLPSpanExporter(
|
|
endpoint=_signal_endpoint(endpoint, "v1/traces"),
|
|
headers=headers,
|
|
)
|
|
)
|
|
)
|
|
meter_provider = MeterProvider(
|
|
resource=resource,
|
|
metric_readers=[
|
|
PeriodicExportingMetricReader(
|
|
OTLPMetricExporter(
|
|
endpoint=_signal_endpoint(endpoint, "v1/metrics"),
|
|
headers=headers,
|
|
),
|
|
export_interval_millis=settings.otel_metric_export_interval_millis,
|
|
)
|
|
],
|
|
)
|
|
logger_provider = LoggerProvider(resource=resource)
|
|
logger_provider.add_log_record_processor(
|
|
BatchLogRecordProcessor(
|
|
OTLPLogExporter(
|
|
endpoint=_signal_endpoint(endpoint, "v1/logs"),
|
|
headers=headers,
|
|
)
|
|
)
|
|
)
|
|
handler = LoggingHandler(level=logging.NOTSET, logger_provider=logger_provider)
|
|
handler.addFilter(_NoOtelLogs())
|
|
logging.getLogger().addHandler(handler)
|
|
mixin = TelemetryMixin(
|
|
meter_provider=meter_provider,
|
|
tracer_provider=tracer_provider,
|
|
logger_provider=logger_provider,
|
|
log_handler=handler,
|
|
session_store=session_store,
|
|
game_store=game_store,
|
|
poll_interval_seconds=settings.otel_metrics_poll_interval_seconds,
|
|
)
|
|
return Telemetry(
|
|
meter_provider=meter_provider,
|
|
tracer_provider=tracer_provider,
|
|
logger_provider=logger_provider,
|
|
log_handler=handler,
|
|
mixin=mixin,
|
|
)
|