Add optional OpenTelemetry traces, metrics and OTLP logs
This commit is contained in:
@@ -1,8 +1,10 @@
|
||||
"""Application entry point.
|
||||
|
||||
Assembles the kaya app with sessions, OIDC, Tortoise, OpenAPI, the KCA API
|
||||
and the SPA shell. Optional CORS mirrors spendwise's environment-driven
|
||||
configuration.
|
||||
and the SPA shell. Optional CORS mirrors spendwise's environment-driven
|
||||
configuration. When ``OTEL_ENABLED`` is set, kaya-otel adds HTTP traces and
|
||||
metrics, and :class:`~kca.telemetry.TelemetryMixin` adds process metrics,
|
||||
database spans and OTLP log export.
|
||||
"""
|
||||
from __future__ import annotations
|
||||
|
||||
@@ -19,6 +21,14 @@ from .config import Settings, settings
|
||||
from .logging_config import configure_logging
|
||||
from .mixin import Kca, KcaMixin
|
||||
from .openapi import SCHEMAS, SECURITY_SCHEMES, KcaOpenAPI
|
||||
from .telemetry import (
|
||||
CountableSessionStore,
|
||||
CountingInMemorySessionStore,
|
||||
CountingRedisSessionStore,
|
||||
otel_headers,
|
||||
session_tag_hook,
|
||||
telemetry_from_settings,
|
||||
)
|
||||
from .tortoise_mixin import TortoiseMixin
|
||||
|
||||
configure_logging(settings.logging_config)
|
||||
@@ -39,6 +49,45 @@ def cors_mixin_from_settings(settings: Settings) -> Optional[CorsMixin]:
|
||||
)
|
||||
|
||||
|
||||
def otel_mixin_from_settings(
|
||||
settings: Settings,
|
||||
meter_provider: Optional[Any] = None,
|
||||
tracer_provider: Optional[Any] = None,
|
||||
) -> Optional[KayaMixin]:
|
||||
"""Build a :class:`~kaya.otel.OTelMixin` from the OTEL_* settings.
|
||||
|
||||
Returns ``None`` — telemetry disabled — unless ``OTEL_ENABLED`` is
|
||||
truthy. kaya-otel is an optional dependency (the ``otel`` extra), so it
|
||||
is imported lazily here: default installs and the test suite never need
|
||||
the OpenTelemetry packages.
|
||||
"""
|
||||
if not settings.otel_enabled:
|
||||
return None
|
||||
try:
|
||||
from kaya.otel import OTelMixin
|
||||
except ImportError as exc:
|
||||
raise RuntimeError(
|
||||
"OTEL_ENABLED is set but kaya-otel is not installed; "
|
||||
"install kca-app with the 'otel' extra"
|
||||
) from exc
|
||||
kwargs: Dict[str, Any] = {
|
||||
"service_name": settings.otel_service_name,
|
||||
"endpoint": settings.otel_exporter_endpoint,
|
||||
"headers": otel_headers(settings),
|
||||
"excluded_paths": settings.otel_excluded_paths,
|
||||
"metric_export_interval_millis": settings.otel_metric_export_interval_millis,
|
||||
# Runs after the session mixin's after hook, so the session id has
|
||||
# been persisted/minted and the OIDC claims are on the session.
|
||||
"server_response_hook": session_tag_hook,
|
||||
"websocket_close_hook": session_tag_hook,
|
||||
}
|
||||
if meter_provider is not None:
|
||||
kwargs["meter_provider"] = meter_provider
|
||||
if tracer_provider is not None:
|
||||
kwargs["tracer_provider"] = tracer_provider
|
||||
return OTelMixin(**kwargs)
|
||||
|
||||
|
||||
if settings.master_key_is_dev:
|
||||
log.warning(
|
||||
"KCA_MASTER_KEY is unset: using the built-in development key. "
|
||||
@@ -46,14 +95,10 @@ if settings.master_key_is_dev:
|
||||
)
|
||||
|
||||
if settings.redis_url is not None:
|
||||
from kaya.session.redis import RedisSessionStore
|
||||
|
||||
session_store: Any = RedisSessionStore(Redis.from_url(settings.redis_url))
|
||||
session_store: CountableSessionStore = CountingRedisSessionStore(Redis.from_url(settings.redis_url))
|
||||
log.info("using the Redis session store")
|
||||
else:
|
||||
from kaya.session import InMemorySessionStore
|
||||
|
||||
session_store = InMemorySessionStore()
|
||||
session_store = CountingInMemorySessionStore()
|
||||
log.info("REDIS_URL unset: using the in-memory session store")
|
||||
|
||||
session_mixin = SessionMixin(session_store, secure=settings.session_cookie_secure)
|
||||
@@ -99,6 +144,28 @@ mixins: list[KayaMixin] = [
|
||||
KcaMixin(kca),
|
||||
]
|
||||
|
||||
telemetry = telemetry_from_settings(settings, session_store)
|
||||
if telemetry is not None:
|
||||
otel_mixin = otel_mixin_from_settings(
|
||||
settings,
|
||||
meter_provider=telemetry.meter_provider,
|
||||
tracer_provider=telemetry.tracer_provider,
|
||||
)
|
||||
assert otel_mixin is not None # OTEL_ENABLED was checked above
|
||||
# kaya-otel first: before hooks run in registration order (after hooks
|
||||
# in reverse), so the span covers session loading, OIDC handling and
|
||||
# the handler itself. CORS, when enabled, is still prepended before it
|
||||
# so preflight short-circuits stay untraced. The telemetry mixin owns
|
||||
# the metric/logger providers' polling and shutdown, so it must be in
|
||||
# the list too.
|
||||
mixins.insert(0, telemetry.mixin)
|
||||
mixins.insert(0, otel_mixin)
|
||||
log.info(
|
||||
"OpenTelemetry enabled: service=%s endpoint=%s (traces, metrics, logs)",
|
||||
settings.otel_service_name,
|
||||
settings.otel_exporter_endpoint or "(OTLP default)",
|
||||
)
|
||||
|
||||
cors_mixin = cors_mixin_from_settings(settings)
|
||||
if cors_mixin is not None:
|
||||
mixins.insert(0, cors_mixin)
|
||||
|
||||
@@ -0,0 +1,368 @@
|
||||
"""OpenTelemetry metrics and log export beyond kaya-otel.
|
||||
|
||||
kaya-otel instruments HTTP requests 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):
|
||||
|
||||
* the application gauge ``kca.active_sessions`` (sessions held in the
|
||||
session store);
|
||||
* 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 spans through :func:`session_tag_hook`
|
||||
(kaya-otel's response hook), 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, Optional, Union
|
||||
|
||||
from kaya.core import KayaApp, KayaMixin
|
||||
from kaya.session import InMemorySessionStore
|
||||
from kaya.session.redis import RedisSessionStore
|
||||
from redis.asyncio import Redis
|
||||
|
||||
from .auth import cached_user, session_user
|
||||
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_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}/v1/{signal}" if base else None
|
||||
|
||||
|
||||
def session_tag_hook(span: Any, carrier: Any) -> None:
|
||||
"""Tag an HTTP request span with the request's session/user.
|
||||
|
||||
Wired into kaya-otel as its ``server_response_hook``: it runs 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).
|
||||
Requests authenticated with a personal access token have no session
|
||||
user; their ``user.id`` comes from the user the auth guard resolved
|
||||
and cached on the request.
|
||||
"""
|
||||
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],
|
||||
)
|
||||
sub = None
|
||||
user = session_user(session)
|
||||
if user is not None:
|
||||
sub = user.get("sub")
|
||||
if sub is None:
|
||||
cached = cached_user(carrier)
|
||||
if cached is not None:
|
||||
sub = cached.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
|
||||
|
||||
|
||||
CountableSessionStore = Union[CountingInMemorySessionStore, CountingRedisSessionStore]
|
||||
|
||||
|
||||
class TelemetryMixin(KayaMixin):
|
||||
"""Application gauge, 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,
|
||||
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._poll_interval = poll_interval_seconds
|
||||
self._active_sessions: 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_sessions(options: CallbackOptions):
|
||||
if self._active_sessions is not None:
|
||||
yield Observation(self._active_sessions)
|
||||
|
||||
meter.create_observable_gauge(
|
||||
"kca.active_sessions",
|
||||
callbacks=[active_sessions],
|
||||
unit="{session}",
|
||||
description="Sessions currently held in the session store.",
|
||||
)
|
||||
|
||||
# -- 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_sessions = await self._session_store.count()
|
||||
except Exception:
|
||||
log.warning("active_sessions 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,
|
||||
) -> 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 kca-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, "traces"),
|
||||
headers=headers,
|
||||
)
|
||||
)
|
||||
)
|
||||
meter_provider = MeterProvider(
|
||||
resource=resource,
|
||||
metric_readers=[
|
||||
PeriodicExportingMetricReader(
|
||||
OTLPMetricExporter(
|
||||
endpoint=_signal_endpoint(endpoint, "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, "logs"),
|
||||
headers=headers,
|
||||
)
|
||||
)
|
||||
)
|
||||
# KCA's console logging defaults to DEBUG, including per-query Tortoise
|
||||
# records. Export INFO+ so the OTLP log volume stays useful.
|
||||
handler = LoggingHandler(level=logging.INFO, 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,
|
||||
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,
|
||||
)
|
||||
|
||||
|
||||
__all__ = [
|
||||
"CountableSessionStore",
|
||||
"CountingInMemorySessionStore",
|
||||
"CountingRedisSessionStore",
|
||||
"Telemetry",
|
||||
"TelemetryMixin",
|
||||
"otel_headers",
|
||||
"session_tag_hook",
|
||||
"telemetry_from_settings",
|
||||
]
|
||||
Reference in New Issue
Block a user