ERP/bot/app/observability.py

"""Silent observer — records the whole bot pipeline into Postgres (phase 1).

Design rules (final plan v5):
- DB is the single source of truth; no external tools, no dashboards here.
- ZERO extra LLM tokens: we only persist values that already exist in code.
- Never raises, never blocks the reply path (fire-and-forget like runtime._log).
- Never deletes anything (no retention/cleanup tasks exist by policy).
- `_jsonable` guarantees JSONB-safety for UUID/datetime/Decimal/... payloads.

Stages captured (see plan §4.3): input.text, input.voice, stt.run, stt.result,
nlu.request, nlu.result, entities.extracted, jev.request, jev.result,
routing.decision, ambiguity.sent, ambiguity.user_choice, user_choice.pick,
draft.render, draft.edit, draft.commit, draft.cancel.
"""
import asyncio
import logging
import uuid
from datetime import date, datetime, time
from decimal import Decimal
from enum import Enum
from pathlib import Path

from sqlalchemy import select, update

from app.config import settings
from app.db import SessionLocal
from app.models import BotTrace, BotTraceEvent

logger = logging.getLogger("bot.obs")

_bg_tasks: set = set()


def _fire(coro) -> None:
    """Schedule a coroutine without awaiting; keep a ref so it is not GC'd."""
    try:
        task = asyncio.get_running_loop().create_task(coro)
        _bg_tasks.add(task)
        task.add_done_callback(_bg_tasks.discard)
    except RuntimeError:
        # No running loop (should not happen inside the bot) — drop silently but log.
        logger.warning("obs: no running loop; dropped %r", coro)


def _jsonable(obj):
    """Recursively make any Python object JSONB-safe (UUID/datetime/Decimal/…)."""
    if obj is None or isinstance(obj, (bool, int, float, str)):
        return obj
    if isinstance(obj, (uuid.UUID, Path)):
        return str(obj)
    if isinstance(obj, (datetime, date, time)):
        return obj.isoformat()
    if isinstance(obj, Decimal):
        return str(obj)  # دقت حفظ می‌شود؛ در تحلیل با ::numeric قابل تبدیل است
    if isinstance(obj, Enum):
        return _jsonable(obj.value)
    if isinstance(obj, dict):
        return {str(k): _jsonable(v) for k, v in obj.items()}
    if isinstance(obj, (list, tuple, set, frozenset)):
        return [_jsonable(v) for v in obj]
    if hasattr(obj, "model_dump"):          # pydantic v2
        return _jsonable(obj.model_dump())
    if hasattr(obj, "__dataclass_fields__"):
        return _jsonable(vars(obj))
    return str(obj)                          # تور نهایی — هرگز raise نمی‌کند


# ---------------------------------------------------------------------------
# traces
# ---------------------------------------------------------------------------

async def trace_start(chat_id: int, message_id: int | None, kind: str,
                      source: str = "bale") -> str | None:
    """Open a new trace; returns its id (str) or None on failure."""
    try:
        async with SessionLocal() as s:
            t = BotTrace(chat_id=chat_id, message_id=message_id, kind=kind, source=source)
            s.add(t)
            await s.commit()
            return str(t.id)
    except Exception:
        logger.exception("obs: trace_start failed")
        return None


async def link_draft(trace_id: str | None, draft_id, draft_kind: str | None) -> None:
    """Attach a draft to its originating trace (so later button clicks can find it)."""
    if not trace_id:
        return
    try:
        async with SessionLocal() as s:
            await s.execute(
                update(BotTrace)
                .where(BotTrace.id == trace_id)
                .values(draft_id=str(draft_id), draft_kind=draft_kind)
            )
            await s.commit()
    except Exception:
        logger.exception("obs: link_draft failed")


async def latest_trace_for_draft(draft_id) -> str | None:
    """Newest trace that produced this draft — used by button/render flows."""
    try:
        async with SessionLocal() as s:
            row = (await s.execute(
                select(BotTrace.id)
                .where(BotTrace.draft_id == str(draft_id))
                .order_by(BotTrace.created_at.desc())
                .limit(1)
            )).scalar()
            return str(row) if row else None
    except Exception:
        logger.exception("obs: latest_trace_for_draft failed")
        return None


async def set_trace_status(trace_id: str | None, status: str,
                           committed_quote_id: str | None = None) -> None:
    if not trace_id:
        return
    try:
        async with SessionLocal() as s:
            values = {"status": status}
            if committed_quote_id:
                values["committed_quote_id"] = str(committed_quote_id)
            await s.execute(update(BotTrace).where(BotTrace.id == trace_id).values(**values))
            await s.commit()
    except Exception:
        logger.exception("obs: set_trace_status failed")


# ---------------------------------------------------------------------------
# events
# ---------------------------------------------------------------------------

async def event(trace_id, stage: str, *, ok: bool = True, latency_ms: int | None = None,
                model: str | None = None, field: str | None = None,
                payload: dict | None = None) -> None:
    """Append one pipeline event. Never raises; failures are loud in the log."""
    if not trace_id or not settings.OBS_ENABLED:
        return
    try:
        async with SessionLocal() as s:
            s.add(BotTraceEvent(
                trace_id=str(trace_id), stage=stage, ok=ok, latency_ms=latency_ms,
                model=model, field=field, payload=_jsonable(payload or {}),
            ))
            await s.commit()
    except Exception:
        logger.exception("obs: event %s failed", stage)   # خطای خاموش نمی‌ماند


async def log_resolution(trace_id, field: str, mention, status: str, candidates: list) -> None:
    """Record one matching attempt (difflib baseline / fallback paths)."""
    await event(trace_id, "routing.decision", field=field, payload={
        "source": "difflib",
        "mention": mention,
        "status": status,
        "candidates": candidates[:4],
    })


class span:
    """with span('stt.run', trace_id=t, provider='whisper'): ... → one DB event with latency/ok."""

    def __init__(self, name: str, trace_id: str | None = None, **attrs):
        self.name, self.trace_id, self.attrs = name, trace_id, attrs
        self._t0 = None

    def __enter__(self):
        import time as _t
        self._t0 = _t.perf_counter_ns()
        return self

    def __exit__(self, exc_type, exc, tb):
        import time as _t
        try:
            _fire(event(
                self.trace_id, self.name, ok=exc_type is None,
                latency_ms=int((_t.perf_counter_ns() - self._t0) / 1e6),
                model=self.attrs.get("model"), field=self.attrs.get("field"),
                payload=self.attrs,
            ))
        except Exception:
            logger.exception("obs: span %s failed", self.name)
        return False   # استثنا هرگز بلعیده نمی‌شود


# ---------------------------------------------------------------------------
# voice persistence (never deleted)
# ---------------------------------------------------------------------------

def save_voice(trace_id: str | None, message_id: int, content: bytes,
               ext: str = ".ogg") -> str | None:
    """Persist a voice note under OBS_VOICE_DIR; creates the day folder safely."""
    try:
        day = datetime.utcnow().strftime("%Y%m%d")
        base = Path(settings.OBS_VOICE_DIR) / day
        base.mkdir(parents=True, exist_ok=True)     # الزام سخت‌سازی: مسیر همیشه ساخته می‌شود
        path = base / f"{trace_id}_{message_id}{ext}"
        path.write_bytes(content)
        _mirror_bg(path, "audio/ogg")
        return str(path)
    except Exception:
        logger.warning("obs: save_voice failed for trace %s", trace_id, exc_info=True)
        return None


def save_enhanced_voice(trace_id: str | None, message_id: int, content: bytes,
                        ext: str = ".ogg") -> str | None:
    """Persist an enhanced voice note under OBS_VOICE_DIR/{YYYYMMDD}/{trace_id}_{message_id}_enhanced{ext}."""
    try:
        day = datetime.utcnow().strftime("%Y%m%d")
        base = Path(settings.OBS_VOICE_DIR) / day
        base.mkdir(parents=True, exist_ok=True)
        if ext and not ext.startswith("."):
            ext = f".{ext}"
        path = base / f"{trace_id}_{message_id}_enhanced{ext or '.ogg'}"
        path.write_bytes(content)
        _mirror_bg(path, "audio/ogg")
        return str(path)
    except Exception:
        logger.warning("obs: save_enhanced_voice failed for trace %s", trace_id, exc_info=True)
        return None


async def _mirror(path: Path, content_type: str) -> None:
    """Second copy in MinIO (fire-and-forget; see app/storage.py)."""
    try:
        from app import storage
        ref = storage.media_ref(path)
        if ref:
            await storage.mirror_to_minio(ref, path, content_type)
    except Exception:
        pass


def _mirror_bg(path: Path, content_type: str) -> None:
    """Sync-context wrapper around the MinIO mirror (never raises)."""
    try:
        asyncio.get_running_loop().create_task(_mirror(path, content_type))
    except RuntimeError:
        pass