feat(observability): phase-1 silent pipeline recorder + phase-0 Jev validation

Phase 0 — Jev validated with the real key (5 Persian scenarios, api.typesafe.ai): stale project name «منشیانه»->«منشانه» conf 0.73 (ambiguity band), STT spelling variants «مصطفوی/مستفدی/مسطفی»->«بازرگانی مصطفوی» conf 0.93, exact «دفتر» 0.88, proper _none rejection for «کاغذ A4» 0.92, and two mentions in ONE request (0.77/0.64). Exact model version to pin: jev-1.13.0. Latency 0.7-1.1s per field request; ~450-650 in / 64-133 out tokens. Phase 1 — Observability (DB-only, zero extra LLM tokens, nothing is ever deleted): - new tables bot_traces + bot_trace_events (idempotent DDL in db_init.py; ORM in models.py) - new app/observability.py: _jsonable (UUID/datetime/Decimal/set/enum/dataclass-safe), trace_start, event, log_resolution, link_draft, latest_trace_for_draft, set_trace_status, span() context manager, save_voice (Path.mkdir parents+exist_ok, day folders) - capture points wired: input.text; input.voice (+voice persisted under OBS_VOICE_DIR); stt.run + per-provider stt.result (success AND failure, latency, model); nlu.request + nlu.result with prompt_hash/prompt_version; entities.extracted; routing.decision (difflib baseline for the phase-6 A/B); ambiguity.sent; ambiguity.user_choice (buttons + free-text reply path); user_choice.pick; draft.render; draft.edit (wizard-side edits detected by the sync loop); draft.commit (quote/supplier/material/project + trace status/quote id); draft.cancel - compose: persistent ./bot/data:/srv/bot/data volume; bot/.gitignore: data/ (runtime data never committed, never deleted) - tests: bot/tools/test_observability.py -> 8/8 pass (jsonable cases, trace lifecycle, JSONB round-trip, draft linking, status update, save_voice day-folder mkdir, span task). Verified live: voice file lands on the host volume and is gitignored; rows + files persist across bot restart.
2026-10-12 21:04:50 +03:30
parent 693e7511c6
commit d58b619107
16 changed files with 660 additions and 57 deletions
@@ -0,0 +1,140 @@
+"""Phase-1 tests for the Observability subsystem (run INSIDE the bot container):
+
+    docker compose exec bot python tools/test_observability.py
+
+Covers: _jsonable safety (UUID/datetime/Decimal/set/enum/dataclass), trace
+lifecycle, event round-trip through JSONB, draft linking, status updates,
+save_voice (day-folder mkdir), and the span() context manager.
+
+NOTE (policy): test rows/files are tagged `_test` and are NEVER deleted —
+the observability subsystem has no retention/cleanup by design.
+"""
+import asyncio
+import dataclasses
+import sys
+import uuid
+from datetime import datetime, timezone
+from decimal import Decimal
+from enum import Enum
+from pathlib import Path
+
+sys.path.insert(0, str(Path(__file__).resolve().parents[1]))
+
+from sqlalchemy import select
+
+from app import observability as obs
+from app.db import SessionLocal
+from app.db_init import ensure_schema
+from app.models import BotTrace, BotTraceEvent
+
+PASSED: list[str] = []
+FAILED: list[str] = []
+
+
+def check(name: str, ok: bool, extra: str = "") -> None:
+    (PASSED if ok else FAILED).append(name)
+    print(f"{'PASS' if ok else 'FAIL'}  {name}{'  — ' + str(extra) if extra else ''}")
+
+
+class SampleColor(Enum):
+    RED = "red"
+
+
+@dataclasses.dataclass
+class SampleRec:
+    a: int
+    b: str
+
+
+def test_jsonable() -> None:
+    payload = {
+        "uuid": uuid.uuid4(),
+        "dt": datetime(2026, 10, 12, 10, 30, tzinfo=timezone.utc),
+        "dec": Decimal("123.45"),
+        "set": {"x", "y"},
+        "enum": SampleColor.RED,
+        "dc": SampleRec(a=1, b="two"),
+        "nested": [{"inner": uuid.UUID(int=1)}],
+        "none": None,
+    }
+    out = obs._jsonable(payload)
+    ok = (
+        isinstance(out["uuid"], str)
+        and isinstance(out["dt"], str)
+        and isinstance(out["dec"], str)
+        and isinstance(out["set"], list)
+        and out["enum"] == "red"
+        and isinstance(out["dc"], dict)
+    )
+    check("_jsonable produces JSON-serializable output", ok,
+          f"dt={out['dt'][:19]}, dec={out['dec']!r}")
+
+
+async def main() -> None:
+    await ensure_schema()
+    test_jsonable()
+
+    # 1) trace lifecycle
+    tid = await obs.trace_start(chat_id=0, message_id=999001, kind="voice")
+    check("trace_start returns an id", bool(tid), str(tid))
+
+    # 2) events with tricky payloads (must not raise; must be stored)
+    await obs.event(tid, "input.voice", payload={
+        "_test": True, "size": 1234,
+        "when": datetime.now(timezone.utc),
+        "amount": Decimal("9.9"),
+    })
+    await obs.event(tid, "routing.decision", field="project", payload={
+        "_test": True,
+        "candidates": [{"id": uuid.uuid4(), "name": "منشانه"}],
+    })
+    await obs.log_resolution(tid, "supplier", "مصطفوی", "many",
+                             [{"id": "x", "name": "بازرگانی مصطفوی"}])
+
+    # 3) draft linking + latest lookup
+    draft_id = str(uuid.uuid4())
+    await obs.link_draft(tid, draft_id, "quote")
+    latest = await obs.latest_trace_for_draft(draft_id)
+    check("latest_trace_for_draft returns the linked trace", latest == tid, latest)
+
+    # 4) status update + JSONB round-trip
+    await obs.set_trace_status(tid, "committed", str(uuid.uuid4()))
+    async with SessionLocal() as s:
+        tr = (await s.execute(select(BotTrace).where(BotTrace.id == tid))).scalar_one()
+        check("trace status + quote id updated",
+              tr.status == "committed" and tr.committed_quote_id is not None)
+        rows = (await s.execute(
+            select(BotTraceEvent).where(BotTraceEvent.trace_id == tid)
+            .order_by(BotTraceEvent.id)
+        )).scalars().all()
+        check("events persisted", len(rows) >= 3, f"{len(rows)} rows")
+        proj = next((r for r in rows if r.stage == "routing.decision"), None)
+        check("JSONB payload round-trip keeps values as strings",
+              proj is not None and isinstance(proj.payload["candidates"][0]["id"], str))
+
+    # 5) save_voice (parents mkdir + day folder)
+    path = obs.save_voice(tid, 999001, b"OGGFAKE", ext=".ogg")
+    check("save_voice writes file under day folder",
+          bool(path) and Path(path).exists(), str(path))
+
+    # 6) span() context manager (fire-and-forget task)
+    with obs.span("span.test", trace_id=tid, note="unit"):
+        pass
+    await asyncio.sleep(0.4)
+    async with SessionLocal() as s:
+        n = (await s.execute(
+            select(BotTraceEvent).where(
+                BotTraceEvent.trace_id == tid, BotTraceEvent.stage == "span.test"
+            )
+        )).scalars().all()
+        check("span() recorded via background task", len(n) == 1, f"{len(n)} rows")
+
+    total = len(PASSED) + len(FAILED)
+    print(f"\n{len(PASSED)}/{total} passed")
+    if FAILED:
+        print("FAILED:", FAILED)
+        raise SystemExit(1)
+
+
+if __name__ == "__main__":
+    asyncio.run(main())