Tag log lines with the chat, silence uvicorn access noise, log stack traces for unexpected failures

bot.py

@@ -15,6 +15,7 @@ del _sys
 import asyncio
 import atexit
 import contextlib
+import contextvars
 import hashlib
 import json
 import logging
@@ -81,6 +82,11 @@ def _current_log_secrets() -> tuple[str, ...]:
     return tuple(sorted(set(values), key=len, reverse=True))
 
 
+# Метка текущего чата на всех строках обработки: aiogram печатает только update
+# id, и собрать путь одного запроса по логу было нельзя (прод 27.10.2026).
+_LOG_CHAT: contextvars.ContextVar[str] = contextvars.ContextVar("log_chat", default="")
+
+
 class _SecretLogFormatter(logging.Formatter):
     def format(self, record: logging.LogRecord, _secrets=_current_log_secrets) -> str:
         # Секреты через замыкание, а не глобал: при финализации интерпретатора
@@ -88,6 +94,9 @@ class _SecretLogFormatter(logging.Formatter):
         # Остатки teardown глушим: строка без вычистки лучше шумного трейсбека.
         text = super().format(record)
         with contextlib.suppress(Exception):
+            chat = _LOG_CHAT.get()
+            if chat:
+                text = f"[{chat}] {text}"
             for secret in _secrets():
                 text = text.replace(secret, "<REDACTED>")
         return text
@@ -127,7 +136,9 @@ def _setup_logging() -> logging.Logger:
     for name in ("httpx", "google_genai", "aiohttp", "uvicorn.access"):
         logging.getLogger(name).setLevel(logging.WARNING)
     # Единый логгер "bot": __main__ в проде расходился с lumen_*.py (видно в Sentry).
-    return logging.getLogger("bot")
+    logger = logging.getLogger("bot")
+    logger.info("[setup] Logging: level=%s, file=%s", logging.getLevelName(level), LOG_FILE_PATH)
+    return logger
 
 logger = _setup_logging()
 log = logger
@@ -1287,6 +1298,16 @@ async def global_error_handler(event: Any) -> bool:
 
 @dp.message()
 async def handle_message(message: Message) -> None:
+    # Метка чата на всех строках обработки (см. _LOG_CHAT); сброс в finally —
+    # иначе значение утечёт в следующий апдейт этого же процесса.
+    token = _LOG_CHAT.set(f"chat={message.chat.id if message.chat else 0}")
+    try:
+        await _handle_message(message)
+    finally:
+        _LOG_CHAT.reset(token)
+
+
+async def _handle_message(message: Message) -> None:
     # Владельческая блокировка: ни ответа, ни контекста группы, ни счётчиков —
     # отсекаем раньше всего, включая медиагруппы и пассивный фон.
     if message.from_user is not None and _is_banned(message.from_user.id):
@@ -1574,7 +1595,10 @@ async def main() -> None:
     startup_task = asyncio.create_task(_webhook_startup(), name="webhook_startup")
     flush_task = asyncio.create_task(_flush_dirty_state(), name="state_flush")
     srv_config = uvicorn.Config(
-        app=app, host="0.0.0.0", port=7860, log_level="info", loop="asyncio", log_config=None,
+        # log_level=None: uvicorn с любым уровнем сам выставляет uvicorn.access
+        # обратно в INFO и перебивает глушение в _setup_logging — health-check
+        # GET / шёл в лог раз в минуту (прод 27.10.2026).
+        app=app, host="0.0.0.0", port=7860, log_level=None, loop="asyncio", log_config=None,
     )
     server = uvicorn.Server(srv_config)
     try:

lumen_admin.py

@@ -168,7 +168,7 @@ async def webhook_handler(request: Request) -> Any:
             log.warning("[webhook] Bot not initialized yet, asking Telegram to retry")
             return JSONResponse(status_code=503, content={"ok": False, "retry": True})
     except Exception as exc:
-        log.warning("[webhook] Failed to process incoming update: %s", exc)
+        log.warning("[webhook] Failed to process incoming update: %s", exc, exc_info=True)
         # Битое тело — не успех: пусть Telegram повторит, а не считает дроп
         # обработанным (аудит M2, 10.2026).
         return JSONResponse(status_code=503, content={"ok": False, "retry": True})

lumen_chat_state.py

@@ -719,7 +719,7 @@ async def _flush_dirty_state_once() -> None:
                     if _quota_generation == started_quota_generation:
                         _quota_dirty = False
     except Exception as exc:
-        log.warning('[state] Periodic state flush failed: %s', exc)
+        log.warning('[state] Periodic state flush failed: %s', exc, exc_info=True)
 
 
 async def _flush_dirty_state() -> None:

lumen_commands.py

@@ -327,7 +327,7 @@ async def _synthesize_tts_voice(text: str) -> tuple[bytes, str, int]:
                 log.warning("[tts] ffmpeg OGG conversion failed, falling back to raw audio")
                 final_filename = f"speech{src_ext}"
     except Exception as conv_exc:
-        log.warning("[tts] ffmpeg conversion error: %s", conv_exc)
+        log.warning("[tts] ffmpeg conversion error: %s", conv_exc, exc_info=True)
         final_filename = f"speech{src_ext}"
     return final_audio, final_filename, voice_duration
 

lumen_devtrace.py

@@ -88,7 +88,7 @@ def _append(kind: str, payload: dict) -> bool:
             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__)
+        log.warning("[devtrace] Failed to append trace entry: %s", exc.__class__.__name__, exc_info=True)
         return False
 
 

lumen_tiktok_flow.py

@@ -149,7 +149,7 @@ async def _send_tiktok_music(session, media_data: dict, message: Message, author
                         # Длительность — явно: без неё Telegram показывает 0:00 (та же история, что была с видео).
                         music_duration = await bot._probe_audio_duration(tmp_mp3_path)
          except Exception as tag_err:
-              log.warning("[tiktok] failed to write embedded tags to MP3: %s", tag_err)
+              log.warning("[tiktok] failed to write embedded tags to MP3: %s", tag_err, exc_info=True)
 
          # Слэш и управляющие из чужого названия — в "_" (AUD-E-005),
          # иначе multipart-имя файла битое.
@@ -517,10 +517,11 @@ async def handle_tiktok(message: Message, url: str) -> None:
          # Полные подписанные URL не пишем, только счётчики (аудит M7, 10.2026).
          if images_debug := media_data.get("images"):
               log.info(
-                   '[tikwm][diag] slideshow post: response keys=%s, images=%d, has_live_images=%s, has_play=%s has_hdplay=%s has_wmplay=%s',
-                   sorted(media_data.keys()), len(images_debug), bool(media_data.get("live_images")),
+                   '[tikwm][diag] slideshow post: images=%d, has_live_images=%s, has_play=%s has_hdplay=%s has_wmplay=%s',
+                   len(images_debug), bool(media_data.get("live_images")),
                    bool(media_data.get("play")), bool(media_data.get("hdplay")), bool(media_data.get("wmplay")),
               )
+              log.debug('[tikwm][diag] slideshow post keys=%s', sorted(media_data.keys()))
 
          author = (media_data.get("author") or {}).get("nickname") or bot._t(message.chat.id, "tiktok_author")
 

tests/test_bot_admin.py

@@ -535,6 +535,20 @@ def test_secret_log_formatter_survives_interpreter_teardown():
         bot._SECRET_NAMES = orig
 
 
+def test_secret_log_formatter_prefixes_and_clears_chat_context():
+    # Метка чата на строках обработки — единственная связь лога с чатом;
+    # сброс обязателен, иначе метка утечёт в следующий апдейт (прод 27.10.2026).
+    import logging
+    fmt = bot._SecretLogFormatter()
+    rec = logging.LogRecord("bot", logging.INFO, __file__, 1, "hello", (), None)
+    token = bot._LOG_CHAT.set("chat=42")
+    try:
+        assert fmt.format(rec) == "[chat=42] hello"
+    finally:
+        bot._LOG_CHAT.reset(token)
+    assert fmt.format(rec) == "hello"
+
+
 def _sleep_then_cancel(loop_sleeps):
     # Первые loop_sleeps+1 вызовов sleep проходят (1.5с старта + тики),
     # дальше CancelledError останавливает бесконечный цикл стартапа.