v0.0.51: максимальное логирование (LOG_LEVEL env) + детальные логи SSE/воркера для диагностики обрыва

History/2026-08-20-logging.md

@@ -0,0 +1,32 @@
+# 2026-08-20 — Максимальное логирование (v0.0.51)
+
+## Проблема
+SSE рвётся на проде (пару минут), обработка при этом продолжается (воркер жив).
+Логов в поде не было — приложение не писало в stdout, нельзя было диагностировать
+обрыв (внешний шлюз vs генератор).
+
+## Решение
+1. `site/app.py` — `setup_logging()`:
+   - уровень из env `LOG_LEVEL` (DEBUG/INFO/WARNING), default INFO
+   - `logging.basicConfig(..., stream=sys.stderr, force=True)` — в stdout/stderr пода
+   - формат с таймстампом; уровни для логгеров drhider/app/routes/session
+   - `LOG_LEVEL` задаётся через env-переменные приложения на платформе
+2. `site/routes/api_bp.py` — подробные логи:
+   - upload: каждый файл (имя, размер), итог, ошибки
+   - process_stream: start, worker start/done (время, токены, zip_len),
+     каждое событие progress (start/done) с idx/name/elapsed,
+     disconnect на heartbeat/progress/complete/error (с причиной),
+     result/complete, error event
+3. VERSION поднята до 0.0.51
+
+## Проверка (локально, DEBUG)
+Upload 1 файла + SSE: видны все события от upload до complete.
+`LLM NER failed: Illegal header value b'Bearer '` — ожидаемо без ключа (локально).
+
+## Как читать логи пода после деплоя
+```
+kubectl logs -n 20a75175-a58c-49cb-b8fa-e86367b1a8dc <pod> --tail=500 --timestamps
+```
+- Если `process_stream: disconnect on progress` — клиент/шлюз оборвал.
+- Если worker дошёл до `complete`, а клиент не получил — рвёт шлюз/браузер.
+- Если `worker: exception` — ошибка обработки.

site/app.py

@@ -12,6 +12,7 @@ DrHider — Managed Flask приложение на платформе Штур
 
 import os
 import sys
+import logging
 from flask import Flask
 
 # Добавляем корень проекта в sys.path для импорта пакета drhider
@@ -20,7 +21,27 @@ if _sys_path_root not in sys.path:
     sys.path.insert(0, _sys_path_root)
 
 # Версия приложения (меняется при изменениях)
-VERSION = "0.0.50"
+VERSION = "0.0.51"
+
+
+def setup_logging():
+    """Настроить логирование. Уровень берётся из env LOG_LEVEL (DEBUG/INFO/WARNING)."""
+    level_name = os.environ.get("LOG_LEVEL", "INFO").upper()
+    level = getattr(logging, level_name, logging.INFO)
+    logging.basicConfig(
+        level=level,
+        format="%(asctime)s %(levelname)s [%(name)s] %(message)s",
+        datefmt="%Y-%m-%d %H:%M:%S",
+        stream=sys.stderr,
+        force=True,
+    )
+    logging.getLogger("drhider").setLevel(level)
+    logging.getLogger("app").setLevel(level)
+    logging.getLogger("routes").setLevel(level)
+    logging.getLogger("session").setLevel(level)
+    logging.getLogger(__name__).setLevel(level)
+    log = logging.getLogger("app")
+    log.info("Logging configured, level=%s, version=%s", level_name, VERSION)
 
 
 def create_app():
@@ -34,6 +55,7 @@ def create_app():
     Returns:
         Экземпляр Flask с зарегистрированными blueprint'ами.
     """
+    setup_logging()
     app = Flask(__name__)
 
     # Конфигурация

site/routes/api_bp.py

@@ -15,6 +15,7 @@ import queue
 import threading
 import zipfile
 import traceback
+import logging
 from datetime import datetime, timedelta
 from flask import Blueprint, request, send_file, jsonify, Response, stream_with_context
 
@@ -23,6 +24,7 @@ from session import (create_session, add_file, get_files, store_result,
                      get_result, store_csv, get_csv, cleanup, file_count)
 
 api_bp = Blueprint("api", __name__, url_prefix="/api")
+log = logging.getLogger("routes.api_bp")
 
 
 def _disconnect_exceptions():
@@ -38,6 +40,7 @@ def upload():
         sid = create_session()
     uploaded = request.files.getlist("files")
     if not uploaded:
+        log.warning("upload: no files, sid=%s", sid)
         return jsonify({"ok": False, "error": "No file"}), 400
 
     added = 0
@@ -46,14 +49,19 @@ def upload():
         if not f.filename:
             had_unnamed = True
             continue
-        if not add_file(sid, f.filename, f.read()):
+        data = f.read()
+        log.info("upload: sid=%s file=%r size=%d", sid, f.filename, len(data))
+        if not add_file(sid, f.filename, data):
+            log.warning("upload: session not found/limit, sid=%s file=%r", sid, f.filename)
             return jsonify({"ok": False, "error": "Session not found"}), 404
         added += 1
 
     if added == 0:
         err = "No filename" if had_unnamed else "No file"
+        log.warning("upload: %s, sid=%s", err, sid)
         return jsonify({"ok": False, "error": err}), 400
 
+    log.info("upload: done sid=%s added=%d total=%d", sid, added, file_count(sid))
     return jsonify({"ok": True, "session": sid, "count": file_count(sid)})
 
 
@@ -73,6 +81,7 @@ def process_stream(sid):
         return jsonify({"ok": False, "error": "No files"}), 400
 
     all_files = [(fname, content, "") for fname, content in files]
+    log.info("process_stream: start sid=%s files=%d", sid, len(all_files))
 
     def generate():
         llm = LLMClient()
@@ -83,6 +92,8 @@ def process_stream(sid):
             q.put(("progress", phase, idx, name, total_, elapsed))
 
         def worker():
+            log.info("worker: start sid=%s files=%d", sid, len(all_files))
+            t0 = datetime.utcnow()
             try:
                 zip_data, csv_str = obfuscate_files(
                     all_files, llm_client=llm, progress_cb=progress
@@ -91,17 +102,23 @@ def process_stream(sid):
                     "tokens": llm.tokens_total,
                     "llm_sec": round(llm.llm_sec, 1),
                 }
+                dt = (datetime.utcnow() - t0).total_seconds()
+                log.info("worker: done sid=%s in %.1fs tokens=%d llm_sec=%.1f zip_len=%d",
+                         sid, dt, llm.tokens_total, llm.llm_sec, len(zip_data))
                 q.put(("result", zip_data, csv_str, stats))
             except Exception as e:
+                log.error("worker: exception sid=%s: %r\n%s", sid, e, traceback.format_exc())
                 q.put(("error", repr(e)))
 
         threading.Thread(target=worker, daemon=True).start()
+        log.debug("process_stream: worker thread started sid=%s", sid)
 
         while True:
             try:
                 evt = q.get(timeout=1)
             except queue.Empty:
                 if cancel.is_set():
+                    log.info("process_stream: cancelled sid=%s (generator exit)", sid)
                     return
                 # Heartbeat: живая статистика LLM (для таймера в UI)
                 try:
@@ -109,7 +126,8 @@ def process_stream(sid):
                         f"event: llm\n"
                         f"data: {json.dumps({'active': llm.llm_active, 'elapsed': round(llm.llm_elapsed_now(), 1), 'tokens': llm.tokens_total})}\n\n"
                     )
-                except _disconnect_exceptions():
+                except _disconnect_exceptions() as e:
+                    log.warning("process_stream: disconnect during heartbeat sid=%s err=%r", sid, e)
                     cancel.set()
                     return
                 continue
@@ -118,37 +136,45 @@ def process_stream(sid):
 
             if kind == "progress":
                 _, phase, idx, name, total_, elapsed = evt
+                log.debug("process_stream: event=%s idx=%d name=%r elapsed=%s sid=%s",
+                          phase, idx, name, elapsed, sid)
                 try:
                     yield (
                         f"event: {phase}\n"
                         f"data: {json.dumps({'idx': idx, 'name': name, 'total': total_, 'elapsed': elapsed})}\n\n"
                     )
-                except _disconnect_exceptions():
+                except _disconnect_exceptions() as e:
+                    log.warning("process_stream: disconnect on progress sid=%s phase=%s err=%r", sid, phase, e)
                     cancel.set()
                     return
 
             elif kind == "result":
                 _, zip_data, csv_str, stats = evt
+                log.info("process_stream: result sid=%s, storing result", sid)
                 store_result(sid, zip_data)
                 if csv_str:
                     store_csv(sid, csv_str)
                 count = 0
                 with zipfile.ZipFile(io.BytesIO(zip_data)) as zf:
                     count = len([n for n in zf.namelist() if n != "mapping.csv"])
+                log.info("process_stream: complete sid=%s count=%d stats=%r", sid, count, stats)
                 try:
                     yield (
                         f"event: complete\n"
                         f"data: {json.dumps({'total': count, **stats})}\n\n"
                     )
-                except _disconnect_exceptions():
+                except _disconnect_exceptions() as e:
+                    log.warning("process_stream: disconnect on complete sid=%s err=%r", sid, e)
                     return
                 return
 
             elif kind == "error":
                 _, msg = evt
+                log.error("process_stream: error event sid=%s msg=%r", sid, msg)
                 try:
                     yield f"event: error\ndata: {json.dumps({'error': msg})}\n\n"
-                except _disconnect_exceptions():
+                except _disconnect_exceptions() as e:
+                    log.warning("process_stream: disconnect on error sid=%s err=%r", sid, e)
                     return
                 return