Add opt-in JSONL dev trace module, tests and docs

README.md

@@ -55,7 +55,7 @@ A Telegram bot styled after Claude's tone and personality (direct, warm, light o
 
 Lumen is a single FastAPI + aiogram service. Telegram delivers updates to a webhook. Each message gets routed through a chain of candidate models, built on the fly from the message's content: attachments, links, and a couple of lightweight heuristics for "does this need current information" and "is this a heavy request." Plain text starts on Groq, search and link reading go to Gemini, OpenRouter covers the rest; the first provider that answers wins, the next one is tried as a fallback if its whole chain fails. Models that already returned 429 today are skipped by the router.
 
-The codebase is a modular monolith. `bot.py` is the entry point and composition root; the rest is split into focused modules: `lumen_admin.py` (FastAPI app, secret gates, admin/diag/export endpoints), `lumen_message_core.py` (message-handling core), `lumen_routes.py` (LLM calls with fallback, `_run_route`), `lumen_streaming.py` (provider-agnostic streaming), `lumen_chat_state.py` (chat state, quotas, locks), `lumen_commands.py` (commands, TTS/draw pipelines, pick buttons), `lumen_tiktok_flow.py` (TikTok send orchestration), `lumen_rich.py` (sending: guests, Rich Messages, chunking), `lumen_media_flow.py` (Telegram attachment downloads), `lumen_transport_calls.py` (sessions, proxy rotation, Telegram calls), `lumen_errors.py` (model error classification), `lumen_limits.py` (rate window, pick queue), `lumen_router_config.py` (model routing), `lumen_formatting.py` (markdown to Telegram HTML, plus Rich Messages for tables/headings/math), `lumen_security.py` (injection and leak defenses), `lumen_message_parse.py` (links, draw/tts triggers, media references), `lumen_media.py` (mime types, file-id parsing), `lumen_images.py`, `lumen_tts.py`, `lumen_tiktok.py`, `lumen_telegram_transport.py`, `lumen_state_storage.py`, `lumen_typing_pace.py`, `lumen_model_speed.py`, and `lumen_lang.py` (bot language: system messages in 25 languages).
+The codebase is a modular monolith. `bot.py` is the entry point and composition root; the rest is split into focused modules: `lumen_admin.py` (FastAPI app, secret gates, admin/diag/export endpoints), `lumen_message_core.py` (message-handling core), `lumen_routes.py` (LLM calls with fallback, `_run_route`), `lumen_streaming.py` (provider-agnostic streaming), `lumen_chat_state.py` (chat state, quotas, locks), `lumen_commands.py` (commands, TTS/draw pipelines, pick buttons), `lumen_tiktok_flow.py` (TikTok send orchestration), `lumen_rich.py` (sending: guests, Rich Messages, chunking), `lumen_media_flow.py` (Telegram attachment downloads), `lumen_transport_calls.py` (sessions, proxy rotation, Telegram calls), `lumen_errors.py` (model error classification), `lumen_limits.py` (rate window, pick queue), `lumen_router_config.py` (model routing), `lumen_formatting.py` (markdown to Telegram HTML, plus Rich Messages for tables/headings/math), `lumen_security.py` (injection and leak defenses), `lumen_message_parse.py` (links, draw/tts triggers, media references), `lumen_media.py` (mime types, file-id parsing), `lumen_images.py`, `lumen_tts.py`, `lumen_tiktok.py`, `lumen_telegram_transport.py`, `lumen_state_storage.py`, `lumen_typing_pace.py`, `lumen_model_speed.py`, and `lumen_lang.py` (bot language: system messages in 25 languages). `lumen_devtrace.py` writes an opt-in JSONL trace (requests, answers, passive background) for prompt debugging.
 
 See **[docs/ARCHITECTURE.md](docs/ARCHITECTURE.md)** for a deeper look at routing, streaming, the security layers, and the TikTok downloader.
 
@@ -94,13 +94,14 @@ The proxy only forwards to an explicit host allowlist (`api.telegram.org`, `www.
 
 ## Diagnostics
 
-All three endpoints below require `Authorization: Bearer <ADMIN_PANEL_KEY>` (`/admin_keys`, covered in the deploy steps above, uses `BOT_TOKEN` instead):
+All endpoints below require `Authorization: Bearer <ADMIN_PANEL_KEY>` (`/admin_keys`, covered in the deploy steps above, uses `BOT_TOKEN` instead):
 
 | Endpoint | Purpose |
 |---|---|
 | `GET /diag` | Checks outbound network reachability (Telegram, Gemini, OpenRouter, TikWM, Pollinations, etc.) from inside the container. |
 | `GET /webhook_url` | Shows the computed webhook URL and a ready-to-open registration link. |
 | `GET /export_state` | Dumps all chat histories and quota counters as JSON, for manual backup. |
+| `GET /devtrace?n=200` | Tails the dev trace (requests, answers, passive background) as JSON, for prompt debugging. Needs `DEV_TRACE=1`. |
 
 `/logs` (a Telegram command, owner-only) sends the current `bot.log` with secrets redacted.
 

docs/ENVIRONMENT.md

@@ -145,6 +145,9 @@ These ceilings are fixed in code; change them only with a code edit:
 | `BOT_LOG_PATH` | `/app/bot.log` | Log file path. Mainly relevant for tests; leave it alone in production. |
 | `LOG_LEVEL` | `INFO` | Standard logging level (`DEBUG`/`INFO`/`WARNING`/...). |
 | `DIAG_TOTAL_BUDGET_SEC` | `25s` | Total budget for the `/diag` network check across all probed hosts, so a hanging host cannot hang the diagnostic. |
+| `DEV_TRACE` | `0` | Set to `1` to log every request, answer and passive group background as JSONL (`devtrace.jsonl` next to `bot.log`), for prompt debugging. Off by default: the file holds chat texts. |
+| `DEV_TRACE_PATH` | `<BOT_LOG_PATH dir>/devtrace.jsonl` | Where the dev trace file lives. Point it at a temp dir in tests. |
+| `DEV_TRACE_MAX_BYTES` | `5 MB` | File size cap before rotation to a single `.1` backup; garbage values fall back to the default. |
 | `ADMIN_SECRET_SEED` | — | Secret seed for deriving `WEBHOOK_SECRET` and `ADMIN_PANEL_KEY`. **Set it to its own random value, separate from `BOT_TOKEN`.** Without it both keys are derived from `BOT_TOKEN`, so a leaked token also exposes `/export_state` and `/webhook` (the bot logs a warning at startup). Changing the seed (or setting it for the first time) rotates both keys at once: on restart the bot re-registers the Telegram webhook with the new `WEBHOOK_SECRET` by itself, but anything using the old `ADMIN_PANEL_KEY` (browser bookmarks, cron export scripts) gets `401` until updated — fetch the new key via `GET /admin_keys` with Bearer `BOT_TOKEN`. |
 
 Sentry setup: create a free Python project at [sentry.io](https://sentry.io) (Developer tier: 5,000 events/month as of 06.10.2026), copy the DSN from the project settings, and add it as a Space secret.

lumen_devtrace.py

@@ -0,0 +1,182 @@
+"""lumen_devtrace.py — построчный JSONL-след запросов и ответов для разбора багов."""
+from __future__ import annotations
+
+import json
+import logging
+import os
+from datetime import datetime, timezone
+from pathlib import Path
+
+log = logging.getLogger("bot")
+
+_TRUE_VALUES = frozenset({"1", "true", "yes", "on"})
+
+_DEFAULT_MAX_BYTES = 5 * 1024 * 1024
+TAIL_HARD_CAP = 1000
+_USER_CLIP = 2000
+_REPLY_CLIP = 4000
+_CTX_TAIL_LINES = 3
+_CTX_CLIP = 500
+_ERROR_CLIP = 500
+
+
+def enabled() -> bool:
+    return os.getenv("DEV_TRACE", "").strip().lower() in _TRUE_VALUES
+
+
+def trace_path() -> Path:
+    explicit = os.getenv("DEV_TRACE_PATH", "").strip()
+    if explicit:
+        return Path(explicit)
+    # Рядом с bot.log: в тестах BOT_LOG_PATH уже ведёт во временный каталог.
+    base = os.path.dirname(os.getenv("BOT_LOG_PATH", "/app/bot.log")) or "/app"
+    return Path(base) / "devtrace.jsonl"
+
+
+def max_bytes() -> int:
+    try:
+        value = int(os.getenv("DEV_TRACE_MAX_BYTES", str(_DEFAULT_MAX_BYTES)).strip())
+    except (TypeError, ValueError):
+        return _DEFAULT_MAX_BYTES
+    # Мусор и нули в env давали бы ротацию на каждой строке.
+    return value if value >= 1024 else _DEFAULT_MAX_BYTES
+
+
+def _clip(text: str, limit: int) -> str:
+    if not isinstance(text, str):
+        text = str(text)
+    return text if len(text) <= limit else text[:limit]
+
+
+def _current_secrets() -> tuple[str, ...]:
+    # Ленивый импорт: bot импортирует этот модуль, топ-уровень закольцует.
+    try:
+        import bot as _bot
+        getter = getattr(_bot, "_current_log_secrets", None)
+        if callable(getter):
+            return tuple(getter())
+    except Exception:
+        pass
+    return ()
+
+
+def _scrub(text: str) -> str:
+    for secret in _current_secrets():
+        if secret:
+            text = text.replace(secret, "<REDACTED>")
+    return text
+
+
+def _append(kind: str, payload: dict) -> bool:
+    if not enabled():
+        return False
+    try:
+        payload["ts"] = datetime.now(timezone.utc).isoformat()
+        payload["kind"] = kind
+        path = trace_path()
+        path.parent.mkdir(parents=True, exist_ok=True)
+        if path.exists() and path.stat().st_size >= max_bytes():
+            # Один бэкап вместо series: диску на Space есть предел, старьё не копим.
+            backup = Path(str(path) + ".1")
+            try:
+                if backup.exists():
+                    backup.unlink()
+                path.rename(backup)
+            except OSError:
+                pass
+        with open(path, "a", encoding="utf-8") as f:
+            f.write(json.dumps(payload, ensure_ascii=False) + "\n")
+        return True
+    except Exception as exc:
+        log.warning("[devtrace] Failed to append trace entry: %s", exc.__class__.__name__)
+        return False
+
+
+def _route_names(route: list | None) -> list[str]:
+    names = []
+    for item in route or []:
+        if isinstance(item, (list, tuple)) and len(item) == 2:
+            names.append(f"{item[0]}:{item[1]}")
+        else:
+            names.append(str(item))
+    return names
+
+
+def record_passive(chat_id: int, text: str, *, is_private: bool = False, mentioned: bool = False) -> bool:
+    # Сначала вычистка, потом обрезка: секрет в хвосте иначе срезался бы молча.
+    return _append("passive", {
+        "chat_id": chat_id,
+        "text": _clip(_scrub(text or ""), _USER_CLIP),
+        "private": bool(is_private),
+        "mentioned": bool(mentioned),
+    })
+
+
+def record_blocked(chat_id: int, *, reason: str, prompt_len: int = 0) -> bool:
+    # Текст не пишем, только длину: тот же запрет, что у injection-варнинга в логе.
+    return _append("blocked", {"chat_id": chat_id, "reason": reason, "prompt_len": int(prompt_len)})
+
+
+def record_answer(
+    chat_id: int,
+    *,
+    user_text: str,
+    route: list | None = None,
+    provider: str = "",
+    model: str = "",
+    latency_ms: int = 0,
+    reply: str = "",
+    ctx_tail: list | None = None,
+    flags: dict | None = None,
+) -> bool:
+    tail = [_clip(_scrub(line), _CTX_CLIP) for line in (ctx_tail or []) if isinstance(line, str)]
+    return _append("answer", {
+        "chat_id": chat_id,
+        "user": _clip(_scrub(user_text or ""), _USER_CLIP),
+        "route": _route_names(route),
+        "provider": provider or "",
+        "model": model or "",
+        "latency_ms": int(latency_ms),
+        "ctx_tail": tail[-_CTX_TAIL_LINES:],
+        "flags": dict(flags or {}),
+        "reply": _clip(_scrub(reply or ""), _REPLY_CLIP),
+    })
+
+
+def record_failure(
+    chat_id: int, *, user_text: str, route: list | None = None, error: str = "", latency_ms: int = 0,
+) -> bool:
+    return _append("failure", {
+        "chat_id": chat_id,
+        "user": _clip(_scrub(user_text or ""), _USER_CLIP),
+        "route": _route_names(route),
+        "error": _clip(_scrub(error or ""), _ERROR_CLIP),
+        "latency_ms": int(latency_ms),
+    })
+
+
+def read_tail(n: int = 200) -> list[dict]:
+    try:
+        count = max(1, min(int(n), TAIL_HARD_CAP))
+    except (TypeError, ValueError):
+        count = 200
+    try:
+        path = trace_path()
+        if not path.exists():
+            return []
+        with open(path, "r", encoding="utf-8") as f:
+            lines = f.readlines()
+        # С конца до N валидных: битая строка в хвосте иначе съедала бы лимит.
+        out = []
+        for line in reversed(lines):
+            if len(out) >= count:
+                break
+            try:
+                item = json.loads(line)
+            except ValueError:
+                continue
+            if isinstance(item, dict):
+                out.append(item)
+        return out[::-1]
+    except OSError:
+        return []

tests/test_lumen_devtrace.py

@@ -0,0 +1,95 @@
+"""test_lumen_devtrace.py — JSONL-след запросов и ответов для разбора багов."""
+import asyncio
+from types import SimpleNamespace
+
+import bot
+import lumen_devtrace
+from tests.bot_test_helpers import _FakeAdminRequest
+
+
+def _enable_trace(monkeypatch, tmp_path):
+    monkeypatch.setenv("DEV_TRACE", "1")
+    monkeypatch.setenv("DEV_TRACE_PATH", str(tmp_path / "trace.jsonl"))
+
+
+def test_devtrace_disabled_by_default_writes_nothing(monkeypatch, tmp_path):
+    # Сторож: без DEV_TRACE=1 файл не создаётся даже при прямом вызове.
+    monkeypatch.delenv("DEV_TRACE", raising=False)
+    monkeypatch.setenv("DEV_TRACE_PATH", str(tmp_path / "trace.jsonl"))
+    assert lumen_devtrace.record_answer(1, user_text="hi", reply="hello") is False
+    assert not (tmp_path / "trace.jsonl").exists()
+
+
+def test_devtrace_answer_clips_and_redacts_secret(monkeypatch, tmp_path):
+    # Защищает разбор глупостей модели (полный маршрут и ответ в файле) и
+    # отсутствие секретов в нём: регрессия — сырой токен в trace-файле.
+    _enable_trace(monkeypatch, tmp_path)
+    monkeypatch.setattr(bot, "BOT_TOKEN", "devtrace-secret-abc")
+    ok = lumen_devtrace.record_answer(
+        5, user_text="devtrace-secret-abc " + "x" * 2500, route=[("groq", "m1")],
+        provider="groq", model="m1", latency_ms=12, reply="y" * 5000,
+    )
+    assert ok is True
+    raw = (tmp_path / "trace.jsonl").read_text(encoding="utf-8")
+    assert "devtrace-secret-abc" not in raw
+    assert "<REDACTED>" in raw
+    entries = lumen_devtrace.read_tail(10)
+    assert len(entries) == 1 and entries[0]["kind"] == "answer"
+    assert len(entries[0]["user"]) == 2000
+    assert len(entries[0]["reply"]) == 4000
+    assert entries[0]["route"] == ["groq:m1"]
+
+
+def test_devtrace_read_tail_returns_last_n_and_skips_broken(monkeypatch, tmp_path):
+    # Хвост для /devtrace: последние N и пропуск битых строк вместо 500.
+    _enable_trace(monkeypatch, tmp_path)
+    for i in range(5):
+        assert lumen_devtrace.record_passive(7, f"msg {i}") is True
+    with open(tmp_path / "trace.jsonl", "a", encoding="utf-8") as f:
+        f.write("{broken\n")
+    last = lumen_devtrace.read_tail(2)
+    assert [e["text"] for e in last] == ["msg 3", "msg 4"]
+
+
+def test_devtrace_endpoint_rejects_missing_or_wrong_key(monkeypatch):
+    original = bot.ADMIN_PANEL_KEY
+    bot.ADMIN_PANEL_KEY = "real-admin-key"
+    try:
+        result = asyncio.run(bot.devtrace(_FakeAdminRequest(headers={"Authorization": "Bearer wrong"})))
+        assert result.status_code == 401
+    finally:
+        bot.ADMIN_PANEL_KEY = original
+
+
+def test_devtrace_endpoint_returns_entries(monkeypatch, tmp_path):
+    # Сторож: валидный ключ отдаёт записанный след, а не пустой список.
+    _enable_trace(monkeypatch, tmp_path)
+    original = bot.ADMIN_PANEL_KEY
+    bot.ADMIN_PANEL_KEY = "real-admin-key"
+    try:
+        assert lumen_devtrace.record_failure(9, user_text="q", error="boom") is True
+        result = asyncio.run(bot.devtrace(_FakeAdminRequest(headers={"Authorization": "Bearer real-admin-key"})))
+        assert result["count"] == 1
+        assert result["entries"][0]["kind"] == "failure"
+        assert result["enabled"] is True
+    finally:
+        bot.ADMIN_PANEL_KEY = original
+
+
+def test_devtrace_passive_hook_writes_background(monkeypatch, tmp_path):
+    # Фон группы попадает в след: иначе разбирать влияние контекста не по чему.
+    from aiogram.enums import ChatType
+    _enable_trace(monkeypatch, tmp_path)
+    monkeypatch.setattr(bot, "_should_only_record_passively", lambda *a, **k: True)
+    monkeypatch.setattr(bot, "is_guest_message", lambda m: False)
+    monkeypatch.setattr(bot, "message_mentions_bot", lambda m: False)
+    msg = SimpleNamespace(
+        text="фоновый текст", caption=None,
+        chat=SimpleNamespace(id=777002, type=ChatType.GROUP),
+        from_user=SimpleNamespace(id=456), reply_to_message=None,
+    )
+    asyncio.run(bot._handle_message_core(msg))
+    entries = lumen_devtrace.read_tail(10)
+    assert entries and entries[-1]["kind"] == "passive"
+    assert "фоновый" in entries[-1]["text"]
+    bot.chat_state.pop(777002, None)