"""Side-channel provider-call observability (HEL-543). This module is additive-only and must never change what any existing call returns or raises. It exists purely to answer, after the fact and without touching routing: which provider/interface was called, whether it succeeded, how stale/complete the payload looked, and why a fallback fired. Hard rules enforced here: - Every public entry point (`observe`, `record_call`) is wrapped so that a database failure, a classifier bug, or any other internal error is swallowed and logged at DEBUG level. It never raises into the caller and never delays/blocks the caller's real data path beyond a best-effort timing measurement. - `observe()` always returns exactly what `fn()` returned, and re-raises exactly what `fn()` raised (same exception object, unmodified). It does not retry, does not change ordering, and does not add new failure modes. - No mock data is ever produced or returned by this module. """ from __future__ import annotations import re import time from typing import Any, Callable, TypeVar from datahub.timeutil import isoformat, now_shanghai _T = TypeVar("_T") # Additive-only schema: two new tables, no changes to any existing table. # Merged into datahub.db.SCHEMA the same way EXTENDED_SCHEMA is. OBS_SCHEMA = """ CREATE TABLE IF NOT EXISTS provider_call_log ( id INTEGER PRIMARY KEY AUTOINCREMENT, provider TEXT NOT NULL, interface TEXT NOT NULL, fetched_at TEXT NOT NULL, latency_ms INTEGER, status TEXT NOT NULL, error TEXT, fallback_reason TEXT, data_age_seconds INTEGER, created_at TEXT NOT NULL ); CREATE TABLE IF NOT EXISTS provider_health ( provider TEXT NOT NULL, interface TEXT NOT NULL, state TEXT NOT NULL, last_ok_at TEXT, last_error TEXT, last_fallback_reason TEXT, consec_failures INTEGER NOT NULL DEFAULT 0, last_latency_ms INTEGER, last_data_age_seconds INTEGER, updated_at TEXT NOT NULL, PRIMARY KEY (provider, interface) ); CREATE INDEX IF NOT EXISTS idx_provider_call_log_created ON provider_call_log(created_at); CREATE INDEX IF NOT EXISTS idx_provider_call_log_provider ON provider_call_log(provider, interface, created_at); """ DEFAULT_STALE_SECONDS = 300 _BLOCKED_MARKERS = ( " bool: """Runtime kill switch (``Settings.observability_enabled`` / ``DATAHUB_OBSERVABILITY``, wired onto the db handle in ``Hub.__init__``). Defaults to enabled when the attribute is absent — e.g. a bare ``HubDB`` built directly in a test, or any call site that predates HEL-543 — so this can never accidentally disable an existing deployment. Never raises. """ try: return bool(getattr(db, "observability_enabled", True)) except Exception: # pragma: no cover - defensive, must never raise return True def classify_error(message: str) -> tuple[str, str]: """Best-effort, side-reading classification of an exception message. Never raises. Unknown shapes fall back to a generic ``error`` status so a classifier miss can never be mistaken for a healthy call. """ try: lower = (message or "").lower() if any(marker in lower for marker in _BLOCKED_MARKERS): return "blocked", "response_looks_like_intercept_page" if "timeout" in lower or "timed out" in lower: return "timeout", "request_timeout" mismatch = _COUNT_MISMATCH_RE.search(lower) if mismatch and int(mismatch.group(1)) == 0: return "empty", "empty_or_incomplete_response" if mismatch: return "degraded", "partial_or_mismatched_response" if "empty" in lower or "no intraday chart data" in lower or "missing" in lower: return "empty", "empty_or_incomplete_response" if "too small" in lower or "incomplete" in lower or "mismatch" in lower: return "degraded", "partial_or_mismatched_response" return "error", "" except Exception: # pragma: no cover - defensive, must never raise return "error", "" def classify_rows( rows: Any, *, required_fields: tuple[str, ...] | None = None, freshness_field: str | None = "quote_time_epoch", max_age_seconds: int = DEFAULT_STALE_SECONDS, ) -> tuple[str, str, int | None]: """Read-only classification of an already-successful payload. Only ever called on a value a caller is about to use as-is; this never mutates ``rows`` and a classifier bug always degrades to ``("ok", "", None)`` rather than mislabeling a real success as a failure. """ try: if isinstance(rows, dict): items = [rows] if rows else [] elif isinstance(rows, (list, tuple)): items = [item for item in rows if isinstance(item, dict)] else: items = [] if not items: return "empty", "no_rows_returned", None if required_fields: missing: set[str] = set() for item in items: for field in required_fields: if item.get(field) in (None, ""): missing.add(field) if missing: return "missing_fields", "missing:" + ",".join(sorted(missing)), None data_age: int | None = None if freshness_field: now_epoch = time.time() ages: list[int] = [] for item in items: raw = item.get(freshness_field) try: epoch = int(raw or 0) except (TypeError, ValueError): epoch = 0 if epoch > 0: ages.append(max(0, int(now_epoch - epoch))) if ages: data_age = max(ages) if data_age > max_age_seconds: return "stale", "data_age_exceeds_threshold", data_age return "ok", "", data_age except Exception: # pragma: no cover - defensive, must never raise return "ok", "", None def record_call( db: Any, provider: str, interface: str, *, status: str, latency_ms: int | None = None, error: str = "", fallback_reason: str = "", data_age_seconds: int | None = None, ) -> None: """Fail-open recorder. Never raises; a write failure here must never be able to take down a real, otherwise-successful data path.""" if db is None or not is_enabled(db): return try: now = isoformat(now_shanghai()) ok = status == "ok" error_text = (error or "")[:500] reason_text = (fallback_reason or "")[:200] with db.write() as connection: connection.execute( "INSERT INTO provider_call_log(" "provider, interface, fetched_at, latency_ms, status, error, " "fallback_reason, data_age_seconds, created_at) " "VALUES (?,?,?,?,?,?,?,?,?)", (provider, interface, now, latency_ms, status, error_text, reason_text, data_age_seconds, now), ) connection.execute( """ INSERT INTO provider_health( provider, interface, state, last_ok_at, last_error, last_fallback_reason, consec_failures, last_latency_ms, last_data_age_seconds, updated_at) VALUES (?,?,?,?,?,?,?,?,?,?) ON CONFLICT(provider, interface) DO UPDATE SET state = excluded.state, last_ok_at = CASE WHEN excluded.state = 'ok' THEN excluded.last_ok_at ELSE provider_health.last_ok_at END, last_error = CASE WHEN excluded.state = 'ok' THEN '' ELSE excluded.last_error END, last_fallback_reason = excluded.last_fallback_reason, consec_failures = CASE WHEN excluded.state = 'ok' THEN 0 ELSE provider_health.consec_failures + 1 END, last_latency_ms = excluded.last_latency_ms, last_data_age_seconds = excluded.last_data_age_seconds, updated_at = excluded.updated_at """, ( provider, interface, status, now if ok else None, "" if ok else (error_text or reason_text or "unknown_error"), reason_text, 0 if ok else 1, latency_ms, data_age_seconds, now, ), ) except Exception: # pragma: no cover - defensive, must never raise try: _logger().debug( "observability record_call failed (fail-open)", extra={"hub": {"provider": provider, "interface": interface}}, exc_info=True, ) except Exception: pass def _safe_record_failure(db: Any, provider: str, interface: str, latency_ms: int, exc: BaseException) -> None: if db is None: return try: message = str(exc) status, reason = classify_error(message) record_call( db, provider, interface, status=status, latency_ms=latency_ms, error=message, fallback_reason=reason, ) except Exception: # pragma: no cover - defensive, must never raise pass def _safe_record_success( db: Any, provider: str, interface: str, latency_ms: int, result: Any, classify: Callable[[Any], tuple[str, str, int | None] | None] | None, ) -> None: if db is None: return status, reason, data_age = "ok", "", None if classify is not None: try: classified = classify(result) if classified: status, reason, data_age = classified except Exception: # pragma: no cover - defensive, must never raise # A classifier bug must never mislabel (or hide) a real success; # degrade to a plain "ok" call rather than skipping the log. status, reason, data_age = "ok", "", None try: record_call( db, provider, interface, status=status, latency_ms=latency_ms, fallback_reason=reason, data_age_seconds=data_age, ) except Exception: # pragma: no cover - defensive, must never raise pass def observe( db: Any, provider: str, interface: str, fn: Callable[[], _T], *, classify: Callable[[Any], tuple[str, str, int | None] | None] | None = None, ) -> _T: """Call ``fn()`` and record a side-channel status row. Returns exactly what ``fn()`` returns and re-raises exactly what ``fn()`` raises. ``db`` may be ``None`` (e.g. in call sites that are not wired to a database yet); in that case this is a transparent passthrough with no recording at all. Same when the ``DATAHUB_OBSERVABILITY`` kill switch is off (see ``is_enabled``): this becomes ``return fn()`` with no timing, no classification, and no db access whatsoever. """ if db is not None and not is_enabled(db): return fn() started = time.perf_counter() try: result = fn() except Exception: latency_ms = round((time.perf_counter() - started) * 1000) import sys exc = sys.exc_info()[1] if exc is not None: _safe_record_failure(db, provider, interface, latency_ms, exc) raise latency_ms = round((time.perf_counter() - started) * 1000) _safe_record_success(db, provider, interface, latency_ms, result, classify) return result