From 59a66278a3d268440ac43f8da7e936b3e8b74096 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E2=80=9CNaeel=E2=80=9D?= Date: Thu, 20 Aug 2026 07:55:11 +0300 Subject: [PATCH] =?UTF-8?q?v0.0.51:=20=D0=BC=D0=B0=D0=BA=D1=81=D0=B8=D0=BC?= =?UTF-8?q?=D0=B0=D0=BB=D1=8C=D0=BD=D0=BE=D0=B5=20=D0=BB=D0=BE=D0=B3=D0=B8?= =?UTF-8?q?=D1=80=D0=BE=D0=B2=D0=B0=D0=BD=D0=B8=D0=B5=20(LOG=5FLEVEL=20env?= =?UTF-8?q?)=20+=20=D0=B4=D0=B5=D1=82=D0=B0=D0=BB=D1=8C=D0=BD=D1=8B=D0=B5?= =?UTF-8?q?=20=D0=BB=D0=BE=D0=B3=D0=B8=20SSE/=D0=B2=D0=BE=D1=80=D0=BA?= =?UTF-8?q?=D0=B5=D1=80=D0=B0=20=D0=B4=D0=BB=D1=8F=20=D0=B4=D0=B8=D0=B0?= =?UTF-8?q?=D0=B3=D0=BD=D0=BE=D1=81=D1=82=D0=B8=D0=BA=D0=B8=20=D0=BE=D0=B1?= =?UTF-8?q?=D1=80=D1=8B=D0=B2=D0=B0?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- History/2026-08-20-logging.md | 32 +++++++++++++++++++++++++++++++ site/app.py | 24 ++++++++++++++++++++++- site/routes/api_bp.py | 36 ++++++++++++++++++++++++++++++----- 3 files changed, 86 insertions(+), 6 deletions(-) create mode 100644 History/2026-08-20-logging.md diff --git a/History/2026-08-20-logging.md b/History/2026-08-20-logging.md new file mode 100644 index 0000000..a12106b --- /dev/null +++ b/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 --tail=500 --timestamps +``` +- Если `process_stream: disconnect on progress` — клиент/шлюз оборвал. +- Если worker дошёл до `complete`, а клиент не получил — рвёт шлюз/браузер. +- Если `worker: exception` — ошибка обработки. diff --git a/site/app.py b/site/app.py index 9b8fd9a..ff7f2bc 100644 --- a/site/app.py +++ b/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__) # Конфигурация diff --git a/site/routes/api_bp.py b/site/routes/api_bp.py index fa3198c..69abde2 100644 --- a/site/routes/api_bp.py +++ b/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